[Freeswitch-users] Getting RC=200 OK instead of RC=183 Session Progress // Reason: Q.850; cause=16; text="NORMAL_CLEARING"
Kerem Erciyes
kerem.erciyes at gmail.com
Mon Mar 28 20:54:39 MSD 2011
Hi Melih,
Read the output, the error is USER_NOT_REGISTERED. You have
registration and authentication problems.
<snip>
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]
</snip>
Also try using pastebin for pasting your logs and conf files. See:
http://wiki.freeswitch.org/wiki/Reporting_Bugs#Using_The_Pastebin
--KE
On Mon, Mar 28, 2011 at 5:10 PM, Melih Vardar <vardar.melih at gmail.com> wrote:
> 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.1
> hash(insert/xx.yy.zz.1-spymap/1016/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
> EXECUTE sofia/internal/1016 at xx.yy.zz.1
> hash(insert/xx.yy.zz.1-last_dial/1016/1000)
> EXECUTE sofia/internal/1016 at xx.yy.zz.1
> hash(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.1
> set(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.1
> set(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.1
> hash(insert/xx.yy.zz.1-call_return/1000/1016)
> EXECUTE sofia/internal/1016 at xx.yy.zz.1
> hash(insert/xx.yy.zz.1-last_dial_ext/1000/4c7785ba-5943-11e0-8c96-03c3bfaa409b)
> EXECUTE sofia/internal/1016 at xx.yy.zz.1
> set(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.1
> hash(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
>
>
>
>
>
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
--
Kerem Erciyes - Sistem Danismani
http://keremerciyes.com
More information about the FreeSWITCH-users
mailing list