?xml version="1.0" encoding="UTF-8" standalone="no"?>
2018-05-31 11:44:19.493667 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3f780d4cd0 released. Dialplan: sofia/default/7900757132@91.12.24.13 parsing [default->00555140094888] continue=false Dialplan: sofia/default/7900757132@91.12.24.13 Regex (PASS) [00555140094888] destination_number(00555140094888) =~ /00555140094888/ break=on-false Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_destination_number=00555140094888) Dialplan: sofia/default/7900757132@91.12.24.13 Action sched_hangup(+1440 normal_clearing) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(callstart=2018-05-31 10:23:08) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(hangup_after_bridge=true) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(continue_on_fail=0,1,2,3,6,7,16,17,19,18,20,21,22,23,25,27,28,29,30,34,38,41,42,43,44,45,47,50,52,54,57,58,63,65,66,69,79,81,88,95,96,97,98,99,100,101,102,103,111,127,487,500,501,502,503,600,601,602,603,604,605,606,607,608,609) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(account_id=10) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(parent_id=0) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(entity_id=0) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(call_processed=internal) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(call_direction=outbound) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(accountname=default) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(fax_enable_t38=true) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(fax_enable_t38_request=true) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(origination_rates=ID:88809|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.01680|INC:0|INITIALBLOCK:0|RATEGROUP:9|MARKUP:0|ACCID:10) Dialplan: sofia/default/7900757132@91.12.24.13 Action limit(db 7900757132 user_7900757132 1/0 !SWITCH_CONGESTION) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(is_recording=1) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(media_bug_answer_req=true) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(RECORD_STEREO=true) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(record_sample_rate=8000) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(execute_on_answer=record_session /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_name=28) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_number=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(sip_from_display=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(calltype=STANDARD) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(termination_rates=ID:235812|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00804|INC:0|INITIALBLOCK:0|TRUNK:4|PROVIDER:6) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(trunk_id=4) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(provider_id=6) Dialplan: sofia/default/7900757132@91.12.24.13 Action bridge([absolute_codec_string=]sofia/gateway/ONO/00555140094888) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_name=28) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_number=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(sip_from_display=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(calltype=STANDARD) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(termination_rates=ID:149037|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00900|INC:0|INITIALBLOCK:0|TRUNK:8|PROVIDER:78) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(trunk_id=8) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(provider_id=78) Dialplan: sofia/default/7900757132@91.12.24.13 Action bridge([absolute_codec_string=^^:PCMA:PCMU:OPUS:G729]sofia/gateway/Alisys/300000555140094888) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_name=28) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_number=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(sip_from_display=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(calltype=STANDARD) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(termination_rates=ID:182566|CODE:^005551.*|DESTINATION:BRAZIL (OTHERS CITIES)|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00290|INC:0|INITIALBLOCK:0|TRUNK:5|PROVIDER:7) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(trunk_id=5) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(provider_id=7) Dialplan: sofia/default/7900757132@91.12.24.13 Action bridge([absolute_codec_string=^^:PCMA:PCMU:OPUS:G729]sofia/gateway/Orange_2/00555140094888) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_name=28) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(effective_caller_id_number=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action export(sip_from_display=0034) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(calltype=STANDARD) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(termination_rates=ID:3971|CODE:^0055.*|DESTINATION:BRAZIL|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00310|INC:0|INITIALBLOCK:0|TRUNK:5|PROVIDER:7) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(trunk_id=5) Dialplan: sofia/default/7900757132@91.12.24.13 Action set(provider_id=7) Dialplan: sofia/default/7900757132@91.12.24.13 Action bridge([absolute_codec_string=^^:PCMA:PCMU:OPUS:G729]sofia/gateway/Orange_2/00555140094888) 2018-05-31 11:44:19.493667 [DEBUG] switch_core_state_machine.c:286 (sofia/default/7900757132@91.12.24.13) State Change CS_ROUTING -> CS_EXECUTE 2018-05-31 11:44:19.493667 [DEBUG] switch_core_state_machine.c:643 (sofia/default/7900757132@91.12.24.13) State ROUTING going to sleep 2018-05-31 11:44:19.493667 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7900757132@91.12.24.13) Running State Change CS_EXECUTE (Cur 1 Tot 616) 2018-05-31 11:44:19.493667 [DEBUG] switch_core_state_machine.c:650 (sofia/default/7900757132@91.12.24.13) State EXECUTE 2018-05-31 11:44:19.493667 [DEBUG] mod_sofia.c:198 sofia/default/7900757132@91.12.24.13 SOFIA EXECUTE 2018-05-31 11:44:19.493667 [DEBUG] switch_core_state_machine.c:328 sofia/default/7900757132@91.12.24.13 Standard EXECUTE EXECUTE sofia/default/7900757132@91.12.24.13 set(effective_destination_number=00555140094888) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [effective_destination_number]=[00555140094888] EXECUTE sofia/default/7900757132@91.12.24.13 sched_hangup(+1440 normal_clearing) 2018-05-31 11:44:19.493667 [DEBUG] switch_scheduler.c:249 Added task 224 switch_ivr_schedule_hangup (f08dd287-60c1-407c-a012-77cdb134e3d0) to run at 1527761299 EXECUTE sofia/default/7900757132@91.12.24.13 set(callstart=2018-05-31 10:23:08) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [callstart]=[2018-05-31 10:23:08] EXECUTE sofia/default/7900757132@91.12.24.13 set(hangup_after_bridge=true) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [hangup_after_bridge]=[true] EXECUTE sofia/default/7900757132@91.12.24.13 set(continue_on_fail=0,1,2,3,6,7,16,17,19,18,20,21,22,23,25,27,28,29,30,34,38,41,42,43,44,45,47,50,52,54,57,58,63,65,66,69,79,81,88,95,96,97,98,99,100,101,102,103,111,127,487,500,501,502,503,600,601,602,603,604,605,606,607,608,609) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [continue_on_fail]=[0,1,2,3,6,7,16,17,19,18,20,21,22,23,25,27,28,29,30,34,38,41,42,43,44,45,47,50,52,54,57,58,63,65,66,69,79,81,88,95,96,97,98,99,100,101,102,103,111,127,487,500,501,502,503,600,601,602,603,604,605,606,607,608,609] EXECUTE sofia/default/7900757132@91.12.24.13 set(account_id=10) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [account_id]=[10] EXECUTE sofia/default/7900757132@91.12.24.13 set(parent_id=0) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [parent_id]=[0] EXECUTE sofia/default/7900757132@91.12.24.13 set(entity_id=0) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [entity_id]=[0] EXECUTE sofia/default/7900757132@91.12.24.13 set(call_processed=internal) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [call_processed]=[internal] EXECUTE sofia/default/7900757132@91.12.24.13 set(call_direction=outbound) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [call_direction]=[outbound] EXECUTE sofia/default/7900757132@91.12.24.13 set(accountname=default) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [accountname]=[default] EXECUTE sofia/default/7900757132@91.12.24.13 set(fax_enable_t38=true) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [fax_enable_t38]=[true] EXECUTE sofia/default/7900757132@91.12.24.13 set(fax_enable_t38_request=true) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [fax_enable_t38_request]=[true] EXECUTE sofia/default/7900757132@91.12.24.13 set(origination_rates=ID:88809|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.01680|INC:0|INITIALBLOCK:0|RATEGROUP:9|MARKUP:0|ACCID:10) 2018-05-31 11:44:19.493667 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [origination_rates]=[ID:88809|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.01680|INC:0|INITIALBLOCK:0|RATEGROUP:9|MARKUP:0|ACCID:10] EXECUTE sofia/default/7900757132@91.12.24.13 limit(db 7900757132 user_7900757132 1/0 !SWITCH_CONGESTION) 2018-05-31 11:44:19.493667 [DEBUG] switch_limit.c:126 incr called: 7900757132_user_7900757132 max:1, interval:0 2018-05-31 11:44:19.513646 [DEBUG] mod_db.c:194 Usage for 7900757132_user_7900757132 is now 1/1 EXECUTE sofia/default/7900757132@91.12.24.13 export(is_recording=1) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [is_recording]=[1] EXECUTE sofia/default/7900757132@91.12.24.13 export(media_bug_answer_req=true) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [media_bug_answer_req]=[true] EXECUTE sofia/default/7900757132@91.12.24.13 export(RECORD_STEREO=true) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RECORD_STEREO]=[true] EXECUTE sofia/default/7900757132@91.12.24.13 export(record_sample_rate=8000) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [record_sample_rate]=[8000] EXECUTE sofia/default/7900757132@91.12.24.13 export(execute_on_answer=record_session /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [execute_on_answer]=[record_session /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav] EXECUTE sofia/default/7900757132@91.12.24.13 set(effective_caller_id_name=28) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [effective_caller_id_name]=[28] EXECUTE sofia/default/7900757132@91.12.24.13 set(effective_caller_id_number=0034) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [effective_caller_id_number]=[0034] EXECUTE sofia/default/7900757132@91.12.24.13 export(sip_from_display=0034) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_from_display]=[0034] EXECUTE sofia/default/7900757132@91.12.24.13 set(calltype=STANDARD) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [calltype]=[STANDARD] EXECUTE sofia/default/7900757132@91.12.24.13 set(termination_rates=ID:235812|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00804|INC:0|INITIALBLOCK:0|TRUNK:4|PROVIDER:6) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [termination_rates]=[ID:235812|CODE:^0055514.*|DESTINATION:Brasil Resto|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00804|INC:0|INITIALBLOCK:0|TRUNK:4|PROVIDER:6] EXECUTE sofia/default/7900757132@91.12.24.13 set(trunk_id=4) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [trunk_id]=[4] EXECUTE sofia/default/7900757132@91.12.24.13 set(provider_id=6) 2018-05-31 11:44:19.593638 [DEBUG] mod_dptools.c:1530 SET sofia/default/7900757132@91.12.24.13 [provider_id]=[6] EXECUTE sofia/default/7900757132@91.12.24.13 bridge([absolute_codec_string=]sofia/gateway/ONO/00555140094888) 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [is_recording]=[1] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [media_bug_answer_req]=[true] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [RECORD_STEREO]=[true] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [record_sample_rate]=[8000] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [execute_on_answer]=[record_session /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_channel.c:1250 sofia/default/7900757132@91.12.24.13 EXPORTING[export_vars] [sip_from_display]=[0034] to event 2018-05-31 11:44:19.593638 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2018-05-31 11:44:19.593638 [DEBUG] switch_ivr_originate.c:2663 Parsing session specific variables 2018-05-31 11:44:19.593638 [NOTICE] switch_channel.c:1104 New Channel sofia/default/00555140094888 [5410786f-17aa-48e5-8172-34bb4a15c972] 2018-05-31 11:44:19.593638 [DEBUG] mod_sofia.c:4818 (sofia/default/00555140094888) State Change CS_NEW -> CS_INIT 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_INIT (Cur 2 Tot 617) 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:627 (sofia/default/00555140094888) State INIT 2018-05-31 11:44:19.593638 [DEBUG] mod_sofia.c:90 sofia/default/00555140094888 SOFIA INIT 2018-05-31 11:44:19.593638 [DEBUG] sofia_glue.c:1264 sip:91.12.24.13 Setting proxy route to sofia/default/00555140094888 2018-05-31 11:44:19.593638 [DEBUG] sofia_glue.c:1295 sofia/default/00555140094888 sending invite version: 1.6.17 64bit Local SDP: v=0 o=FreeSWITCH 1527734559 1527734560 IN IP4 91.12.24.33 s=FreeSWITCH c=IN IP4 91.12.24.33 t=0 0 m=audio 25300 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:40 sofia/default/00555140094888 Standard INIT 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:48 (sofia/default/00555140094888) State Change CS_INIT -> CS_ROUTING 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:627 (sofia/default/00555140094888) State INIT going to sleep 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_ROUTING (Cur 2 Tot 617) 2018-05-31 11:44:19.593638 [DEBUG] sofia.c:7048 Channel sofia/default/00555140094888 entering state [calling][0] 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:643 (sofia/default/00555140094888) State ROUTING 2018-05-31 11:44:19.593638 [DEBUG] mod_sofia.c:143 sofia/default/00555140094888 SOFIA ROUTING 2018-05-31 11:44:19.593638 [DEBUG] switch_ivr_originate.c:67 (sofia/default/00555140094888) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:643 (sofia/default/00555140094888) State ROUTING going to sleep 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 617) 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:662 (sofia/default/00555140094888) State CONSUME_MEDIA 2018-05-31 11:44:19.593638 [DEBUG] switch_core_state_machine.c:662 (sofia/default/00555140094888) State CONSUME_MEDIA going to sleep 2018-05-31 11:44:19.713669 [DEBUG] sofia.c:7048 Channel sofia/default/00555140094888 entering state [proceeding][183] 2018-05-31 11:44:19.713669 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=- 245317407 0 IN IP4 89.14.21.140 s=session c=IN IP4 62.175.233.8 t=0 0 m=audio 4380 RTP/AVP 8 101 c=IN IP4 62.175.233.8 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4465 Bah HUMBUG! Sticking with PCMA@8000h@20i 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:3056 Set Codec sofia/default/00555140094888 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2018-05-31 11:44:19.713669 [DEBUG] switch_core_codec.c:111 sofia/default/00555140094888 Original read codec set to PCMA:8 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:4754 sofia/default/00555140094888 Set 2833 dtmf send payload to 101 recv payload to 101 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/default/00555140094888] 91.12.24.33 port 25300 -> 62.175.233.8 port 4380 codec: 8 ms: 20 2018-05-31 11:44:19.713669 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:7166 sofia/default/00555140094888 Set 2833 dtmf send payload to 101 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:7173 sofia/default/00555140094888 Set 2833 dtmf receive payload to 101 2018-05-31 11:44:19.713669 [DEBUG] switch_core_media.c:7196 sofia/default/00555140094888 Set rtp dtmf delay to 40 2018-05-31 11:44:19.713669 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/00555140094888! 2018-05-31 11:44:19.733625 [DEBUG] switch_channel.c:3473 (sofia/default/00555140094888) Callstate Change DOWN -> EARLY 2018-05-31 11:44:19.733625 [INFO] switch_ivr_originate.c:3639 Sending early media 2018-05-31 11:44:19.733625 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/default/7900757132@91.12.24.13] 91.12.24.33 port 30766 -> 117.247.91.162 port 2016 codec: 8 ms: 20 2018-05-31 11:44:19.733625 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2018-05-31 11:44:19.733625 [DEBUG] switch_core_media.c:7166 sofia/default/7900757132@91.12.24.13 Set 2833 dtmf send payload to 101 2018-05-31 11:44:19.733625 [DEBUG] switch_core_media.c:7173 sofia/default/7900757132@91.12.24.13 Set 2833 dtmf receive payload to 101 2018-05-31 11:44:19.733625 [DEBUG] switch_core_media.c:7196 sofia/default/7900757132@91.12.24.13 Set rtp dtmf delay to 40 2018-05-31 11:44:19.733625 [DEBUG] mod_sofia.c:2363 Ring SDP: v=0 o=FreeSWITCH 1527729093 1527729094 IN IP4 91.12.24.33 s=FreeSWITCH c=IN IP4 91.12.24.33 t=0 0 m=audio 30766 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2018-05-31 11:44:19.733625 [NOTICE] mod_sofia.c:2366 Pre-Answer sofia/default/7900757132@91.12.24.13! 2018-05-31 11:44:19.733625 [DEBUG] switch_channel.c:3473 (sofia/default/7900757132@91.12.24.13) Callstate Change RINGING -> EARLY 2018-05-31 11:44:19.733625 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/default/00555140094888] 2018-05-31 11:44:19.733625 [DEBUG] sofia.c:7048 Channel sofia/default/7900757132@91.12.24.13 entering state [early][183] 2018-05-31 11:44:19.733625 [DEBUG] switch_ivr_bridge.c:1601 (sofia/default/00555140094888) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2018-05-31 11:44:19.733625 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 617) 2018-05-31 11:44:19.733625 [DEBUG] switch_core_state_machine.c:653 (sofia/default/00555140094888) State EXCHANGE_MEDIA 2018-05-31 11:44:19.733625 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2018-05-31 11:44:19.773656 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2018-05-31 11:44:20.033686 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2018-05-31 11:44:33.273648 [DEBUG] sofia.c:7048 Channel sofia/default/00555140094888 entering state [completing][200] 2018-05-31 11:44:33.273648 [DEBUG] sofia.c:7055 Duplicate SDP v=0 o=- 245317407 0 IN IP4 89.14.21.140 s=session c=IN IP4 62.175.233.8 t=0 0 m=audio 4380 RTP/AVP 8 101 c=IN IP4 62.175.233.8 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 2018-05-31 11:44:33.293625 [DEBUG] sofia.c:7048 Channel sofia/default/00555140094888 entering state [ready][200] 2018-05-31 11:44:33.293625 [NOTICE] sofia.c:8123 Channel [sofia/default/00555140094888] has been answered EXECUTE sofia/default/00555140094888 record_session(/home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav) 2018-05-31 11:44:33.293625 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/default/7900757132@91.12.24.13. 2018-05-31 11:44:33.293625 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/7900757132@91.12.24.13: v=0 o=FreeSWITCH 1527729093 1527729095 IN IP4 91.12.24.33 s=FreeSWITCH c=IN IP4 91.12.24.33 t=0 0 m=audio 30766 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2018-05-31 11:44:33.293625 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/default/7900757132@91.12.24.13] has been answered 2018-05-31 11:44:33.293625 [DEBUG] sofia.c:7048 Channel sofia/default/7900757132@91.12.24.13 entering state [completed][200] EXECUTE sofia/default/7900757132@91.12.24.13 record_session(/home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav) 2018-05-31 11:44:33.353634 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to sofia/default/00555140094888 2018-05-31 11:44:33.393636 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to sofia/default/7900757132@91.12.24.13 2018-05-31 11:44:33.393636 [DEBUG] switch_channel.c:3772 (sofia/default/00555140094888) Callstate Change EARLY -> ACTIVE 2018-05-31 11:44:33.393636 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech 2018-05-31 11:44:33.393636 [DEBUG] switch_channel.c:3772 (sofia/default/7900757132@91.12.24.13) Callstate Change EARLY -> ACTIVE 2018-05-31 11:44:33.393636 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech 2018-05-31 11:44:33.413687 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2018-05-31 11:44:33.413687 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMA:8 2018-05-31 11:44:33.573650 [DEBUG] sofia.c:7048 Channel sofia/default/7900757132@91.12.24.13 entering state [ready][200] 2018-05-31 11:44:35.453647 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2018-05-31 11:44:35.453647 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMA:8 freeswitch@freeswitch> freeswitch@freeswitch> 2018-05-31 11:44:58.173630 [NOTICE] sofia.c:1012 Hangup sofia/default/7900757132@91.12.24.13 [CS_EXECUTE] [NORMAL_CLEARING] 2018-05-31 11:44:58.173630 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/00555140094888] 2018-05-31 11:44:58.173630 [NOTICE] switch_ivr_bridge.c:891 Hangup sofia/default/00555140094888 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:653 (sofia/default/00555140094888) State EXCHANGE_MEDIA going to sleep 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_HANGUP (Cur 2 Tot 617) 2018-05-31 11:44:58.173630 [DEBUG] switch_ivr_async.c:1316 Stop recording file /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav 2018-05-31 11:44:58.173630 [DEBUG] switch_ivr_async.c:1380 Channel is hung up 2018-05-31 11:44:58.173630 [DEBUG] switch_core_media_bug.c:1124 Removing BUG from sofia/default/00555140094888 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:850 (sofia/default/00555140094888) Callstate Change ACTIVE -> HANGUP 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:852 (sofia/default/00555140094888) State HANGUP 2018-05-31 11:44:58.173630 [DEBUG] mod_sofia.c:432 sofia/default/00555140094888 Overriding SIP cause 480 with 200 from the other leg 2018-05-31 11:44:58.173630 [DEBUG] mod_sofia.c:438 Channel sofia/default/00555140094888 hanging up, cause: NORMAL_CLEARING 2018-05-31 11:44:58.173630 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/default/00555140094888 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:60 sofia/default/00555140094888 Standard HANGUP, cause: NORMAL_CLEARING 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:852 (sofia/default/00555140094888) State HANGUP going to sleep 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:619 (sofia/default/00555140094888) State Change CS_HANGUP -> CS_REPORTING 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:584 (sofia/default/00555140094888) Running State Change CS_REPORTING (Cur 2 Tot 617) 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:938 (sofia/default/00555140094888) State REPORTING 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:174 sofia/default/00555140094888 Standard REPORTING, cause: NORMAL_CLEARING 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:938 (sofia/default/00555140094888) State REPORTING going to sleep 2018-05-31 11:44:58.173630 [DEBUG] switch_core_state_machine.c:610 (sofia/default/00555140094888) State Change CS_REPORTING -> CS_DESTROY 2018-05-31 11:44:58.173630 [DEBUG] switch_core_session.c:1664 Session 617 (sofia/default/00555140094888) Locked, Waiting on external entities 2018-05-31 11:44:58.273622 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/7900757132@91.12.24.13] 2018-05-31 11:44:58.273622 [DEBUG] switch_ivr_bridge.c:1702 sofia/default/7900757132@91.12.24.13 skip receive message [UNBRIDGE] (channel is hungup already) 2018-05-31 11:44:58.273622 [NOTICE] switch_core_session.c:1682 Session 617 (sofia/default/00555140094888) Ended 2018-05-31 11:44:58.273622 [NOTICE] switch_core_session.c:1686 Close Channel sofia/default/00555140094888 [CS_DESTROY] 2018-05-31 11:44:58.273622 [DEBUG] switch_core_session.c:2814 sofia/default/7900757132@91.12.24.13 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:650 (sofia/default/7900757132@91.12.24.13) State EXECUTE going to sleep 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7900757132@91.12.24.13) Running State Change CS_HANGUP (Cur 1 Tot 617) 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:741 (sofia/default/00555140094888) Running State Change CS_DESTROY (Cur 1 Tot 617) 2018-05-31 11:44:58.273622 [DEBUG] switch_ivr_async.c:1316 Stop recording file /home/shared/recordings/f08dd287-60c1-407c-a012-77cdb134e3d0.wav 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:751 (sofia/default/00555140094888) State DESTROY 2018-05-31 11:44:58.273622 [DEBUG] mod_sofia.c:343 sofia/default/00555140094888 SOFIA DESTROY 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:181 sofia/default/00555140094888 Standard DESTROY 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:751 (sofia/default/00555140094888) State DESTROY going to sleep 2018-05-31 11:44:58.273622 [DEBUG] switch_ivr_async.c:1380 Channel is hung up 2018-05-31 11:44:58.273622 [DEBUG] switch_core_media_bug.c:1124 Removing BUG from sofia/default/7900757132@91.12.24.13 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:850 (sofia/default/7900757132@91.12.24.13) Callstate Change ACTIVE -> HANGUP 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:852 (sofia/default/7900757132@91.12.24.13) State HANGUP 2018-05-31 11:44:58.273622 [DEBUG] mod_sofia.c:438 Channel sofia/default/7900757132@91.12.24.13 hanging up, cause: NORMAL_CLEARING 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:60 sofia/default/7900757132@91.12.24.13 Standard HANGUP, cause: NORMAL_CLEARING 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:852 (sofia/default/7900757132@91.12.24.13) State HANGUP going to sleep 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:619 (sofia/default/7900757132@91.12.24.13) State Change CS_HANGUP -> CS_REPORTING 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7900757132@91.12.24.13) Running State Change CS_REPORTING (Cur 1 Tot 617) 2018-05-31 11:44:58.273622 [DEBUG] switch_core_state_machine.c:938 (sofia/default/7900757132@91.12.24.13) State REPORTING 2018-05-31 11:44:58.273622 [INFO] mod_json_cdr.c:271 Process [f08dd287-60c1-407c-a012-77cdb134e3d0.cdr.json] 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:174 sofia/default/7900757132@91.12.24.13 Standard REPORTING, cause: NORMAL_CLEARING 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:938 (sofia/default/7900757132@91.12.24.13) State REPORTING going to sleep 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:610 (sofia/default/7900757132@91.12.24.13) State Change CS_REPORTING -> CS_DESTROY 2018-05-31 11:44:58.453639 [DEBUG] switch_core_session.c:1664 Session 616 (sofia/default/7900757132@91.12.24.13) Locked, Waiting on external entities 2018-05-31 11:44:58.453639 [NOTICE] switch_core_session.c:1682 Session 616 (sofia/default/7900757132@91.12.24.13) Ended 2018-05-31 11:44:58.453639 [NOTICE] switch_core_session.c:1686 Close Channel sofia/default/7900757132@91.12.24.13 [CS_DESTROY] 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:741 (sofia/default/7900757132@91.12.24.13) Running State Change CS_DESTROY (Cur 0 Tot 617) 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:751 (sofia/default/7900757132@91.12.24.13) State DESTROY 2018-05-31 11:44:58.453639 [DEBUG] mod_sofia.c:343 sofia/default/7900757132@91.12.24.13 SOFIA DESTROY 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:181 sofia/default/7900757132@91.12.24.13 Standard DESTROY 2018-05-31 11:44:58.453639 [DEBUG] switch_core_state_machine.c:751 (sofia/default/7900757132@91.12.24.13) State DESTROY going to sleep 2018-05-31 11:44:58.613632 [DEBUG] switch_scheduler.c:144 Deleting task 224 switch_ivr_schedule_hangup (f08dd287-60c1-407c-a012-77cdb134e3d0) freeswitch@freeswitch> freeswitch@freeswitch> freeswitch@freeswitch> /exit