+OK log level [7] 2023-02-23 16:59:48.733445 99.47% [NOTICE] switch_channel.c:1123 New Channel sofia/external/7182087657@sip.telnyx.com [94a98667-27f0-44a9-840f-1eb9a8ba7a9e] 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_NEW (Cur 1 Tot 6679) 2023-02-23 16:59:48.733445 99.47% [INFO] sofia.c:10468 sofia/external/7182087657@sip.telnyx.com receiving invite from 144.202.23.145:5060 version: 1.10.8 -release.14 64bit call-id: f5e56634-a0f9-4133-bae0-20aaaf996f63 2023-02-23 16:59:48.733445 99.47% [DEBUG] sofia.c:7502 Channel sofia/external/7182087657@sip.telnyx.com entering state [received][100] 2023-02-23 16:59:48.733445 99.47% [DEBUG] sofia.c:7512 Remote SDP: v=0 o=Telnyx 1677152944 1677152945 IN IP4 64.16.227.16 s=Telnyx c=IN IP4 64.16.227.16 t=0 0 m=audio 18644 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtcp:18645 IN IP4 64.16.227.16 a=ptime:20 2023-02-23 16:59:48.733445 99.47% [DEBUG] sofia.c:7915 (sofia/external/7182087657@sip.telnyx.com) State Change CS_NEW -> CS_INIT 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:600 (sofia/external/7182087657@sip.telnyx.com) State NEW 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_INIT (Cur 1 Tot 6679) 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:624 (sofia/external/7182087657@sip.telnyx.com) State INIT 2023-02-23 16:59:48.733445 99.47% [DEBUG] mod_sofia.c:97 sofia/external/7182087657@sip.telnyx.com SOFIA INIT 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:40 sofia/external/7182087657@sip.telnyx.com Standard INIT 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:48 (sofia/external/7182087657@sip.telnyx.com) State Change CS_INIT -> CS_ROUTING 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:624 (sofia/external/7182087657@sip.telnyx.com) State INIT going to sleep 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_ROUTING (Cur 1 Tot 6679) 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_channel.c:2380 (sofia/external/7182087657@sip.telnyx.com) Callstate Change DOWN -> RINGING 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:640 (sofia/external/7182087657@sip.telnyx.com) State ROUTING 2023-02-23 16:59:48.733445 99.47% [DEBUG] mod_sofia.c:158 sofia/external/7182087657@sip.telnyx.com SOFIA ROUTING 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:230 sofia/external/7182087657@sip.telnyx.com Standard ROUTING 2023-02-23 16:59:48.733445 99.47% [INFO] mod_dialplan_xml.c:639 Processing VILLAGOMEZ,JOSH <7182087657>->7047417204 in context public Dialplan: sofia/external/7182087657@sip.telnyx.com parsing [public->public_conference_extensions] continue=false Dialplan: sofia/external/7182087657@sip.telnyx.com Regex (PASS) [public_conference_extensions] destination_number(7047417204) =~ /^(.*)$/ break=on-false Dialplan: sofia/external/7182087657@sip.telnyx.com Action python(routing_inbound) 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:281 (sofia/external/7182087657@sip.telnyx.com) State Change CS_ROUTING -> CS_EXECUTE 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:640 (sofia/external/7182087657@sip.telnyx.com) State ROUTING going to sleep 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_EXECUTE (Cur 1 Tot 6679) 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:647 (sofia/external/7182087657@sip.telnyx.com) State EXECUTE 2023-02-23 16:59:48.733445 99.47% [DEBUG] mod_sofia.c:213 sofia/external/7182087657@sip.telnyx.com SOFIA EXECUTE 2023-02-23 16:59:48.733445 99.47% [DEBUG] switch_core_state_machine.c:323 sofia/external/7182087657@sip.telnyx.com Standard EXECUTE EXECUTE [depth=0] sofia/external/7182087657@sip.telnyx.com python(routing_inbound) 2023-02-23 16:59:48.733445 99.47% [NOTICE] mod_python.c:213 Invoking py module: routing_inbound 2023-02-23 16:59:48.733445 99.47% [DEBUG] mod_python.c:306 Call python script 2023-02-23 16:59:48.733445 99.47% [INFO] switch_cpp.cpp:1392 Python INBOUND CALL !! 2023-02-23 16:59:48.774592 99.47% [INFO] switch_cpp.cpp:1392 exten :1106 , domain : inextrixdevs 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('hangup_after_bridge', 'true') 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('inherit_codec', 'true') 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('sip_h_X-Tenant', 'inextrixdevs') 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('continue_on_fail', 'true') EXECUTE [depth=0] sofia/external/7182087657@sip.telnyx.com set(ringback=%(2000,4000,440.0,480.0)) 2023-02-23 16:59:48.774592 99.47% [DEBUG] mod_dptools.c:1673 SET sofia/external/7182087657@sip.telnyx.com [ringback]=[%(2000,4000,440.0,480.0)] 2023-02-23 16:59:48.774592 99.47% [INFO] switch_cpp.cpp:1392 Launch Auto Attendence 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5579 Set telephone-event payload to 101@8000 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:3883 Set Codec sofia/external/7182087657@sip.telnyx.com G722/8000 20 ms 160 samples 64000 bits 1 channels 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_codec.c:111 sofia/external/7182087657@sip.telnyx.com Original read codec set to G722:9 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5928 Set telephone-event payload to 101@8000 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:5986 sofia/external/7182087657@sip.telnyx.com Set 2833 dtmf send payload to 101 recv payload to 101 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:8787 AUDIO RTP [sofia/external/7182087657@sip.telnyx.com] 155.138.235.49 port 32502 -> 64.16.227.16 port 18644 codec: 9 ms: 20 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:9007 Activating RTCP PORT 18645 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_rtp.c:5017 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 18645 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 64.16.227.16:18645 2 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:9099 sofia/external/7182087657@sip.telnyx.com Set 2833 dtmf send payload to 101 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:9106 sofia/external/7182087657@sip.telnyx.com Set 2833 dtmf receive payload to 101 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:9129 sofia/external/7182087657@sip.telnyx.com Set rtp dtmf delay to 40 2023-02-23 16:59:48.774592 99.47% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/7182087657@sip.telnyx.com! 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_channel.c:3622 (sofia/external/7182087657@sip.telnyx.com) Callstate Change RINGING -> EARLY 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_core_media.c:8769 Audio params are unchanged for sofia/external/7182087657@sip.telnyx.com. 2023-02-23 16:59:48.774592 99.47% [DEBUG] mod_sofia.c:913 Local SDP sofia/external/7182087657@sip.telnyx.com: v=0 o=FreeSWITCH 1677139086 1677139087 IN IP4 155.138.235.49 s=FreeSWITCH c=IN IP4 155.138.235.49 t=0 0 m=audio 32502 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv a=rtcp:32503 IN IP4 155.138.235.49 2023-02-23 16:59:48.774592 99.47% [NOTICE] switch_cpp.cpp:703 Channel [sofia/external/7182087657@sip.telnyx.com] has been answered 2023-02-23 16:59:48.774592 99.47% [DEBUG] switch_channel.c:3950 (sofia/external/7182087657@sip.telnyx.com) Callstate Change EARLY -> ACTIVE 2023-02-23 16:59:48.774592 99.47% [INFO] switch_cpp.cpp:1392 Time Date : 2023-02-23 10:59:48.810273-06:00 2023-02-23 16:59:48.774592 99.47% [INFO] switch_cpp.cpp:1392 Sound File 1 found 2023-02-23 16:59:48.774592 99.47% [DEBUG] sofia.c:7502 Channel sofia/external/7182087657@sip.telnyx.com entering state [completed][200] 2023-02-23 16:59:48.893445 99.47% [DEBUG] sofia.c:7502 Channel sofia/external/7182087657@sip.telnyx.com entering state [ready][200] 2023-02-23 16:59:49.053453 99.30% [DEBUG] switch_rtp.c:1982 rtcp_stats_init: audio ssrc[1750339364] base_seq[43863] 2023-02-23 16:59:49.053453 99.30% [DEBUG] switch_rtp.c:7925 Correct audio ip/port confirmed. 2023-02-23 16:59:50.293446 99.27% [DEBUG] switch_core_file.c:444 File /var/nfs_share/sounds/message-1106-inextrixdevs-1.wav sample rate 8000 doesn't match requested rate 16000 2023-02-23 16:59:50.293446 99.27% [DEBUG] switch_ivr_play_say.c:1566 Codec Activated L16@16000hz 1 channels 20ms 2023-02-23 16:59:52.893452 99.03% [DEBUG] switch_rtp.c:7326 Correct audio RTCP ip/port confirmed. 2023-02-23 16:59:58.073449 98.67% [DEBUG] switch_rtp.c:8170 RTP RECV DTMF 8:1120 2023-02-23 16:59:58.073449 98.67% [INFO] switch_channel.c:527 RECV DTMF 8:1120 2023-02-23 16:59:58.073449 98.67% [DEBUG] switch_ivr_play_say.c:2015 done playing file /var/nfs_share/sounds/message-1106-inextrixdevs-1.wav 2023-02-23 17:00:05.073451 98.53% [INFO] switch_cpp.cpp:1392 Intro exten : 8 2023-02-23 17:00:05.073451 98.53% [INFO] switch_cpp.cpp:1392 Accepted-- 2023-02-23 17:00:05.073451 98.53% [INFO] switch_cpp.cpp:1392 Problem with index '8' 2023-02-23 17:00:05.573462 98.53% [DEBUG] switch_core_file.c:444 File /var/nfs_share/sounds/that-was-an-invalid-entry.wav sample rate 48000 doesn't match requested rate 16000 2023-02-23 17:00:05.573462 98.53% [DEBUG] switch_ivr_play_say.c:1566 Codec Activated L16@16000hz 1 channels 20ms 2023-02-23 17:00:09.173458 98.20% [DEBUG] switch_ivr_play_say.c:2015 done playing file /var/nfs_share/sounds/that-was-an-invalid-entry.wav 2023-02-23 17:00:09.673479 98.20% [DEBUG] mod_python.c:308 Finished calling python script 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_cpp.cpp:1209 sofia/external/7182087657@sip.telnyx.com destroy/unlink session from object 2023-02-23 17:00:09.673479 98.20% [NOTICE] switch_core_state_machine.c:382 sofia/external/7182087657@sip.telnyx.com has executed the last dialplan instruction, hanging up. 2023-02-23 17:00:09.673479 98.20% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/external/7182087657@sip.telnyx.com [CS_EXECUTE] [NORMAL_CLEARING] 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:647 (sofia/external/7182087657@sip.telnyx.com) State EXECUTE going to sleep 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_HANGUP (Cur 1 Tot 6679) 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:844 (sofia/external/7182087657@sip.telnyx.com) Callstate Change ACTIVE -> HANGUP 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:846 (sofia/external/7182087657@sip.telnyx.com) State HANGUP 2023-02-23 17:00:09.673479 98.20% [DEBUG] mod_sofia.c:468 Channel sofia/external/7182087657@sip.telnyx.com hanging up, cause: NORMAL_CLEARING 2023-02-23 17:00:09.673479 98.20% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/external/7182087657@sip.telnyx.com 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:59 sofia/external/7182087657@sip.telnyx.com Standard HANGUP, cause: NORMAL_CLEARING 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:846 (sofia/external/7182087657@sip.telnyx.com) State HANGUP going to sleep 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:616 (sofia/external/7182087657@sip.telnyx.com) State Change CS_HANGUP -> CS_REPORTING 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:581 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_REPORTING (Cur 1 Tot 6679) 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:932 (sofia/external/7182087657@sip.telnyx.com) State REPORTING 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:168 sofia/external/7182087657@sip.telnyx.com Standard REPORTING, cause: NORMAL_CLEARING 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:932 (sofia/external/7182087657@sip.telnyx.com) State REPORTING going to sleep 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:607 (sofia/external/7182087657@sip.telnyx.com) State Change CS_REPORTING -> CS_DESTROY 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_session.c:1747 Session 6679 (sofia/external/7182087657@sip.telnyx.com) Locked, Waiting on external entities 2023-02-23 17:00:09.673479 98.20% [NOTICE] switch_core_session.c:1765 Session 6679 (sofia/external/7182087657@sip.telnyx.com) Ended 2023-02-23 17:00:09.673479 98.20% [NOTICE] switch_core_session.c:1769 Close Channel sofia/external/7182087657@sip.telnyx.com [CS_DESTROY] 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:735 (sofia/external/7182087657@sip.telnyx.com) Running State Change CS_DESTROY (Cur 0 Tot 6679) 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7182087657@sip.telnyx.com) State DESTROY 2023-02-23 17:00:09.673479 98.20% [DEBUG] mod_sofia.c:379 sofia/external/7182087657@sip.telnyx.com SOFIA DESTROY 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:175 sofia/external/7182087657@sip.telnyx.com Standard DESTROY 2023-02-23 17:00:09.673479 98.20% [DEBUG] switch_core_state_machine.c:745 (sofia/external/7182087657@sip.telnyx.com) State DESTROY going to sleep freeswitch@freeswitch2> /exit [root@freeswitch2 ~]#