here is debug logs when 480 is received from working sems master (bbc1e33a110b8f462dffd13a09dade3d9d8d26bc) and failing one (39f7685192bcccf51cf28453fd790148b24e508a).
looks like the major difference is here. working: Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [process, AmSession.cpp:713] DEBUG: AmSession processing event Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onRxReply, AmSipDialog.cpp:388] DEBUG: onRxReply(rep = 480 Temporalily Unavailable): transaction found! Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmB2BSession.cpp:470] DEBUG: onSipReply: INVITE -> 480 Temporalily Unavailable (fwd=false), c-t= Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmSession.cpp:832] DEBUG: Dialog status changed Trying -> Disconnected (stopped=false) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmB2BSession.cpp:511] DEBUG: relaying B2B SIP reply 480 Temporalily Unavailable ... failing: Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [process, AmSession.cpp:725] DEBUG: AmSession processing event Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [onRxReply, AmBasicSipDialog.cpp:397] DEBUG: onRxReply(rep = 480 Temporalily Unavailable): transaction found! Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [onRemoteDisappeared, AmB2BSession.cpp:567] DEBUG: remote unreachable, ending other leg -- juha
Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [run, udp_trsp.cpp:322] DEBUG: vv M [|] u recvd msg via UDP vv#012--++--#012SIP/2.0 480 Temporalily Unavailable#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKIR0tZaHP;rport=5090;received=127.0.0.1#015#012From: <sip:[email protected]>;tag=622BA3C3-544DF8A2000110C0-55D2B700#015#012To: sip:[email protected];tag=a7393417f396669b5dcacb2147836728.66dc#015#012CSeq: 10 INVITE#015#012Call-ID: 6271EFE2-544DF8A2000110D2-55D2B700#015#012Server: OpenXg SIP Proxy (4.2.0-0 (x86_64/linux))#015#012Content-Length: 0#015#012#015#012--++-- Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKIR0tZaHP Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [send_request, trans_layer.cpp:994] DEBUG: update_uac_request tt->_t =(nil) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [update_uac_request, trans_layer.cpp:1532] DEBUG: update_uac_request(t=0xc5c900) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [reset_timer, sip_trans.cpp:188] DEBUG: New timer of type A at time=721 (repeated=0) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [reset_timer, sip_trans.cpp:188] DEBUG: New timer of type B at time=2296 (repeated=0) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [reset_timer, sip_trans.cpp:188] DEBUG: New timer of type M at time=1096 (repeated=0) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [received_msg, trans_layer.cpp:1290] DEBUG: Reply matched an existing transaction Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [update_uac_reply, trans_layer.cpp:1341] DEBUG: update_uac_reply(reply code = 480, trans=0xc5c900) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [reset_timer, sip_trans.cpp:140] DEBUG: Clearing old timer of type A (this=0xc5ca10) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [reset_timer, sip_trans.cpp:140] DEBUG: Clearing old timer of type M (this=0xc5ca90) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [reset_timer, sip_trans.cpp:140] DEBUG: Clearing old timer of type B (this=0xc5ca50) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [send_non_200_ack, trans_layer.cpp:1722] DEBUG: About to send ACK Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [send, udp_trsp.cpp:245] DEBUG: send msg#012--++--#012ACK sip:[email protected] SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKIR0tZaHP;rport#015#012Route: <sip:127.0.0.1:5070;lr>#015#012From: <sip:[email protected]>;tag=622BA3C3-544DF8A2000110C0-55D2B700#015#012To: sip:[email protected];tag=a7393417f396669b5dcacb2147836728.66dc#015#012Call-ID: 6271EFE2-544DF8A2000110D2-55D2B700#015#012CSeq: 10 ACK#015#012#015#012--++-- Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [reset_timer, sip_trans.cpp:188] DEBUG: New timer of type D at time=2296 (repeated=0) Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:609] DEBUG: Received reply: 480 Temporalily Unavailable Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:610] DEBUG: reply.callid = <6271EFE2-544DF8A2000110D2-55D2B700> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:611] DEBUG: reply.from_tag = <622BA3C3-544DF8A2000110C0-55D2B700> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:612] DEBUG: reply.to_tag = <a7393417f396669b5dcacb2147836728.66dc> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:613] DEBUG: reply.contact = <> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:614] DEBUG: reply.to_uri = <> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:615] DEBUG: cseq = <10> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:616] DEBUG: reply.route = <> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:617] DEBUG: hdrs = <Server: OpenXg SIP Proxy (4.2.0-0 (x86_64/linux))#015#012> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:618] DEBUG: body-ct = <> Oct 27 09:47:46 siika sems[18755]: [#7f8755e2c700] [handle_sip_reply, SipCtrlInterface.cpp:624] DEBUG: ^^ M [6271EFE2-544DF8A2000110D2-55D2B700|622BA3C3-544DF8A2000110C0-55D2B700] ru SIP reply 480 Temporalily Unavailable handled ^^ Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [saveSessionDescription, AmB2BSession.cpp:610] DEBUG: saving session description (application/sdp, v=0#015#012o=- 1503660447 714259649 IN IP4 192.168.43.14...) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [process, AmSession.cpp:713] DEBUG: AmSession processing event Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onRxReply, AmSipDialog.cpp:388] DEBUG: onRxReply(rep = 480 Temporalily Unavailable): transaction found! Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmB2BSession.cpp:470] DEBUG: onSipReply: INVITE -> 480 Temporalily Unavailable (fwd=false), c-t= Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmSession.cpp:832] DEBUG: Dialog status changed Trying -> Disconnected (stopped=false) Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onSipReply, AmB2BSession.cpp:511] DEBUG: relaying B2B SIP reply 480 Temporalily Unavailable Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [relayEvent, AmB2BSession.cpp:541] DEBUG: AmB2BSession::relayEvent: to other_id='7C0536D4-544DF8A10002D22D-55F2D700' Oct 27 09:47:46 siika sems[18755]: [#7f8755d2b700] [processingCycle, AmSession.cpp:368] DEBUG: vv S [774418eafba908c6|7C0536D4-544DF8A10002D22D-55F2D700] Connected, running, 0 UACTransPending vv Oct 27 09:47:46 siika sems[18755]: [#7f8755d2b700] [process, Ivr.cpp:761] DEBUG: IvrDialog::process Oct 27 09:47:46 siika sems[18755]: [#7f8755d2b700] [onB2BEvent, AmB2BSession.cpp:953] DEBUG: 480 Temporalily Unavailable reply received from other leg Oct 27 09:47:46 siika sems[18755]: [#7f8755d2b700] [relayEvent, AmB2BSession.cpp:541] DEBUG: AmB2BSession::relayEvent: to other_id='622BA3C3-544DF8A2000110C0-55D2B700' Oct 27 09:47:46 siika sems[18755]: [#7f8755d2b700] [ivr_log, Ivr.cpp:80] INFO: Ivr-Python: test: got reply: 480 Temporalily Unavailable Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onB2BEvent, AmB2BSession.cpp:133] DEBUG: AmB2BSession::onB2BEvent Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [onB2BEvent, AmB2BSession.cpp:255] DEBUG: terminateLeg() Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [bye, AmSipDialog.cpp:900] DEBUG: bye(): we are not connected (status=Disconnected). do nothing! Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [processingCycle, AmSession.cpp:386] DEBUG: ^^ S [6271EFE2-544DF8A2000110D2-55D2B700|622BA3C3-544DF8A2000110C0-55D2B700] Disconnected, stopped, 0 UACTransPending ^^ Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [run, AmSession.cpp:271] DEBUG: session event loop ended, finalizing session Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [finalize, AmSession.cpp:447] DEBUG: running finalize sequence... Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [destroy, AmSession.cpp:487] DEBUG: AmSession::destroy() Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [stop, AmThread.cpp:114] DEBUG: Thread 140219235079936 (140219235079936) calling on_stop, give it a chance to clean up. Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [on_stop, AmSession.cpp:461] DEBUG: AmSession::stop() Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [clearAudio, AmSession.cpp:705] DEBUG: Audio cleared !!! Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [stop, AmThread.cpp:129] DEBUG: Thread 140219235079936 (140219235079936) finished detach. Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [finalize, AmSession.cpp:453] DEBUG: session is stopped. Oct 27 09:47:46 siika sems[18755]: [#7f8755b29700] [_start, AmThread.cpp:68] DEBUG: Thread 140219235079936 is ending. Oct 27 09:47:49 siika sems[18755]: [#7f8755d2b700] [ivr_log, Ivr.cpp:80] INFO: Ivr-Python: test: trying to connectCallee sip:[email protected]
Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [run, udp_trsp.cpp:322] DEBUG: vv M [|] u recvd msg via UDP vv#012--++--#012SIP/2.0 480 Temporalily Unavailable#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKYyfmnaL4;rport=5090;received=127.0.0.1#015#012From: <sip:[email protected]>;tag=42684DE3-544DF81E000EB41D-715F4700#015#012To: sip:[email protected];tag=a7393417f396669b5dcacb2147836728.cf24#015#012CSeq: 10 INVITE#015#012Call-ID: 55860D4E-544DF81E000EB430-715F4700#015#012Server: OpenXg SIP Proxy (4.2.0-0 (x86_64/linux))#015#012Content-Length: 0#015#012#015#012--++-- Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKYyfmnaL4 Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [received_msg, trans_layer.cpp:1310] DEBUG: Reply matched an existing transaction Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [update_uac_reply, trans_layer.cpp:1362] DEBUG: update_uac_reply(reply code = 480, trans=0x2922200) Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [reset_timer, sip_trans.cpp:143] DEBUG: Clearing old timer of type A (this=0x2922320) Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [reset_timer, sip_trans.cpp:143] DEBUG: Clearing old timer of type M (this=0x29223a0) Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [reset_timer, sip_trans.cpp:143] DEBUG: Clearing old timer of type B (this=0x2922360) Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [send_non_200_ack, trans_layer.cpp:1743] DEBUG: About to send ACK Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [send, udp_trsp.cpp:245] DEBUG: send msg#012--++--#012ACK sip:[email protected] SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1:5090;branch=z9hG4bKYyfmnaL4;rport#015#012Route: <sip:127.0.0.1:5070;lr>#015#012From: <sip:[email protected]>;tag=42684DE3-544DF81E000EB41D-715F4700#015#012To: sip:[email protected];tag=a7393417f396669b5dcacb2147836728.cf24#015#012Call-ID: 55860D4E-544DF81E000EB430-715F4700#015#012CSeq: 10 ACK#015#012#015#012--++-- Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [reset_timer, sip_trans.cpp:200] DEBUG: New timer of type D at time=7849 (repeated=0) Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:665] DEBUG: Received reply: 480 Temporalily Unavailable Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:666] DEBUG: reply.callid = <55860D4E-544DF81E000EB430-715F4700> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:667] DEBUG: reply.from_tag = <42684DE3-544DF81E000EB41D-715F4700> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:668] DEBUG: reply.to_tag = <a7393417f396669b5dcacb2147836728.cf24> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:669] DEBUG: reply.contact = <> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:670] DEBUG: reply.to_uri = <> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:671] DEBUG: cseq = <10> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:672] DEBUG: reply.route = <> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:673] DEBUG: hdrs = <Server: OpenXg SIP Proxy (4.2.0-0 (x86_64/linux))#015#012> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:674] DEBUG: body-ct = <> Oct 27 09:45:34 siika sems[18057]: [#7f71717f6700] [handle_sip_reply, SipCtrlInterface.cpp:680] DEBUG: ^^ M [55860D4E-544DF81E000EB430-715F4700|42684DE3-544DF81E000EB41D-715F4700] ru SIP reply 480 Temporalily Unavailable handled ^^ Oct 27 09:45:34 siika /usr/bin/sip-proxy[18183]: INFO: Routing in-dialog ACK <sip:127.0.0.1:5070;lr> from <sip:[email protected]> to <sip:127.0.0.1:5070;lr> based on route uri Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [processingCycle, AmSession.cpp:377] DEBUG: vv S [55860D4E-544DF81E000EB430-715F4700|42684DE3-544DF81E000EB41D-715F4700] Trying, running, 1 UACTransPending, 0 usages vv Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [process, AmSession.cpp:725] DEBUG: AmSession processing event Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [onRxReply, AmBasicSipDialog.cpp:397] DEBUG: onRxReply(rep = 480 Temporalily Unavailable): transaction found! Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [onRemoteDisappeared, AmB2BSession.cpp:567] DEBUG: remote unreachable, ending other leg Oct 27 09:45:34 siika sems[18057]: [#7f71713f2700] [relayEvent, AmB2BSession.cpp:517] DEBUG: AmB2BSession::relayEvent: to other_id='39C23EA7-544DF81E00011152-718F7700' Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [processingCycle, AmSession.cpp:377] DEBUG: vv S [9fb09c186cf9b349|39C23EA7-544DF81E00011152-718F7700] Connected, running, 0 UACTransPending, 0 usages vv Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [process, Ivr.cpp:764] DEBUG: IvrDialog::process Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [onB2BEvent, AmB2BSession.cpp:150] DEBUG: AmB2BSession::onB2BEvent Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [onB2BEvent, AmB2BSession.cpp:261] DEBUG: terminateLeg() Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port (5070) to int (5070) Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [set_next_hop, trans_layer.cpp:720] DEBUG: next_hop:next_port is <127.0.0.1:5070> Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [set_destination_ip, trans_layer.cpp:731] DEBUG: checking whether '127.0.0.1' is IP address... Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [set_destination_ip, trans_layer.cpp:773] DEBUG: set destination to 127.0.0.1:5070 Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [send_request, trans_layer.cpp:927] DEBUG: send_request to R-URI <sip:[email protected];gr=urn:uuid:c9a3fff2-15f1-4b85-84b3-99598e3b8860> Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [parse_sip_uri, parse_uri.cpp:332] DEBUG: Converted URI port () to int (5060) Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [parse_via_params, parse_via.cpp:525] DEBUG: parsed branch: z9hG4bKmLfCPajN Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [parse_via_params, parse_via.cpp:548] DEBUG: has_rport: 1 Oct 27 09:45:34 siika sems[18057]: [#7f71715f4700] [send_request, trans_layer.cpp:997] DEBUG: Sending to 127.0.0.1:5070 <BYE sip:[email protected];gr=urn:uuid:c9a3fff2-15...>
_______________________________________________ Semsdev mailing list [email protected] http://lists.iptel.org/mailman/listinfo/semsdev
