2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:40 sofia/default/0779205097 Standard INIT
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:48 (sofia/default/0779205097) State Change CS_INIT -> CS_ROUTING
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:624 (sofia/default/0779205097) State INIT going to sleep
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0779205097) Running State Change CS_ROUTING (Cur 2 Tot 972)
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:640 (sofia/default/0779205097) State ROUTING
2022-06-27 15:32:03.153453 98.03% [DEBUG] mod_sofia.c:158 sofia/default/0779205097 SOFIA ROUTING
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_ivr_originate.c:67 (sofia/default/0779205097) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:640 (sofia/default/0779205097) State ROUTING going to sleep
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0779205097) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 972)
2022-06-27 15:32:03.153453 98.03% [DEBUG] sofia.c:7499 Channel sofia/default/0779205097 entering state [calling][0]
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:659 (sofia/default/0779205097) State CONSUME_MEDIA
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:659 (sofia/default/0779205097) State CONSUME_MEDIA going to sleep
2022-06-27 15:32:03.153453 98.03% [DEBUG] sofia.c:7499 Channel sofia/default/0779205097 entering state [terminated][503]
2022-06-27 15:32:03.153453 98.03% [NOTICE] sofia.c:8738 Hangup sofia/default/0779205097 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0779205097) Running State Change CS_HANGUP (Cur 2 Tot 972)
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:844 (sofia/default/0779205097) Callstate Change DOWN -> HANGUP
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:846 (sofia/default/0779205097) State HANGUP
2022-06-27 15:32:03.153453 98.03% [DEBUG] mod_sofia.c:468 Channel sofia/default/0779205097 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:59 sofia/default/0779205097 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:846 (sofia/default/0779205097) State HANGUP going to sleep
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_channel.c:2178 (sofia/default/0902@102.220.200.133) Callstate Change RING_WAIT -> ACTIVE
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:616 (sofia/default/0779205097) State Change CS_HANGUP -> CS_REPORTING
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0779205097) Running State Change CS_REPORTING (Cur 2 Tot 972)
2022-06-27 15:32:03.153453 98.03% [INFO] mod_dptools.c:3653 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_state_machine.c:932 (sofia/default/0779205097) State REPORTING
2022-06-27 15:32:03.153453 98.03% [INFO] mod_json_cdr.c:271 Process [2317c617-a1a1-495f-aa63-ae823ef8a5b0.cdr.json]
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_core_file.c:444 File /usr/share/freeswitch/sounds/en/us/callie/astpp-callingcard-menu.wav sample rate 16000 doesn't match requested rate 8000
2022-06-27 15:32:03.153453 98.03% [DEBUG] switch_ivr_play_say.c:1556 Codec Activated L16@8000hz 1 channels 30ms
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:168 sofia/default/0779205097 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:932 (sofia/default/0779205097) State REPORTING going to sleep
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:607 (sofia/default/0779205097) State Change CS_REPORTING -> CS_DESTROY
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_session.c:1753 Session 972 (sofia/default/0779205097) Locked, Waiting on external entities
2022-06-27 15:32:03.233382 98.03% [NOTICE] switch_core_session.c:1771 Session 972 (sofia/default/0779205097) Ended
2022-06-27 15:32:03.233382 98.03% [NOTICE] switch_core_session.c:1775 Close Channel sofia/default/0779205097 [CS_DESTROY]
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:735 (sofia/default/0779205097) Running State Change CS_DESTROY (Cur 1 Tot 972)
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:745 (sofia/default/0779205097) State DESTROY
2022-06-27 15:32:03.233382 98.03% [DEBUG] mod_sofia.c:379 sofia/default/0779205097 SOFIA DESTROY
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:175 sofia/default/0779205097 Standard DESTROY
2022-06-27 15:32:03.233382 98.03% [DEBUG] switch_core_state_machine.c:745 (sofia/default/0779205097) State DESTROY going to sleep
2022-06-27 15:32:09.333444 97.70% [DEBUG] switch_ivr_play_say.c:2001 done playing file /usr/share/freeswitch/sounds/en/us/callie/astpp-callingcard-menu.wav
2022-06-27 15:32:11.733444 97.70% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF 3:1360
2022-06-27 15:32:11.733444 97.70% [INFO] switch_channel.c:527 RECV DTMF 3:1360
2022-06-27 15:32:11.733444 97.70% [DEBUG] switch_cpp.cpp:1465 [ASTPP] Got DTMF digits: 3retries:0
2022-06-27 15:32:11.733444 97.70% [DEBUG] switch_core_file.c:444 File /usr/share/freeswitch/sounds/en/us/callie/astpp-goodbye.wav sample rate 16000 doesn't match requested rate 8000
2022-06-27 15:32:11.733444 97.70% [DEBUG] switch_ivr_play_say.c:1556 Codec Activated L16@8000hz 1 channels 30ms
2022-06-27 15:32:12.413448 97.73% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF #:1840
2022-06-27 15:32:12.413448 97.73% [INFO] switch_channel.c:527 RECV DTMF #:1840
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_ivr_play_say.c:2001 done playing file /usr/share/freeswitch/sounds/en/us/callie/astpp-goodbye.wav
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_cpp.cpp:749 CoreSession::hangup
2022-06-27 15:32:12.553452 97.73% [NOTICE] switch_cpp.cpp:751 Hangup sofia/default/0902@102.220.200.133 [CS_EXECUTE] [NORMAL_CLEARING]
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_cpp.cpp:1465 [ASTPP] Got DTMF digits: retries:1
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_cpp.cpp:1465 [ASTPP] Got DTMF digits: retries:2
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_cpp.cpp:749 CoreSession::hangup
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_cpp.cpp:1209 sofia/default/0902@102.220.200.133 destroy/unlink session from object
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_session.c:2983 sofia/default/0902@102.220.200.133 skip receive message [PHONE_EVENT] (channel is hungup already)
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:647 (sofia/default/0902@102.220.200.133) State EXECUTE going to sleep
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0902@102.220.200.133) Running State Change CS_HANGUP (Cur 1 Tot 972)
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:844 (sofia/default/0902@102.220.200.133) Callstate Change ACTIVE -> HANGUP
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/default/0902@102.220.200.133) State HANGUP
2022-06-27 15:32:12.553452 97.73% [DEBUG] mod_sofia.c:462 sofia/default/0902@102.220.200.133 Overriding SIP cause 480 with 503 from the other leg
2022-06-27 15:32:12.553452 97.73% [DEBUG] mod_sofia.c:468 Channel sofia/default/0902@102.220.200.133 hanging up, cause: NORMAL_CLEARING
2022-06-27 15:32:12.553452 97.73% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/default/0902@102.220.200.133
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:59 sofia/default/0902@102.220.200.133 Standard HANGUP, cause: NORMAL_CLEARING
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/default/0902@102.220.200.133) State HANGUP going to sleep
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:616 (sofia/default/0902@102.220.200.133) State Change CS_HANGUP -> CS_REPORTING
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/default/0902@102.220.200.133) Running State Change CS_REPORTING (Cur 1 Tot 972)
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/default/0902@102.220.200.133) State REPORTING
2022-06-27 15:32:12.553452 97.73% [INFO] mod_json_cdr.c:271 Process [c8c9e22e-c42e-45ec-8754-d7ddfddbaec3.cdr.json]
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:168 sofia/default/0902@102.220.200.133 Standard REPORTING, cause: NORMAL_CLEARING
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/default/0902@102.220.200.133) State REPORTING going to sleep
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:607 (sofia/default/0902@102.220.200.133) State Change CS_REPORTING -> CS_DESTROY
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_session.c:1753 Session 971 (sofia/default/0902@102.220.200.133) Locked, Waiting on external entities
2022-06-27 15:32:12.553452 97.73% [NOTICE] switch_core_session.c:1771 Session 971 (sofia/default/0902@102.220.200.133) Ended
2022-06-27 15:32:12.553452 97.73% [NOTICE] switch_core_session.c:1775 Close Channel sofia/default/0902@102.220.200.133 [CS_DESTROY]
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:735 (sofia/default/0902@102.220.200.133) Running State Change CS_DESTROY (Cur 0 Tot 972)
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:745 (sofia/default/0902@102.220.200.133) State DESTROY
2022-06-27 15:32:12.553452 97.73% [DEBUG] mod_sofia.c:379 sofia/default/0902@102.220.200.133 SOFIA DESTROY
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:175 sofia/default/0902@102.220.200.133 Standard DESTROY
2022-06-27 15:32:12.553452 97.73% [DEBUG] switch_core_state_machine.c:745 (sofia/default/0902@102.220.200.133) State DESTROY going to sleep
2022-06-27 15:32:12.673382 97.73% [DEBUG] switch_scheduler.c:147 Deleting task 10 switch_ivr_schedule_hangup (c8c9e22e-c42e-45ec-8754-d7ddfddbaec3)