=========
DIAL PLAN
=========
==================
ORIGINATES I TRIED
==================
originate {fax_verbose=true,ignore_early_media=true}sofia/internal/RECVFAXEXT@192.168.56.101 SENDFAXEXT XML default_context mycallername +123456
originate {ignore_early_media=true,absolute_codec_string='PCMU,PCMA',fax_enable_t38=true,fax_verbose=true,fax_use_ecm=true,fax_enable_t38_request=true}sofia/internal/RECVFAXEXT@192.168.56.101 SENDFAXEXT XML default_context mycallername +123456
originate {ignore_early_media=true,absolute_codec_string='PCMU,PCMA',fax_enable_t38=true,fax_verbose=true,fax_use_ecm=false,fax_enable_t38_request=false}sofia/internal/RECVFAXEXT@192.168.56.101 SENDFAXEXT XML default_context mycallername +123456
====================
ORIGINATE RESULT LOG
====================
+OK log level [7]
freeswitch@debian> originate {fax_verbose=true,ignore_early_media=true}sofia/internal/RECVFAXEXT@192.168.56.101 SENDFAXEXT XML default_context mycallername +123456
+OK b82fdeb1-d954-4159-9778-7fde1ab67680
2017-06-13 09:41:48.481892 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-13 09:41:48.481892 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/RECVFAXEXT@192.168.56.101 [b82fdeb1-d954-4159-9778-7fde1ab67680]
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:4818 (sofia/internal/RECVFAXEXT@192.168.56.101) State Change CS_NEW -> CS_INIT
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/RECVFAXEXT@192.168.56.101) Running State Change CS_INIT (Cur 1 Tot 1)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/RECVFAXEXT@192.168.56.101) State INIT
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:90 sofia/internal/RECVFAXEXT@192.168.56.101 SOFIA INIT
2017-06-13 09:41:48.481892 [DEBUG] sofia_glue.c:1295 sofia/internal/RECVFAXEXT@192.168.56.101 sending invite version: 1.6.17 -34-0fc0946 64bit
Local SDP:
v=0
o=FreeSWITCH 1497339796 1497339797 IN IP4 192.168.56.101
s=FreeSWITCH
c=IN IP4 192.168.56.101
t=0 0
m=audio 21512 RTP/AVP 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
2017-06-13 09:41:48.481892 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/+123456@192.168.56.101 [79f2c010-499c-41cf-bc2e-a8fbab1e558d]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:40 sofia/internal/RECVFAXEXT@192.168.56.101 Standard INIT
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/RECVFAXEXT@192.168.56.101) State Change CS_INIT -> CS_ROUTING
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/RECVFAXEXT@192.168.56.101) State INIT going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/RECVFAXEXT@192.168.56.101) Running State Change CS_ROUTING (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/RECVFAXEXT@192.168.56.101 entering state [calling][0]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/RECVFAXEXT@192.168.56.101) State ROUTING
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:143 sofia/internal/RECVFAXEXT@192.168.56.101 SOFIA ROUTING
2017-06-13 09:41:48.481892 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/RECVFAXEXT@192.168.56.101) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/RECVFAXEXT@192.168.56.101) State ROUTING going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/RECVFAXEXT@192.168.56.101) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/RECVFAXEXT@192.168.56.101) State CONSUME_MEDIA
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/RECVFAXEXT@192.168.56.101) State CONSUME_MEDIA going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+123456@192.168.56.101) Running State Change CS_NEW (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:9834 sofia/internal/+123456@192.168.56.101 receiving invite from 192.168.56.101:5060 version: 1.6.17 -34-0fc0946 64bit
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/+123456@192.168.56.101 entering state [received][100]
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=FreeSWITCH 1497339796 1497339797 IN IP4 192.168.56.101
s=FreeSWITCH
c=IN IP4 192.168.56.101
t=0 0
m=audio 21512 RTP/AVP 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/+123456@192.168.56.101 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-13 09:41:48.481892 [DEBUG] switch_core_codec.c:111 sofia/internal/+123456@192.168.56.101 Original read codec set to PCMU:0
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4754 sofia/internal/+123456@192.168.56.101 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7471 (sofia/internal/+123456@192.168.56.101) State Change CS_NEW -> CS_INIT
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/+123456@192.168.56.101) State NEW
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+123456@192.168.56.101) Running State Change CS_INIT (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/+123456@192.168.56.101) State INIT
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:90 sofia/internal/+123456@192.168.56.101 SOFIA INIT
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:40 sofia/internal/+123456@192.168.56.101 Standard INIT
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/+123456@192.168.56.101) State Change CS_INIT -> CS_ROUTING
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/+123456@192.168.56.101) State INIT going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+123456@192.168.56.101) Running State Change CS_ROUTING (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_channel.c:2249 (sofia/internal/+123456@192.168.56.101) Callstate Change DOWN -> RINGING
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/+123456@192.168.56.101) State ROUTING
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:143 sofia/internal/+123456@192.168.56.101 SOFIA ROUTING
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:236 sofia/internal/+123456@192.168.56.101 Standard ROUTING
2017-06-13 09:41:48.481892 [INFO] mod_dialplan_xml.c:637 Processing mycallername <+123456>->RECVFAXEXT in context default_context
Dialplan: sofia/internal/+123456@192.168.56.101 parsing [default_context->send_fax] continue=false
Dialplan: sofia/internal/+123456@192.168.56.101 Regex (FAIL) [send_fax] destination_number(RECVFAXEXT) =~ /SENDFAXEXT/ break=on-false
Dialplan: sofia/internal/+123456@192.168.56.101 parsing [default_context->recv_fax] continue=false
Dialplan: sofia/internal/+123456@192.168.56.101 Regex (PASS) [recv_fax] destination_number(RECVFAXEXT) =~ /RECVFAXEXT/ break=on-false
Dialplan: sofia/internal/+123456@192.168.56.101 Action answer()
Dialplan: sofia/internal/+123456@192.168.56.101 Action log(ALERT inside recv_fax)
Dialplan: sofia/internal/+123456@192.168.56.101 Action rxfax(/tmp/rx.tiff)
Dialplan: sofia/internal/+123456@192.168.56.101 Action hangup()
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/+123456@192.168.56.101) State Change CS_ROUTING -> CS_EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/+123456@192.168.56.101) State ROUTING going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/+123456@192.168.56.101) Running State Change CS_EXECUTE (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/+123456@192.168.56.101) State EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:198 sofia/internal/+123456@192.168.56.101 SOFIA EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:328 sofia/internal/+123456@192.168.56.101 Standard EXECUTE
EXECUTE sofia/internal/+123456@192.168.56.101 answer()
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/+123456@192.168.56.101] 192.168.56.101 port 31130 -> 192.168.56.101 port 21512 codec: 0 ms: 20
2017-06-13 09:41:48.481892 [DEBUG] switch_rtp.c:4114 Not using a timer
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7166 sofia/internal/+123456@192.168.56.101 Set 2833 dtmf send payload to 101
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7173 sofia/internal/+123456@192.168.56.101 Set 2833 dtmf receive payload to 101
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7196 sofia/internal/+123456@192.168.56.101 Set rtp dtmf delay to 40
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7202 Set comfort noise payload to 13
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/+123456@192.168.56.101:
v=0
o=FreeSWITCH 1497330178 1497330179 IN IP4 192.168.56.101
s=FreeSWITCH
c=IN IP4 192.168.56.101
t=0 0
m=audio 31130 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
2017-06-13 09:41:48.481892 [INFO] sofia.c:1279 sofia/internal/RECVFAXEXT@192.168.56.101 Update Callee ID to "RECVFAXEXT"
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/RECVFAXEXT@192.168.56.101 entering state [completing][200]
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=FreeSWITCH 1497330178 1497330179 IN IP4 192.168.56.101
s=FreeSWITCH
c=IN IP4 192.168.56.101
t=0 0
m=audio 31130 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/RECVFAXEXT@192.168.56.101 entering state [ready][200]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/RECVFAXEXT@192.168.56.101 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-13 09:41:48.481892 [DEBUG] switch_core_codec.c:111 sofia/internal/RECVFAXEXT@192.168.56.101 Original read codec set to PCMU:0
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:4754 sofia/internal/RECVFAXEXT@192.168.56.101 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/RECVFAXEXT@192.168.56.101] 192.168.56.101 port 21512 -> 192.168.56.101 port 31130 codec: 0 ms: 20
2017-06-13 09:41:48.481892 [DEBUG] switch_rtp.c:4114 Not using a timer
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/+123456@192.168.56.101 entering state [completed][200]
2017-06-13 09:41:48.481892 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/+123456@192.168.56.101] has been answered
2017-06-13 09:41:48.481892 [DEBUG] switch_channel.c:3772 (sofia/internal/+123456@192.168.56.101) Callstate Change RINGING -> ACTIVE
2017-06-13 09:41:48.481892 [DEBUG] sofia.c:7048 Channel sofia/internal/+123456@192.168.56.101 entering state [ready][200]
EXECUTE sofia/internal/+123456@192.168.56.101 log(ALERT inside recv_fax)
2017-06-13 09:41:48.481892 [ALERT] mod_dptools.c:1724 inside recv_fax
EXECUTE sofia/internal/+123456@192.168.56.101 rxfax(/tmp/rx.tiff)
2017-06-13 09:41:48.481892 [DEBUG] mod_spandsp_fax.c:1448 Raw read codec activation Success L16 20000
2017-06-13 09:41:48.481892 [DEBUG] switch_core_codec.c:223 sofia/internal/+123456@192.168.56.101 Push codec L16:100
2017-06-13 09:41:48.481892 [DEBUG] mod_spandsp_fax.c:1466 Raw write codec activation Success L16
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7166 sofia/internal/RECVFAXEXT@192.168.56.101 Set 2833 dtmf send payload to 101
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7173 sofia/internal/RECVFAXEXT@192.168.56.101 Set 2833 dtmf receive payload to 101
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7196 sofia/internal/RECVFAXEXT@192.168.56.101 Set rtp dtmf delay to 40
2017-06-13 09:41:48.481892 [DEBUG] switch_core_media.c:7202 Set comfort noise payload to 13
2017-06-13 09:41:48.481892 [NOTICE] sofia.c:8182 Channel [sofia/internal/RECVFAXEXT@192.168.56.101] has been answered
2017-06-13 09:41:48.481892 [DEBUG] switch_channel.c:3772 (sofia/internal/RECVFAXEXT@192.168.56.101) Callstate Change DOWN -> ACTIVE
2017-06-13 09:41:48.481892 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/RECVFAXEXT@192.168.56.101]
2017-06-13 09:41:48.481892 [DEBUG] switch_ivr.c:2165 (sofia/internal/RECVFAXEXT@192.168.56.101) State Change CS_CONSUME_MEDIA -> CS_ROUTING
2017-06-13 09:41:48.481892 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/RECVFAXEXT@192.168.56.101 to XML[SENDFAXEXT@default_context]
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/RECVFAXEXT@192.168.56.101) Running State Change CS_ROUTING (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/RECVFAXEXT@192.168.56.101) State ROUTING
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:143 sofia/internal/RECVFAXEXT@192.168.56.101 SOFIA ROUTING
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:236 sofia/internal/RECVFAXEXT@192.168.56.101 Standard ROUTING
2017-06-13 09:41:48.481892 [INFO] mod_dialplan_xml.c:637 Processing mycallername <+123456>->SENDFAXEXT in context default_context
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 parsing [default_context->send_fax] continue=false
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 Regex (PASS) [send_fax] destination_number(SENDFAXEXT) =~ /SENDFAXEXT/ break=on-false
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 Action answer()
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 Action log(ALERT inside sendfax destination: ${destination_number})
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 Action txfax(/tmp/tx.tiff)
Dialplan: sofia/internal/RECVFAXEXT@192.168.56.101 Action hangup()
2017-06-13 09:41:48.481892 [INFO] switch_channel.c:3129 sofia/internal/RECVFAXEXT@192.168.56.101 Flipping CID from "mycallername" <+123456> to "RECVFAXEXT"
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/RECVFAXEXT@192.168.56.101) State Change CS_ROUTING -> CS_EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/RECVFAXEXT@192.168.56.101) State ROUTING going to sleep
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/RECVFAXEXT@192.168.56.101) Running State Change CS_EXECUTE (Cur 2 Tot 2)
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/RECVFAXEXT@192.168.56.101) State EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] mod_sofia.c:198 sofia/internal/RECVFAXEXT@192.168.56.101 SOFIA EXECUTE
2017-06-13 09:41:48.481892 [DEBUG] switch_core_state_machine.c:328 sofia/internal/RECVFAXEXT@192.168.56.101 Standard EXECUTE
EXECUTE sofia/internal/RECVFAXEXT@192.168.56.101 answer()
EXECUTE sofia/internal/RECVFAXEXT@192.168.56.101 log(ALERT inside sendfax destination: SENDFAXEXT)
2017-06-13 09:41:48.481892 [ALERT] mod_dptools.c:1724 inside sendfax destination: SENDFAXEXT
EXECUTE sofia/internal/RECVFAXEXT@192.168.56.101 txfax(/tmp/tx.tiff)
2017-06-13 09:41:48.521420 [DEBUG] mod_spandsp_fax.c:1448 Raw read codec activation Success L16 20000
2017-06-13 09:41:48.521420 [DEBUG] switch_core_codec.c:223 sofia/internal/RECVFAXEXT@192.168.56.101 Push codec L16:100
2017-06-13 09:41:48.521420 [DEBUG] mod_spandsp_fax.c:1466 Raw write codec activation Success L16