[Freeswitch-users] 480 Temporarily Unavailable[MANDATORY_IE_MISSING]

Rutu Patel rutu.patel at inextrix.com
Wed Mar 23 16:46:49 MSK 2016


Hi,

We are sending call to asterisk PBX but we are getting 480 Temporarily
Unavailable immediately. from freeswitch server.

Call flow is as below:

User => opensips => FS => PBX,

but call not sending out from FS and drop by FS.

Here I am attaching both sip logs and freeswitch logs.

Can anyone please help to sort out the issue.
--
Thanks,
Rutu Patel
<http://www.inextrix.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20160323/98efe3c6/attachment-0001.html 
-------------- next part --------------
U x.x.x.45:5060 -> x.x.x.46:5060
INVITE sip:xxxxxxxx30 at x.x.x.46:5060 SIP/2.0.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bKbc5.ada31d41.0.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as5ca05dc6.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Contact: <sip:xxxxxxxx65 at x.x.x.45;did=cf6.e51f4043>.
Call-ID: DLGCH_fBZQWGZ/Z2d/FFwNZi1gZ31DBA83KGRgeklSWjZ/aDcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: Asterisk PBX.
Max-Forwards: 30.
Date: Wed, 23 Mar 2016 13:08:41 GMT.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO.
Supported: replaces.
Content-Type: application/sdp.
Content-Length: 232.
X-AUTH-IP: x.x.x.10.
.
v=0.
o=root 2668 2668 IN IP4 x.x.x.10.
s=session.
c=IN IP4 x.x.x.10.
t=0 0.
m=audio 10014 RTP/AVP 18 101.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=ptime:20.
a=sendrecv.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bKbc5.ada31d41.0;rport=5060.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as5ca05dc6.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Call-ID: DLGCH_fBZQWGZ/Z2d/FFwNZi1gZ31DBA83KGRgeklSWjZ/aDcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Content-Length: 0.
.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 480 Temporarily Unavailable.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bKbc5.ada31d41.0;rport=5060.
Max-Forwards: 30.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as5ca05dc6.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>;tag=4Z841U31epcmc.
Call-ID: DLGCH_fBZQWGZ/Z2d/FFwNZi1gZ31DBA83KGRgeklSWjZ/aDcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Accept: application/sdp.
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY.
Supported: timer, path, replaces.
Allow-Events: talk, hold, conference, refer.
Reason: Q.850;cause=96;text="MANDATORY_IE_MISSING".
Content-Length: 0.
.


U x.x.x.45:5060 -> x.x.x.46:5060
ACK sip:xxxxxxxx30 at x.x.x.46:5060 SIP/2.0.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bKbc5.ada31d41.0.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as5ca05dc6.
Call-ID: DLGCH_fBZQWGZ/Z2d/FFwNZi1gZ31DBA83KGRgeklSWjZ/aDcPRFRAZHB+a39eVF4-.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>;tag=4Z841U31epcmc.
CSeq: 102 ACK.
Max-Forwards: 70.
User-Agent: Cvt SIP Proxy.
Content-Length: 0.
.


U x.x.x.45:5060 -> x.x.x.46:5060
INVITE sip:xxxxxxxx30 at x.x.x.46:5060 SIP/2.0.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK2862.2c0ef1d3.0.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as62f8fc78.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Contact: <sip:xxxxxxxx65 at x.x.x.45;did=2b7.b271d902>.
Call-ID: DLGCH_fUJcVmBwaDF7RVwIY3FjNX5GA1cweTRgeUFRCzEqaWcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: Asterisk PBX.
Max-Forwards: 30.
Date: Wed, 23 Mar 2016 13:08:42 GMT.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO.
Supported: replaces.
Content-Type: application/sdp.
Content-Length: 232.
X-AUTH-IP: x.x.x.10.
.
v=0.
o=root 2668 2668 IN IP4 x.x.x.10.
s=session.
c=IN IP4 x.x.x.10.
t=0 0.
m=audio 10044 RTP/AVP 18 101.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=ptime:20.
a=sendrecv.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK2862.2c0ef1d3.0;rport=5060.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as62f8fc78.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Call-ID: DLGCH_fUJcVmBwaDF7RVwIY3FjNX5GA1cweTRgeUFRCzEqaWcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Content-Length: 0.
.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 480 Temporarily Unavailable.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK2862.2c0ef1d3.0;rport=5060.
Max-Forwards: 30.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as62f8fc78.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>;tag=9c70a3QK02UHp.
Call-ID: DLGCH_fUJcVmBwaDF7RVwIY3FjNX5GA1cweTRgeUFRCzEqaWcPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Accept: application/sdp.
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY.
Supported: timer, path, replaces.
Allow-Events: talk, hold, conference, refer.
Reason: Q.850;cause=96;text="MANDATORY_IE_MISSING".
Content-Length: 0.
.


