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.1 hash(insert/xx.yy.zz.1-spymap/1016/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016@xx.yy.zz.1 hash(insert/xx.yy.zz.1-last_dial/1016/1000)
EXECUTE sofia/internal/1016@xx.yy.zz.1 hash(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.1 set(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.1 set(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.1 hash(insert/xx.yy.zz.1-call_return/1000/1016)
EXECUTE sofia/internal/1016@xx.yy.zz.1 hash(insert/xx.yy.zz.1-last_dial_ext/1000/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016@xx.yy.zz.1 set(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.1 hash(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