search

drachtio / drachtio-freeswitch-modules

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

audio fork websocket not closing #117

Closed spointer closed 1 year ago

spointer commented 1 year ago

Hello Dave,

It seems audio forking websocket is not closed when endpoint is destroyed after updated to 0.7.0 and updated drachtio-fsmrf to 3.0.23

davehorton commented 1 year ago

can you share logs?

davehorton commented 1 year ago

please turn freeswitch logs to debug and do a simple test of opening a websocket and then hanging up the call (which should close it)

spointer commented 1 year ago

Here is the log.

fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] switch_ivr_async.c:1347 Record session sample rate: 8000 -> 8000
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/drachtio_mrf/nobody@172.31.13.176:5060
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] sofia.c:7290 Channel sofia/drachtio_mrf/nobody@172.31.13.176:5060 entering state [ready][200]
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] switch_channel.c:3865 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Callstate Change EARLY -> ACTIVE
fac19e10-039c-11ee-9b7f-8d209c14e8b6 EXECUTE [depth=0] sofia/drachtio_mrf/nobody@172.31.13.176:5060 sched_hangup(+3600 max_call_timeout)
2023-06-05 21:32:05.191318 [DEBUG] switch_scheduler.c:252 Added task 4 switch_ivr_schedule_hangup (fac19e10-039c-11ee-9b7f-8d209c14e8b6) to run at 1685971925
fac19e10-039c-11ee-9b7f-8d209c14e8b6 EXECUTE [depth=0] sofia/drachtio_mrf/nobody@172.31.13.176:5060 set(send_silence_when_idle=-1)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] mod_dptools.c:1672 SET sofia/drachtio_mrf/nobody@172.31.13.176:5060 [send_silence_when_idle]=[-1]
fac19e10-039c-11ee-9b7f-8d209c14e8b6 EXECUTE [depth=0] sofia/drachtio_mrf/nobody@172.31.13.176:5060 socket(192.168.131.254:3430 async full)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [NOTICE] mod_event_socket.c:447 Trying host: 192.168.131.254:3430
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] switch_ivr.c:1034 Codec Activated L16@8000hz 1 channels 20ms
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.191318 [DEBUG] switch_ivr_async.c:1636 No silence detection configured; assuming start of speech
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.271319 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.271319 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2023-06-05 21:32:05.291321 [DEBUG] mod_audio_fork.c:169 mod_audio_fork cmd: fac19e10-039c-11ee-9b7f-8d209c14e8b6 start http://127.0.0.1:3440/socket/inbound/e6115ffd-8a2f-487b-b599-7398d95c9085?callId=_pMT3TwVlQu592a mono 8000 '{"event":"start","data":{"startTime":"2023-06-05T12:32:05.168Z"}}'
2023-06-05 21:32:05.291321 [DEBUG] lws_glue.cpp:365 parse_ws_uri - host 127.0.0.1, path /socket/inbound/e6115ffd-8a2f-487b-b599-7398d95c9085?callId=_pMT3TwVlQu592a
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [INFO] mod_audio_fork.c:73 mod_audio_fork (audio_fork): streaming 8000 sampling to 127.0.0.1 path /socket/inbound/e6115ffd-8a2f-487b-b599-7398d95c9085?callId=_pMT3TwVlQu592a port 3440 tls: no.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] mod_audio_fork.c:89 calling fork_session_init.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] lws_glue.cpp:261 (2) no resampling needed for this call
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] lws_glue.cpp:264 (2) fork_data_init
2023-06-05 21:32:05.291321 [NOTICE] lws_glue.cpp:291 fac19e10-039c-11ee-9b7f-8d209c14e8b6 after adding connect there are 1 pending connects

fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] mod_audio_fork.c:95 adding bug.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/drachtio_mrf/nobody@172.31.13.176:5060
2023-06-05 21:32:05.291321 [NOTICE] lws_glue.cpp:291 fac19e10-039c-11ee-9b7f-8d209c14e8b6 attempting connection, wsi is 0x7f30b0003af0

fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] mod_audio_fork.c:99 setting bug private data.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] mod_audio_fork.c:102 exiting start_capture.
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [INFO] lws_glue.cpp:169 connection successful
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.291321 [DEBUG] lws_glue.cpp:172 sending initial metadata {"event":"start","data":{"startTime":"2023-06-05T12:32:05.168Z"}}
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.591319 [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@172.31.13.176:5060 Command Execute [depth=1] playback(http://127.0.0.1:3555/api/play/e6115ffd-8a2f-487b-b599-7398d95c9085/1606636921/1685968325477.wav)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 EXECUTE [depth=1] sofia/drachtio_mrf/nobody@172.31.13.176:5060 playback(http://127.0.0.1:3555/api/play/e6115ffd-8a2f-487b-b599-7398d95c9085/1606636921/1685968325477.wav)
2023-06-05 21:32:05.651319 [DEBUG] mod_httapi.c:2639 caching: url:http://127.0.0.1:3555/api/play/e6115ffd-8a2f-487b-b599-7398d95c9085/1606636921/1685968325477.wav to /usr/local/freeswitch/storage/http_file_cache/d061fbfad4e67a4c4569149b0dea6815.wav (97768 bytes)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:05.651319 [DEBUG] switch_ivr_play_say.c:1492 Codec Activated L16@8000hz 1 channels 20ms
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:11.751319 [DEBUG] switch_ivr_play_say.c:1933 done playing file http://127.0.0.1:3555/api/play/e6115ffd-8a2f-487b-b599-7398d95c9085/1606636921/1685968325477.wav

fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@172.31.13.176:5060 Command Execute [depth=1] hangup()
fac19e10-039c-11ee-9b7f-8d209c14e8b6 EXECUTE [depth=1] sofia/drachtio_mrf/nobody@172.31.13.176:5060 hangup()
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [NOTICE] mod_dptools.c:1380 Hangup sofia/drachtio_mrf/nobody@172.31.13.176:5060 [CS_EXECUTE] [NORMAL_CLEARING]
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_core_session.c:2905 sofia/drachtio_mrf/nobody@172.31.13.176:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_ivr.c:679 sofia/drachtio_mrf/nobody@172.31.13.176:5060 skip receive message [AUDIO_SYNC] (channel is hungup already)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_core_session.c:2905 sofia/drachtio_mrf/nobody@172.31.13.176:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_core_state_machine.c:651 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State EXECUTE going to sleep
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_core_state_machine.c:585 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Running State Change CS_HANGUP (Cur 1 Tot 2)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.091322 [DEBUG] switch_ivr_async.c:1441 Stop recording file /audio-storage/callstore/recordings/d21fb987-7e3f-123c-bf8c-2e043165bf37.wav
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_ivr_async.c:1516 Channel is hung up
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_media_bug.c:1289 Removing BUG from sofia/drachtio_mrf/nobody@172.31.13.176:5060
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [INFO] mod_audio_fork.c:38 Got SWITCH_ABC_TYPE_CLOSE for bug
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] lws_glue.cpp:428 fork_session_cleanup: no bug - websocket conection already closed
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_media_bug.c:1289 Removing BUG from sofia/drachtio_mrf/nobody@172.31.13.176:5060
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:848 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Callstate Change ACTIVE -> HANGUP
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:850 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State HANGUP
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] mod_sofia.c:460 Channel sofia/drachtio_mrf/nobody@172.31.13.176:5060 hanging up, cause: NORMAL_CLEARING
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] mod_sofia.c:514 Sending BYE to sofia/drachtio_mrf/nobody@172.31.13.176:5060
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:60 sofia/drachtio_mrf/nobody@172.31.13.176:5060 Standard HANGUP, cause: NORMAL_CLEARING
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:850 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State HANGUP going to sleep
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:620 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State Change CS_HANGUP -> CS_REPORTING
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:585 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Running State Change CS_REPORTING (Cur 1 Tot 2)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:936 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State REPORTING
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:174 sofia/drachtio_mrf/nobody@172.31.13.176:5060 Standard REPORTING, cause: NORMAL_CLEARING
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:936 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State REPORTING going to sleep
send 514 bytes to udp/[192.168.131.254]:5060 at 21:32:16.124769:
------------------------------------------------------------------------
BYE sip:172.31.13.176:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.131.254:3556;rport;branch=z9hG4bKB2mvB50j5QXvB
Max-Forwards: 70
From: <sip:drachtio@192.168.131.254:3556>;tag=BSHKXNQ75FgZF
To: <sip:172.31.13.176:5060>;tag=taaZX46tymj4g
Call-ID: d21fb987-7e3f-123c-bf8c-2e043165bf37
CSeq: 68430376 BYE
User-Agent: drachtio MRF
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: path, replaces
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0

fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:611 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State Change CS_REPORTING -> CS_DESTROY
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_session.c:1726 Session 2 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Locked, Waiting on external entities
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [NOTICE] switch_core_session.c:1744 Session 2 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Ended
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [NOTICE] switch_core_session.c:1748 Close Channel sofia/drachtio_mrf/nobody@172.31.13.176:5060 [CS_DESTROY]
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:739 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) Running State Change CS_DESTROY (Cur 0 Tot 2)
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:749 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State DESTROY
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] mod_sofia.c:365 sofia/drachtio_mrf/nobody@172.31.13.176:5060 SOFIA DESTROY
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:181 sofia/drachtio_mrf/nobody@172.31.13.176:5060 Standard DESTROY
fac19e10-039c-11ee-9b7f-8d209c14e8b6 2023-06-05 21:32:16.111322 [DEBUG] switch_core_state_machine.c:749 (sofia/drachtio_mrf/nobody@172.31.13.176:5060) State DESTROY going to sleep
recv 291 bytes from udp/[192.168.131.254]:5060 at 21:32:16.127085:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.131.254:3556;rport=3556;branch=z9hG4bKB2mvB50j5QXvB
From: <sip:drachtio@192.168.131.254:3556>;tag=BSHKXNQ75FgZF
To: <sip:172.31.13.176:5060>;tag=taaZX46tymj4g
Call-ID: d21fb987-7e3f-123c-bf8c-2e043165bf37
CSeq: 68430376 BYE
Content-Length: 0

2023-06-05 21:32:16.191472 [DEBUG] switch_scheduler.c:147 Deleting task 4 switch_ivr_schedule_hangup (fac19e10-039c-11ee-9b7f-8d209c14e8b6)
davehorton commented 1 year ago

Thanks I've checked in a fix. Could you do a quick test before I tag it?

eac4272 (HEAD -> main, origin/main, origin/HEAD) fix prev commit: mod_audio_fork websocket not closed
5560f30 (tag: 0.7.0) changes to allow multiple mod_audio_fork bugs on a session at the sam… (#115)
spointer commented 1 year ago

Sorry, i can test tomorrow and let you know.

Thanks.