sip.js websocket terminated by Freeswitch

[murmillo13]

trafficstars

Hi everyone,

we are currently running a custom-build phone application using sip.js which registers to the websocket of our Freeswitch. Our Freeswitch uses version 1.10.3 64 bit on a Debian buster.

We started to notice the following: In a set out of ~4000 successful calls we have about 80 calls where during call initiation the websocket is closed by the freeswitch. Which forces the sip.js library to re-register to the websocket. After this occurence there is somehow still rtp coming from the phone application but not from the freeswitch to the phone application. The call is timed-out after 30seconds.

The sip.js library logs the following to chrome console: Fri Jan 22 2021 16:34:57 GMT+0100 (Mitteleuropäische Normalzeit) | sip.transport | WebSocket closed without SIP.js requesting it

I increased the loglevel to 9 in console and managed to capture this:

tport.c:2784 tport_wakeup() tport_wakeup(0x7fdc9439e440): events IN tport.c:2882 tport_recv_event() tport_recv_event(0x7fdc9439e440) tport.c:2165 tport_shutdown0() tport_shutdown0(0x7fdc9439e440, 2) tport.c:2098 tport_close() tport_close(0x7fdc9439e440): wss/10.128.130.129:56027/sips nua_registrar.c:203 registrar_tport_error() tport error 0: Success tport.c:4240 tport_release() tport_release(0x7fdc9439e440): (nil) by 0x7fdc941e0f90 with (nil) nua_stack.c:271 nua_stack_event() nua(0x7fdc941e0f90): event i_media_error 500 Transport error detected tport.c:4240 tport_release() tport_release(0x7fdc9439e440): 0x7fdc94148b40 by 0x7fdc94060310 with (nil) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2792 tport_wakeup() tport_wakeup(0x7fdc9439e440): tport is closed! Setting secondary timer!

Anybody else ran into this issue and might know what causes it?

Kind Regards,

[pcastrejon]

Hi, same issue for me, running FS 1.10.5-release-17-25569c1631~64bit on Debian buster.

Im connecting through secure websocket on port 7443, client is also an Angular + SIPJS, using letsecncrypt certs and FS is connected to Twilio account to handle both incoming and outgoing calls.

The issue seems to be random but when it happens, it is always when I click the 'Answer' button and in that moment, the websocket is closed.

Prior to the Agent registration, I have the websocket connected at transport level and a ping every 3 seconds as a keepalive for the connection (I have also tried 20 seconds to avoid too much traffic in short periods of time)

Before answering, I have to register my agent so I send the REGISTER command from the webapp and this works just fine, FS is challenging for the auth and finally reigstration is done OK.

For more info, Im running FS in an azure subscription (all IPs and ports are supposedly whitelisted as required) but my clients are connected trhough a VPN, when the call is correctly connected, Im have voice on both sides and Im able to correctly hang up the call so Im discariding a problem with certs because that has to be binary, it works or not.

So any thought or idea on what can be wrong is welcome, Im also getting the "i_media_error 500 Transport error detected" message in the FS logs:

