Hello, I am trying to call a softphone via a Java Applet application. I have a VPN and there is no proxy just Freeswitch between the 2 phones. Everything works fine with 2 SJPhones. But trying it with my Applet causes -> Reason: Q.850;cause=16;text="NORMAL_CLEARING". When I check the network traffic I see that after 100(Trying) comes directly 200(OK). By using SJPhone it is 183(Session Progress) after 100(Trying) and the connection is esablished for voice communication. I also attached the SIP outputs and the log from server ( generated with "sofia loglevel all 9" ). I have searched a lot of sites but I haven't found the problem. I appreciate any help, Thanks, Melih +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ INVITE sip:1000@xx.yy.zz.1 SIP/2.0 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 1 INVITE From: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 To: <sip:1000@xx.yy.zz.1> Via: SIP/2.0/UDP xx.yy.zz.66:4829;rport;branch=z9hG4bK89f52f6729c740781eac05ab4a1a99bb Max-Forwards: 70 Contact: <sip:1016@xx.yy.zz.66> User-Agent: JavaSoftPhone v1.0 Supported: replaces,norefersub,timer Content-Type: application/sdp Content-Length: 306 v=0 o=- 814489 815858 IN IP4 xx.yy.zz.66 s=JavaSoftPhone c=IN IP4 xx.yy.zz.66 t=0 0 m=audio 3454 RTP/AVP 0 3 4 5 101 c=IN IP4 xx.yy.zz.66 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:4 G723/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=setup:active a=sendrecv SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.yy.zz.66:4829;rport=4829;branch=z9hG4bK89f52f6729c740781eac05ab4a1a99bb From: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 To: <sip:1000@xx.yy.zz.1> Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Content-Length: 0 SIP/2.0 200 OK Via: SIP/2.0/UDP xx.yy.zz.66:4829;rport=4829;branch=z9hG4bK89f52f6729c740781eac05ab4a1a99bb From: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 To: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 1 INVITE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Require: timer Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Session-Expires: 120;refresher=uac Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 239 v=0 o=FreeSWITCH 1301299753 1301299754 IN IP4 xx.yy.zz.1 s=FreeSWITCH c=IN IP4 xx.yy.zz.1 t=0 0 m=audio 21030 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 ACK sip:1000@xx.yy.zz.1:5060;transport=udp SIP/2.0 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 1 ACK From: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 To: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ Via: SIP/2.0/UDP xx.yy.zz.66:4829;rport;branch=6b3a31302e352e352e36363a3438323 Max-Forwards: 70 Content-Length: 0 BYE sip:1016@xx.yy.zz.66 SIP/2.0 Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces *Reason: Q.850;cause=16;text="NORMAL_CLEARING"* Content-Length: 0 BYE sip:1016@xx.yy.zz.66 SIP/2.0 Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces *Reason: Q.850;cause=16;text="NORMAL_CLEARING"* Content-Length: 0 BYE sip:1016@xx.yy.zz.66 SIP/2.0 Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces *Reason: Q.850;cause=16;text="NORMAL_CLEARING"* Content-Length: 0 BYE sip:1016@xx.yy.zz.66 SIP/2.0 Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces *Reason: Q.850;cause=16;text="NORMAL_CLEARING"* Content-Length: 0 BYE sip:1016@xx.yy.zz.66 SIP/2.0 Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Contact: <sip:1000@xx.yy.zz.1:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-hacked Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces *Reason: Q.850;cause=16;text="NORMAL_CLEARING"* Content-Length: 0 SIP/2.0 200 OK Via: SIP/2.0/UDP xx.yy.zz.1;rport;branch=z9hG4bKUcjg7QjFeXSyB Max-Forwards: 70 From: <sip:1000@xx.yy.zz.1>;tag=HFr8848ZK8yjQ To: "My Name" <sip:1016@xx.yy.zz.1>;tag=3799 Call-ID: a830cf50124857e3ba148763920bf674@xx.yy.zz.66 CSeq: 10324328 BYE Content-Length: 0 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ freeswitch@internal> sofia status profile xx.yy.zz.1 ================================================================================================= Name xx.yy.zz.1 Domain Name N/A Alias Of internal DBName sofia_reg_internal Pres Hosts Dialplan XML Context public Challenge Realm auto_from RTP-IP xx.yy.zz.1 Ext-RTP-IP xx.yy.zz.1 SIP-IP xx.yy.zz.1 Ext-SIP-IP xx.yy.zz.1 URL sip:mod_sofia@xx.yy.zz.1:5060 BIND-URL sip:mod_sofia@xx.yy.zz.1:5060 HOLD-MUSIC local_stream://moh OUTBOUND-PROXY N/A CODECS G7221@32000h,G7221@16000h ,G722,PCMU,PCMA,GSM,speex@16000h@20i TEL-EVENT 101 DTMF-MODE rfc2833 CNG 13 SESSION-TO 0 MAX-DIALOG 0 NOMEDIA false LATE-NEG false PROXY-MEDIA false AGGRESSIVENAT false STUN-ENABLED true STUN-AUTO-DISABLE false CALLS-IN 483 FAILED-CALLS-IN 34 CALLS-OUT 1098 FAILED-CALLS-OUT 865 Registrations: ================================================================================================= ================================================================================================= freeswitch@internal> nta: timer J fired, terminate 401 response incoming_reclaim_all((nil), (nil), 0x4123cea0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/17 free nta: timer set next to 2192 ms nta: timer J fired, terminate 403 response incoming_reclaim_all((nil), (nil), 0x4123cea0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/16 free nta: timer not set tport_wakeup_pri(0x7028b0): events IN tport_recv_event(0x7028b0) tport_recv_iovec(0x7028b0) msg 0x11662d0 from (udp/xx.yy.zz.1:5060) has 364 bytes, veclen = 1 tport_deliver(0x7028b0): msg 0x11662d0 (364 bytes) from udp/xx.yy.zz.66:5060/sip next=(nil) nta: received REGISTER sip:xx.yy.zz.1:5060 SIP/2.0 (CSeq 1) nta: canonizing sip:xx.yy.zz.1:5060 with contact nta: REGISTER (1) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x6efae0, 0x7154c0, 0x71df40) called soa_set_params(static::0x1148020, ...) called nua(0x71df40): event i_register 100 Trying nua: nua_application_event: entering nua: nua_respond: entering nua(0x71df40): sent signal r_respond nua: nua_handle_destroy: entering nua(0x71df40): sent signal r_destroy nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x71df40): recv signal r_respond 401 Unauthorized nua: nua_stack_set_params: entering soa_set_params(static::0x1148020, ...) called tport_tsend(0x7028b0) tpn = UDP/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name UDP/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 628 bytes of 628 to udp/xx.yy.zz.66:4829 tport_vsend returned 628 nta: sent 401 Unauthorized for REGISTER (1) nta: timer set to 32000 ms nua(0x71df40): recv signal r_destroy nta_leg_destroy((nil)) soa_destroy(static::0x1148020) called freeswitch@internal> freeswitch@internal> freeswitch@internal> freeswitch@internal> tport_wakeup_pri(0x7028b0): events IN tport_recv_event(0x7028b0) tport_recv_iovec(0x7028b0) msg 0x768b30 from (udp/xx.yy.zz.1:5060) has 568 bytes, veclen = 1 tport_deliver(0x7028b0): msg 0x768b30 (568 bytes) from udp/xx.yy.zz.66:5060/sip next=(nil) nta: received REGISTER sip:xx.yy.zz.1:5060 SIP/2.0 (CSeq 2) nta: canonizing sip:xx.yy.zz.1:5060 with contact nta: REGISTER (2) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x6efae0, 0x7154c0, 0x1118070) called soa_set_params(static::0x1148020, ...) called nua(0x1118070): event i_register 100 Trying nua: nua_application_event: entering nua: nua_respond: entering nua(0x1118070): sent signal r_respond nua(0x1118070): recv signal r_respond 200 OK nua: nua_stack_set_params: entering soa_set_params(static::0x1148020, ...) called tport_tsend(0x7028b0) tpn = UDP/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name UDP/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 551 bytes of 551 to udp/xx.yy.zz.66:4829 tport_vsend returned 551 nta: sent 200 OK for REGISTER (2) nua: nua_handle_destroy: entering nua(0x1118070): sent signal r_destroy nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x1118070): recv signal r_destroy nta_leg_destroy((nil)) soa_destroy(static::0x1148020) called freeswitch@internal> freeswitch@internal> freeswitch@internal> freeswitch@internal> freeswitch@internal> tport_wakeup_pri(0x7028b0): events IN tport_recv_event(0x7028b0) tport_recv_iovec(0x7028b0) msg 0x1108a50 from (udp/xx.yy.zz.1:5060) has 744 bytes, veclen = 1 tport_deliver(0x7028b0): msg 0x1108a50 (744 bytes) from udp/xx.yy.zz.66:5060/sip next=(nil) nta: received INVITE sip:1000@xx.yy.zz.1 SIP/2.0 (CSeq 1) nta: canonizing sip:1000@xx.yy.zz.1 with contact nta: INVITE (1) going to a default leg nta: timer shortened to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x6efae0, 0x7154c0, 0x11170f0) called soa_set_params(static::0x1148020, ...) called nta_leg_tcreate(0x110a160) soa_init_offer_answer(static::0x1148020) called soa_set_remote_sdp(static::0x1148020, (nil), 0x117ad96, 306) called nua(0x11170f0): adding session usage tport_tsend(0x7028b0) tpn = UDP/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name UDP/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 328 bytes of 328 to udp/xx.yy.zz.66:4829 tport_vsend returned 328 nta: sent 100 Trying for INVITE (1) nua(0x11170f0): event i_invite 100 Trying nua(0x11170f0): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x1148020, [0x4123c558], [0x4123c550], [(nil)]) called nua(0x11170f0): event i_state 100 Trying nua: nua_application_event: entering 2011-03-28 15:57:20.161392 [DEBUG] sofia.c:4671 IP xx.yy.zz.66 Approved by acl "domains[]". Access Granted. 2011-03-28 15:57:20.161392 [NOTICE] switch_channel.c:613 New Channel sofia/internal/1016@xx.yy.zz.1 [4c7785ba-5943-11e0-8c96-03c3bfaa409b] nua: nua_handle_bind: entering 2011-03-28 15:57:20.161392 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_NEW 2011-03-28 15:57:20.161392 [DEBUG] switch_core_state_machine.c:404 (sofia/internal/1016@xx.yy.zz.1) State NEW 2011-03-28 15:57:20.161392 [DEBUG] sofia.c:5408 Setting NAT mode based on nat.auto nua: nua_handle_magic: entering nua: nua_application_event: entering 2011-03-28 15:57:20.161392 [DEBUG] sofia.c:3334 Channel sofia/internal/1016@xx.yy.zz.1 entering state [received][100] 2011-03-28 15:57:20.161392 [DEBUG] sofia.c:3341 Remote SDP: v=0 o=- 652619 653988 IN IP4 xx.yy.zz.66 s=JavaSoftPhone c=IN IP4 xx.yy.zz.66 t=0 0 m=audio 1370 RTP/AVP 0 3 4 5 101 c=IN IP4 xx.yy.zz.66 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:4 G723/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=setup:active 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:3136 Audio Codec Compare [PCMU:0:8000:0]/[G7221:115:32000:20] 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:3136 Audio Codec Compare [PCMU:0:8000:0]/[G7221:107:16000:20] 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:3136 Audio Codec Compare [PCMU:0:8000:0]/[G722:9:8000:20] 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:3136 Audio Codec Compare [PCMU:0:8000:0]/[PCMU:0:8000:20] 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:2094 Set Codec sofia/internal/1016@xx.yy.zz.1 PCMU/8000 20 ms 160 samples 2011-03-28 15:57:20.161392 [DEBUG] sofia_glue.c:3096 Set 2833 dtmf payload to 101 2011-03-28 15:57:20.161392 [DEBUG] sofia.c:3502 (sofia/internal/1016@xx.yy.zz.1) State Change CS_NEW -> CS_INIT 2011-03-28 15:57:20.161392 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] nua: nua_handle_magic: entering 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_INIT 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:422 (sofia/internal/1016@xx.yy.zz.1) State INIT 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:83 sofia/internal/1016@xx.yy.zz.1 SOFIA INIT 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:111 (sofia/internal/1016@xx.yy.zz.1) State Change CS_INIT -> CS_ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:422 (sofia/internal/1016@xx.yy.zz.1) State INIT going to sleep 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425 (sofia/internal/1016@xx.yy.zz.1) State ROUTING 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:130 sofia/internal/1016@xx.yy.zz.1 SOFIA ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:78 sofia/internal/1016@xx.yy.zz.1 Standard ROUTING 2011-03-28 15:57:20.181410 [INFO] mod_dialplan_xml.c:391 Processing My Name->1000 in context public Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [public->unloop] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [public->outside_call] continue=true Dialplan: sofia/internal/1016@xx.yy.zz.1 Absolute Condition [outside_call] Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(outside_call=true) Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [public->call_debug] continue=true Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (PASS) [public_extensions] destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 Action transfer(1000 XML default) 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/1016@xx.yy.zz.1) State Change CS_ROUTING -> CS_EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425 (sofia/internal/1016@xx.yy.zz.1) State ROUTING going to sleep 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:432 (sofia/internal/1016@xx.yy.zz.1) State EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:173 sofia/internal/1016@xx.yy.zz.1 SOFIA EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:151 sofia/internal/1016@xx.yy.zz.1 Standard EXECUTE EXECUTE sofia/internal/1016@xx.yy.zz.1 set(outside_call=true) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [outside_call]=[true] EXECUTE sofia/internal/1016@xx.yy.zz.1 transfer(1000 XML default) 2011-03-28 15:57:20.181410 [DEBUG] switch_ivr.c:1344 (sofia/internal/1016@xx.yy.zz.1) State Change CS_EXECUTE -> CS_ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.181410 [DEBUG] switch_ivr.c:1348 sofia/internal/1016@xx.yy.zz.1 receive message [TRANSFER] 2011-03-28 15:57:20.181410 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.181410 [NOTICE] switch_ivr.c:1350 Transfer sofia/internal/1016@xx.yy.zz.1 to XML[1000@default] 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:432 (sofia/internal/1016@xx.yy.zz.1) State EXECUTE going to sleep 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425 (sofia/internal/1016@xx.yy.zz.1) State ROUTING 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:130 sofia/internal/1016@xx.yy.zz.1 SOFIA ROUTING 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:78 sofia/internal/1016@xx.yy.zz.1 Standard ROUTING 2011-03-28 15:57:20.181410 [INFO] mod_dialplan_xml.c:391 Processing My Name->1000 in context default Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->unloop] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->tod_example] continue=true Dialplan: day of week[2] =~ 2-6 (PASS) Dialplan: hour[15] =~ 9-18 (PASS) Dialplan: sofia/internal/1016@xx.yy.zz.1 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(open=true) Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [global-intercept] destination_number(1000) =~ /^886$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [group-intercept] destination_number(1000) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [intercept-ext] destination_number(1000) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->redial] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [redial] destination_number(1000) =~ /^870$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->global] continue=true Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1016@xx.yy.zz.1 Absolute Condition [global] Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [snom-demo-2] destination_number(1000) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [snom-demo-1] destination_number(1000) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^88(.*)$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^779$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->call_return] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [call_return] destination_number(1000) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->del-group] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [del-group] destination_number(1000) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->add-group] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [add-group] destination_number(1000) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [call-group-simo] destination_number(1000) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [call-group-order] destination_number(1000) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (FAIL) [extension-intercom] destination_number(1000) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1016@xx.yy.zz.1 Regex (PASS) [Local_Extension] destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(dialed_extension=1000) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action export(dialed_extension=1000) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action bind_meta_app(2 b s record_session::/opt/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(call_timeout=30) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(continue_on_fail=true) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action answer() Dialplan: sofia/internal/1016@xx.yy.zz.1 Action sleep(1000) Dialplan: sofia/internal/1016@xx.yy.zz.1 Action voicemail(default ${domain_name} ${dialed_extension}) 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/1016@xx.yy.zz.1) State Change CS_ROUTING -> CS_EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425 (sofia/internal/1016@xx.yy.zz.1) State ROUTING going to sleep 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:432 (sofia/internal/1016@xx.yy.zz.1) State EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:173 sofia/internal/1016@xx.yy.zz.1 SOFIA EXECUTE 2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:151 sofia/internal/1016@xx.yy.zz.1 Standard EXECUTE EXECUTE sofia/internal/1016@xx.yy.zz.1 set(open=true) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [open]=[true] EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-spymap/1016/4c7785ba-5943-11e0-8c96-03c3bfaa409b) EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/1016/1000) EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/global/4c7785ba-5943-11e0-8c96-03c3bfaa409b) EXECUTE sofia/internal/1016@xx.yy.zz.1 set(dialed_extension=1000) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [dialed_extension]=[1000] EXECUTE sofia/internal/1016@xx.yy.zz.1 export(dialed_extension=1000) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:886 EXPORT [dialed_extension]=[1000] EXECUTE sofia/internal/1016@xx.yy.zz.1 bind_meta_app(1 b s execute_extension::dx XML features) 2011-03-28 15:57:20.181410 [INFO] switch_ivr_async.c:1835 Bound B-Leg: 1 execute_extension::dx XML features EXECUTE sofia/internal/1016@xx.yy.zz.1 bind_meta_app(2 b s record_session::/opt/freeswitch/recordings/1016.2011-03-28-15-57-20.wav) 2011-03-28 15:57:20.181410 [INFO] switch_ivr_async.c:1835 Bound B-Leg: 2 record_session::/opt/freeswitch/recordings/1016.2011-03-28-15-57-20.wav EXECUTE sofia/internal/1016@xx.yy.zz.1 bind_meta_app(3 b s execute_extension::cf XML features) 2011-03-28 15:57:20.181410 [INFO] switch_ivr_async.c:1835 Bound B-Leg: 3 execute_extension::cf XML features EXECUTE sofia/internal/1016@xx.yy.zz.1set(ringback=%(2000,4000,440.0,480.0)) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [ringback]=[%(2000,4000,440.0,480.0)] EXECUTE sofia/internal/1016@xx.yy.zz.1set(transfer_ringback=local_stream://moh) 2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1016@xx.yy.zz.1 set(call_timeout=30) 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [call_timeout]=[30] EXECUTE sofia/internal/1016@xx.yy.zz.1 set(hangup_after_bridge=true) 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1016@xx.yy.zz.1 set(continue_on_fail=true) 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-call_return/1000/1016) EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial_ext/1000/4c7785ba-5943-11e0-8c96-03c3bfaa409b) EXECUTE sofia/internal/1016@xx.yy.zz.1set(called_party_callgroup=techsupport) 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748 sofia/internal/1016@xx.yy.zz.1 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1016@xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/techsupport/4c7785ba-5943-11e0-8c96-03c3bfaa409b) EXECUTE sofia/internal/1016@xx.yy.zz.1 bridge(user/1000@xx.yy.zz.1) 2011-03-28 15:57:20.191371 [DEBUG] switch_ivr_originate.c:1047 variable string 0 = [presence_id=1000@xx.yy.zz.1] 2011-03-28 15:57:20.191371 [ERR] switch_ivr_originate.c:1531 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2011-03-28 15:57:20.191371 [DEBUG] switch_ivr_originate.c:2170 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2011-03-28 15:57:20.191371 [ERR] switch_ivr_originate.c:1531 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED] 2011-03-28 15:57:20.191371 [DEBUG] switch_ivr_originate.c:2170 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2011-03-28 15:57:20.191371 [INFO] mod_dptools.c:2114 Originate Failed. Cause: USER_NOT_REGISTERED 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:2141 Continue on fail [true]: Cause: USER_NOT_REGISTERED EXECUTE sofia/internal/1016@xx.yy.zz.1 answer() 2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:649 sofia/internal/1016@xx.yy.zz.1 receive message [ANSWER] 2011-03-28 15:57:20.191371 [DEBUG] sofia_glue.c:2328 AUDIO RTP [sofia/internal/1016@xx.yy.zz.1] xx.yy.zz.1 port 17768 -> xx.yy.zz.66 port 1370 codec: 0 ms: 20 2011-03-28 15:57:20.191371 [DEBUG] switch_rtp.c:1155 Starting timer [soft] 160 bytes per 20ms 2011-03-28 15:57:20.201410 [DEBUG] mod_sofia.c:536 Local SDP sofia/internal/1016@xx.yy.zz.1: v=0 o=FreeSWITCH 1301302872 1301302873 IN IP4 xx.yy.zz.1 s=FreeSWITCH c=IN IP4 xx.yy.zz.1 t=0 0 m=audio 17768 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv nua: nua_respond: entering nua(0x11170f0): sent signal r_respond 2011-03-28 15:57:20.201410 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:20.201410 [NOTICE] mod_dptools.c:649 Channel [sofia/internal/1016@xx.yy.zz.1] has been answered 2011-03-28 15:57:20.201410 [DEBUG] switch_channel.c:182 sofia/internal/1016@xx.yy.zz.1 receive message [AUDIO_SYNC] EXECUTE sofia/internal/1016@xx.yy.zz.1 sleep(1000) nua(0x11170f0): recv signal r_respond 200 OK nua: nua_stack_set_params: entering soa_set_params(static::0x1148020, ...) called soa_set_user_sdp(static::0x1148020, (nil), 0x7fb13c02316d, -1) called soa_set_capability_sdp(static::0x1148020, (nil), 0x7fb13c02316d, -1) called nua: nua_invite_server_respond: entering soa_generate_answer(static::0x1148020) called soa_static_offer_answer_action(0x1148020, soa_generate_answer): called soa_static(0x1148020, soa_generate_answer): generating local description soa_static(0x1148020, soa_generate_answer): upgrade with remote description soa_sdp_mode_set(0x4123caa0, 0x116ef80, ""): called soa_static(0x1148020, soa_generate_answer): storing local description soa_activate(static::0x1148020, (nil)) called soa_get_local_sdp(static::0x1148020, [(nil)], [0x4123cc90], [0x4123cc9c]) called tport_tsend(0x7028b0) tpn = UDP/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name UDP/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 1064 bytes of 1064 to udp/xx.yy.zz.66:4829 tport_vsend returned 1064 nta: sent 200 OK for INVITE (1) nua(0x11170f0): call state changed: received -> completed, sent answer soa_get_local_sdp(static::0x1148020, [0x4123cde8], [0x4123cde0], [(nil)]) called soa_get_params(static::0x1148020, ...) called nua(0x11170f0): event i_state 200 OK 2011-03-28 15:57:20.201410 [DEBUG] switch_channel.c:182 sofia/internal/1016@xx.yy.zz.1 receive message [AUDIO_SYNC] nua: nua_application_event: entering 2011-03-28 15:57:20.201410 [DEBUG] sofia.c:3334 Channel sofia/internal/1016@xx.yy.zz.1 entering state [completed][200] nua: nua_handle_magic: entering tport_wakeup_pri(0x7028b0): events IN tport_recv_event(0x7028b0) tport_recv_iovec(0x7028b0) msg 0x1125e50 from (udp/xx.yy.zz.1:5060) has 327 bytes, veclen = 1 tport_deliver(0x7028b0): msg 0x1125e50 (327 bytes) from udp/xx.yy.zz.66:5060/sip next=(nil) nta: received ACK sip:1000@xx.yy.zz.1:5060;transport=udp SIP/2.0 (CSeq 1) nta: ACK (1) is going to INVITE (1) nua: process_ack_or_cancel: entering soa_clear_remote_sdp(static::0x1148020) called nua(0x11170f0): event i_ack 200 OK nua(0x11170f0): call state changed: completed -> ready nua(0x11170f0): event i_state 200 OK nua(0x11170f0): event i_active 200 Call active nua(): refresh session after 88 seconds (in [88..88]) nua: nua_application_event: entering nua: nua_handle_magic: entering nua: nua_application_event: entering 2011-03-28 15:57:20.231367 [DEBUG] sofia.c:3334 Channel sofia/internal/1016@xx.yy.zz.1 entering state [ready][200] nua: nua_handle_magic: entering nua: nua_application_event: entering nua: nua_handle_magic: entering nta: timer set next to 4862 ms EXECUTE sofia/internal/1016@xx.yy.zz.1 voicemail(default xx.yy.zz.1 1000) 2011-03-28 15:57:21.201425 [DEBUG] mod_voicemail.c:788 [default] rwlock 2011-03-28 15:57:21.201425 [ERR] mod_voicemail.c:2927 Error creating /opt/freeswitch/storage/voicemail/default/xx.yy.zz.1/1000 2011-03-28 15:57:21.201425 [DEBUG] switch_ivr_play_say.c:118 No language specified - Using [en] 2011-03-28 15:57:21.201425 [ERR] switch_ivr_play_say.c:148 Can't find language tag. 2011-03-28 15:57:21.201425 [WARNING] switch_ivr_play_say.c:364 Macro [voicemail_goodbye] did not match any patterns 2011-03-28 15:57:21.201425 [NOTICE] switch_core_state_machine.c:179 Hangup sofia/internal/1016@xx.yy.zz.1 [CS_EXECUTE] [NORMAL_CLEARING] 2011-03-28 15:57:21.201425 [DEBUG] switch_channel.c:1726 Send signal sofia/internal/1016@xx.yy.zz.1 [KILL] 2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1016@xx.yy.zz.1) State HANGUP 2011-03-28 15:57:21.201425 [DEBUG] mod_sofia.c:338 Channel sofia/internal/1016@xx.yy.zz.1 hanging up, cause: NORMAL_CLEARING 2011-03-28 15:57:21.201425 [DEBUG] mod_sofia.c:376 Sending BYE to sofia/internal/1016@xx.yy.zz.1 nua: nua_bye: entering nua(0x11170f0): sent signal r_bye nua(0x11170f0): recv signal r_bye nua: nua_stack_set_params: entering soa_set_params(static::0x1148020, ...) called soa_terminate(static::0x1148020) called soa_init_offer_answer(static::0x1148020) called nta: selecting scheme sip tport_tsend(0x7028b0) tpn = udp/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name udp/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 604 bytes of 604 to udp/xx.yy.zz.66:4829 tport_vsend returned 604 nta: sent BYE (10324256) to udp/xx.yy.zz.66:4829 tport_pend(0x7028b0): pending 0x7fb1440d6100 for udp/xx.yy.zz.1:5060 (already 0) nta: timer shortened to 500 ms 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1016@xx.yy.zz.1 Standard HANGUP, cause: NORMAL_CLEARING 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1016@xx.yy.zz.1) State HANGUP going to sleep 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:432 (sofia/internal/1016@xx.yy.zz.1) State EXECUTE going to sleep 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_HANGUP 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:538 handler already called, skipping state handler. 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/1016@xx.yy.zz.1) State Change CS_HANGUP -> CS_REPORTING 2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_REPORTING 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1016@xx.yy.zz.1) State REPORTING 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1016@xx.yy.zz.1 Standard REPORTING, cause: NORMAL_CLEARING 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1016@xx.yy.zz.1) State REPORTING going to sleep 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/1016@xx.yy.zz.1) State Change CS_REPORTING -> CS_DESTROY 2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/1016@xx.yy.zz.1 [BREAK] 2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:1069 Session 1582 (sofia/internal/1016@xx.yy.zz.1) Locked, Waiting on external entities 2011-03-28 15:57:21.201425 [NOTICE] switch_core_session.c:1087 Session 1582 (sofia/internal/1016@xx.yy.zz.1) Ended 2011-03-28 15:57:21.201425 [NOTICE] switch_core_session.c:1089 Close Channel sofia/internal/1016@xx.yy.zz.1 [CS_DESTROY] 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:497 (sofia/internal/1016@xx.yy.zz.1) Running State Change CS_DESTROY 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:508 (sofia/internal/1016@xx.yy.zz.1) State DESTROY 2011-03-28 15:57:21.201425 [DEBUG] mod_sofia.c:255 sofia/internal/1016@xx.yy.zz.1 SOFIA DESTROY 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1016@xx.yy.zz.1 Standard DESTROY 2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:508 (sofia/internal/1016@xx.yy.zz.1) State DESTROY going to sleep nta: timer E fired, retransmit BYE (10324256) tport_release(0x7028b0): 0x7fb1440d6100 by 0x7fb144068530 with (nil) tport_tsend(0x7028b0) tpn = udp/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name udp/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 604 bytes of 604 to udp/xx.yy.zz.66:4829 tport_vsend returned 604 nta: resent BYE (10324256) to udp/xx.yy.zz.66:4829 tport_pend(0x7028b0): pending 0x7fb1440d6100 for udp/xx.yy.zz.1:5060 (already 0) nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta: timer set next to 1000 ms nta: timer E fired, retransmit BYE (10324256) tport_release(0x7028b0): 0x7fb1440d6100 by 0x7fb144068530 with (nil) tport_tsend(0x7028b0) tpn = udp/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name udp/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 604 bytes of 604 to udp/xx.yy.zz.66:4829 tport_vsend returned 604 nta: resent BYE (10324256) to udp/xx.yy.zz.66:4829 tport_pend(0x7028b0): pending 0x7fb1440d6100 for udp/xx.yy.zz.1:5060 (already 0) nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta: timer set next to 2000 ms nta: timer E fired, retransmit BYE (10324256) tport_release(0x7028b0): 0x7fb1440d6100 by 0x7fb144068530 with (nil) tport_tsend(0x7028b0) tpn = udp/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name udp/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 604 bytes of 604 to udp/xx.yy.zz.66:4829 tport_vsend returned 604 nta: resent BYE (10324256) to udp/xx.yy.zz.66:4829 tport_pend(0x7028b0): pending 0x7fb1440d6100 for udp/xx.yy.zz.1:5060 (already 0) nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta: timer set next to 522 ms nta: timer I fired, terminate 200 response incoming_reclaim_all((nil), (nil), 0x4123cea0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/18 free nta: timer set next to 2738 ms nta: timer J fired, terminate 401 response incoming_reclaim_all((nil), (nil), 0x4123cea0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/17 free nta: timer set next to 730 ms nta: timer E fired, retransmit BYE (10324256) tport_release(0x7028b0): 0x7fb1440d6100 by 0x7fb144068530 with (nil) tport_tsend(0x7028b0) tpn = udp/xx.yy.zz.66:4829 tport_resolve addrinfo = xx.yy.zz.66:4829 tport_by_addrinfo(0x7028b0): not found by name udp/xx.yy.zz.66:4829 tport_vsend(0x7028b0): 604 bytes of 604 to udp/xx.yy.zz.66:4829 tport_vsend returned 604 nta: resent BYE (10324256) to udp/xx.yy.zz.66:4829 tport_pend(0x7028b0): pending 0x7fb1440d6100 for udp/xx.yy.zz.1:5060 (already 0) nta_outgoing_timer: 1/1 resent, 0/1 tout, 0/0 term, 0/1 free nta: timer set next to 4000 ms tport_wakeup_pri(0x7028b0): events IN tport_recv_event(0x7028b0) tport_recv_iovec(0x7028b0) msg 0x117e8c0 from (udp/xx.yy.zz.1:5060) has 283 bytes, veclen = 1 tport_deliver(0x7028b0): msg 0x117e8c0 (283 bytes) from udp/xx.yy.zz.66:5060/sip next=(nil) nta: received 200 OK for BYE (10324256) nta: 200 OK is going to a transaction nta_outgoing: RTT is 8366.26 ms tport_release(0x7028b0): 0x7fb1440d6100 by 0x7fb144068530 with 0x117e8c0 nua(0x11170f0): event r_bye 200 OK nua(0x11170f0): call state changed: terminating -> terminated nua(0x11170f0): event i_state 200 to BYE nua(0x11170f0): event i_terminated 200 to BYE nua(0x11170f0): removing session usage soa_destroy(static::0x1148020) called nta_leg_destroy(0x110a160) nua: terminated session 0x11170f0 nua: nua_application_event: entering nua: nua_handle_magic: entering nua: nua_application_event: entering nua: nua_handle_magic: entering nua: nua_handle_bind: entering nua: nua_application_event: entering nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x11170f0): recv signal r_destroy nta_leg_destroy((nil)) nua(0x11170f0): sent signal r_destroy nta: timer set next to 1856 ms nta: timer K fired, terminate BYE (10324256) outgoing_reclaim_all((nil), (nil), 0x4123ce90) nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer set next to 8799 ms