2016-03-23 13:48:43.435074 [INFO] mod_dialplan_xml.c:637 Processing +xxxxxxxxx65 <xxxxxxxxx65>->+xxxxxxxxx01 in context default
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 parsing [default->+xxxxxxxxx01] continue=false
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Regex (PASS) [+xxxxxxxxx01] destination_number(+xxxxxxxxx01) =~ // break=on-false
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(callstart=2016-03-23 11:48:43)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(call_processed=internal)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(originated_destination_number=xxxxxxxx01)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action export(t38_passthru=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(fax_enable_t38=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(fax_enable_t38_request=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(call_direction=inbound) 
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action sched_hangup(+172800 allotted_timeout)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(effective_destination_number=xxxxxxxx01)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action export(t38_passthru=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(fax_enable_t38=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(fax_enable_t38_request=true)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action set(did_calltype=LOCAL)
    Dialplan: sofia/default/+xxxxxxxxx65@x.x.x.86 Action bridge({sip_invite_to_uri=<sip:xxxxxxxx01@x.x.x.42:5060>,sip_invite_req_uri=sip:xxxxxxxx01@x.x.x.42:5060}sofia/default/sip:test-user@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@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@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@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@x.x.x.86) State EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] mod_sofia.c:196 sofia/default/+xxxxxxxxx65@x.x.x.86 SOFIA EXECUTE
    2016-03-23 13:48:43.615031 [DEBUG] switch_core_state_machine.c:258 sofia/default/+xxxxxxxxx65@x.x.x.86 Standard EXECUTE
    EXECUTE sofia/default/+xxxxxxxxx65@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@x.x.x.86 [callstart]=[2016-03-23 11:48:43]
    EXECUTE sofia/default/+xxxxxxxxx65@x.x.x.86 set(call_processed=internal)
    2016-03-23 13:48:43.615031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65@x.x.x.86 [call_processed]=[internal]
    EXECUTE sofia/default/+xxxxxxxxx65@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@x.x.x.86 [originated_destination_number]=[xxxxxxxx01]
    EXECUTE sofia/default/+xxxxxxxxx65@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@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@x.x.x.86 [fax_enable_t38]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65@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@x.x.x.86 [fax_enable_t38_request]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65@x.x.x.86 set(call_direction=inbound)
    2016-03-23 13:48:43.635031 [DEBUG] mod_dptools.c:1498 SET sofia/default/+xxxxxxxxx65@x.x.x.86 [call_direction]=[inbound]
    EXECUTE sofia/default/+xxxxxxxxx65@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@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@x.x.x.86 [effective_destination_number]=[xxxxxxxx01]
    EXECUTE sofia/default/+xxxxxxxxx65@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@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@x.x.x.86 [fax_enable_t38]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65@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@x.x.x.86 [fax_enable_t38_request]=[true]
    EXECUTE sofia/default/+xxxxxxxxx65@x.x.x.86 bridge({sip_invite_to_uri=<sip:xxxxxxxx01@x.x.x.42:5060>,sip_invite_req_uri=sip:xxxxxxxx01@x.x.x.42:5060}sofia/default/sip:test-user@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@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@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@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@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@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@x.x.x.42:5060) State INIT
    2016-03-23 13:48:43.635031 [DEBUG] mod_sofia.c:88 sofia/default/test-user@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@x.x.x.42:5060
    2016-03-23 13:48:43.635031 [DEBUG] sofia_glue.c:1257 sofia/default/test-user@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@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@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@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@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@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@x.x.x.42:5060) State ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] mod_sofia.c:141 sofia/default/test-user@x.x.x.42:5060 SOFIA ROUTING
    2016-03-23 13:48:43.635031 [DEBUG] switch_ivr_originate.c:67 (sofia/default/test-user@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@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@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@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@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@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@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@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@x.x.x.42:5060) State HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:431 Channel sofia/default/test-user@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@x.x.x.42:5060
    2016-03-23 13:48:43.775034 [DEBUG] switch_core_state_machine.c:60 sofia/default/test-user@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@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@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@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@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@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@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@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@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@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@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@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@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@x.x.x.42:5060) State DESTROY
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:341 sofia/default/test-user@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@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@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@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@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@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@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@x.x.x.86) State HANGUP
    2016-03-23 13:48:43.775034 [DEBUG] mod_sofia.c:431 Channel sofia/default/+xxxxxxxxx65@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@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@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@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@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@x.x.x.86) State REPORTING
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:104 sofia/default/+xxxxxxxxx65@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@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@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@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@x.x.x.86) Ended
    2016-03-23 13:48:44.035036 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/+xxxxxxxxx65@x.x.x.86 [CS_DESTROY]
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:630 (sofia/default/+xxxxxxxxx65@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@x.x.x.86) State DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] mod_sofia.c:341 sofia/default/+xxxxxxxxx65@x.x.x.86 SOFIA DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:111 sofia/default/+xxxxxxxxx65@x.x.x.86 Standard DESTROY
    2016-03-23 13:48:44.035036 [DEBUG] switch_core_state_machine.c:640 (sofia/default/+xxxxxxxxx65@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)