I created a Fax Server with extension 7000. The destination number is empty as per the instructions I read (but gets populated anyways when I save) and the destination email points to my email address. I then create an inbound Destination with Actions -> 7000 and Fax detection -> 7000. Usage is checked as Fax and the inbound DID is T.38 enabled.
As far as I can tell that should be all that needs to be done to receive faxes. However, when I send a fax to my DID, the Freeswitch log shows no fax activity and the Fax Server log is empty. I am trying desperately to move from Asterisk to Freeswitch. Please help. I posted my log below.
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] switch_ivr.c:2296 Transfer sofia/internal/15141111111@voxbone.com to XML[7000@fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_ivr.c:2289 (sofia/internal/15141111111@voxbone.com) State Change CS_EXECUTE -> CS_ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com transfer(7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media_bug.c:978 Attaching BUG to sofia/internal/15141111111@voxbone.com
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_ivr_async.c:4371 Adding tone spec 1100 index 0 hits 1
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] mod_dptools.c:2321 Enabling tone detection fax 1100
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com tone_detect(fax 1100 r +5000)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] sofia.c:7499 Channel sofia/internal/15141111111@voxbone.com entering state [early][183]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_channel.c:3622 (sofia/internal/15141111111@voxbone.com) Callstate Change RINGING -> EARLY
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] mod_sofia.c:2613 Pre-Answer sofia/internal/15141111111@voxbone.com!
86d8d8c1-6842-4062-b67d-cfd301aaa449
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=sendrecv
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=ptime:20
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=fmtp:101 0-15
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:101 telephone-event/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:0 PCMU/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 m=audio 21570 RTP/AVP 0 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 t=0 0
86d8d8c1-6842-4062-b67d-cfd301aaa449 c=IN IP4 1xx.1xx.1xx.xxx
86d8d8c1-6842-4062-b67d-cfd301aaa449 s=FreeSWITCH
86d8d8c1-6842-4062-b67d-cfd301aaa449 o=FreeSWITCH 1655396075 1655396076 IN IP4 1xx.1xx.1xx.xxx
86d8d8c1-6842-4062-b67d-cfd301aaa449 v=0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] mod_sofia.c:2610 Ring SDP:
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9119 sofia/internal/15141111111@voxbone.com Set rtp dtmf delay to 40
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9096 sofia/internal/15141111111@voxbone.com Set 2833 dtmf receive payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9089 sofia/internal/15141111111@voxbone.com Set 2833 dtmf send payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/internal/15141111111@voxbone.com] 1xx.1xx.1xx.xxx port 21570 -> 81.201.85.82 port 14236 codec: 0 ms: 20
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] switch_core_session.c:2797 Sending early media
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_session.c:2795 Application tone_detect Requires media! pre_answering channel sofia/internal/15141111111@voxbone.com
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:323 sofia/internal/15141111111@voxbone.com Standard EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:213 sofia/internal/15141111111@voxbone.com SOFIA EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15141111111@voxbone.com) State EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_EXECUTE (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15141111111@voxbone.com) State ROUTING going to sleep
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/15141111111@voxbone.com) State Change CS_ROUTING -> CS_EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action ()
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action transfer(7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action tone_detect(fax 1100 r +5000)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [execute_on_tone_detect]=[transfer 7000 XML fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(execute_on_tone_detect=transfer 7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(execute_on_tone_detect=transfer 7000 XML ${domain_name}) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [tone_detect_hits]=[1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(tone_detect_hits=1)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(tone_detect_hits=1) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [domain_name]=[fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(domain_name=fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(domain_name=fpbx.mypbx.com) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [domain_uuid]=[86e8db27-0d60-43b2-b16b-f28a3a0403b3]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(domain_uuid=86e8db27-0d60-43b2-b16b-f28a3a0403b3)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(domain_uuid=86e8db27-0d60-43b2-b16b-f28a3a0403b3) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[inbound]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com export(call_direction=inbound)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action export(call_direction=inbound) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Regex (PASS) [15149999999] destination_number(15149999999) =~ /^(15149999999)$/ break=on-false
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com parsing [public->15149999999] continue=false
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] mod_dialplan_xml.c:639 Processing 15141111111 <15141111111>->15149999999 in context public
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:230 sofia/internal/15141111111@voxbone.com Standard ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:158 sofia/internal/15141111111@voxbone.com SOFIA ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15141111111@voxbone.com) State ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_channel.c:2380 (sofia/internal/15141111111@voxbone.com) Callstate Change DOWN -> RINGING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_ROUTING (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15141111111@voxbone.com) State INIT going to sleep
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15141111111@voxbone.com) State Change CS_INIT -> CS_ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:40 sofia/internal/15141111111@voxbone.com Standard INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:97 sofia/internal/15141111111@voxbone.com SOFIA INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15141111111@voxbone.com) State INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_INIT (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/15141111111@voxbone.com) State NEW
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7933 (sofia/internal/15141111111@voxbone.com) State Change CS_NEW -> CS_INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5973 sofia/internal/15141111111@voxbone.com Set 2833 dtmf send payload to 101 recv payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_codec.c:111 sofia/internal/15141111111@voxbone.com Original read codec set to PCMU:0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:3870 Set Codec sofia/internal/15141111111@voxbone.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=ptime:20
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=fmtp:101 0-16
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:101 telephone-event/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:8 PCMA/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:0 PCMU/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 m=audio 14236 RTP/AVP 0 8 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 t=0 0
86d8d8c1-6842-4062-b67d-cfd301aaa449 c=IN IP4 81.201.85.82
86d8d8c1-6842-4062-b67d-cfd301aaa449 s=session
86d8d8c1-6842-4062-b67d-cfd301aaa449 o=- 1500508156 1500508156 IN IP4 81.201.85.82
86d8d8c1-6842-4062-b67d-cfd301aaa449 v=0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7509 Remote SDP:
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7499 Channel sofia/internal/15141111111@voxbone.com entering state [received][100]
2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:10585 IP 81.201.85.45 Approved by acl "domains[]". Access Granted.
2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 81.201.85.45:0.
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] sofia.c:10462 sofia/internal/15141111111@voxbone.com receiving invite from 81.201.85.45:5060 version: 1.10.7 -release 64bit call-id: EJFMD19BUD6435OSLOHLB7ED64@81.201.85.48
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_NEW (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/15141111111@voxbone.com [86d8d8c1-6842-4062-b67d-cfd301aaa449]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15141111111@voxbone.com) State DESTROY going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:175 sofia/internal/15141111111@voxbone.com Standard DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] mod_sofia.c:379 sofia/internal/15141111111@voxbone.com SOFIA DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15141111111@voxbone.com) State DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/15141111111@voxbone.com) Running State Change CS_DESTROY (Cur 0 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/15141111111@voxbone.com [CS_DESTROY]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [NOTICE] switch_core_session.c:1771 Session 194 (sofia/internal/15141111111@voxbone.com) Ended
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_session.c:1753 Session 194 (sofia/internal/15141111111@voxbone.com) Locked, Waiting on external entities
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/15141111111@voxbone.com) State Change CS_REPORTING -> CS_DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15141111111@voxbone.com) State REPORTING going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:168 sofia/internal/15141111111@voxbone.com Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7000) State DESTROY going to sleep
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:175 sofia/external/7000 Standard DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] mod_sofia.c:379 sofia/external/7000 SOFIA DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7000) State DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:735 (sofia/external/7000) Running State Change CS_DESTROY (Cur 1 Tot 195)
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [NOTICE] switch_core_session.c:1775 Close Channel sofia/external/7000 [CS_DESTROY]
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [NOTICE] switch_core_session.c:1771 Session 195 (sofia/external/7000) Ended
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15141111111@voxbone.com) State REPORTING
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_REPORTING (Cur 2 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/15141111111@voxbone.com) State Change CS_HANGUP -> CS_REPORTING
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15141111111@voxbone.com) State HANGUP going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:59 sofia/internal/15141111111@voxbone.com Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 408
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:468 Channel sofia/internal/15141111111@voxbone.com hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:462 sofia/internal/15141111111@voxbone.com Overriding SIP cause 504 with 408 from the other leg
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15141111111@voxbone.com) State HANGUP
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/15141111111@voxbone.com) Callstate Change EARLY -> HANGUP
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_media_bug.c:1328 Removing BUG from sofia/internal/15141111111@voxbone.com
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_HANGUP (Cur 2 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15141111111@voxbone.com) State EXECUTE going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_session.c:2983 sofia/internal/15141111111@voxbone.com skip receive message [PHONE_EVENT] (channel is hungup already)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [NOTICE] switch_channel.c:5050 Hangup sofia/internal/15141111111@voxbone.com [CS_EXECUTE] [RECOVERY_ON_TIMER_EXPIRE]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [INFO] mod_dptools.c:3653 Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_session.c:1753 Session 195 (sofia/external/7000) Locked, Waiting on external entities
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:607 (sofia/external/7000) State Change CS_REPORTING -> CS_DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/external/7000) State REPORTING going to sleep
As far as I can tell that should be all that needs to be done to receive faxes. However, when I send a fax to my DID, the Freeswitch log shows no fax activity and the Fax Server log is empty. I am trying desperately to move from Asterisk to Freeswitch. Please help. I posted my log below.
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] switch_ivr.c:2296 Transfer sofia/internal/15141111111@voxbone.com to XML[7000@fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_ivr.c:2289 (sofia/internal/15141111111@voxbone.com) State Change CS_EXECUTE -> CS_ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com transfer(7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media_bug.c:978 Attaching BUG to sofia/internal/15141111111@voxbone.com
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_ivr_async.c:4371 Adding tone spec 1100 index 0 hits 1
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] mod_dptools.c:2321 Enabling tone detection fax 1100
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com tone_detect(fax 1100 r +5000)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] sofia.c:7499 Channel sofia/internal/15141111111@voxbone.com entering state [early][183]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_channel.c:3622 (sofia/internal/15141111111@voxbone.com) Callstate Change RINGING -> EARLY
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [NOTICE] mod_sofia.c:2613 Pre-Answer sofia/internal/15141111111@voxbone.com!
86d8d8c1-6842-4062-b67d-cfd301aaa449
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=sendrecv
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=ptime:20
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=fmtp:101 0-15
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:101 telephone-event/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:0 PCMU/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 m=audio 21570 RTP/AVP 0 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 t=0 0
86d8d8c1-6842-4062-b67d-cfd301aaa449 c=IN IP4 1xx.1xx.1xx.xxx
86d8d8c1-6842-4062-b67d-cfd301aaa449 s=FreeSWITCH
86d8d8c1-6842-4062-b67d-cfd301aaa449 o=FreeSWITCH 1655396075 1655396076 IN IP4 1xx.1xx.1xx.xxx
86d8d8c1-6842-4062-b67d-cfd301aaa449 v=0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] mod_sofia.c:2610 Ring SDP:
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9119 sofia/internal/15141111111@voxbone.com Set rtp dtmf delay to 40
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9096 sofia/internal/15141111111@voxbone.com Set 2833 dtmf receive payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.980420 97.23% [DEBUG] switch_core_media.c:9089 sofia/internal/15141111111@voxbone.com Set 2833 dtmf send payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/internal/15141111111@voxbone.com] 1xx.1xx.1xx.xxx port 21570 -> 81.201.85.82 port 14236 codec: 0 ms: 20
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] switch_core_session.c:2797 Sending early media
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_session.c:2795 Application tone_detect Requires media! pre_answering channel sofia/internal/15141111111@voxbone.com
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:323 sofia/internal/15141111111@voxbone.com Standard EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:213 sofia/internal/15141111111@voxbone.com SOFIA EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15141111111@voxbone.com) State EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_EXECUTE (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15141111111@voxbone.com) State ROUTING going to sleep
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/15141111111@voxbone.com) State Change CS_ROUTING -> CS_EXECUTE
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action ()
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action transfer(7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action tone_detect(fax 1100 r +5000)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [execute_on_tone_detect]=[transfer 7000 XML fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(execute_on_tone_detect=transfer 7000 XML fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(execute_on_tone_detect=transfer 7000 XML ${domain_name}) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [tone_detect_hits]=[1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(tone_detect_hits=1)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(tone_detect_hits=1) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [domain_name]=[fpbx.mypbx.com]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(domain_name=fpbx.mypbx.com)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(domain_name=fpbx.mypbx.com) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_dptools.c:1685 SET sofia/internal/15141111111@voxbone.com [domain_uuid]=[86e8db27-0d60-43b2-b16b-f28a3a0403b3]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com set(domain_uuid=86e8db27-0d60-43b2-b16b-f28a3a0403b3)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action set(domain_uuid=86e8db27-0d60-43b2-b16b-f28a3a0403b3) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[inbound]
86d8d8c1-6842-4062-b67d-cfd301aaa449 EXECUTE [depth=0] sofia/internal/15141111111@voxbone.com export(call_direction=inbound)
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Action export(call_direction=inbound) INLINE
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com Regex (PASS) [15149999999] destination_number(15149999999) =~ /^(15149999999)$/ break=on-false
86d8d8c1-6842-4062-b67d-cfd301aaa449 Dialplan: sofia/internal/15141111111@voxbone.com parsing [public->15149999999] continue=false
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] mod_dialplan_xml.c:639 Processing 15141111111 <15141111111>->15149999999 in context public
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:230 sofia/internal/15141111111@voxbone.com Standard ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:158 sofia/internal/15141111111@voxbone.com SOFIA ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15141111111@voxbone.com) State ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_channel.c:2380 (sofia/internal/15141111111@voxbone.com) Callstate Change DOWN -> RINGING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_ROUTING (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15141111111@voxbone.com) State INIT going to sleep
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15141111111@voxbone.com) State Change CS_INIT -> CS_ROUTING
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:40 sofia/internal/15141111111@voxbone.com Standard INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] mod_sofia.c:97 sofia/internal/15141111111@voxbone.com SOFIA INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15141111111@voxbone.com) State INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_INIT (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/15141111111@voxbone.com) State NEW
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7933 (sofia/internal/15141111111@voxbone.com) State Change CS_NEW -> CS_INIT
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5973 sofia/internal/15141111111@voxbone.com Set 2833 dtmf send payload to 101 recv payload to 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_codec.c:111 sofia/internal/15141111111@voxbone.com Original read codec set to PCMU:0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:3870 Set Codec sofia/internal/15141111111@voxbone.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
86d8d8c1-6842-4062-b67d-cfd301aaa449
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=ptime:20
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=fmtp:101 0-16
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:101 telephone-event/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:8 PCMA/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 a=rtpmap:0 PCMU/8000
86d8d8c1-6842-4062-b67d-cfd301aaa449 m=audio 14236 RTP/AVP 0 8 101
86d8d8c1-6842-4062-b67d-cfd301aaa449 t=0 0
86d8d8c1-6842-4062-b67d-cfd301aaa449 c=IN IP4 81.201.85.82
86d8d8c1-6842-4062-b67d-cfd301aaa449 s=session
86d8d8c1-6842-4062-b67d-cfd301aaa449 o=- 1500508156 1500508156 IN IP4 81.201.85.82
86d8d8c1-6842-4062-b67d-cfd301aaa449 v=0
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7509 Remote SDP:
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:7499 Channel sofia/internal/15141111111@voxbone.com entering state [received][100]
2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:10585 IP 81.201.85.45 Approved by acl "domains[]". Access Granted.
2022-06-16 18:14:05.960428 97.23% [DEBUG] sofia.c:10556 verifying acl "domains" for ip/port 81.201.85.45:0.
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [INFO] sofia.c:10462 sofia/internal/15141111111@voxbone.com receiving invite from 81.201.85.45:5060 version: 1.10.7 -release 64bit call-id: EJFMD19BUD6435OSLOHLB7ED64@81.201.85.48
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_NEW (Cur 1 Tot 196)
86d8d8c1-6842-4062-b67d-cfd301aaa449 2022-06-16 18:14:05.960428 97.23% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/15141111111@voxbone.com [86d8d8c1-6842-4062-b67d-cfd301aaa449]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15141111111@voxbone.com) State DESTROY going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:175 sofia/internal/15141111111@voxbone.com Standard DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] mod_sofia.c:379 sofia/internal/15141111111@voxbone.com SOFIA DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15141111111@voxbone.com) State DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/15141111111@voxbone.com) Running State Change CS_DESTROY (Cur 0 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/15141111111@voxbone.com [CS_DESTROY]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [NOTICE] switch_core_session.c:1771 Session 194 (sofia/internal/15141111111@voxbone.com) Ended
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_session.c:1753 Session 194 (sofia/internal/15141111111@voxbone.com) Locked, Waiting on external entities
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/15141111111@voxbone.com) State Change CS_REPORTING -> CS_DESTROY
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15141111111@voxbone.com) State REPORTING going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.680427 98.07% [DEBUG] switch_core_state_machine.c:168 sofia/internal/15141111111@voxbone.com Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7000) State DESTROY going to sleep
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:175 sofia/external/7000 Standard DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] mod_sofia.c:379 sofia/external/7000 SOFIA DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7000) State DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [DEBUG] switch_core_state_machine.c:735 (sofia/external/7000) Running State Change CS_DESTROY (Cur 1 Tot 195)
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [NOTICE] switch_core_session.c:1775 Close Channel sofia/external/7000 [CS_DESTROY]
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.560422 98.07% [NOTICE] switch_core_session.c:1771 Session 195 (sofia/external/7000) Ended
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15141111111@voxbone.com) State REPORTING
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_REPORTING (Cur 2 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/15141111111@voxbone.com) State Change CS_HANGUP -> CS_REPORTING
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15141111111@voxbone.com) State HANGUP going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:59 sofia/internal/15141111111@voxbone.com Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 408
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:468 Channel sofia/internal/15141111111@voxbone.com hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] mod_sofia.c:462 sofia/internal/15141111111@voxbone.com Overriding SIP cause 504 with 408 from the other leg
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15141111111@voxbone.com) State HANGUP
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/15141111111@voxbone.com) Callstate Change EARLY -> HANGUP
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_media_bug.c:1328 Removing BUG from sofia/internal/15141111111@voxbone.com
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15141111111@voxbone.com) Running State Change CS_HANGUP (Cur 2 Tot 195)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15141111111@voxbone.com) State EXECUTE going to sleep
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_session.c:2983 sofia/internal/15141111111@voxbone.com skip receive message [PHONE_EVENT] (channel is hungup already)
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [NOTICE] switch_channel.c:5050 Hangup sofia/internal/15141111111@voxbone.com [CS_EXECUTE] [RECOVERY_ON_TIMER_EXPIRE]
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [INFO] mod_dptools.c:3653 Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE
2c0da670-e1f9-40e5-9842-e2edcbd67cf1 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_session.c:1753 Session 195 (sofia/external/7000) Locked, Waiting on external entities
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:607 (sofia/external/7000) State Change CS_REPORTING -> CS_DESTROY
467baaec-7774-41fc-a4e2-7a7db4eb441e 2022-06-16 18:14:03.540440 98.07% [DEBUG] switch_core_state_machine.c:932 (sofia/external/7000) State REPORTING going to sleep
