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