search

drachtio / drachtio-freeswitch-modules

A collection of open-sourced freeswitch modules that I use in various drachtio applications
MIT License
171 stars 119 forks source link

Unable to fork concurrent websocket connections #76

Open vskg9 opened 2 years ago

vskg9 commented 2 years ago

Hello @davehorton

I am trying to fork the audio call using the below command to which the server is listening on 3001 port(Ran ws_server.js to start the server. Slightly modified to code to write to different files based on the different websocket connections) 

uuid_audio_fork 0c22a0ae-7690-497c-9a1b-671ee63bda86 start http://3.19.242.172:3001 mixed 32000

First connection is forked correctly and the audio is saved to the file. But when I fork the second call, the first stream stops writing the buffer to the audio file. Can you suggest what could be the problem here? Is it with the node or drachtio?

davehorton commented 2 years ago

Can you get a freeswitch log at debug level showing the full sequence you describe above, first one call being forked and then the second

vskg9 commented 2 years ago

Here is the full log of the freeswitch and both the client connections are successful but the forked media is not saved to the first file as soon as the second call is established. Both the calls are still active but the media forked is not saved after the second call.

ontinue=false
Dialplan: sofia/internal/1008@3.19.242.172:5070 Regex (PASS) [Local_Extension] destination_number(1007) =~ /^(10[01][0-9]|0011010220101[0-9]|1719212[0-9][0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action export(dialed_extension=1007)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action set(call_timeout=30)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action answer()
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action sleep(1000)
Dialplan: sofia/internal/1008@3.19.242.172:5070 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2022-01-20 08:56:16.025878 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1008@3.19.242.172:5070) State Change CS_ROUTING -> CS_EXECUTE
2022-01-20 08:56:16.025878 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1008@3.19.242.172:5070) State ROUTING going to sleep
2022-01-20 08:56:16.025878 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1008@3.19.242.172:5070) Running State Change CS_EXECUTE (Cur 1 Tot 29)
2022-01-20 08:56:16.025878 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1008@3.19.242.172:5070) State EXECUTE
2022-01-20 08:56:16.025878 [DEBUG] mod_sofia.c:209 sofia/internal/1008@3.19.242.172:5070 SOFIA EXECUTE
2022-01-20 08:56:16.025878 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1008@3.19.242.172:5070 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2022-01-20 08:56:16.025878 [CRIT] mod_dptools.c:1866 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
2022-01-20 08:56:16.045853 [CRIT] mod_dptools.c:1866 Open /usr/local/freeswitch/conf/vars.xml and change the default_password.
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 log(CRIT Once changed type 'reloadxml' at the console.)
2022-01-20 08:56:16.045853 [CRIT] mod_dptools.c:1866 Once changed type 'reloadxml' at the console.
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2022-01-20 08:56:16.045853 [CRIT] mod_dptools.c:1866 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 sleep(10000)
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 export(dialed_extension=1007)
2022-01-20 08:56:26.065864 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [dialed_extension]=[1007]
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 bind_meta_app(1 b s execute_extension::dx XML features)
2022-01-20 08:56:26.065864 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1008.2022-01-20-08-56-26.wav)
2022-01-20 08:56:26.065864 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1008.2022-01-20-08-56-26.wav
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 bind_meta_app(3 b s execute_extension::cf XML features)
2022-01-20 08:56:26.065864 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2022-01-20 08:56:26.065864 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 set(ringback=%(2000,4000,440,480))
2022-01-20 08:56:26.065864 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1008@3.19.242.172:5070 [ringback]=[%(2000,4000,440,480)]
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 set(transfer_ringback=local_stream://moh)
2022-01-20 08:56:26.065864 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1008@3.19.242.172:5070 [transfer_ringback]=[local_stream://moh]
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 set(call_timeout=30)
2022-01-20 08:56:26.065864 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1008@3.19.242.172:5070 [call_timeout]=[30]
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 set(hangup_after_bridge=true)
2022-01-20 08:56:26.065864 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1008@3.19.242.172:5070 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/1008@3.19.242.172:5070 bridge(user/1007@172.31.33.159)
2022-01-20 08:56:26.065864 [DEBUG] switch_channel.c:1264 sofia/internal/1008@3.19.242.172:5070 EXPORTING[export_vars] [dialed_extension]=[1007] to event
2022-01-20 08:56:26.065864 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2022-01-20 08:56:26.065864 [DEBUG] switch_channel.c:1264 sofia/internal/1008@3.19.242.172:5070 EXPORTING[export_vars] [dialed_extension]=[1007] to event
2022-01-20 08:56:26.065864 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2022-01-20 08:56:26.065864 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1007@49.206.45.27:46321 [3b93777c-90fc-4dd3-8bc6-61d1421c3ca1]
2022-01-20 08:56:26.065864 [DEBUG] mod_sofia.c:5089 (sofia/internal/1007@49.206.45.27:46321) State Change CS_NEW -> CS_INIT
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1007@49.206.45.27:46321) Running State Change CS_INIT (Cur 2 Tot 30)
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1007@49.206.45.27:46321) State INIT
2022-01-20 08:56:26.065864 [DEBUG] mod_sofia.c:93 sofia/internal/1007@49.206.45.27:46321 SOFIA INIT
2022-01-20 08:56:26.065864 [DEBUG] sofia_glue.c:1618 sofia/internal/1007@49.206.45.27:46321 sending invite version: 1.10.5-release git 25569c1 2020-08-18 18:51:21Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1642643884 1642643885 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 25102 RTP/AVP 102 9 0 8 103 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1007@49.206.45.27:46321 Standard INIT
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1007@49.206.45.27:46321) State Change CS_INIT -> CS_ROUTING
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1007@49.206.45.27:46321) State INIT going to sleep
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1007@49.206.45.27:46321) Running State Change CS_ROUTING (Cur 2 Tot 30)
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1007@49.206.45.27:46321) State ROUTING
2022-01-20 08:56:26.065864 [DEBUG] mod_sofia.c:154 sofia/internal/1007@49.206.45.27:46321 SOFIA ROUTING
2022-01-20 08:56:26.065864 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1007@49.206.45.27:46321) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1007@49.206.45.27:46321) State ROUTING going to sleep
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1007@49.206.45.27:46321) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 30)
2022-01-20 08:56:26.065864 [DEBUG] sofia.c:7326 Channel sofia/internal/1007@49.206.45.27:46321 entering state [calling][0]
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/1007@49.206.45.27:46321) State CONSUME_MEDIA
2022-01-20 08:56:26.065864 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/1007@49.206.45.27:46321) State CONSUME_MEDIA going to sleep
2022-01-20 08:56:26.865863 [DEBUG] sofia.c:7326 Channel sofia/internal/1007@49.206.45.27:46321 entering state [proceeding][180]
2022-01-20 08:56:26.865863 [NOTICE] sofia.c:7437 Ring-Ready sofia/internal/1007@49.206.45.27:46321!
2022-01-20 08:56:26.865863 [DEBUG] switch_channel.c:3437 (sofia/internal/1007@49.206.45.27:46321) Callstate Change DOWN -> RINGING
2022-01-20 08:56:26.865863 [INFO] switch_ivr_originate.c:1275 Sending early media
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[opus:116:48000:20:0:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2022-01-20 08:56:26.865863 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:26.865863 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1008@3.19.242.172:5070 opus/48000 20 ms 960 samples 0 bits 1 channels
2022-01-20 08:56:26.865863 [DEBUG] switch_core_codec.c:111 sofia/internal/1008@3.19.242.172:5070 Original read codec set to opus:116
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:5911 sofia/internal/1008@3.19.242.172:5070 Set 2833 dtmf send payload to 101 recv payload to 101
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1008@3.19.242.172:5070] 172.31.33.159 port 28484 -> 192.168.0.101 port 56978 codec: 120 ms: 20
2022-01-20 08:56:26.865863 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 960 bytes per 20ms
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:8977 sofia/internal/1008@3.19.242.172:5070 Set 2833 dtmf send payload to 101
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:8984 sofia/internal/1008@3.19.242.172:5070 Set 2833 dtmf receive payload to 101
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:9007 sofia/internal/1008@3.19.242.172:5070 Set rtp dtmf delay to 40
2022-01-20 08:56:26.865863 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1008@3.19.242.172:5070!
2022-01-20 08:56:26.865863 [DEBUG] switch_channel.c:3565 (sofia/internal/1008@3.19.242.172:5070) Callstate Change RINGING -> EARLY
2022-01-20 08:56:26.865863 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1008@3.19.242.172:5070.
2022-01-20 08:56:26.865863 [DEBUG] mod_sofia.c:2593 Ring SDP:
v=0
o=FreeSWITCH 1642640502 1642640503 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 28484 RTP/AVP 120 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:56:26.865863 [DEBUG] switch_ivr_originate.c:1333 Raw Codec Activation Success L16@48000hz 1 channel 20ms
2022-01-20 08:56:26.865863 [DEBUG] switch_core_codec.c:223 sofia/internal/1008@3.19.242.172:5070 Push codec L16:100
2022-01-20 08:56:26.865863 [DEBUG] switch_ivr_originate.c:1407 Play Ringback Tone [%(2000,4000,440,480)]
2022-01-20 08:56:26.885853 [DEBUG] sofia.c:7326 Channel sofia/internal/1008@3.19.242.172:5070 entering state [early][183]
2022-01-20 08:56:27.545871 [INFO] switch_rtp.c:7719 Auto Changing audio port from 192.168.0.101:56978 to 49.206.45.27:46124
2022-01-20 08:56:29.645857 [DEBUG] sofia.c:7326 Channel sofia/internal/1007@49.206.45.27:46321 entering state [completing][200]
2022-01-20 08:56:29.645857 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=- 2912330963 3 IN IP4 192.168.0.101
s=Bria release 6.5.1 stamp 108815
c=IN IP4 192.168.0.101
t=0 0
m=audio 53598 RTP/AVP 102 9 0 8 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2022-01-20 08:56:29.645857 [DEBUG] sofia.c:7326 Channel sofia/internal/1007@49.206.45.27:46321 entering state [ready][200]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2022-01-20 08:56:29.645857 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:29.645857 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1007@49.206.45.27:46321 opus/48000 20 ms 960 samples 0 bits 1 channels
2022-01-20 08:56:29.645857 [DEBUG] switch_core_codec.c:111 sofia/internal/1007@49.206.45.27:46321 Original read codec set to opus:116
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:5911 sofia/internal/1007@49.206.45.27:46321 Set 2833 dtmf send payload to 101 recv payload to 101
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1007@49.206.45.27:46321] 172.31.33.159 port 25102 -> 192.168.0.101 port 53598 codec: 102 ms: 20
2022-01-20 08:56:29.645857 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 960 bytes per 20ms
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:8977 sofia/internal/1007@49.206.45.27:46321 Set 2833 dtmf send payload to 101
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:8984 sofia/internal/1007@49.206.45.27:46321 Set 2833 dtmf receive payload to 101
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:9007 sofia/internal/1007@49.206.45.27:46321 Set rtp dtmf delay to 40
2022-01-20 08:56:29.645857 [NOTICE] sofia.c:8504 Channel [sofia/internal/1007@49.206.45.27:46321] has been answered
2022-01-20 08:56:29.645857 [DEBUG] switch_channel.c:3865 (sofia/internal/1007@49.206.45.27:46321) Callstate Change RINGING -> ACTIVE
2022-01-20 08:56:29.645857 [DEBUG] switch_core_codec.c:248 sofia/internal/1008@3.19.242.172:5070 Restore previous codec opus:116.
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1008@3.19.242.172:5070.
2022-01-20 08:56:29.645857 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1008@3.19.242.172:5070:
v=0
o=FreeSWITCH 1642640502 1642640504 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 28484 RTP/AVP 120 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:56:29.645857 [NOTICE] switch_ivr_originate.c:3794 Channel [sofia/internal/1008@3.19.242.172:5070] has been answered
2022-01-20 08:56:29.645857 [DEBUG] switch_channel.c:3865 (sofia/internal/1008@3.19.242.172:5070) Callstate Change EARLY -> ACTIVE
2022-01-20 08:56:29.645857 [DEBUG] sofia.c:7326 Channel sofia/internal/1008@3.19.242.172:5070 entering state [completed][200]
2022-01-20 08:56:29.645857 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/1007@49.206.45.27:46321]
2022-01-20 08:56:29.645857 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/1007@49.206.45.27:46321]
2022-01-20 08:56:29.645857 [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/1007@49.206.45.27:46321) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2022-01-20 08:56:29.645857 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1007@49.206.45.27:46321) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 30)
2022-01-20 08:56:29.645857 [DEBUG] switch_core_state_machine.c:654 (sofia/internal/1007@49.206.45.27:46321) State EXCHANGE_MEDIA
2022-01-20 08:56:29.645857 [DEBUG] mod_sofia.c:656 SOFIA EXCHANGE_MEDIA
2022-01-20 08:56:29.645857 [INFO] switch_cpp.cpp:1447 bd331b13-3907-4bed-9c3e-1b01e75f96bb RAJEEVLUA running uuid:
2022-01-20 08:56:29.645857 [INFO] switch_cpp.cpp:1447 uuid_audio_fork bd331b13-3907-4bed-9c3e-1b01e75f96bb start http://3.19.242.172:3001 mixed 32000
2022-01-20 08:56:29.645857 [DEBUG] mod_audio_fork.c:167 mod_audio_fork cmd: bd331b13-3907-4bed-9c3e-1b01e75f96bb start http://3.19.242.172:3001 mixed 32000
2022-01-20 08:56:29.645857 [DEBUG] lws_glue.cpp:361 parse_ws_uri - host 3.19.242.172, path /
2022-01-20 08:56:29.645857 [INFO] mod_audio_fork.c:73 mod_audio_fork: streaming 32000 sampling to 3.19.242.172 path / port 3001 tls: no.
2022-01-20 08:56:29.645857 [DEBUG] mod_audio_fork.c:89 calling fork_session_init.
2022-01-20 08:56:29.645857 [DEBUG] lws_glue.cpp:249 (12) resampling from 48000 to 32000
2022-01-20 08:56:29.645857 [DEBUG] lws_glue.cpp:260 (12) fork_data_init
2022-01-20 08:56:29.645857 [NOTICE] lws_glue.cpp:287 bd331b13-3907-4bed-9c3e-1b01e75f96bb after adding connect there are 1 pending connects

