2021-12-10 09:58:30.589182 97.83% [NOTICE] switch_ivr_bridge.c:731 Channel [sofia/vm_inside/302102241522@172.16.0.30:6066] has been answered
2021-12-10 09:58:30.589182 97.83% [DEBUG] switch_channel.c:3950 (sofia/vm_inside/302102241522@172.16.0.30:6066) Callstate Change EARLY -> ACTIVE
2021-12-10 09:58:30.589182 97.83% [DEBUG] sofia.c:7499 Channel sofia/vm_inside/302102241522@172.16.0.30:6066 entering state [completed][200]
2021-12-10 09:58:30.629181 97.83% [DEBUG] sofia.c:7499 Channel sofia/vm_inside/302102241522@172.16.0.30:6066 entering state [ready][200]
2021-12-10 09:58:30.649185 97.83% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
2021-12-10 09:58:30.649185 97.83% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
2021-12-10 09:58:55.409183 98.97% [DEBUG] mod_nibblebill.c:695 Received request via SESSION_HEARTBEAT!
2021-12-10 09:58:55.409183 98.97% [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.03983 per minute to account 19
2021-12-10 09:58:55.409183 98.97% [INFO] mod_nibblebill.c:565 Beginning new billing on 84efb3c9-58d7-4eb3-be92-bf82aa74b5c7
2021-12-10 09:58:55.409183 98.97% [DEBUG] mod_nibblebill.c:573 24 seconds passed since last bill time of 2021-12-10 09:58:30
2021-12-10 09:58:55.409183 98.97% [DEBUG] mod_nibblebill.c:590 Billing $0.016596 to 19 (Call: 84efb3c9-58d7-4eb3-be92-bf82aa74b5c7 / 0.000000 so far)
2021-12-10 09:58:55.409183 98.97% [DEBUG] mod_nibblebill.c:395 Doing update query
[Update accounts SET balance=IF(posttoexternal=1,balance+0.016596,balance-0.016596) WHERE id='19']
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:422 Doing lookup query
[SELECT if(posttoexternal=1,credit_limit+(balance*-1),balance) AS nibble_balance FROM accounts WHERE id='19']
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account 19 (balance = 0.334040)
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:645 Balance of 0.334040 fell below low balance amount of 5.000000! (Account 19)
2021-12-10 09:58:55.429184 98.97% [ERR] switch_core_session.c:2770 Invalid Application play
2021-12-10 09:58:55.429184 98.97% [NOTICE] switch_core_session.c:2771 Hangup sofia/vm_inside/302102241522@172.16.0.30:6066 [CS_EXECUTE] [DESTINATION_OUT_OF_ORDER]
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_hash.c:293 Usage for CPS_9265777341_CPS_user_9265777341 is now 0
2021-12-10 09:58:55.429184 98.97% [ERR] mod_nibblebill.c:649 Low balance action didn't execute
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/vm_inside/302102241522@172.16.0.30:6066]
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_ivr_bridge.c:820 sofia/vm_inside/302102241522@172.16.0.30:6066 ending bridge by request from write function
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/external_without_reg/9991306974108809]
2021-12-10 09:58:55.429184 98.97% [NOTICE] switch_ivr_bridge.c:1029 Hangup sofia/external_without_reg/9991306974108809 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:650 (sofia/external_without_reg/9991306974108809) State EXCHANGE_MEDIA going to sleep
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external_without_reg/9991306974108809) Running State Change CS_HANGUP (Cur 2 Tot 650)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:844 (sofia/external_without_reg/9991306974108809) Callstate Change ACTIVE -> HANGUP
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:846 (sofia/external_without_reg/9991306974108809) State HANGUP
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_sofia.c:468 Channel sofia/external_without_reg/9991306974108809 hanging up, cause: NORMAL_CLEARING
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/external_without_reg/9991306974108809
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:59 sofia/external_without_reg/9991306974108809 Standard HANGUP, cause: NORMAL_CLEARING
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:846 (sofia/external_without_reg/9991306974108809) State HANGUP going to sleep
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:616 (sofia/external_without_reg/9991306974108809) State Change CS_HANGUP -> CS_REPORTING
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external_without_reg/9991306974108809) Running State Change CS_REPORTING (Cur 2 Tot 650)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:932 (sofia/external_without_reg/9991306974108809) State REPORTING
2021-12-10 09:58:55.429184 98.97% [INFO] mod_json_cdr.c:271 Process [725a04c6-f56c-40ff-aae4-46fbfed40d68.cdr.json]
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_ivr_bridge.c:1892 sofia/external_without_reg/9991306974108809 skip receive message [UNBRIDGE] (channel is hungup already)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_ivr_bridge.c:1895 sofia/vm_inside/302102241522@172.16.0.30:6066 skip receive message [UNBRIDGE] (channel is hungup already)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_session.c:2983 sofia/vm_inside/302102241522@172.16.0.30:6066 skip receive message [PHONE_EVENT] (channel is hungup already)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:647 (sofia/vm_inside/302102241522@172.16.0.30:6066) State EXECUTE going to sleep
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:581 (sofia/vm_inside/302102241522@172.16.0.30:6066) Running State Change CS_HANGUP (Cur 2 Tot 650)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:844 (sofia/vm_inside/302102241522@172.16.0.30:6066) Callstate Change ACTIVE -> HANGUP
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:846 (sofia/vm_inside/302102241522@172.16.0.30:6066) State HANGUP
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_sofia.c:468 Channel sofia/vm_inside/302102241522@172.16.0.30:6066 hanging up, cause: DESTINATION_OUT_OF_ORDER
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/vm_inside/302102241522@172.16.0.30:6066
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.03983 per minute to account 19
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:573 0 seconds passed since last bill time of 2021-12-10 09:58:55
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:422 Doing lookup query
[SELECT if(posttoexternal=1,credit_limit+(balance*-1),balance) AS nibble_balance FROM accounts WHERE id='19']
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account 19 (balance = 0.334040)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:59 sofia/vm_inside/302102241522@172.16.0.30:6066 Standard HANGUP, cause: DESTINATION_OUT_OF_ORDER
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:846 (sofia/vm_inside/302102241522@172.16.0.30:6066) State HANGUP going to sleep
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:616 (sofia/vm_inside/302102241522@172.16.0.30:6066) State Change CS_HANGUP -> CS_REPORTING
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:581 (sofia/vm_inside/302102241522@172.16.0.30:6066) Running State Change CS_REPORTING (Cur 2 Tot 650)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:932 (sofia/vm_inside/302102241522@172.16.0.30:6066) State REPORTING
2021-12-10 09:58:55.429184 98.97% [INFO] mod_json_cdr.c:271 Process [84efb3c9-58d7-4eb3-be92-bf82aa74b5c7.cdr.json]
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:168 sofia/external_without_reg/9991306974108809 Standard REPORTING, cause: NORMAL_CLEARING
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:932 (sofia/external_without_reg/9991306974108809) State REPORTING going to sleep
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:607 (sofia/external_without_reg/9991306974108809) State Change CS_REPORTING -> CS_DESTROY
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_session.c:1753 Session 650 (sofia/external_without_reg/9991306974108809) Locked, Waiting on external entities
2021-12-10 09:58:55.429184 98.97% [NOTICE] switch_core_session.c:1771 Session 650 (sofia/external_without_reg/9991306974108809) Ended
2021-12-10 09:58:55.429184 98.97% [NOTICE] switch_core_session.c:1775 Close Channel sofia/external_without_reg/9991306974108809 [CS_DESTROY]
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:735 (sofia/external_without_reg/9991306974108809) Running State Change CS_DESTROY (Cur 1 Tot 650)
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:745 (sofia/external_without_reg/9991306974108809) State DESTROY
2021-12-10 09:58:55.429184 98.97% [DEBUG] mod_sofia.c:379 sofia/external_without_reg/9991306974108809 SOFIA DESTROY
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:175 sofia/external_without_reg/9991306974108809 Standard DESTROY
2021-12-10 09:58:55.429184 98.97% [DEBUG] switch_core_state_machine.c:745 (sofia/external_without_reg/9991306974108809) State DESTROY going to sleep
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:168 sofia/vm_inside/302102241522@172.16.0.30:6066 Standard REPORTING, cause: DESTINATION_OUT_OF_ORDER
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:932 (sofia/vm_inside/302102241522@172.16.0.30:6066) State REPORTING going to sleep
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:607 (sofia/vm_inside/302102241522@172.16.0.30:6066) State Change CS_REPORTING -> CS_DESTROY
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_session.c:1753 Session 649 (sofia/vm_inside/302102241522@172.16.0.30:6066) Locked, Waiting on external entities
2021-12-10 09:58:55.469180 98.97% [NOTICE] switch_core_session.c:1771 Session 649 (sofia/vm_inside/302102241522@172.16.0.30:6066) Ended
2021-12-10 09:58:55.469180 98.97% [NOTICE] switch_core_session.c:1775 Close Channel sofia/vm_inside/302102241522@172.16.0.30:6066 [CS_DESTROY]
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:735 (sofia/vm_inside/302102241522@172.16.0.30:6066) Running State Change CS_DESTROY (Cur 0 Tot 650)
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:745 (sofia/vm_inside/302102241522@172.16.0.30:6066) State DESTROY
2021-12-10 09:58:55.469180 98.97% [DEBUG] mod_sofia.c:379 sofia/vm_inside/302102241522@172.16.0.30:6066 SOFIA DESTROY
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:175 sofia/vm_inside/302102241522@172.16.0.30:6066 Standard DESTROY
2021-12-10 09:58:55.469180 98.97% [DEBUG] switch_core_state_machine.c:745 (sofia/vm_inside/302102241522@172.16.0.30:6066) State DESTROY going to sleep
2021-12-10 09:58:55.909188 98.90% [DEBUG] switch_scheduler.c:147 Deleting task 855 switch_core_session_sched_heartbeat (84efb3c9-58d7-4eb3-be92-bf82aa74b5c7)
2021-12-10 09:58:55.909188 98.90% [DEBUG] switch_scheduler.c:147 Deleting task 856 switch_ivr_schedule_hangup (725a04c6-f56c-40ff-aae4-46fbfed40d68)