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>