[Freeswitch-users] Getting RC=200 OK instead of RC=183 Session Progress // Reason: Q.850; cause=16; text="NORMAL_CLEARING"
Melih Vardar
vardar.melih at gmail.com
Mon Mar 28 18:10:03 MSD 2011
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 at xx.yy.zz.1 SIP/2.0
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 1 INVITE
From: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
To: <sip:1000 at xx.yy.zz.1>
Via: SIP/2.0/UDP
xx.yy.zz.66:4829;rport;branch=z9hG4bK89f52f6729c740781eac05ab4a1a99bb
Max-Forwards: 70
Contact: <sip:1016 at 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 at xx.yy.zz.1>;tag=3799
To: <sip:1000 at xx.yy.zz.1>
Call-ID: a830cf50124857e3ba148763920bf674 at 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 at xx.yy.zz.1>;tag=3799
To: <sip:1000 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 1 INVITE
Contact: <sip:1000 at 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 at xx.yy.zz.1:5060;transport=udp SIP/2.0
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 1 ACK
From: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
To: <sip:1000 at 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 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Contact: <sip:1000 at 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 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Contact: <sip:1000 at 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 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Contact: <sip:1000 at 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 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Contact: <sip:1000 at 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 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Contact: <sip:1000 at 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 at xx.yy.zz.1>;tag=HFr8848ZK8yjQ
To: "My Name" <sip:1016 at xx.yy.zz.1>;tag=3799
Call-ID: a830cf50124857e3ba148763920bf674 at xx.yy.zz.66
CSeq: 10324328 BYE
Content-Length: 0
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
freeswitch at 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 at xx.yy.zz.1:5060
BIND-URL sip:mod_sofia at xx.yy.zz.1:5060
HOLD-MUSIC local_stream://moh
OUTBOUND-PROXY N/A
CODECS G7221 at 32000h,G7221 at 16000h
,G722,PCMU,PCMA,GSM,speex at 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 at 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 at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at 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 at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at internal>
freeswitch at 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 at xx.yy.zz.1 SIP/2.0 (CSeq 1)
nta: canonizing sip:1000 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at xx.yy.zz.1) State INIT
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:83
sofia/internal/1016 at xx.yy.zz.1 SOFIA INIT
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:111
(sofia/internal/1016 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:422
(sofia/internal/1016 at 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 at 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 at xx.yy.zz.1) State ROUTING
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:130
sofia/internal/1016 at xx.yy.zz.1 SOFIA ROUTING
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:78
sofia/internal/1016 at 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 at xx.yy.zz.1 parsing [public->unloop]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [public->outside_call]
continue=true
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Absolute Condition [outside_call]
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(outside_call=true)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [public->call_debug]
continue=true
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [public->public_extensions]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (PASS) [public_extensions]
destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1016 at 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 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425
(sofia/internal/1016 at 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 at 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 at xx.yy.zz.1) State EXECUTE
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:173
sofia/internal/1016 at xx.yy.zz.1 SOFIA EXECUTE
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:151
sofia/internal/1016 at xx.yy.zz.1 Standard EXECUTE
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(outside_call=true)
2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [outside_call]=[true]
EXECUTE sofia/internal/1016 at xx.yy.zz.1 transfer(1000 XML default)
2011-03-28 15:57:20.181410 [DEBUG] switch_ivr.c:1344
(sofia/internal/1016 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.181410 [DEBUG] switch_ivr.c:1348
sofia/internal/1016 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.181410 [NOTICE] switch_ivr.c:1350 Transfer
sofia/internal/1016 at xx.yy.zz.1 to XML[1000 at default]
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:432
(sofia/internal/1016 at 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 at 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 at xx.yy.zz.1) State ROUTING
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:130
sofia/internal/1016 at xx.yy.zz.1 SOFIA ROUTING
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:78
sofia/internal/1016 at 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 at xx.yy.zz.1 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1016 at 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 at xx.yy.zz.1 Date/Time Match (PASS)
[tod_example] break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(open=true)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->global-intercept]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [global-intercept]
destination_number(1000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->group-intercept]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [group-intercept]
destination_number(1000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->intercept-ext]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [intercept-ext]
destination_number(1000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->redial]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [redial]
destination_number(1000) =~ /^870$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->global]
continue=true
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1016 at 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 at xx.yy.zz.1 Absolute Condition [global]
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->snom-demo-2]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [snom-demo-2]
destination_number(1000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->snom-demo-1]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [snom-demo-1]
destination_number(1000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [eavesdrop]
destination_number(1000) =~ /^88(.*)$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [eavesdrop]
destination_number(1000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->call_return]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [call_return]
destination_number(1000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->del-group]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [del-group]
destination_number(1000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->add-group]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [add-group]
destination_number(1000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->call-group-simo]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [call-group-simo]
destination_number(1000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->call-group-order]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [call-group-order]
destination_number(1000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (FAIL) [extension-intercom]
destination_number(1000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 parsing [default->Local_Extension]
continue=false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Regex (PASS) [Local_Extension]
destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(dialed_extension=1000)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
export(dialed_extension=1000)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/1016 at 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 at xx.yy.zz.1 Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(call_timeout=30)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name}
var callgroup)})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action
bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action answer()
Dialplan: sofia/internal/1016 at xx.yy.zz.1 Action sleep(1000)
Dialplan: sofia/internal/1016 at 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 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:425
(sofia/internal/1016 at 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 at 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 at xx.yy.zz.1) State EXECUTE
2011-03-28 15:57:20.181410 [DEBUG] mod_sofia.c:173
sofia/internal/1016 at xx.yy.zz.1 SOFIA EXECUTE
2011-03-28 15:57:20.181410 [DEBUG] switch_core_state_machine.c:151
sofia/internal/1016 at xx.yy.zz.1 Standard EXECUTE
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(open=true)
2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [open]=[true]
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-spymap/1016/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/1016/1000)
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/global/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(dialed_extension=1000)
2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [dialed_extension]=[1000]
EXECUTE sofia/internal/1016 at 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 at 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 at 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 at 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 at 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 at xx.yy.zz.1 SET [ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE sofia/internal/1016 at xx.yy.zz.1set(transfer_ringback=local_stream://moh)
2011-03-28 15:57:20.181410 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(call_timeout=30)
2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [call_timeout]=[30]
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(hangup_after_bridge=true)
2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1016 at xx.yy.zz.1 set(continue_on_fail=true)
2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-call_return/1000/1016)
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial_ext/1000/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016 at xx.yy.zz.1set(called_party_callgroup=techsupport)
2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:748
sofia/internal/1016 at xx.yy.zz.1 SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1016 at xx.yy.zz.1hash(insert/xx.yy.zz.1-last_dial/techsupport/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
EXECUTE sofia/internal/1016 at xx.yy.zz.1 bridge(user/1000 at xx.yy.zz.1)
2011-03-28 15:57:20.191371 [DEBUG] switch_ivr_originate.c:1047 variable
string 0 = [presence_id=1000 at 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 at xx.yy.zz.1 answer()
2011-03-28 15:57:20.191371 [DEBUG] mod_dptools.c:649
sofia/internal/1016 at xx.yy.zz.1 receive message [ANSWER]
2011-03-28 15:57:20.191371 [DEBUG] sofia_glue.c:2328 AUDIO RTP
[sofia/internal/1016 at 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 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:20.201410 [NOTICE] mod_dptools.c:649 Channel
[sofia/internal/1016 at xx.yy.zz.1] has been answered
2011-03-28 15:57:20.201410 [DEBUG] switch_channel.c:182
sofia/internal/1016 at xx.yy.zz.1 receive message [AUDIO_SYNC]
EXECUTE sofia/internal/1016 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at xx.yy.zz.1 [KILL]
2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/1016 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:560
(sofia/internal/1016 at xx.yy.zz.1) State HANGUP
2011-03-28 15:57:21.201425 [DEBUG] mod_sofia.c:338 Channel
sofia/internal/1016 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/1016 at 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 at xx.yy.zz.1) State REPORTING
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:53
sofia/internal/1016 at 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 at 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 at 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 at xx.yy.zz.1 [BREAK]
2011-03-28 15:57:21.201425 [DEBUG] switch_core_session.c:1069 Session 1582
(sofia/internal/1016 at 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 at xx.yy.zz.1) Ended
2011-03-28 15:57:21.201425 [NOTICE] switch_core_session.c:1089 Close Channel
sofia/internal/1016 at xx.yy.zz.1 [CS_DESTROY]
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:497
(sofia/internal/1016 at 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 at xx.yy.zz.1) State DESTROY
2011-03-28 15:57:21.201425 [DEBUG] mod_sofia.c:255
sofia/internal/1016 at xx.yy.zz.1 SOFIA DESTROY
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:60
sofia/internal/1016 at xx.yy.zz.1 Standard DESTROY
2011-03-28 15:57:21.201425 [DEBUG] switch_core_state_machine.c:508
(sofia/internal/1016 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20110328/b9a6ef18/attachment-0001.html
More information about the FreeSWITCH-users
mailing list