nua_stack.c:271 nua_stack_event() nua(0x7fc960000ca0): event i_state 180 Ringing
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
tport.c:2311 tport_set_secondary_timer() tport(0x7fc9400d8860): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:370 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:370 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:370 nua_handle_magic() nua: nua_handle_magic: entering
2021-02-15 19:19:36.322059 [DEBUG] sofia.c:7326 Channel sofia/internal/[email protected] entering state [proceeding][180]
2021-02-15 19:19:36.322059 [NOTICE] sofia.c:7437 Ring-Ready sofia/internal/[email protected]!
2021-02-15 19:19:36.322059 [DEBUG] switch_channel.c:3437 (sofia/internal/[email protected]) Callstate Change DOWN -> RINGING
nua.c:370 nua_handle_magic() nua: nua_handle_magic: entering
nta.c:1300 agent_timer() nta: timer set next to 3307 ms
tport.c:2795 tport_wakeup() tport_wakeup(0x7fc9400d8860): events IN
tport.c:2893 tport_recv_event() tport_recv_event(0x7fc9400d8860)
tport.c:3234 tport_recv_iovec() tport_recv_iovec(0x7fc9400d8860) msg 0x7fc9400cc0a0 from (wss/10.201.248.5:56356) has 4 bytes, veclen = 1
tport.c:3052 tport_deliver() tport_deliver(0x7fc9400d8860): bad msg 0x7fc9400cc0a0 (0 bytes) from wss/10.201.248.5:56356/sips next=(nil)
tport.c:2311 tport_set_secondary_timer() tport(0x7fc9400d8860): reset timer
tport.c:2795 tport_wakeup() tport_wakeup(0x7fc9400d8860): events IN
tport.c:2893 tport_recv_event() tport_recv_event(0x7fc9400d8860)
tport.c:2165 tport_shutdown0() tport_shutdown0(0x7fc9400d8860, 2)
tport.c:2098 tport_close() tport_close(0x7fc9400d8860): wss/10.201.248.5:56356/sips
tport.c:4251 tport_release() tport_release(0x7fc9400d8860): 0x7fc9400c4420 by 0x7fc9400c79c0 with (nil)
nua_registrar.c:203 registrar_tport_error() tport error 0: Success
tport.c:4251 tport_release() tport_release(0x7fc9400d8860): (nil) by 0x7fc9400cf780 with (nil)
nua_stack.c:271 nua_stack_event() nua(0x7fc9400cf780): event i_media_error 500 Transport error detected
tport.c:4251 tport_release() tport_release(0x7fc9400d8860): 0x7fc9407ec4f0 by 0x7fc9400a3360 with (nil)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
tport.c:2803 tport_wakeup() tport_wakeup(0x7fc9400d8860): tport is closed! Setting secondary timer!

Thanks in advance

[tornad]

Have similar issue. Resulting in websocket disconnected (1006). Any news or clue for this ?

[murmillo13]

We implemented a workaround by moving the websocket to a proxy which terminates it for us and forwards the sip messages to the freeswitch. We could not find the root cause of it. Since we have the proxy in place the calls are no longer terminated.

Hope this is atleast a little helpful.

[tornad]

We implemented a workaround by moving the websocket to a proxy which terminates it for us and forwards the sip messages to the freeswitch. We could not find the root cause of it. Since we have the proxy in place the calls are no longer terminated.

Hope this is atleast a little helpful.

Thanks for this return. I quickly tried a similar solution but failed to implement quickly the proxy and make it works.

• Can you tell me which proxy have you use for this ?

thx

[tornad]

@Gumunryong Can you confirm me the proxy you use for websocket ?

[diminou91]

Hi, I have a similar issue as well. I did try out https://www.nginx.com/blog/websocket-nginx/ as a proxy, mentionned by Gumunryong but with no success. @Gumunryong did you use nginx to mitigate the isssue ? Or something else ? Thanks in advance! :)

[martyrs]

Hello, Same issue here.

nua_stack.c:529 nua_signal() nua(0x7f566401c620): sent signal r_handle_unref
nua.c:1181 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:529 nua_signal() nua((nil)): sent signal r_unref
tport.c:2165 tport_shutdown0() tport_shutdown0(0x7f56640680c0, 2)
tport.c:2098 tport_close() tport_close(0x7f56640680c0): wss/176.91.193.107:33888/sips
nua_registrar.c:203 registrar_tport_error() tport error 0: Success
tport.c:4251 tport_release() tport_release(0x7f56640680c0): (nil) by 0x7f5664052a50 with (nil)
nua_stack.c:271 nua_stack_event() nua(0x7f5664052a50): event i_media_error 500 Transport error detected
nua_registrar.c:203 registrar_tport_error() tport error 0: Success
tport.c:4251 tport_release() tport_release(0x7f56640680c0): (nil) by 0x7f566401c620 with (nil)
nua_stack.c:271 nua_stack_event() nua(0x7f566401c620): event i_media_error 500 Transport error detected

[murmillo13]

We put a kamailio infront of the freeswitch as proxy. It terminates the websocket on the kamailio and passes through the registration as a regular sip request to the freeswitch. This came as the ideal choice since it can do websocket and speaks SIP at the same time. You can probably do it with any proxy that is capable of editing header fields.
Since implementation we had no more issues.

[szdefine]

we have the same problem here too. freeswitch is :1.10.5-release.8~64bit and jssip is :3.7 how can this bug can be fixed? thanks!

[MichleOrange]

in my opnion, openssl library caused this.

[tornad]

in my opnion, openssl library caused this.

