Hello Bogdan,<div><br></div><div><br></div><div><br></div><div>This is the scenario between the AS and S-CSCF</div><div><br></div><div><div>|Time | 172.22.36.199 |</div><div>| | | 172.17.48.250 | </div>
<div>|7,912 | INVITE SDP ( g711A g729 telephone-event) |SIP From: <a href="mailto:sip%3A%2B33171083330@172.22.38.3">sip:+33171083330@172.22.38.3</a> To:tel:+33603xxxxxx</div><div>| |(54725) ------------------> (5060) |</div>
<div>|7,927 | 100 Giving a try |SIP Status</div><div>| |(54725) <------------------ (5060) |</div><div>|7,929 | INVITE SDP ( g711A g729 telephone-event) |SIP Request</div>
<div>| |(5090) <------------------ (5060) |</div><div>|7,991 | 100 Trying| |SIP Status</div><div>| |(5090) ------------------> (5060) |</div><div>|8,062 | 183 Session Progress SDP ( g711A g729 telephon...vent) |SIP Status</div>
<div>| |(5090) ------------------> (5060) |</div><div>|8,070 | 183 Session Progress SDP ( g711A g729 telephon...vent) |SIP Status</div><div>| |(54725) <------------------ (5060) |</div>
<div>|11,544 | 180 Ringing SDP ( g711A g729 telephone-event) |SIP Status</div><div>| |(5090) ------------------> (5060) |</div><div>|11,551 | 180 Ringing SDP ( g711A g729 telephone-event) |SIP Status</div>
<div>| |(54725) <------------------ (5060) |</div><div>|17,383 | INVITE SDP ( g711A g729 telephone-event) |SIP Request</div><div>| |(5090) <------------------ (5060) |</div>
<div>|17,387 | CANCEL | |SIP Request</div><div>| |(5090) <------------------ (5060) |</div><div>|17,391 | 100 Trying| |SIP Status</div><div>| |(5090) ------------------> (5060) |</div>
<div>|17,392 | 200 OK | |SIP Status</div><div>| |(5090) ------------------> (5060) |</div><div>|17,414 | 487 Request Terminated SDP ( g711A g729 teleph...-event) |SIP Status</div>
<div>| |(5090) ------------------> (5060) |</div><div>|17,422 | ACK | |SIP Request</div><div>| |(5090) <------------------ (5060) |</div><div>|17,465 | 183 Session Progress SDP ( g711A g729 telephon...vent) |SIP Status</div>
<div>| |(5090) ------------------> (5060) |</div><div>|17,470 | 183 Session Progress SDP ( g711A g729 telephon...vent) |SIP Status</div><div>| |(54725) <------------------ (5060) |</div>
<div>|19,377 | 180 Ringing SDP ( g711A g729 telephone-event) |SIP Status</div><div>| |(5090) ------------------> (5060) |</div><div>|19,385 | 180 Ringing SDP ( g711A g729 telephone-event) |SIP Status</div>
<div>| |(54725) <------------------ (5060) |</div><div>|23,693 | <b><u> 408 Request Timeout </u></b> |SIP Status</div><div>| |(54725) <------------------ (5060) |</div><div>
|23,699 | ACK | |SIP Request</div><div>| |(54725) ------------------> (5060) |</div><div>|23,701 | CANCEL | |SIP Request</div><div>| |(5090) <------------------ (5060) |</div>
<div>|23,706 | 200 OK | |SIP Status</div><div>| |(5090) ------------------> (5060) |</div><div>|23,724 | 487 Request Terminated SDP ( g711A g729 teleph...-event) |SIP Status</div>
<div>| |(5090) ------------------> (5060) |</div><div>|23,735 | ACK | |SIP Request</div><div>| |(5090) <------------------ (5060) |</div></div><div><br></div>
<div>The problem is the 408 Timeout before the third call due to a timer overflow </div><div>I isolated the part of the log concerning this part: </div><div><br></div><div><div>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</div>
<div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 256, id 0 entered</div><div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:reply_received: FR_INV_TIMER = 5</div>
<div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:set_timer: relative timeout is 5</div><div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:insert_timer_unsafe: [1]: 0xb39753bc (270)</div>
<div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0</div><div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:core:destroy_avp_list: destroying list (nil)</div>
<div>Jul 19 15:54:23 intbims2 /usr/local/sbin/opensips[8166]: DBG:core:receive_msg: cleaning up</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:<b>timer_routine: timer routine:1,tl=0xb39753bc next=(nil), timeout=270</b></div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb3975140)</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:t_should_relay_response: T_code=180, new_code=408</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:<b>t_pick_branch: picked branch 1, code 408 (prio=800)</b></div><div>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</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 64, id 0 entered</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:cpl-c:reply_callback: negativ reply received</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:cpl-c:reply_callback: resuming proxying....</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:cpl-c:remove_first_location: removing <tel:+33603140607></div>
<div>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></div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:mk_proxy: doing DNS lookup...</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:str2ip: too few dots in []</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:str2ip6: too few colons in []</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:sip_resolvehost: no port, no proto -> do NAPTR lookup!</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:get_record: lookup(, 35) failed</div><div>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...</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:get_record: lookup(_sip._udp., 33) failed</div><div>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...</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: CRITICAL:core:mk_proxy: could not resolve hostname: ""</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: ERROR:tm:uri2proxy: bad host name in URI <tel:+33603xxxxxx></div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: ERROR:tm:t_forward_nonack: failure to add branches</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: ERROR:tm:w_t_relay: t_forward_nonack failed</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:relay_reply: branch=1, save=0, relay=1</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:parse_headers: flags=ffffffffffffffff</div>
<div>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</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:set_timer: relative timeout is 30</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:insert_timer_unsafe: [0]: 0xb3975224 (300)</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send: tcp connection found (0xb395c150), acquiring fd</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send: c= 0xb395c150, n=8</div><div>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)</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send: after receive_fd: c= 0xb395c150 n=4 fd=17</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send: sending...</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:tcp_send: after write: c= 0xb395c150 n=901 fd=17</div><div>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: <<a href="mailto:sip%3A%2B33171083330@172.22.38.3">sip:+33171083330@172.22.38.3</a>;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</div>
<div>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</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:run_trans_callbacks: trans=0xb3975140, callback type 256, id 0 entered</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:cpl-c:reply_callback: code=408, final reply received</div><div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:tm:build_local: using FROM=<From: <<a href="mailto:sip%3A%2B3317108xxxx@172.22.38.3">sip:+3317108xxxx@172.22.38.3</a>;user=phone>;tag=200113fc41ccf-2750515196-3-908-906-905-3321-jzbg53#015#012>, TO=<To: <tel:+33603140603>#015#012>, CSEQ_N=<CSeq: 1000></div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:parse_headers: flags=ffffffffffffffff</div><div>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</div>
<div>Jul 19 15:54:28 intbims2 /usr/local/sbin/opensips[8169]: DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16</div></div><div><br></div><div>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? </div>
<div><br></div><div>Thanks,</div><div><br></div><div><br></div><div>Mehdi Boudou</div><div><br></div><div><br></div>