2022-01-20 08:56:29.645857 [DEBUG] mod_audio_fork.c:95 adding bug.
2022-01-20 08:56:29.645857 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/1008@3.19.242.172:5070
2022-01-20 08:56:29.645857 [NOTICE] lws_glue.cpp:287 bd331b13-3907-4bed-9c3e-1b01e75f96bb attempting connection, wsi is 0x7fbd6003d300

2022-01-20 08:56:29.645857 [DEBUG] mod_audio_fork.c:99 setting bug private data.
2022-01-20 08:56:29.645857 [DEBUG] mod_audio_fork.c:102 exiting start_capture.
2022-01-20 08:56:29.665865 [INFO] lws_glue.cpp:166 connection successful
2022-01-20 08:56:29.706486 [DEBUG] switch_rtp.c:7759 Correct audio ip/port confirmed.
2022-01-20 08:56:29.706486 [DEBUG] switch_core_io.c:448 Setting BUG Codec opus:116
2022-01-20 08:56:29.706486 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[139] Bytes encoded[13106] Encoded length ms[2780] Average encoded bitrate bps[52424]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[115] PLC[0] FEC[0]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:56:29.745937 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:56:29.925857 [INFO] switch_rtp.c:7719 Auto Changing audio port from 192.168.0.101:53598 to 49.206.45.27:46127
2022-01-20 08:56:30.005855 [DEBUG] sofia.c:7326 Channel sofia/internal/1008@3.19.242.172:5070 entering state [ready][200]
2022-01-20 08:57:05.365928 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1006@3.19.242.172:5070 [1d1a7adb-5afb-4536-85c2-0661adffef1a]
2022-01-20 08:57:05.365928 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1006@3.19.242.172:5070) Running State Change CS_NEW (Cur 3 Tot 31)
2022-01-20 08:57:05.365928 [DEBUG] sofia.c:10280 sofia/internal/1006@3.19.242.172:5070 receiving invite from 49.206.45.27:46319 version: 1.10.5-release git 25569c1 2020-08-18 18:51:21Z 64bit
2022-01-20 08:57:05.365928 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 49.206.45.27:0.
2022-01-20 08:57:05.365928 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1006@3.19.242.172:5070) State NEW
2022-01-20 08:57:05.365928 [DEBUG] sofia.c:2434 detaching session 1d1a7adb-5afb-4536-85c2-0661adffef1a
2022-01-20 08:57:06.045858 [DEBUG] sofia.c:2544 Re-attaching to session 1d1a7adb-5afb-4536-85c2-0661adffef1a
2022-01-20 08:57:06.065858 [DEBUG] sofia.c:10280 sofia/internal/1006@3.19.242.172:5070 receiving invite from 49.206.45.27:46319 version: 1.10.5-release git 25569c1 2020-08-18 18:51:21Z 64bit
2022-01-20 08:57:06.065858 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 49.206.45.27:0.
2022-01-20 08:57:06.065858 [DEBUG] sofia.c:11477 Setting NAT mode based on nat.auto
2022-01-20 08:57:06.065858 [DEBUG] sofia.c:7326 Channel sofia/internal/1006@3.19.242.172:5070 entering state [received][100]
2022-01-20 08:57:06.065858 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=- 1642669025009675 1 IN IP4 192.168.0.101
s=Bria release 6.5.1 stamp 108815
c=IN IP4 192.168.0.101
t=0 0
m=audio 53738 RTP/AVP 120 9 18 0 8 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2022-01-20 08:57:06.065858 [DEBUG] sofia.c:7739 (sofia/internal/1006@3.19.242.172:5070) State Change CS_NEW -> CS_INIT
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1006@3.19.242.172:5070) Running State Change CS_INIT (Cur 3 Tot 31)
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1006@3.19.242.172:5070) State INIT
2022-01-20 08:57:06.065858 [DEBUG] mod_sofia.c:93 sofia/internal/1006@3.19.242.172:5070 SOFIA INIT
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1006@3.19.242.172:5070 Standard INIT
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1006@3.19.242.172:5070) State Change CS_INIT -> CS_ROUTING
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1006@3.19.242.172:5070) State INIT going to sleep
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1006@3.19.242.172:5070) Running State Change CS_ROUTING (Cur 3 Tot 31)
2022-01-20 08:57:06.065858 [DEBUG] switch_channel.c:2332 (sofia/internal/1006@3.19.242.172:5070) Callstate Change DOWN -> RINGING
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1006@3.19.242.172:5070) State ROUTING
2022-01-20 08:57:06.065858 [DEBUG] mod_sofia.c:154 sofia/internal/1006@3.19.242.172:5070 SOFIA ROUTING
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1006@3.19.242.172:5070 Standard ROUTING
2022-01-20 08:57:06.065858 [INFO] mod_dialplan_xml.c:637 Processing 1006 <1006>->1005 in context default
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1006@3.19.242.172:5070 Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1006@3.19.242.172:5070 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [global-intercept] destination_number(1005) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [group-intercept] destination_number(1005) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [intercept-ext] destination_number(1005) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->redial] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [redial] destination_number(1005) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->global] continue=true
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (PASS) [global] ${default_password}(1234) =~ /^1234$/ break=never
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action log(CRIT Once changed type 'reloadxml' at the console.)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action sleep(10000)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 1642669025009675 1 IN IP4 192.168.0.101
s=Bria release 6.5.1 stamp 108815
c=IN IP4 192.168.0.101
t=0 0
m=audio 53738 RTP/AVP 120 9 18 0 8 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [snom-demo-2] destination_number(1005) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [snom-demo-1] destination_number(1005) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [eavesdrop] destination_number(1005) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [eavesdrop] destination_number(1005) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [call_return] destination_number(1005) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [del-group] destination_number(1005) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [add-group] destination_number(1005) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [call-group-simo] destination_number(1005) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [call-group-order] destination_number(1005) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [extension-intercom] destination_number(1005) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->wbxCCRoutePoint1] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (FAIL) [wbxCCRoutePoint1] destination_number(1005) =~ /^1800.+$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Regex (PASS) [Local_Extension] destination_number(1005) =~ /^(10[01][0-9]|0011010220101[0-9]|1719212[0-9][0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action export(dialed_extension=1005)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action set(call_timeout=30)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action answer()
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action sleep(1000)
Dialplan: sofia/internal/1006@3.19.242.172:5070 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1006@3.19.242.172:5070) State Change CS_ROUTING -> CS_EXECUTE
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1006@3.19.242.172:5070) State ROUTING going to sleep
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1006@3.19.242.172:5070) Running State Change CS_EXECUTE (Cur 3 Tot 31)
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1006@3.19.242.172:5070) State EXECUTE
2022-01-20 08:57:06.065858 [DEBUG] mod_sofia.c:209 sofia/internal/1006@3.19.242.172:5070 SOFIA EXECUTE
2022-01-20 08:57:06.065858 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1006@3.19.242.172:5070 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2022-01-20 08:57:06.065858 [CRIT] mod_dptools.c:1866 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
2022-01-20 08:57:06.065858 [CRIT] mod_dptools.c:1866 Open /usr/local/freeswitch/conf/vars.xml and change the default_password.
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 log(CRIT Once changed type 'reloadxml' at the console.)
2022-01-20 08:57:06.065858 [CRIT] mod_dptools.c:1866 Once changed type 'reloadxml' at the console.
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2022-01-20 08:57:06.065858 [CRIT] mod_dptools.c:1866 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 sleep(10000)
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 export(dialed_extension=1005)
2022-01-20 08:57:16.085867 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [dialed_extension]=[1005]
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 bind_meta_app(1 b s execute_extension::dx XML features)
2022-01-20 08:57:16.085867 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1006.2022-01-20-08-57-16.wav)
2022-01-20 08:57:16.085867 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1006.2022-01-20-08-57-16.wav
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 bind_meta_app(3 b s execute_extension::cf XML features)
2022-01-20 08:57:16.085867 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2022-01-20 08:57:16.085867 [INFO] switch_ivr_async.c:4457 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 set(ringback=%(2000,4000,440,480))
2022-01-20 08:57:16.085867 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1006@3.19.242.172:5070 [ringback]=[%(2000,4000,440,480)]
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 set(transfer_ringback=local_stream://moh)
2022-01-20 08:57:16.085867 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1006@3.19.242.172:5070 [transfer_ringback]=[local_stream://moh]
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 set(call_timeout=30)
2022-01-20 08:57:16.085867 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1006@3.19.242.172:5070 [call_timeout]=[30]
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 set(hangup_after_bridge=true)
2022-01-20 08:57:16.085867 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1006@3.19.242.172:5070 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/1006@3.19.242.172:5070 bridge(user/1005@172.31.33.159)
2022-01-20 08:57:16.085867 [DEBUG] switch_channel.c:1264 sofia/internal/1006@3.19.242.172:5070 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-01-20 08:57:16.085867 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2022-01-20 08:57:16.085867 [DEBUG] switch_channel.c:1264 sofia/internal/1006@3.19.242.172:5070 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-01-20 08:57:16.085867 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2022-01-20 08:57:16.085867 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1005@49.206.45.27:46318 [93e54377-cfc9-45c9-8417-23e40244cb3f]
2022-01-20 08:57:16.085867 [DEBUG] mod_sofia.c:5089 (sofia/internal/1005@49.206.45.27:46318) State Change CS_NEW -> CS_INIT
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1005@49.206.45.27:46318) Running State Change CS_INIT (Cur 4 Tot 32)
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1005@49.206.45.27:46318) State INIT
2022-01-20 08:57:16.085867 [DEBUG] mod_sofia.c:93 sofia/internal/1005@49.206.45.27:46318 SOFIA INIT
2022-01-20 08:57:16.085867 [DEBUG] sofia_glue.c:1618 sofia/internal/1005@49.206.45.27:46318 sending invite version: 1.10.5-release git 25569c1 2020-08-18 18:51:21Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1642632174 1642632175 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 36862 RTP/AVP 102 9 0 8 103 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1005@49.206.45.27:46318 Standard INIT
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1005@49.206.45.27:46318) State Change CS_INIT -> CS_ROUTING
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1005@49.206.45.27:46318) State INIT going to sleep
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1005@49.206.45.27:46318) Running State Change CS_ROUTING (Cur 4 Tot 32)
2022-01-20 08:57:16.085867 [DEBUG] sofia.c:7326 Channel sofia/internal/1005@49.206.45.27:46318 entering state [calling][0]
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1005@49.206.45.27:46318) State ROUTING
2022-01-20 08:57:16.085867 [DEBUG] mod_sofia.c:154 sofia/internal/1005@49.206.45.27:46318 SOFIA ROUTING
2022-01-20 08:57:16.085867 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1005@49.206.45.27:46318) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1005@49.206.45.27:46318) State ROUTING going to sleep
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1005@49.206.45.27:46318) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 32)
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/1005@49.206.45.27:46318) State CONSUME_MEDIA
2022-01-20 08:57:16.085867 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/1005@49.206.45.27:46318) State CONSUME_MEDIA going to sleep
2022-01-20 08:57:16.505864 [DEBUG] sofia.c:7326 Channel sofia/internal/1005@49.206.45.27:46318 entering state [proceeding][180]
2022-01-20 08:57:16.505864 [NOTICE] sofia.c:7437 Ring-Ready sofia/internal/1005@49.206.45.27:46318!
2022-01-20 08:57:16.505864 [DEBUG] switch_channel.c:3437 (sofia/internal/1005@49.206.45.27:46318) Callstate Change DOWN -> RINGING
2022-01-20 08:57:16.505864 [INFO] switch_ivr_originate.c:1275 Sending early media
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[opus:116:48000:20:0:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:120:48000:20:0:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2022-01-20 08:57:16.505864 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:16.505864 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1006@3.19.242.172:5070 opus/48000 20 ms 960 samples 0 bits 1 channels
2022-01-20 08:57:16.505864 [DEBUG] switch_core_codec.c:111 sofia/internal/1006@3.19.242.172:5070 Original read codec set to opus:116
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:5911 sofia/internal/1006@3.19.242.172:5070 Set 2833 dtmf send payload to 101 recv payload to 101
2022-01-20 08:57:16.505864 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1006@3.19.242.172:5070] 172.31.33.159 port 36142 -> 192.168.0.101 port 53738 codec: 120 ms: 20
2022-01-20 08:57:16.505864 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 960 bytes per 20ms
2022-01-20 08:57:16.525855 [DEBUG] switch_core_media.c:8977 sofia/internal/1006@3.19.242.172:5070 Set 2833 dtmf send payload to 101
2022-01-20 08:57:16.525855 [DEBUG] switch_core_media.c:8984 sofia/internal/1006@3.19.242.172:5070 Set 2833 dtmf receive payload to 101
2022-01-20 08:57:16.525855 [DEBUG] switch_core_media.c:9007 sofia/internal/1006@3.19.242.172:5070 Set rtp dtmf delay to 40
2022-01-20 08:57:16.525855 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1006@3.19.242.172:5070!
2022-01-20 08:57:16.525855 [DEBUG] switch_channel.c:3565 (sofia/internal/1006@3.19.242.172:5070) Callstate Change RINGING -> EARLY
2022-01-20 08:57:16.525855 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1006@3.19.242.172:5070.
2022-01-20 08:57:16.525855 [DEBUG] mod_sofia.c:2593 Ring SDP:
v=0
o=FreeSWITCH 1642632894 1642632895 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 36142 RTP/AVP 120 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:57:16.525855 [DEBUG] switch_ivr_originate.c:1333 Raw Codec Activation Success L16@48000hz 1 channel 20ms
2022-01-20 08:57:16.525855 [DEBUG] switch_core_codec.c:223 sofia/internal/1006@3.19.242.172:5070 Push codec L16:100
2022-01-20 08:57:16.525855 [DEBUG] switch_ivr_originate.c:1407 Play Ringback Tone [%(2000,4000,440,480)]
2022-01-20 08:57:16.545862 [DEBUG] sofia.c:7326 Channel sofia/internal/1006@3.19.242.172:5070 entering state [early][183]
2022-01-20 08:57:17.146063 [INFO] switch_rtp.c:7719 Auto Changing audio port from 192.168.0.101:53738 to 49.206.45.27:46153
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:57:19.905865 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:24.985873 [DEBUG] sofia.c:7326 Channel sofia/internal/1005@49.206.45.27:46318 entering state [completing][200]
2022-01-20 08:57:24.985873 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=- 2699241826 3 IN IP4 192.168.0.101
s=Bria release 6.5.1 stamp 108815
c=IN IP4 192.168.0.101
t=0 0
m=audio 51348 RTP/AVP 102 9 0 8 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2022-01-20 08:57:24.985873 [DEBUG] sofia.c:7326 Channel sofia/internal/1005@49.206.45.27:46318 entering state [ready][200]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:2]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:2]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2022-01-20 08:57:24.985873 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:24.985873 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1005@49.206.45.27:46318 opus/48000 20 ms 960 samples 0 bits 1 channels
2022-01-20 08:57:24.985873 [DEBUG] switch_core_codec.c:111 sofia/internal/1005@49.206.45.27:46318 Original read codec set to opus:116
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:5911 sofia/internal/1005@49.206.45.27:46318 Set 2833 dtmf send payload to 101 recv payload to 101
2022-01-20 08:57:24.985873 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/1005@49.206.45.27:46318] 172.31.33.159 port 36862 -> 192.168.0.101 port 51348 codec: 102 ms: 20
2022-01-20 08:57:24.985873 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 960 bytes per 20ms
2022-01-20 08:57:25.006474 [DEBUG] switch_core_media.c:8977 sofia/internal/1005@49.206.45.27:46318 Set 2833 dtmf send payload to 101
2022-01-20 08:57:25.006474 [DEBUG] switch_core_media.c:8984 sofia/internal/1005@49.206.45.27:46318 Set 2833 dtmf receive payload to 101
2022-01-20 08:57:25.006474 [DEBUG] switch_core_media.c:9007 sofia/internal/1005@49.206.45.27:46318 Set rtp dtmf delay to 40
2022-01-20 08:57:25.006474 [NOTICE] sofia.c:8504 Channel [sofia/internal/1005@49.206.45.27:46318] has been answered
2022-01-20 08:57:25.006474 [DEBUG] switch_channel.c:3865 (sofia/internal/1005@49.206.45.27:46318) Callstate Change RINGING -> ACTIVE
2022-01-20 08:57:25.025858 [DEBUG] switch_core_codec.c:248 sofia/internal/1006@3.19.242.172:5070 Restore previous codec opus:116.
2022-01-20 08:57:25.025858 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/1006@3.19.242.172:5070.
2022-01-20 08:57:25.025858 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1006@3.19.242.172:5070:
v=0
o=FreeSWITCH 1642632894 1642632896 IN IP4 3.19.242.172
s=FreeSWITCH
c=IN IP4 3.19.242.172
t=0 0
m=audio 36142 RTP/AVP 120 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2022-01-20 08:57:25.025858 [NOTICE] switch_ivr_originate.c:3794 Channel [sofia/internal/1006@3.19.242.172:5070] has been answered
2022-01-20 08:57:25.025858 [DEBUG] switch_channel.c:3865 (sofia/internal/1006@3.19.242.172:5070) Callstate Change EARLY -> ACTIVE
2022-01-20 08:57:25.025858 [DEBUG] sofia.c:7326 Channel sofia/internal/1006@3.19.242.172:5070 entering state [completed][200]
2022-01-20 08:57:25.025858 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/1005@49.206.45.27:46318]
2022-01-20 08:57:25.025858 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/internal/1005@49.206.45.27:46318]
2022-01-20 08:57:25.025858 [DEBUG] switch_ivr_bridge.c:1793 (sofia/internal/1005@49.206.45.27:46318) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2022-01-20 08:57:25.025858 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1005@49.206.45.27:46318) Running State Change CS_EXCHANGE_MEDIA (Cur 4 Tot 32)
2022-01-20 08:57:25.025858 [DEBUG] switch_core_state_machine.c:654 (sofia/internal/1005@49.206.45.27:46318) State EXCHANGE_MEDIA
2022-01-20 08:57:25.025858 [DEBUG] mod_sofia.c:656 SOFIA EXCHANGE_MEDIA
2022-01-20 08:57:25.025858 [INFO] switch_cpp.cpp:1447 1d1a7adb-5afb-4536-85c2-0661adffef1a RAJEEVLUA running uuid:
2022-01-20 08:57:25.025858 [INFO] switch_cpp.cpp:1447 uuid_audio_fork 1d1a7adb-5afb-4536-85c2-0661adffef1a start http://3.19.242.172:3001 mixed 32000
2022-01-20 08:57:25.025858 [DEBUG] mod_audio_fork.c:167 mod_audio_fork cmd: 1d1a7adb-5afb-4536-85c2-0661adffef1a start http://3.19.242.172:3001 mixed 32000
2022-01-20 08:57:25.025858 [DEBUG] lws_glue.cpp:361 parse_ws_uri - host 3.19.242.172, path /
2022-01-20 08:57:25.025858 [INFO] mod_audio_fork.c:73 mod_audio_fork: streaming 32000 sampling to 3.19.242.172 path / port 3001 tls: no.
2022-01-20 08:57:25.025858 [DEBUG] mod_audio_fork.c:89 calling fork_session_init.
2022-01-20 08:57:25.025858 [DEBUG] lws_glue.cpp:249 (13) resampling from 48000 to 32000
2022-01-20 08:57:25.025858 [DEBUG] lws_glue.cpp:260 (13) fork_data_init
2022-01-20 08:57:25.025858 [NOTICE] lws_glue.cpp:287 1d1a7adb-5afb-4536-85c2-0661adffef1a after adding connect there are 1 pending connects