U x.x.x.45:5060 -> x.x.x.46:5060
ACK sip:xxxxxxxx30 at x.x.x.46:5060 SIP/2.0.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK2862.2c0ef1d3.0.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as62f8fc78.
Call-ID: DLGCH_fUJcVmBwaDF7RVwIY3FjNX5GA1cweTRgeUFRCzEqaWcPRFRAZHB+a39eVF4-.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>;tag=9c70a3QK02UHp.
CSeq: 102 ACK.
Max-Forwards: 70.
User-Agent: Cvt SIP Proxy.
Content-Length: 0.
.


U x.x.x.45:5060 -> x.x.x.46:5060
INVITE sip:xxxxxxxx30 at x.x.x.46:5060 SIP/2.0.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK6abd.100ba942.0.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as66ba8674.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Contact: <sip:xxxxxxxx65 at x.x.x.45;did=6dc.d5ee8c4>.
Call-ID: DLGCH_eUYBWGtxYmZ4RFEKZSw0Zn8RBgpqcGc1e0VWCmp5NTIPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: Asterisk PBX.
Max-Forwards: 30.
Date: Wed, 23 Mar 2016 13:08:42 GMT.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO.
Supported: replaces.
Content-Type: application/sdp.
Content-Length: 232.
X-AUTH-IP: x.x.x.10.
.
v=0.
o=root 2668 2668 IN IP4 x.x.x.10.
s=session.
c=IN IP4 x.x.x.10.
t=0 0.
m=audio 14732 RTP/AVP 18 101.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=ptime:20.
a=sendrecv.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK6abd.100ba942.0;rport=5060.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as66ba8674.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>.
Call-ID: DLGCH_eUYBWGtxYmZ4RFEKZSw0Zn8RBgpqcGc1e0VWCmp5NTIPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Content-Length: 0.
.


