[OpenSIPS-Users] CPL and Timer -->408 Timeout
mehdi boudou
mehdi.boudou at gmail.com
Mon Jul 19 20:03:05 CEST 2010
Hello Bogdan,
This is the scenario between the AS and S-CSCF
|Time | 172.22.36.199 |
| | | 172.17.48.250 |
|7,912 | INVITE SDP ( g711A g729 telephone-event) |SIP
From: sip:+33171083330 at 172.22.38.3
<sip%3A%2B33171083330 at 172.22.38.3>To:tel:+33603xxxxxx
| |(54725) ------------------> (5060) |
|7,927 | 100 Giving a try |SIP Status
| |(54725) <------------------ (5060) |
|7,929 | INVITE SDP ( g711A g729 telephone-event) |SIP
Request
| |(5090) <------------------ (5060) |
|7,991 | 100 Trying| |SIP Status
| |(5090) ------------------> (5060) |
|8,062 | 183 Session Progress SDP ( g711A g729 telephon...vent)
|SIP Status
| |(5090) ------------------> (5060) |
|8,070 | 183 Session Progress SDP ( g711A g729 telephon...vent)
|SIP Status
| |(54725) <------------------ (5060) |
|11,544 | 180 Ringing SDP ( g711A g729 telephone-event)
|SIP Status
| |(5090) ------------------> (5060) |
|11,551 | 180 Ringing SDP ( g711A g729 telephone-event)
|SIP Status
| |(54725) <------------------ (5060) |
|17,383 | INVITE SDP ( g711A g729 telephone-event) |SIP
Request
| |(5090) <------------------ (5060) |
|17,387 | CANCEL | |SIP Request
| |(5090) <------------------ (5060) |
|17,391 | 100 Trying| |SIP Status
| |(5090) ------------------> (5060) |
|17,392 | 200 OK | |SIP Status
| |(5090) ------------------> (5060) |
|17,414 | 487 Request Terminated SDP ( g711A g729 teleph...-event)
|SIP Status
| |(5090) ------------------> (5060) |
|17,422 | ACK | |SIP Request
| |(5090) <------------------ (5060) |
|17,465 | 183 Session Progress SDP ( g711A g729 telephon...vent)
|SIP Status
| |(5090) ------------------> (5060) |
|17,470 | 183 Session Progress SDP ( g711A g729 telephon...vent)
|SIP Status
| |(54725) <------------------ (5060) |
|19,377 | 180 Ringing SDP ( g711A g729 telephone-event)
|SIP Status
| |(5090) ------------------> (5060) |
|19,385 | 180 Ringing SDP ( g711A g729 telephone-event)
|SIP Status
| |(54725) <------------------ (5060) |
|23,693 | * 408 Request Timeout * |SIP Status
| |(54725) <------------------ (5060) |
|23,699 | ACK | |SIP Request
| |(54725) ------------------> (5060) |
|23,701 | CANCEL | |SIP Request
| |(5090) <------------------ (5060) |
|23,706 | 200 OK | |SIP Status
| |(5090) ------------------> (5060) |
|23,724 | 487 Request Terminated SDP ( g711A g729 teleph...-event)
|SIP Status
| |(5090) ------------------> (5060) |
|23,735 | ACK | |SIP Request
| |(5090) <------------------ (5060) |
The problem is the 408 Timeout before the third call due to a timer
overflow
I isolated the part of the log concerning this part:
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:relay_reply:
sent buf=0x81bf250: SIP/2.0 1..., shmem=0xb3974018: SIP/2.0 1
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]:
DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 256, id 0
entered
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]:
DBG:tm:reply_received: FR_INV_TIMER = 5
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:set_timer:
relative timeout is 5
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]:
DBG:tm:insert_timer_unsafe: [1]: 0xb39753bc (270)
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:t_unref:
UNREF_UNSAFE: after is 0
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]:
DBG:core:destroy_avp_list: destroying list (nil)
Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]:
DBG:core:receive_msg: cleaning up
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:*timer_routine:
timer routine:1,tl=0xb39753bc next=(nil), timeout=270*
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb3975140)
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:t_should_relay_response: T_code=180, new_code=408
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:*t_pick_branch:
picked branch 1, code 408 (prio=800)*
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:is_3263_failure: dns-failover test: branch=1, last_recv=408, flags=2
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 64, id 0 entered
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:cpl-c:reply_callback: negativ reply received
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:cpl-c:reply_callback: resuming proxying....
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:cpl-c:remove_first_location: removing <tel:+33603140607>
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:cpl-c:cpl_proxy_to_loc_set: rewriting Request-URI with
<tel:+33603140607>
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:mk_proxy:
doing DNS lookup...
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:str2ip:
too few dots in []
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:str2ip6:
too few colons in []
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:sip_resolvehost: no port, no proto -> do NAPTR lookup!
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:get_record: lookup(, 35) failed
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:sip_resolvehost: no valid NAPTR record found for , trying direct
SRV lookup...
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:get_record: lookup(_sip._udp., 33) failed
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:sip_resolvehost: no valid SRV record found for _sip._udp., trying A
record lookup...
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
CRITICAL:core:mk_proxy: could not resolve hostname: ""
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: ERROR:tm:uri2proxy:
bad host name in URI <tel:+33603xxxxxx>
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
ERROR:tm:t_forward_nonack: failure to add branches
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: ERROR:tm:w_t_relay:
t_forward_nonack failed
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:relay_reply:
branch=1, save=0, relay=1
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:parse_headers: flags=ffffffffffffffff
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:check_via_address: params 172.22.36.199, 172.22.36.199, 0
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:set_timer:
relative timeout is 30
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:insert_timer_unsafe: [0]: 0xb3975224 (300)
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
tcp connection found (0xb395c150), acquiring fd
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
c= 0xb395c150, n=8
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8183]:
DBG:core:handle_ser_child: read response= b395c150, 1, fd -1 from 6 (8169)
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
after receive_fd: c= 0xb395c150 n=4 fd=17
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
sending...
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
after write: c= 0xb395c150 n=901 fd=17
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send:
buf=#012SIP/2.0 408 Request Timeout#015#012Call-ID:
00113fc41ccf-2750515196-3-908-906-907-3322-gupn8h#015#012Via: SIP/2.0/TCP
172.22.36.199:5090;branch=z9hG4bK862e3fb38e31fe548d2092bf8751bfcb4c3ec9b3-1279550476850212#015#012Via:
SIP/2.0/UDP
127.0.0.1;branch=z9hG4bK_001_1024632600-1025213016;asp=0;ck;lsstag=st-1513-720#015#012Via:
SIP/2.0/UDP 172.22.36.198:5080;received=172.22.36.198;branch=z9hG4bKfdaf67716907f91b157d3bb9f42044814c3ec9a7-1279550476848556#015#012Via:
SIP/2.0/UDP
127.0.0.1;branch=z9hG4bK_003_987850520-985595992;lsstag=rt-3#015#012Via:
SIP/2.0/UDP 172.22.36.133:5060;received=172.22.36.133;branch=z9hG4bK00113fc41ccf-2750515196-3-908-906-905-3321-jzbg53%3857;rport=5060#015#012To:
<tel:+33603140603>;tag=8abe60dde66c8e792add81a9fe3c2011-34dd#015#012From: <
sip:+33171083330 at 172.22.38.3
<sip%3A%2B33171083330 at 172.22.38.3>;user=phone>;tag=200113fc41ccf-2750515196-3-908-906-905-3321-jzbg53#015#012CSeq:
1000 INVITE#015#012Server: OpenSIPS (1.5.0-notls
(i386/linux))#015#012Content-Length: 0#015#012#015#012
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:relay_reply:
sent buf=0x81bd7b8: SIP/2.0 4..., shmem=0xb396e7f8: SIP/2.0 4
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 256, id 0
entered
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:cpl-c:reply_callback: code=408, final reply received
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:build_local:
using FROM=<From:
<sip:+3317108xxxx at 172.22.38.3<sip%3A%2B3317108xxxx at 172.22.38.3>;user=phone>;tag=200113fc41ccf-2750515196-3-908-906-905-3321-jzbg53#015#012>,
TO=<To: <tel:+33603140603>#015#012>, CSEQ_N=<CSeq: 1000>
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:parse_headers: flags=ffffffffffffffff
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK76c1.42c8fc34.1>; state=6
Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]:
DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Must i set the T1 timer to another value to stop the overflow timer? How can
i do to permit the call with 3 locations?
Thanks,
Mehdi Boudou
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.opensips.org/pipermail/users/attachments/20100719/5ac4b63b/attachment.htm
More information about the Users
mailing list