Must not force verto relogin repeatedly for Chrome98

[David-dp-]

Starting in Chrome98 Beta (98.0.4758.54 (Official Build) beta (64-bit)), a verto login -- which uses the browser-native WebSocket constructor -- initially succeeds but then is repeatedly forced by commands from FS 1.10.7 to relogin.

Using DevTools / Network / WS reveals that after login, many non-control frames of length 1028 (displayed as #SPB) are sent to FS. Then verto sends a non-control frame of length 4 (displayed as #SPE) and that is shortly followed by a non-control frame like

{jsonrpc: "2.0", id: 7, method: "verto.clientReady", params: {reattached_sessions: []}}
id: 7
jsonrpc: "2.0"
method: "verto.clientReady"
params: {reattached_sessions: []}

and that is the last frame of the connection; it seems to force verto to relogin because DevTools shows a new connection and a login frame is one of the first to appear.

This was happening with a ws.c from this repo committed around Sept 21, 2021 to fix an iOS 15 issue. We found that you replaced that with libks, so we pulled the head of https://github.com/signalwire/freeswitch ‘s master branch onto Debian 10 and built it, then copied its mod_verto.so to our 1.10.7-release-19-883d2cb662~64bit server and then did ‘reload mod_verto’ in fs_cli. That resulted in repeated error logging like...

2022-01-13 19:24:57.826514 98.37% [INFO] mod_verto.c:606 WRITE 67.174.x.y:60384 [{"jsonrpc":"2.0","id":3,"result":{"message":"logged in","sessid":"6d59bad2-e365-40e1-8ae1-0cfa89fd4f5d"}}]
2022-01-13 19:25:08.146606 97.87% [ERR] kws.c:1156 Read frame error because kws_string_read returned -1

2022-01-13 19:25:08.146606 97.87% [WARNING] mod_verto.c:2032 67.174.172.111:60384 POLL ERROR

Then we tried changing the die at https://github.com/signalwire/freeswitch/blob/f9bb8940c29f55c89fa1e0697e8e614b355bfff2/src/mod/endpoints/mod_verto/mod_verto.c#L2032 to merely a warning, but that resulted in an infinite iteration of the POLL ERROR at the same msec log time.

So now it appears that the assigning of state KS_SOCK_INVALID in https://github.com/signalwire/libks/blob/10b3445c92f17be3908a6c0e5597c0fe997ad637/src/ks_socket.c may be incorrect for these #SPE frames that seem to occur only in Chrome 98 Beta and not Chrome97 nor Firefox.

[David-dp-]

However, the problem might occur after the clientReady message, because we see this pattern in the FS log:

2022-01-14 02:12:24.902634 98.83% [WARNING] mod_verto.c:1072 Login sucessful for user: 1000 domain: 10.0.0.22
2022-01-14 02:12:24.902634 98.83% [DEBUG] mod_verto.c:1155 auth using username & password
2022-01-14 02:12:24.902634 98.83% [INFO] mod_verto.c:606 WRITE 151.210.x.y:51613 [{"jsonrpc":"2.0","id":7,"result":{"message":"logged in","sessid":"0da46e2b-e11b-43d0-9e33-3ad9e96a5828"}}]
2022-01-14 02:12:25.002635 98.83% [INFO] mod_verto.c:606 WRITE 151.210.x.y:51613 [{"jsonrpc":"2.0","id":40,"method":"verto.clientReady","params":{"reattached_sessions":[]}}]
2022-01-14 02:12:29.462631 98.80% [INFO] mod_verto.c:606 WRITE 103.152.c.d:20568 [{"jsonrpc":"2.0","id":41,"method":"verto.ping","params":{"serno":1642126349}}]
2022-01-14 02:12:35.706997 99.00% [ERR] kws.c:1156 Read frame error because kws_string_read returned -1

2022-01-14 02:12:35.706997 99.00% [WARNING] mod_verto.c:2032 151.210.x.y:51613 POLL ERROR
2022-01-14 02:12:35.706997 99.00% [DEBUG] mod_verto.c:2181 151.210.x.y:51613 Ending client thread.
2022-01-14 02:12:35.706997 99.00% [DEBUG] mod_verto.c:2189 151.210.x.y:51613 Thread ended
2022-01-14 02:12:37.082639 98.97% [DEBUG] mod_verto.c:4712 151.210.x.y:51680 Client Connect from 151.210.a.b:51680 accepted

FWIW, the logging while using ws.c was similar:

2022-01-12 02:33:29.525407 98.60% [DEBUG] mod_verto.c:607 WRITE 151.210.x.y:4790 [{
        "jsonrpc":      "2.0",
        "id":   3,
        "result":       {
                "message":      "logged in",
                "sessid":       "97524066-1470-4aca-b143-a04c4eaceed9"
        }
}]
2022-01-12 02:33:29.565399 98.60% [DEBUG] mod_verto.c:607 WRITE 151.210.x.y:4790 [{
        "jsonrpc":      "2.0",
        "id":   501,
        "method":       "verto.clientReady",
        "params":       {
                "reattached_sessions":  []
        }
}]
2022-01-12 02:33:40.565395 98.83% [WARNING] mod_verto.c:1904 151.210.x.y:4790 BAD READ -1
2022-01-12 02:33:40.565395 98.83% [DEBUG] mod_verto.c:2045 151.210.x.y:4790 Ending client thread.
2022-01-12 02:33:40.565395 98.83% [DEBUG] mod_verto.c:2053 151.210.x.y:4790 Thread ended
2022-01-12 02:33:41.785412 98.87% [DEBUG] mod_verto.c:4273 151.210.x.y:33838 Client Connect from 151.210.x.y:33838 accepted
2022-01-12 02:33:41.785412 98.87% [DEBUG] mod_verto.c:2018 151.210.x.y:33838 Starting client thread.
2022-01-12 02:33:44.045410 98.90% [DEBUG] mod_verto.c:1414 READ 151.210.x.y:33838 [{
        "jsonrpc":      "2.0",
        "method":       "login",
        "params":       {
                "sessid":       "97524066-1470-4aca-b143-a04c4eaceed9"
        },
        "id":   4
}]

[David-dp-]

I just noticed that the verto.ping that appears in the FS log never appears in DevTools / Network / WS in any of the (re-)connections. And if it did arrive at the verto client, the most recent edit to handle that seems unlikely to work because it returns json from handleMessage but no caller of handleMessage is expecting a return value and they won't trigger anything like sendMessage('verto.pong', {}). Perhaps the absence of a response to verto.ping is causing the connection to be considered broken.
Once the mystery of why verto.ping is being logged as sent but is not arriving is answered, I can offer a PR for the clientside issue.

[David-dp-]

I diff'd https://github.com/freeswitch/verto-client/tree/master/js/src with our version and there were no major differences; however, I noticed that the #SPx messages are handled by jquery.jsonrpcclient.js and that it has no case to handle #SPE. Because our connections are being forced to relogin after #SPE appears, I tried disabling our use of the speed test, and the repeated relogin problem no longer appeared.

Perhaps your use of libks expects a response for #SPE, doesn't get one, and assumes the connection needs to be re-established.

[edolix]

Hi @David-dp- , to recap: this problem seems not related to freeswitch/verto-client@54feff1 but instead to the "speed test" that sends #SPx messages.
Correct?

[David-dp-]

Hi Edoardo, It's true that disabling the speed test makes the repeated relogins stop. But once that is fixed, I suspect there will still be a problem due to the verto client not responding to verto.ping. But I'm not certain.

…

On Fri, 14 Jan 2022, 9:32 pm Edoardo Gallo, ***@***.***> wrote: Hi @David-dp- <https://github.com/David-dp-> , to recap: this problem seems not related to ***@***.*** <freeswitch/verto-client@54feff1> but instead to the "speed test" that sends #SPx messages. Correct? — Reply to this email directly, view it on GitHub <#121 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA5RKQ4SJTDGUZZKUFBQA4TUV7NTNANCNFSM5L5MXTFQ> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were mentioned.Message ID: ***@***.***>