[prev in list] [next in list] [prev in thread] [next in thread]
List: semsdev
Subject: [Semsdev] ivr script works in 1.5 branch, but fails in master
From: Juha Heinanen <jh () tutpro ! com>
Date: 2014-10-27 8:28:58
Message-ID: 21582.586.918789.883338 () tutpro ! com
[Download RAW message or body]
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
["working.480" (text/plain)]
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:jh@test.tutpro.com>;tag=622BA3C3-544DF8A2000110C0-55D2B700#015#012To: \
sip:foo@test.tutpro.com;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:foo@test.tutpro.com 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:jh@test.tutpro.com>;tag=622BA3C3-544DF8A2000110C0-55D2B700#015#012To: \
sip:foo@test.tutpro.com;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:test@test.tutpro.com
["failing.480" (text/plain)]
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:jh@test.tutpro.com>;tag=42684DE3-544DF81E000EB41D-715F4700#015#012To: \
sip:foo@test.tutpro.com;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:foo@test.tutpro.com 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:jh@test.tutpro.com>;tag=42684DE3-544DF81E000EB41D-715F4700#015#012To: \
sip:foo@test.tutpro.com;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:jh@test.tutpro.com> 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:jh@test.tutpro.com;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:jh@test.tutpro.com;gr=urn:uuid:c9a3fff2-15...>
_______________________________________________
Semsdev mailing list
Semsdev@lists.iptel.org
http://lists.iptel.org/mailman/listinfo/semsdev
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic