freeswitch@Peth-ivr3> freeswitch@Peth-ivr3> bgapi originate {sip_cid_type=pid,service_type=UKNOW,origination_caller_id_number=+2348023565181,igonre_early_media=true}sofia/external/sip:+2347016922641@10.200.161.132 '&lua(/usr/local/freeswitch/scripts/obsession.lua)' +OK Job-UUID: 8850cab4-e89b-4962-97a9-8390ce25295c 2017-04-11 16:00:35.411601 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-04-11 16:00:35.411601 [NOTICE] switch_channel.c:1104 New Channel sofia/external/%2B2347016922641@10.200.161.132 [76dacf0b-aa2a-4ee9-871a-6baf42a5055e] 2017-04-11 16:00:35.411601 [DEBUG] mod_sofia.c:5011 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_NEW -> CS_INIT 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_INIT (Cur 1 Tot 4) 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:627 (sofia/external/%2B2347016922641@10.200.161.132) State INIT 2017-04-11 16:00:35.411601 [DEBUG] mod_sofia.c:93 sofia/external/%2B2347016922641@10.200.161.132 SOFIA INIT 2017-04-11 16:00:35.411601 [DEBUG] sofia_glue.c:1298 sofia/external/%2B2347016922641@10.200.161.132 sending invite version: 1.9.0 git aaa26c6 2017-04-10 20:24:05Z 64bit Local SDP: v=0 o=FreeSWITCH 1491895647 1491895648 IN IP4 10.227.49.19 s=FreeSWITCH c=IN IP4 10.227.49.19 t=0 0 m=audio 27188 RTP/AVP 102 9 0 8 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 24532 RTP/AVP 103 b=AS:1024 a=rtpmap:103 VP8/90000 a=sendrecv a=rtcp-fb:103 ccm fir a=rtcp-fb:103 ccm tmmbr a=rtcp-fb:103 nack a=rtcp-fb:103 nack pli 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:40 sofia/external/%2B2347016922641@10.200.161.132 Standard INIT 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:48 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_INIT -> CS_ROUTING 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:627 (sofia/external/%2B2347016922641@10.200.161.132) State INIT going to sleep 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_ROUTING (Cur 1 Tot 4) 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:643 (sofia/external/%2B2347016922641@10.200.161.132) State ROUTING 2017-04-11 16:00:35.411601 [DEBUG] mod_sofia.c:154 sofia/external/%2B2347016922641@10.200.161.132 SOFIA ROUTING 2017-04-11 16:00:35.411601 [DEBUG] switch_ivr_originate.c:67 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:643 (sofia/external/%2B2347016922641@10.200.161.132) State ROUTING going to sleep 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 4) 2017-04-11 16:00:35.411601 [DEBUG] sofia.c:7247 Channel sofia/external/%2B2347016922641@10.200.161.132 entering state [calling][0] 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:662 (sofia/external/%2B2347016922641@10.200.161.132) State CONSUME_MEDIA 2017-04-11 16:00:35.411601 [DEBUG] switch_core_state_machine.c:662 (sofia/external/%2B2347016922641@10.200.161.132) State CONSUME_MEDIA going to sleep 2017-04-11 16:00:35.611595 [DEBUG] sofia.c:7247 Channel sofia/external/%2B2347016922641@10.200.161.132 entering state [proceeding][183] 2017-04-11 16:00:35.611595 [DEBUG] sofia.c:7257 Remote SDP: v=0 o=- 15454933 15454933 IN IP4 TSS.LGTSS.LGTSS01.NG s=- c=IN IP4 10.200.12.31 t=0 0 a=sendrecv m=audio 39726 RTP/AVP 8 101 c=IN IP4 10.200.12.31 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:40 m=video 0 RTP/AVP 103 b=AS:1024 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5102 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[opus:116:48000:20:0:1] 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5102 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[G722:9:8000:20:64000:1] 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5102 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMU:0:8000:20:64000:1] 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5102 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMA:8:8000:20:64000:1] 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5157 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5018 Set telephone-event payload to 101@8000 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:3425 Set Codec sofia/external/%2B2347016922641@10.200.161.132 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2017-04-11 16:00:35.611595 [DEBUG] switch_core_codec.c:111 sofia/external/%2B2347016922641@10.200.161.132 Original read codec set to PCMA:8 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5361 Set telephone-event payload to 101@8000 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:5420 sofia/external/%2B2347016922641@10.200.161.132 Set 2833 dtmf send payload to 101 recv payload to 101 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:8137 AUDIO RTP [sofia/external/%2B2347016922641@10.200.161.132] 10.227.49.19 port 27188 -> 10.200.12.31 port 39726 codec: 8 ms: 20 2017-04-11 16:00:35.611595 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:8440 sofia/external/%2B2347016922641@10.200.161.132 Set 2833 dtmf send payload to 101 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:8447 sofia/external/%2B2347016922641@10.200.161.132 Set 2833 dtmf receive payload to 101 2017-04-11 16:00:35.611595 [DEBUG] switch_core_media.c:8470 sofia/external/%2B2347016922641@10.200.161.132 Set rtp dtmf delay to 40 2017-04-11 16:00:35.611595 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/%2B2347016922641@10.200.161.132! 2017-04-11 16:00:35.611595 [DEBUG] switch_channel.c:3481 (sofia/external/%2B2347016922641@10.200.161.132) Callstate Change DOWN -> EARLY 2017-04-11 16:00:35.631510 [DEBUG] switch_ivr_originate.c:3695 Originate Resulted in Success: [sofia/external/%2B2347016922641@10.200.161.132] 2017-04-11 16:00:35.631510 [INFO] switch_channel.c:3130 sofia/external/%2B2347016922641@10.200.161.132 Flipping CID from "" <+2348023565181> to "Outbound Call" <+2347016922641> 2017-04-11 16:00:35.631510 [DEBUG] mod_commands.c:4844 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 2017-04-11 16:00:35.631510 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_EXECUTE (Cur 1 Tot 4) 2017-04-11 16:00:35.631510 [DEBUG] switch_core_state_machine.c:650 (sofia/external/%2B2347016922641@10.200.161.132) State EXECUTE 2017-04-11 16:00:35.631510 [DEBUG] mod_sofia.c:209 sofia/external/%2B2347016922641@10.200.161.132 SOFIA EXECUTE 2017-04-11 16:00:35.631510 [DEBUG] switch_core_state_machine.c:328 sofia/external/%2B2347016922641@10.200.161.132 Standard EXECUTE EXECUTE sofia/external/%2B2347016922641@10.200.161.132 lua(/usr/local/freeswitch/scripts/obsession.lua) 2017-04-11 16:00:35.631510 [NOTICE] switch_cpp.cpp:86 bound to all 2017-04-11 16:00:35.651513 [DEBUG] freeswitch_lua.cpp:372 DBH handle 0x7f8ac40297e0 Connected. 2017-04-11 16:00:35.651513 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('ObCause', '') 2017-04-11 16:00:35.671526 [DEBUG] switch_rtp.c:7243 Correct audio ip/port confirmed. EXECUTE sofia/external/%2B2347016922641@10.200.161.132 avmd_start() 2017-04-11 16:00:36.651594 [INFO] mod_avmd.c:1112 Avmd dynamic configuration: debug [0], report_status [1], fast_math [0], require_continuous_streak [1], sample_n_continuous_streak [3], sample_n_to_skip [0], require_continuous_streak_amp [1], sample_n_continuous_streak_amp [3], simplified_estimation [1], inbound_channel [0], outbound_channel [1], detection_mode [2], detectors_n [0], detectors_lagged_n [0] 2017-04-11 16:00:36.651594 [INFO] mod_avmd.c:609 Avmd session initialized, [8000] samples/s 2017-04-11 16:00:36.651594 [DEBUG] switch_core_media_bug.c:841 Attaching BUG to sofia/external/%2B2347016922641@10.200.161.132 2017-04-11 16:00:36.651594 [INFO] mod_avmd.c:1410 Avmd on channel [sofia/external/%2B2347016922641@10.200.161.132] started! 2017-04-11 16:00:36.651594 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-04-11 16:00:36.691741 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMA:8 2017-04-11 16:00:39.951587 [DEBUG] switch_core_io.c:780 Engaging Read Buffer at 320 bytes vs 120 2017-04-11 16:00:50.991578 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/DI/U_know.wav 2017-04-11 16:00:51.751592 [DEBUG] sofia.c:7247 Channel sofia/external/%2B2347016922641@10.200.161.132 entering state [completing][200] 2017-04-11 16:00:51.751592 [DEBUG] sofia.c:7254 Duplicate SDP v=0 o=- 15454933 15454933 IN IP4 TSS.LGTSS.LGTSS01.NG s=- c=IN IP4 10.200.12.31 t=0 0 a=sendrecv m=audio 39726 RTP/AVP 8 101 c=IN IP4 10.200.12.31 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=maxptime:40 m=video 0 RTP/AVP 103 b=AS:1024 2017-04-11 16:00:51.771589 [DEBUG] sofia.c:7247 Channel sofia/external/%2B2347016922641@10.200.161.132 entering state [ready][200] 2017-04-11 16:00:51.771589 [NOTICE] sofia.c:8324 Channel [sofia/external/%2B2347016922641@10.200.161.132] has been answered 2017-04-11 16:00:51.771589 [DEBUG] switch_channel.c:3780 (sofia/external/%2B2347016922641@10.200.161.132) Callstate Change EARLY -> ACTIVE 2017-04-11 16:00:51.831578 [DEBUG] switch_rtp.c:7243 Correct audio ip/port confirmed. EXECUTE sofia/external/%2B2347016922641@10.200.161.132 avmd_stop() 2017-04-11 16:00:53.991593 [INFO] mod_avmd.c:1466 Avmd on channel [sofia/external/%2B2347016922641@10.200.161.132] stopped, beep status: [NOTDETECTED], total running time [17339999] [us] 2017-04-11 16:00:53.991593 [DEBUG] switch_core_media_bug.c:1216 Removing BUG from sofia/external/%2B2347016922641@10.200.161.132 2017-04-11 16:00:53.991593 [DEBUG] switch_cpp.cpp:731 CoreSession::hangup 2017-04-11 16:00:53.991593 [NOTICE] switch_cpp.cpp:733 Hangup sofia/external/%2B2347016922641@10.200.161.132 [CS_EXECUTE] [NORMAL_CLEARING] 2017-04-11 16:00:53.991593 [DEBUG] switch_cpp.cpp:1122 sofia/external/%2B2347016922641@10.200.161.132 destroy/unlink session from object 2017-04-11 16:00:53.991593 [DEBUG] freeswitch_lua.cpp:401 DBH handle 0x7f8ac40297e0 released. 2017-04-11 16:00:53.991593 [NOTICE] switch_event.c:2141 Event Binding deleted for src/switch_cpp.cpp:ALL 2017-04-11 16:00:53.991593 [DEBUG] switch_core_session.c:2884 sofia/external/%2B2347016922641@10.200.161.132 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:650 (sofia/external/%2B2347016922641@10.200.161.132) State EXECUTE going to sleep 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_HANGUP (Cur 1 Tot 4) 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:850 (sofia/external/%2B2347016922641@10.200.161.132) Callstate Change ACTIVE -> HANGUP 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:852 (sofia/external/%2B2347016922641@10.200.161.132) State HANGUP 2017-04-11 16:00:53.991593 [DEBUG] mod_sofia.c:449 Channel sofia/external/%2B2347016922641@10.200.161.132 hanging up, cause: NORMAL_CLEARING 2017-04-11 16:00:53.991593 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/external/%2B2347016922641@10.200.161.132 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:60 sofia/external/%2B2347016922641@10.200.161.132 Standard HANGUP, cause: NORMAL_CLEARING 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:852 (sofia/external/%2B2347016922641@10.200.161.132) State HANGUP going to sleep 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:619 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_HANGUP -> CS_REPORTING 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:584 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_REPORTING (Cur 1 Tot 4) 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:938 (sofia/external/%2B2347016922641@10.200.161.132) State REPORTING 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:174 sofia/external/%2B2347016922641@10.200.161.132 Standard REPORTING, cause: NORMAL_CLEARING 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:938 (sofia/external/%2B2347016922641@10.200.161.132) State REPORTING going to sleep 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:610 (sofia/external/%2B2347016922641@10.200.161.132) State Change CS_REPORTING -> CS_DESTROY 2017-04-11 16:00:53.991593 [DEBUG] switch_core_session.c:1712 Session 4 (sofia/external/%2B2347016922641@10.200.161.132) Locked, Waiting on external entities 2017-04-11 16:00:53.991593 [NOTICE] switch_core_session.c:1730 Session 4 (sofia/external/%2B2347016922641@10.200.161.132) Ended 2017-04-11 16:00:53.991593 [NOTICE] switch_core_session.c:1734 Close Channel sofia/external/%2B2347016922641@10.200.161.132 [CS_DESTROY] 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:741 (sofia/external/%2B2347016922641@10.200.161.132) Running State Change CS_DESTROY (Cur 0 Tot 4) 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:751 (sofia/external/%2B2347016922641@10.200.161.132) State DESTROY 2017-04-11 16:00:53.991593 [DEBUG] mod_sofia.c:354 sofia/external/%2B2347016922641@10.200.161.132 SOFIA DESTROY 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:181 sofia/external/%2B2347016922641@10.200.161.132 Standard DESTROY 2017-04-11 16:00:53.991593 [DEBUG] switch_core_state_machine.c:751 (sofia/external/%2B2347016922641@10.200.161.132) State DESTROY going to sleep freeswitch@Peth-ivr3>