2022-01-20 08:57:25.025858 [DEBUG] mod_audio_fork.c:95 adding bug.
2022-01-20 08:57:25.025858 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/1006@3.19.242.172:5070
2022-01-20 08:57:25.025858 [NOTICE] lws_glue.cpp:287 1d1a7adb-5afb-4536-85c2-0661adffef1a attempting connection, wsi is 0x7fbd600546f0

2022-01-20 08:57:25.025858 [DEBUG] mod_audio_fork.c:99 setting bug private data.
2022-01-20 08:57:25.025858 [DEBUG] mod_audio_fork.c:102 exiting start_capture.
2022-01-20 08:57:25.025858 [INFO] lws_glue.cpp:166 connection successful
2022-01-20 08:57:25.045856 [DEBUG] switch_rtp.c:7759 Correct audio ip/port confirmed.
2022-01-20 08:57:25.045856 [DEBUG] switch_core_io.c:448 Setting BUG Codec opus:116
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[425] Bytes encoded[33284] Encoded length ms[8500] Average encoded bitrate bps[33284]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[401] PLC[0] FEC[0]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:57:25.045856 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:25.225854 [INFO] switch_rtp.c:7719 Auto Changing audio port from 192.168.0.101:51348 to 49.206.45.27:46158
2022-01-20 08:57:25.345857 [DEBUG] sofia.c:7326 Channel sofia/internal/1006@3.19.242.172:5070 entering state [ready][200]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2022-01-20 08:57:26.225853 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]
davehorton commented 2 years ago

