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 >> >> > > > -- > Bogdan-Andrei Iancu > www.voice-system.ro > > > _______________________________________________ > Users mailing list > [email protected] > http://lists.opensips.org/cgi-bin/mailman/listinfo/users > _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