U x.x.x.46:5060 -> x.x.x.45:5060
SIP/2.0 480 Temporarily Unavailable.
Via: SIP/2.0/UDP x.x.x.45:5060;branch=z9hG4bK6abd.100ba942.0;rport=5060.
Max-Forwards: 30.
From: "xxxxxxxx65" <sip:xxxxxxxx65 at x.x.x.10>;tag=as66ba8674.
To: <sip:xxxxxxxx30 at x.x.x.45:5060>;tag=BZSjeSSttm8pD.
Call-ID: DLGCH_eUYBWGtxYmZ4RFEKZSw0Zn8RBgpqcGc1e0VWCmp5NTIPRFRAZHB+a39eVF4-.
CSeq: 102 INVITE.
User-Agent: FreeSWITCH.
Accept: application/sdp.
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY.
Supported: timer, path, replaces.
Allow-Events: talk, hold, conference, refer.
Reason: Q.850;cause=96;text="MANDATORY_IE_MISSING".
Content-Length: 0.
.
-------------- next part --------------
    2016-03-23 13:48:43.435074 [INFO] mod_dialplan_xml.c:637 Processing +xxxxxxxxx65 <xxxxxxxxx65>->+xxxxxxxxx01 in context default
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 parsing [default->+xxxxxxxxx01] continue=false
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Regex (PASS) [+xxxxxxxxx01] destination_number(+xxxxxxxxx01) =~ // break=on-false
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(callstart=2016-03-23 11:48:43)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(call_processed=internal)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(originated_destination_number=xxxxxxxx01)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action export(t38_passthru=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(fax_enable_t38=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(fax_enable_t38_request=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(call_direction=inbound) 
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action sched_hangup(+172800 allotted_timeout)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(effective_destination_number=xxxxxxxx01)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action export(t38_passthru=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(fax_enable_t38=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(fax_enable_t38_request=true)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action set(did_calltype=LOCAL)
    Dialplan: sofia/default/+xxxxxxxxx65 at x.x.x.86 Action bridge({sip_invite_to_uri=<sip:xxxxxxxx01 at x.x.x.42:5060>,sip_invite_req_uri=sip:xxxxxxxx01 at x.x.x.42:5060}sofia/default/sip:test-user at x.x.x.42:5060;fs_path=sip%3Ax.x.x.35%3Blr%3Breceived%3Dsip%3Ax.x.x.42%3A5060)
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:216 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State Change CS_ROUTING -> CS_EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:532 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State ROUTING going to sleep
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:473 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Running State Change CS_EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:539 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] mod_sofia.c:196 sofia/default/+xxxxxxxxx65 at x.x.x.86 SOFIA EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:258 sofia/default/+xxxxxxxxx65 at x.x.x.86 Standard EXECUTE
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(callstart=2016-03-23 11:48:43)
    2016-03-23 13:48:43.615031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [callstart]=[2016-03-23 11:48:43]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(call_processed=internal)
    2016-03-23 13:48:43.615031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [call_processed]=[internal]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(originated_destination_number=xxxxxxxx01)
    2016-03-23 13:48:43.615031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [originated_destination_number]=[xxxxxxxx01]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 export(t38_passthru=true)
    2016-03-23 13:48:43.615031 [DEBUG] switch_channel.c:1293 EXPORT (export_vars) [t38_passthru]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(fax_enable_t38=true)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [fax_enable_t38]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(fax_enable_t38_request=true)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [fax_enable_t38_request]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(call_direction=inbound)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [call_direction]=[inbound]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 sched_hangup(+172800 allotted_timeout)
    2016-03-23 13:48:43.635031 [DEBUG] switch_scheduler.c:249 Added task 21 switch_ivr_schedule_hangup (67849c93-6b10-4377-834e-78657fcc2023) to run at 1458906523
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(effective_destination_number=xxxxxxxx01)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [effective_destination_number]=[xxxxxxxx01]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 export(t38_passthru=true)
    2016-03-23 13:48:43.635031 [DEBUG] switch_channel.c:1293 EXPORT (export_vars) [t38_passthru]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(fax_enable_t38=true)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [fax_enable_t38]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 set(fax_enable_t38_request=true)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65 at x.x.x.86 [fax_enable_t38_request]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65 at x.x.x.86 bridge({sip_invite_to_uri=<sip:xxxxxxxx01 at x.x.x.42:5060>,sip_invite_req_uri=sip:xxxxxxxx01 at x.x.x.42:5060}sofia/default/sip:test-user at x.x.x.42:5060;fs_path=sip%3Ax.x.x.35%3Blr%3Breceived%3Dsip%3Ax.x.x.42%3A5060)
    2016-03-23 13:48:43.635031 [DEBUG] switch_channel.c:1247 sofia/default/+xxxxxxxxx65 at x.x.x.86 EXPORTING[export_vars] [t38_passthru]=[true] to event
    2016-03-23 13:48:43.635031 [DEBUG] switch_channel.c:1247 sofia/default/+xxxxxxxxx65 at x.x.x.86 EXPORTING[export_vars] [t38_passthru]=[true] to event
    2016-03-23 13:48:43.635031 [DEBUG] switch_ivr_originate.c:2128 Parsing global variables
    2016-03-23 13:48:43.635031 [NOTICE] switch_channel.c:1101 New Channel sofia/default/test-user at x.x.x.42:5060 [36b94456-46e2-4ef2-9fb8-9ebe4d9d67b1]
    2016-03-23 13:48:43.635031 [DEBUG] mod_sofia.c:4776 (sofia/default/test-user at x.x.x.42:5060) State Change CS_NEW -> CS_INIT
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:473 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_INIT
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:516 (sofia/default/test-user at x.x.x.42:5060) State INIT
    2016-03-23 13:48:43.635031 [DEBUG] mod_sofia.c:88 sofia/default/test-user at x.x.x.42:5060 SOFIA INIT
    2016-03-23 13:48:43.635031 [DEBUG] sofia_glue.c:1228 sip:x.x.x.35;lr;received=sip:x.x.x.42:5060 Setting proxy route to sofia/default/test-user at x.x.x.42:5060
    2016-03-23 13:48:43.635031 [DEBUG] sofia_glue.c:1257 sofia/default/test-user at x.x.x.42:5060 sending invite version: 1.6.6 git d2d0b32 2016-01-11 20:16:12Z 64bit
    Local SDP:
    v=0
    o=SBC 1458713961 1458713962 IN IP4 x.x.x.37
    s=SBC
    c=IN IP4 x.x.x.37
    t=0 0
    m=audio 19762 RTP/AVP 18 8 101 13
    a=rtpmap:18 G729/8000
    a=fmtp:18 annexb=no
    a=rtpmap:8 PCMA/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=rtpmap:13 CN/8000
    a=ptime:60
    a=sendrecv
     
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:40 sofia/default/test-user at x.x.x.42:5060 Standard INIT
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:48 (sofia/default/test-user at x.x.x.42:5060) State Change CS_INIT -> CS_ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:516 (sofia/default/test-user at x.x.x.42:5060) State INIT going to sleep
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:473 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] sofia.c:6760 Channel sofia/default/test-user at x.x.x.42:5060 entering state [calling][0]
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:532 (sofia/default/test-user at x.x.x.42:5060) State ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] mod_sofia.c:141 sofia/default/test-user at x.x.x.42:5060 SOFIA ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] switch_ivr_originate.c:67 (sofia/default/test-user at x.x.x.42:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:532 (sofia/default/test-user at x.x.x.42:5060) State ROUTING going to sleep
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:473 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_CONSUME_MEDIA
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:551 (sofia/default/test-user at x.x.x.42:5060) State CONSUME_MEDIA
    2016-03-23 13:48:43.635031 [DEBUG] switch_core_state_machine.c:551 (sofia/default/test-user at x.x.x.42:5060) State CONSUME_MEDIA going to sleep
    2016-03-23 13:48:43.775034 [ERR] sofia_reg.c:2583 Cannot locate any authentication credentials to complete an authentication request for realm '"vpbx01.xxx.com"'
    2016-03-23 13:48:43.775034 [NOTICE] sofia_reg.c:2606 Hangup sofia/default/test-user at x.x.x.42:5060 [CS_CONSUME_MEDIA] [MANDATORY_IE_MISSING]
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:473 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:739 (sofia/default/test-user at x.x.x.42:5060) Callstate Change DOWN -> HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:741 (sofia/default/test-user at x.x.x.42:5060) State HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:431 Channel sofia/default/test-user at x.x.x.42:5060 hanging up, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:495 Sending CANCEL to sofia/default/test-user at x.x.x.42:5060
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:60 sofia/default/test-user at x.x.x.42:5060 Standard HANGUP, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:741 (sofia/default/test-user at x.x.x.42:5060) State HANGUP going to sleep
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:508 (sofia/default/test-user at x.x.x.42:5060) State Change CS_HANGUP -> CS_REPORTING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:473 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_REPORTING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:827 (sofia/default/test-user at x.x.x.42:5060) State REPORTING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:104 sofia/default/test-user at x.x.x.42:5060 Standard REPORTING, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:827 (sofia/default/test-user at x.x.x.42:5060) State REPORTING going to sleep
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:499 (sofia/default/test-user at x.x.x.42:5060) State Change CS_REPORTING -> CS_DESTROY
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_session.c:1646 Session 25 (sofia/default/test-user at x.x.x.42:5060) Locked, Waiting on external entities
    2016-03-23 13:48:43.775034 [DEBUG] switch_ivr_originate.c:3751 Originate Resulted in Error Cause: 96 [MANDATORY_IE_MISSING]
    2016-03-23 13:48:43.775034 [NOTICE] switch_core_session.c:1664 Session 25 (sofia/default/test-user at x.x.x.42:5060) Ended
    2016-03-23 13:48:43.775034 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/test-user at x.x.x.42:5060 [CS_DESTROY]
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:630 (sofia/default/test-user at x.x.x.42:5060) Running State Change CS_DESTROY
    2016-03-23 13:48:43.775034 [INFO] mod_dptools.c:3379 Originate Failed.  Cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [NOTICE] switch_channel.c:4804 Hangup sofia/default/+xxxxxxxxx65 at x.x.x.86 [CS_EXECUTE] [MANDATORY_IE_MISSING]
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:640 (sofia/default/test-user at x.x.x.42:5060) State DESTROY
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:341 sofia/default/test-user at x.x.x.42:5060 SOFIA DESTROY
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:111 sofia/default/test-user at x.x.x.42:5060 Standard DESTROY
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:640 (sofia/default/test-user at x.x.x.42:5060) State DESTROY going to sleep
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_session.c:2796 sofia/default/+xxxxxxxxx65 at x.x.x.86 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:539 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State EXECUTE going to sleep
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:473 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Running State Change CS_HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:739 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Callstate Change RINGING -> HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:741 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:431 Channel sofia/default/+xxxxxxxxx65 at x.x.x.86 hanging up, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:568 Responding to INVITE with: 480
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:60 sofia/default/+xxxxxxxxx65 at x.x.x.86 Standard HANGUP, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:741 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State HANGUP going to sleep
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:508 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State Change CS_HANGUP -> CS_REPORTING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:473 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Running State Change CS_REPORTING
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:827 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State REPORTING
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:104 sofia/default/+xxxxxxxxx65 at x.x.x.86 Standard REPORTING, cause: MANDATORY_IE_MISSING
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:827 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State REPORTING going to sleep
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:499 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State Change CS_REPORTING -> CS_DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_session.c:1646 Session 24 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Locked, Waiting on external entities
    2016-03-23 13:48:44.035036 [NOTICE] switch_core_session.c:1664 Session 24 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Ended
    2016-03-23 13:48:44.035036 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/+xxxxxxxxx65 at x.x.x.86 [CS_DESTROY]
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:630 (sofia/default/+xxxxxxxxx65 at x.x.x.86) Running State Change CS_DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:640 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] mod_sofia.c:341 sofia/default/+xxxxxxxxx65 at x.x.x.86 SOFIA DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:111 sofia/default/+xxxxxxxxx65 at x.x.x.86 Standard DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:640 (sofia/default/+xxxxxxxxx65 at x.x.x.86) State DESTROY going to sleep
    2016-03-23 13:48:44.135038 [DEBUG] switch_scheduler.c:144 Deleting task 21 switch_ivr_schedule_hangup (67849c93-6b10-4377-834e-78657fcc2023)



Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users mailing list