are you trying to create two websocket connections on the same call? Or are these two different calls?

vskg9 commented 2 years ago

I am trying to connect to have two different calls and writing the forked content to different files.

Here is the code

const WebSocket = require('ws');
const fs = require('fs');
const argv = require('minimist')(process.argv.slice(2));
const recordingPath = argv._.length ? argv._[0]  : '/tmp/';
const port = argv.port && parseInt(argv.port) ? parseInt(argv.port) : 3001
let wstream;

console.log(`listening on port ${port}, writing incoming raw audio to folder ${recordingPath}`);

const wss = new WebSocket.Server({
    port,
    handleProtocols: (protocols, req) => {
        return 'audiostream.drachtio.org';
    }
});
let conn = 1;
wss.on('connection', (ws, req) => {
    console.log(`received connection from ${req.connection.remoteAddress}`);
    const recordingPath = argv._.length ? argv._[0] : '/tmp/audio'+ Math.round((new Date()).getTime() / 1000) +'.raw';
    console.log(`writing to path ${recordingPath} for connection ${conn}`);
    wstream = fs.createWriteStream(recordingPath);

    ws.on('message', (message) => {
        if (typeof message === 'string') {            
        } else if (message instanceof Buffer) {
            wstream.write(message);
        }
    });
    conn++;

    ws.on('close', (code, reason) => {
        console.log(`socket closed ${code}:${reason}`);
        wstream.end();
    });
});
davehorton commented 2 years ago

could you please confirm via wireshark trace whether or not two audio streams are being sent to your server?

vskg9 commented 2 years ago

@davehorton Yes, verified on wireshark already and noticed that the first client is sending the stream to server even after the second call is made . But on the server log, I am not seeing the message received by the websocket for the first call after the second call forking is started.

davehorton commented 2 years ago

ok so it would seem the issue is on your websocket server code then.