Hi Brett, could you post the logs (even privately) of the entire call ?
Regards, Bogdan Brett Nemeroff wrote: > Bogdan, > I didn't see anything odd about the ACK.. The RURI in it matched the > original RURI from the INVITE... > > U 5.6.7.8:5060 -> 10.249.126.19:5060 > INVITE sip:[email protected] SIP/2.0. > Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport. > From: "15125551212" <sip:[email protected]>;tag=as2c0ca056. > To: <sip:[email protected]>. > Contact: <sip:[email protected]>. > Call-ID: [email protected]. > CSeq: 102 INVITE. > User-Agent: Asterisk PBX. > Max-Forwards: 70. > Remote-Party-ID: "15125551212" > <sip:[email protected]>;privacy=off;screen=no. > Date: Tue, 13 Apr 2010 13:08:25 GMT. > Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO. > Supported: replaces. > Content-Type: application/sdp. > Content-Length: 236. > > > U 10.249.126.19:5060 -> 5.6.7.8:5060 > SIP/2.0 503 Cannot route. > Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport=5060. > From: "15125551212" <sip:[email protected]>;tag=as2c0ca056. > To: <sip:[email protected]>;tag=155c340f586c28d0300cf5a6ccf90d99-c2f7. > Call-ID: [email protected]. > CSeq: 102 INVITE. > Server: OpenSIPS (1.6.2-notls (i386/linux)). > Content-Length: 0. > . > > > U 5.6.7.8:5060 -> 10.249.126.19:5060 > ACK sip:[email protected] SIP/2.0. > Via: SIP/2.0/UDP 5.6.7.8:5060;branch=z9hG4bK70c91e1d;rport. > From: "15125551212" <sip:[email protected]>;tag=as2c0ca056. > To: <sip:[email protected]>;tag=155c340f586c28d0300cf5a6ccf90d99-c2f7. > Contact: <sip:[email protected]>. > Call-ID: [email protected]. > CSeq: 102 ACK. > User-Agent: Asterisk PBX. > Max-Forwards: 70. > Remote-Party-ID: "15125551212" > <sip:[email protected]>;privacy=off;screen=no. > Content-Length: 0. > > .. > > > >From what I understand from the syslog, it appears that the ACK does > match a transaction. but it still performs the retrans.. I hope this > is the right segment to be useful... > ... > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:t_lookup_request: start searching: hash=18475, isACK=1 > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:matching_3261: RFC3261 transaction matched, tid=579b7283 > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:t_lookup_request: REF_UNSAFE: after is 2 > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:t_lookup_request: transaction found (T=0xb60be734) > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:cleanup_uac_timers: RETR/FR timers reset > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:insert_timer_unsafe: [2]: 0xb60be77c (31591) > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:tm:t_unref: UNREF_UNSAFE: after is 1 > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:core:destroy_avp_list: destroying list (nil) > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8177]: > DBG:core:receive_msg: cleaning up > Apr 13 13:16:55 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8178]: > DBG:tm:_reply_light: finished > … > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:utimer_routine: timer routine:4,tl=0xb60be880 next=0xb60be7fc, > timeout=31572400000 > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:utimer_routine: timer routine:4,tl=0xb60be7fc next=(nil), > timeout=31572400000 > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : reply > resending (t=0xb60be734, SIP/2.0 5 ... ) > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5..., > shmem=0xb60bc67c: SIP/2.0 5 > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:set_timer: relative timeout is 1000000 > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:insert_timer_unsafe: [5]: 0xb60be7fc (31573400000) > Apr 13 13:16:56 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : done > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:utimer_routine: timer routine:5,tl=0xb60be7fc next=(nil), > timeout=31573400000 > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : reply > resending (t=0xb60be734, SIP/2.0 5 ... ) > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5..., > shmem=0xb60bc67c: SIP/2.0 5 > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:set_timer: relative timeout is 2000000 > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:insert_timer_unsafe: [6]: 0xb60be7fc (31575400000) > Apr 13 13:16:57 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : done > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:utimer_routine: timer routine:6,tl=0xb60be7fc next=(nil), > timeout=31575400000 > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : reply > resending (t=0xb60be734, SIP/2.0 5 ... ) > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:t_retransmit_reply: buf=0x78e040: SIP/2.0 5..., > shmem=0xb60bc67c: SIP/2.0 5 > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:set_timer: relative timeout is 4000000 > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:insert_timer_unsafe: [7]: 0xb60be7fc (31579400000) > Apr 13 13:16:59 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:retransmission_handler: retransmission_handler : done > Apr 13 13:17:00 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:timer_routine: timer routine:0,tl=0xb60be818 next=(nil), > timeout=31576 > Apr 13 13:17:01 domU-XX-XX-XX-XX-XX-XX /usr/local/sbin/opensips[8182]: > DBG:tm:timer_routine: timer routine:1,tl=0xb60be89c next=(nil), > timeout=31577 > > Thanks for your help! > -Brett > > > On Tue, Apr 13, 2010 at 5:24 AM, Bogdan-Andrei Iancu > <[email protected]> wrote: > >> Hi Brett, >> >> in the failing case, maybe the received ACK does not match the >> transaction, so opensips keeps retransmitting - could you post the >> received INVITE, the sent 503 and the received ACK ? >> >> Regards, >> Bogdan >> >> Brett Nemeroff wrote: >> >>> Hello all, >>> I'm pretty sure I'm missing something obvious here.. >>> >>> After hitting a failure route, I'm seeing retransmissions with a >>> t_reply. If I clear out the failure_route, opensips generates a 500, >>> which is sent out and it's happy with. Almost like the 500 (which is >>> internally generated) is sent statelessly, from a failure route? >>> Opensips sits on a server with a private IP and is NATed. I've set the >>> outside IP address in the advertised_address config param. >>> >>> >>> failure_route[1] { >>> xlog("L_INFO","In failure route"); >>> } >>> >>> >>> (opensips at 10.249.126.19) >>> 0.052840 10.249.126.19 -> 1.2.3.4 SIP/SDP Request: INVITE >>> sip:[email protected], with session description >>> 0.061683 1.2.3.4 -> 10.249.126.19 SIP Status: 100 Trying >>> 0.062550 1.2.3.4 -> 10.249.126.19 SIP Status: 503 Service Unavailable >>> 0.062637 10.249.126.19 -> 1.2.3.4 SIP Request: ACK sip:[email protected] >>> 0.062724 10.249.126.19 -> 5.6.7.8 SIP Status: 500 Service Unavailable >>> 0.100239 5.6.7.8 -> 10.249.126.19 SIP Request: ACK >>> sip:[email protected] >>> (No retransmissions.. everyone happy) >>> >>> >>> --------------- >>> >>> Now if I put a t_reply in there.. >>> failure_route[1] { >>> xlog("L_INFO","In failure route"); >>> t_reply("503","Cannot route"); >>> exit; >>> } >>> >>> >>> 0.042059 10.249.126.19 -> 1.2.3.4 SIP/SDP Request: INVITE >>> sip:[email protected], with session description >>> 0.051466 1.2.3.4 -> 10.249.126.19 SIP Status: 100 Trying >>> 0.051919 1.2.3.4 -> 10.249.126.19 SIP Status: 503 Service Unavailable >>> 0.052222 10.249.126.19 -> 1.2.3.4 SIP Request: ACK sip:[email protected] >>> 0.052436 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route >>> 0.089601 5.6.7.8 -> 10.249.126.19 SIP Request: ACK >>> sip:[email protected] >>> 1.030506 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route >>> 2.030507 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route >>> 4.030615 10.249.126.19 -> 5.6.7.8 SIP Status: 503 Cannot route >>> (not happy) >>> >>> >>> Any ideas?? >>> Thanks! >>> -Brett >>> >>> _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
