Error reading frame header error on sendOneFrameText call

[rhard]

I have a strange error for one of the users which I cannot debug as I can't reproduce it locally. Basically, the WS connection started normally and can receive messages with no problem. However, when for the first time the message needs to be sent by calling sendOneFrameText, I have an immediate error in the listen() loop. Next you can find the log and the WS client implementation. Note the short time between sendOneFrameText call and the error, so there shouldn't be any response yet from the server.

Do you have an idea, what can it be? For most of the users, the code is working without any problem.

OATPP Version 1.3.0

[2022-05-20 17:32:22.570] [scp] [debug] websocket-client sending message 1...
[2022-05-20 17:32:22.570] [scp] [debug] websocket-client sending message 2...
[2022-05-20 17:32:22.570] [scp] [debug] websocket-client sending message 3...
[2022-05-20 17:32:22.572] [scp] [debug] [oatpp::web::protocol::websocket::WebSocket::listen()] Unhandled error occurred. Message='[oatpp::web::protocol::websocket::WebSocket::readFrameHeader()]: Error reading frame header'
[2022-05-20 17:32:22.572] [scp] [debug] websocket-client SOCKET CLOSED!!!

  auto wsConnection = connector->connect(signedUrl.c_str());
  ws = oatpp::websocket::WebSocket::createShared(wsConnection, true /* maskOutgoingMessages must be true for clients */);
  ws->setListener(std::make_shared<WSListener>(shared_from_this(), socketWriteMutex));

  m_wsPingTimer.enable();

  std::thread thread([&]() {
      ws->listen();
      m_wsPingTimer.disable();
      OATPP_LOGD(TAG, "SOCKET CLOSED!!!")
  });

  while (m_wsPingTimer.wait_for(std::chrono::minutes(WS_PING_TIMEOUT_MIN))) {
      OATPP_LOGD(TAG, "sending message 1...")
      std::lock_guard<std::mutex> lock(socketWriteMutex);
      auto ns = WSMessage::createShared();
      ns->action = "ping";
      auto jsonObjectMapper = oatpp::parser::json::mapping::ObjectMapper::createShared();
      oatpp::String jsonq = jsonObjectMapper->writeToString(ns);
      OATPP_LOGD(TAG, "sending message 2...")
      ws->sendOneFrameText(jsonq);
      OATPP_LOGD(TAG, "sending message 3...")
  }

  ws->sendClose();

  thread.join();

[bjornstromberg]

well this was a while ago, but the issue seems to exist in https://github.com/oatpp/example-websocket example also..

built it with tags 1.3.0 for oatpp, oatpp-websocket and the example-websocket, and it seems to fail pretty much the same..

user@host:~/example-websocket/client$ ./websocket-client-exe 
 I |2022-07-03 22:13:13 1656879193764964| websocket-client:Application Started
 I |2022-07-03 22:13:14 1656879194377704| websocket-client:Connected
 D |2022-07-03 22:13:14 1656879194378063| websocket-client:sending message...
 D |2022-07-03 22:13:14 1656879194379271| [oatpp::web::protocol::websocket::WebSocket::listen()]:Unhandled error occurred. Message='[oatpp::web::protocol::websocket::WebSocket::readFrameHeader()]: Error reading frame header'
 D |2022-07-03 22:13:14 1656879194379349| websocket-client:SOCKET CLOSED!!!

no reaction at all on the server side..

also tried to use latest git commit on oatpp and websocket but that gives same issue.

[rhard]

So, looks like we need to wait for @lganzzzo attention.

BTW: I will try to run the test example and see if it fails on my PC.

[rhard]

@bjornstromberg What test do you run exactly? I tried client and server tests – both are OK in my setup.

[rhard]

The output in my case is just invalid API key error:

←[32m I ←[0m|2022-07-04 19:41:32 1656956492418846| websocket-client:Application Started
←[32m I ←[0m|2022-07-04 19:41:33 1656956493041843| websocket-client:Connected
←[34m D ←[0m|2022-07-04 19:41:33 1656956493045195| websocket-client:sending message...
←[34m D ←[0m|2022-07-04 19:41:33 1656956493046621| Client_WSListener:on message received '{"error":"Invalid API key"}'
←[34m D ←[0m|2022-07-04 19:41:33 1656956493050721| Client_WSListener:onClose code=1000
←[34m D ←[0m|2022-07-04 19:41:33 1656956493052255| websocket-client:SOCKET CLOSED!!!```

[bjornstromberg]

on ubuntu 20.04-lts i built & ran the client and server (the folder names in example-websocket) i expect them to connect to each other via localhost, and the connection message on client gives me the impression that they actually do connect to each other like expected, but i have not analysed the code, its more of an expectation that the client and server modules should work together not with a third party, so i might assume something incorrectly here.

i do not see a reason to start a project with a dependency that does not build or the examples are not working since it minimize my irritation of looking for bugs in my code when its really in the library project.

edit: to clarify my assumption, the headers for the logic says its a 'ping' 'pong' type of server / client example, so that is what i expected to happen, not a thrown exception, incorrectly marked as info message, although the message is cosmetic issue the exception is not.

right now i don't have the free time to diagnose this more, i'll solve the issue at hand with periodic polling instead of websocket which would have been prefeered.

more details:
1 built and installed oatpp to system (after package as *.deb)
2 built and installed oatpp-websocket to system (after package as *.deb)
3 built and run example-websocket/{client,server} as two separate build directories and they linked to the installed prebuilts (1 + 2).

[rhard]

Ok, I will try a Linux build as well.

From my understanding, the client test project tries to connect to the demo.piesocket.com and not to the test server.

  auto connectionProvider = oatpp::network::tcp::client::ConnectionProvider::createShared({"demo.piesocket.com", 80});

  auto connector = oatpp::websocket::Connector::createShared(connectionProvider);

  auto connection = connector->connect("v3/channel_1?api_key=oCdCMcMPQpbvNjUIzqtvF1d2X2okWpDQj4AwARJuAgtjhzKxVEjQU6IdCjwm&notify_self");

[bjornstromberg]

yea had to check to update oatpp/example-websocket#7 so half of it is a 'assumption is the mother of all fuckups' type of issue but it still does throw when running the example so other half is still a issue in both cases..

[rhard]

There must be something special to the hardware etc. I have the issue reports only for 2 people from ˜1000. For the rest it works as expected. The test pipelines in the repository are also OK: https://dev.azure.com/lganzzzo/lganzzzo/_build/results?buildId=12683&view=logs&j=0cfa9771-412f-553c-ddf2-7b1509abac1d&t=7b592fa4-1f09-5e38-86b4-b4ae55b2ac10

If I were able to reproduce the issue...

[bjornstromberg]

yea would not even have tried the examples if the library would have flagged anything as issues..

unfortunately this is not prioritized for me at this time, my bottleneck is hours in a day..

[lganzzzo]

Hello guys,

It looks like two different issues to me.

The first one (the easy one) @bjornstromberg:

as @rhard mentioned:

From my understanding, the client test project tries to connect to the demo.piesocket.com and not to the test server.

The WS client example connects to the demo.piesocket.com server, and its API key has expired.
Thus I've updated API key in the example and it works.
I guess I have to change the client example to connect to a different server without any API keys that expire...

[lganzzzo]

Hey @rhard ,

Can you please post your WSListener code...
I have two assumptions:

• your client doesn't respond to server's pings with pongs (I mean the actual WS pings not the custom ping messages from pinger).
• pong messages not synchronized with the same write mutex.

[wanglong001]

I am currently using version 1.3.0, and this issue occurs on Windows, but not on Linux.