Yes I agree. When I tried to identify the cause, my test lets me think the problem occurs at the SSL level, not SIP protocol. the socket is closed from the freeswitch side, but why...

But for me, the bug was introduce between FS 1.10.2 and 1.10.5

We have the bug on different hosts, no problem on FS 1.10.2, only on FS with 1.10.5 or 1.10.6 So we are locked on 1.10.2 for our sipjs/websocket customers. I also could bet the problem is present on normal SIP SSL TCP connection (no websocket); but SIP SSL TCP is less used so not occurs enough to be catch.

On my FS 1.10.2 (no problem) FreeSWITCH (Version 1.10.2 -release-14-f7bdd3845a 64bit) is ready libssl.so.1.1 => /lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007f58d3995000) OpenSSL 1.1.1d 10 Sep 2019

On FS with problem libssl.so.1.1 => /lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007fbf95b66000) OpenSSL 1.1.1d 10 Sep 2019 FreeSWITCH (Version 1.10.5 -release-17-25569c1631 64bit) is ready libssl.so.1.1 => /usr/lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007fe18ecd8000) OpenSSL 1.1.1d 10 Sep 2019 FreeSWITCH (Version 1.10.5 -release-17-25569c1631 64bit) is ready libssl.so.1.1 => /usr/lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007f27116c1000) OpenSSL 1.1.1d 10 Sep 2019 FreeSWITCH (Version 1.10.6 -release-18-1ff9d0a60e 64bit) is ready libssl.so.1.1 => /lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007f7708059000)

[Soulsuke]

Thank you both @Gumunryong and @tornad . A client suddenly asked us to develop a software which needed to connect via websocket to their freeswitch 1.10.6 instance, and we couldn't figure out why we started getting all those 1006 errors.

Sadly, the client opted to downgrade to 1.10.2 (from 1.10.6) instead of putting up a websocket proxy...

I wonder if this bug has already been acknowledged though.

[szdefine]

Thank you both @Gumunryong and @tornad too. we had to downgrade from 1.10.5 to 1.10.2 for using jssip clients. hope this bug will be fixed soon .

[cash168]

Hello. I have this same problem.

The problem only occurs when using Opera browser. I was unable to catch the websocket disconnect in Chromium and Firefox. Same disconnects occur when using sipml5 as client in Opera browser.

FreeSWITCH version 1.10.2 + sip.js version 0.19.0 or 0.20.0 = NO problem FreeSWITCH version1.10.5 + sip.js version 0.19.0 or 0.20.0 = problem FreeSWITCH version1.10.6 + sip.js version 0.19.0 or 0.20.0 = problem

proxying a wss connection through Nginx or direct connection to freeSWITCH does not matter - from time to time the wss connection breaks.

Browsers sip.js log:

sip-0.20.0.js:9440 Tue Oct 19 2021 19:04:53 GMT+0300 (Moscow Standard Time) | sip.Transport | WebSocket closed unexpectedly
print @ sip-0.20.0.js:9440
genericLog @ sip-0.20.0.js:9416
genericLog @ sip-0.20.0.js:9511
warn @ sip-0.20.0.js:9502
onWebSocketClose @ sip-0.20.0.js:10809
(anonymous) @ sip-0.20.0.js:10669
sip-0.20.0.js:9444 Tue Oct 19 2021 19:04:53 GMT+0300 (Moscow Standard Time) | sip.Transport | WebSocket closed wss://my_domain.com:443/wss (code: 1006)
sip-0.20.0.js:9444 Tue Oct 19 2021 19:04:54 GMT+0300 (Moscow Standard Time) | sip.Transport | Transitioned from Connected to Disconnected
main.js?v=0.2:388 Network connectivity lost: Error: WebSocket closed wss://my_domain.com:443/wss (code: 1006)

freeSWITCH log:

