[Spce-user] Getting 408 timeout on fresh install of mr4.1.2.
Venkatesh U
venkatesh.umaashankar at gmail.com
Sat Mar 19 14:10:20 EDT 2016
Hi All,
I have followed the handbook step by step. When I try to make an internal
call, I get 408 timeout error. I use CSipSimple (Android dialer) as my
softphone. This works fine when I use this softphone with other pbx
providers such pbxes.org or with voipswitch. I am not able to figure out
the reason. I would very much appreciate any help regarding this
here are my debugging inputs
root at sipwise:/var/log/ngcp# netstat -tulnp | grep kamailio
tcp 0 0 127.0.0.1:5060 0.0.0.0:* LISTEN
3222/kamailio
tcp 0 0 104.131.22.146:5060 0.0.0.0:* LISTEN
3222/kamailio
tcp 0 0 104.131.22.146:5061 0.0.0.0:* LISTEN
3222/kamailio
tcp 0 0 127.0.0.1:5062 0.0.0.0:* LISTEN
3987/kamailio
udp 0 0 127.0.0.1:5060 0.0.0.0:*
3182/kamailio
udp 0 0 104.131.22.146:5060 0.0.0.0:*
3182/kamailio
udp 0 0 127.0.0.1:5062 0.0.0.0:*
3834/kamailio
*Logs from load balancer*
root at sipwise:/var/log/ngcp# grep hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
kamailio-lb.log
Mar 19 13:30:09 sipwise (local6.notice) lb[3187]: NOTICE: <script>: New
request on lb - M=INVITE R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=udp:
183.83.51.102:45534 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local6.notice) lb[3187]: NOTICE: <script>:
Relaying request, du='sip:127.0.0.1:5062', fs='udp:127.0.0.1:5060' - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local6.notice) lb[3198]: NOTICE: <script>: Reply
from Inbound - S=100 - Trying M=INVITE IP=udp:127.0.0.1:5062
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3198]: NOTICE: <script>: Sending
reply, fs='udp:104.131.22.146:5060' - ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3199]: NOTICE: <script>: Reply
from Inbound - S=407 - Proxy Authentication Required M=INVITE IP=udp:
127.0.0.1:5062 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3199]: NOTICE: <script>: Sending
reply, fs='udp:104.131.22.146:5060' - ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3189]: NOTICE: <script>: New
request on lb - M=ACK R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=udp:
183.83.51.102:45534 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3189]: NOTICE: <script>:
Relaying request, du='sip:127.0.0.1:5062', fs='udp:127.0.0.1:5060' - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3190]: NOTICE: <script>: New
request on lb - M=INVITE R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=udp:
183.83.51.102:45534 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local6.notice) lb[3190]: NOTICE: <script>:
Relaying request, du='sip:127.0.0.1:5062', fs='udp:127.0.0.1:5060' - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local6.notice) lb[3197]: NOTICE: <script>: Reply
from Inbound - S=100 - Trying M=INVITE IP=udp:127.0.0.1:5062
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3197]: NOTICE: <script>: Sending
reply, fs='udp:104.131.22.146:5060' - ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3202]: NOTICE: <script>: Reply
from Inbound - S=101 - Connecting M=INVITE IP=udp:127.0.0.1:5062
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3203]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:09 sipwise (local6.notice) lb[3203]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:10 sipwise (local6.notice) lb[3195]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:10 sipwise (local6.notice) lb[3195]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:11 sipwise (local6.notice) lb[3194]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:11 sipwise (local6.notice) lb[3194]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:13 sipwise (local6.notice) lb[3200]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:13 sipwise (local6.notice) lb[3200]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:17 sipwise (local6.notice) lb[3198]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:17 sipwise (local6.notice) lb[3198]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:25 sipwise (local6.notice) lb[3197]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:25 sipwise (local6.notice) lb[3197]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3202]: NOTICE: <script>: New
request on lb - M=INVITE
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
F=sip:919677225561 at 104.131.22.146 T=sip:fm1000101 at 104.131.22.146 IP=udp:
127.0.0.1:5080 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3202]: NOTICE: <script>:
Relaying request, du='<null>', fs='udp:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff_b2b-1 UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3203]: NOTICE: <script>: Reply
from Inbound - S=408 - Request Timeout M=INVITE IP=udp:127.0.0.1:5062
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3203]: NOTICE: <script>: Sending
reply, fs='udp:104.131.22.146:5060' - ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3192]: NOTICE: <script>: New
request on lb - M=ACK R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=udp:
183.83.51.102:45534 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:41 sipwise (local6.notice) lb[3192]: NOTICE: <script>:
Relaying request, du='sip:127.0.0.1:5062', fs='udp:127.0.0.1:5060' - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
*Logs from proxy*
root at sipwise:/var/log/ngcp# grep hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
kamailio-proxy.log
Mar 19 13:30:09 sipwise (local7.notice) proxy[3916]: NOTICE: <script>: New
request on proxy - M=INVITE R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=
183.83.51.102:45534 (127.0.0.1:5060) ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3916]: NOTICE: <script>:
Authentication failed, no credentials - R=sip:919444763417 at 104.131.22.146
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>: New
request on proxy - M=INVITE R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=
183.83.51.102:45534 (127.0.0.1:5060) ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
User-Provided CLI 'fm1000102' taken from From-User - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
User-provided CLI 'fm1000102' rejected, using network-provided CLI
'919677225561' - R=sip:919444763417 at 104.131.22.146
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting '919677225561 at 104.131.22.146' as initiating user-provided CLI - R=
sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting '919677225561 at 104.131.22.146' as initiating network-provided CLI -
R=sip:919444763417 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Callee was aliased with base '919444763417' - R=sip:fm1000101 at 104.131.22.146
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Callee is local, uuid='5944e76d-bffb-4473-91e7-c300940bf007' - R=
sip:fm1000101 at 104.131.22.146 ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting acc source-leg for uuid '2370fa89-debc-41a3-9dd6-2b0750bb8dcf':
'2370fa89-debc-41a3-9dd6-2b0750bb8dcf|fm1000102|104.131.22.146|919677225561|||4|||0|call|183.83.51.102|1458408609.549210|||||||||||'
- R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting acc destination-leg for uuid
'5944e76d-bffb-4473-91e7-c300940bf007':
'0|||3|919444763417|5944e76d-bffb-4473-91e7-c300940bf007|fm1000101|104.131.22.146|919444763417|104.131.22.146|0|||||||||||'
- R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting caller_cli_userprov/caller_domain_userprov '
919677225561 at 104.131.22.146' for upn -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting From to '<sip:919677225561 at 104.131.22.146>' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting caller_cli_netprov/caller_domain_netprov '
919677225561 at 104.131.22.146' for npn -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting PAI to '<sip:919677225561 at 104.131.22.146>' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Setting P-Called-Party-ID '<sip:fm1000101 at 104.131.22.146>' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Appending P-D-URI 'sip:lb at 127.0.0.1;lr;socket=sip:104.131.22.146:5060' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Forcing request via B2BUA 'sip:127.0.0.1:5080' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3912]: NOTICE: <script>:
Request leaving server, D-URI='sip:127.0.0.1:5080' -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:09 sipwise (local7.notice) proxy[3922]: NOTICE: <script>:
NAT-Reply - S=100 - Connecting M=INVITE IP=183.83.51.102:45534 (
127.0.0.1:5080) ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:41 sipwise (local7.notice) proxy[3905]: NOTICE: <script>:
NAT-Reply - S=408 - Timeout M=INVITE IP=183.83.51.102:45534 (127.0.0.1:5080)
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='<null>'
Mar 19 13:30:41 sipwise (local7.notice) proxy[3905]: NOTICE: <script>:
Failure route for local call -
R=sip:fm1000101 at 183.83.51.102:45518;transport=udp;rinstance=714d04fe8832fb43
ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff UA='CSipSimple_osprey_ud2-22/r2457'
Mar 19 13:30:41 sipwise (local7.notice) proxy[3906]: NOTICE: <script>: New
request on proxy - M=ACK R=sip:919444763417 at 104.131.22.146 F=
sip:fm1000102 at 104.131.22.146 T=sip:919444763417 at 104.131.22.146 IP=
183.83.51.102:45534 (127.0.0.1:5060) ID=hNlZsxlKlpxEERsEYRUYoLoXqHbIp9ff
UA='<null>'
Thanks,
Venki
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20160319/d2bd6113/attachment.html>
More information about the Spce-user
mailing list