tport.c:3052 tport_deliver() tport_deliver(0x7f12f01719b0): msg 0x7f12f0297540 (362 bytes) from wss/10.0.77.36:50718/sips next=(nil)
nta.c:3314 agent_recv_response() nta: received 200 OK for BYE (42773841)
nta.c:3381 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9628 outgoing_estimate_delay() nta_outgoing: RTT is 41.693 ms
tport.c:4251 tport_release() tport_release(0x7f12f01719b0): 0x7f12f0291770 by 0x7f12f01dd8c0 with 0x7f12f0297540
nua_session.c:4140 signal_call_state_change() nua(0x7f12f0292540): call state changed: terminating -> terminated
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f12f0292540): removing session usage
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f12f0292540
nua_stack.c:529 nua_signal() nua(0x7f12f0292540): sent signal r_destroy
nta.c:9165 outgoing_timer_dk() nta: timer D fired, terminate INVITE (42773825)
nta.c:8984 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/6 tout, 1/6 term, 1/12 free
nta.c:9046 outgoing_timer_bf() nta: timer F fired, terminating ACK (42773825)
tport.c:2273 tport_set_secondary_timer() tport(0x7f12f023cca0): set timer at 0 ms because zap
nta.c:8984 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/6 tout, 0/5 term, 1/11 free
tport_type_ws.c:531 tport_ws_deinit_secondary() 0x7f12f023cca0 destroy wss transport 0x7f12f023ce90.

• disconnection can occur not only for incoming calls - I could not find a pattern.
• disconnect initiated by the client side (not freeSWITCH) - tcp [FIN, ACK] is sent when the browser closes the tcp socket (wss connection)

[2954456878]

I have the same problem，Is there a solution？

[lonelyxmas]

I have the same problem，Is there a solution？

[jalsot]

I wonder if it is related to this one: https://github.com/freeswitch/sofia-sip/pull/132 Maybe somebody could try out?

[cash168]

installed version - libsofia-sip-ua0/now 1.13.6-71~7d7568a95a~buster amd64 latest version - libsofia-sip-ua0/stable,now 1.13.8-80~756ab9b5c9~buster amd64 is it enough to update this package (from 1.13.6 to 1.13.8) and restart freeswitch to check?

[jalsot]

The patch in the given PR has not been merged and not released in 1.13.8, so the only way to try out is to apply the patch to sofia-sip git master and recompile it. After that FS restart is needed (maybe reloading mod_sofia module is enough, but not sure).

[cash168]

I compiled libsofia-sip-ua.so.0.6.0 with a fix. the problem with (code: 1006) is still there.

[jalsot]

Have you tried 1.10.7 FS version? Is it possible to reproduce the issues? (we have similar issues but cannot reproduce at will and happens very rarely)

[balazsradak]

We put a kamailio infront of the freeswitch as proxy. It terminates the websocket on the kamailio and passes through the registration as a regular sip request to the freeswitch. This came as the ideal choice since it can do websocket and speaks SIP at the same time. You can probably do it with any proxy that is capable of editing header fields. Since implementation we had no more issues.

HI Gumuryong, I'm having the same issue and trying to figure out how to use kamailio the way you mention. I managed to get work kamailio with the websocket module, but my problem is that kamailio is also act as a registar server, which is not good for me, since freeswitch should be the registart because I need to use the FS call_center module. If you could share me some kamailo.cfg it would be very helpful!

Thanks!

[jalsot]

As far as I understood from the original report and from the additional comments that the issue might be between v1.10.2 and v1.10.3 (last good version and first appearance). Is here anybody who could consistently reproduce (the best would be at will) the issue and collect more details for debugging?

@Gumunryong possibly could you share your Kamailio config as a workaround please?

[Grandmeo]

Hello, we have the same issue, using Freeswitch 1.10.6 and sip.js version 0.16.1. It seems to be linked with network charge, perhaps when the SIP/WSS packets are segmented. Often on the SIP: 200 OK from the callee which is a big packet, if this packet comes in 2 assembled TCP segments this issue sometimes occurs (not in 100% case).

I add two pcap traces with sip on a-leg and wss (tcp:7443) on WebRTC leg, both have the wss closed at end of trace. WebSocketClose20220831-3.zip WebSocketClose20220831-2.zip

Perhaps we should choose the Nginx or Kamailio for proxying wss...

Best regards. Grandméo.

[jerry6021]

Has there been progress on this issue?

still have it with the latest version.

[jerry6021]

we are using: debian 10 FS 1.10.6 libsofia-sip-au 1.13.8 Lets Encrypt WSS

[jerry6021]

we get the 1006 error very randomly... After 3 weeks of trying to get WSS working, there is no noticeable pattern to the failures...

[jerry6021]

For anyone that wants to follow:

https://github.com/freeswitch/sofia-sip/issues/172

[andywolk]

Fixed by https://github.com/freeswitch/sofia-sip/pull/175

[ttaoyuan]

good news！