Websocket client doesn't handle transport timeout errors correctly (IDFGH-16202)

[Lupindakaas]

Answers checklist.

• I have read the documentation for esp-protocols components and the issue is not addressed there.
• I have updated my esp-protocols branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

Might be related to #795.

What i've gathered

The websocket client uses esp_transport_ws for it's transport layer. When using the esp_transport_read() function, you can use a timeout. This is configureable in the websocket client as 'network_timeout_ms'. When this timeout is reached, the esp_transport_read() function returns 0. This is however also the case for length 0 messages like PING or CLOSE. This already makes it hard to detect a timed out message. It seems that when this timeout is reached, an error isn't correctly detected, and we handle the message as regular. After this happens, the websocket client keeps publishing offset/randomly fragmented data.

Log

See log below. When the timeout is reached, the function returns 0. After this though, we don't handle this as a timeout and still emit the data event. This is what the client_handler is subscribed to. After this happens once, we enter a weird 'fragmented read' state where the client is confused about what bit is where. Also the websocket headers get shuffled around.

Funnily enough, this confused/fragmented read state continues untill 'E (294271) transport_ws: Error read data(0)' happens again. Then it recovers. This is clearly linked to the network_timeout_ms, as i can control the frequency of this error by enlongating/shortening the timeout time. Shorter timeout increases the frequency.

I (292621) client_handler: WS received data: opcode=1, len=63, data={"message":"type","data":{"data":{"point":3262,"point2":1952}}}
E (294271) transport_ws: Error read data(0)
E (294271) transport_ws: Error reading payload data(0)

-> len=0 && opcode=1 -> timeout reached but still publishes event

I (294271) client_handler: WS received data: opcode=1, len=0, data= 
E (294281) client_handler: on_data_event(467): Received unexpected text data

-> After this, the client publishes weirdly fragmented data:

I (295091) client_handler: WS received data: opcode=11, len=34, data={"message":"type","data":{"data"
W (295091) client_handler: WS unhandled op code 11
I (295101) client_handler: WS received data: opcode=10, len=30, data=:{"point":3262,"point2":1952}}}
I (295121) client_handler: WS received data: opcode=10, len=2, data=�U
I (295121) client_handler: WS received data: opcode=10, len=56, data={"message":"type","data":{"data":{"point":3262,"point2":
I (295131) client_handler: WS received data: opcode=14, len=7, data=1952}}}
W (295141) client_handler: WS unhandled op code 14
I (295611) client_handler: WS received data: opcode=14, len=2, data=�S
W (295611) client_handler: WS unhandled op code 14
I (295871) client_handler: WS received data: opcode=14, len=63, data={"message":"type","data":{"data":{"point":3262,"point2":1952}}}
W (295881) client_handler: WS unhandled op code 14

-> Another timeout

E (296401) transport_ws: Error read data(0)
E (296401) transport_ws: Error reading payload data(0)
I (296401) client_handler: WS received data: opcode=14, len=0, data=
W (296411) client_handler: WS unhandled op code 14

-> State is restored again

I (296711) app_remote: WS received data: opcode=1, len=63, data={"message":"type","data":{"data":{"point":3262,"point2":1952}}}

I had to obfuscate the actual data being send, so maybe the lengths don't match exactly.

[BultynckO]

Also possibly related to #680

I'm seeing very similar behavior in our application. Example with successive errors correcting each other

--> First WS error

E (560133) transport_ws: Error read data
E (560133) transport_ws: Error reading payload data

--> Garbage frame data coming in

W (560133) HANDLER: Empty binary message received!
W (561113) HANDLER: UNKNOWN MESSAGE: opcode: 15 msg:  [obfuscated raw byte stream]

--> Second WS error

E (563123) transport_ws: Error read data
E (563123) transport_ws: Error reading payload data
W (563123) HANDLER: UNKNOWN MESSAGE: opcode: 15 msg:

--> Frame data starts being interpreted correctly again

W (564113) Queue is full, delete oldest message

[DCSBL]

Hi @glmfe, do you maybe have an update about this issue? My colleague @Lupindakaas created this issue as we have quite some issues in field, affecting customers.

No rush, just want to know what I could expect and how we can help.

Thanks!

[glmfe]

Hi @Lupindakaas, @DCSBL

Thanks the detailed breakdown of what’s happening. I’m diving into this now.

Could you please let me know:

• Which version of ESP-IDF are you using? (idf.py --version)
• Which version of the WebSocket client (esp-protocols) are you testing with?

Thanks!

[DCSBL]

Good one!

We are using ESP-IDF 5.4.1 and client 1.4.0.

We have also tested for a short period with IDF v5.5 and version client 1.5.0, but we see the same problems.

dependencies:
  espressif/esp_websocket_client:
    component_hash: f77326f0e1c38da4e9c97e17c5d649b0dd13027f2645e720e48db269638fd622
    dependencies:
    - name: idf
      require: private
      version: '>=5.0'
    source:
      registry_url: https://components.espressif.com/
      type: service
    version: 1.4.0
  [...]
  idf:
    source:
      type: idf
    version: 5.4.1
direct_dependencies:
- espressif/esp_websocket_client
- [...]
- idf
manifest_hash: [...]
target: esp32s3
version: 2.0.0

[glmfe]

Hi @Lupindakaas @DCSBL.

I’ve linked this to another PR of mine that separates the PONG event from regular data events. With this change, if we receive ws_read() == 0 during payload reception, it will clearly indicate a timeout error. In that case, we should abort the connection and notify the server to close it.

[DCSBL]

Great! Let me know if we can try things out for you. Thank you!

[Lupindakaas]

I've tested #874. Although I do like the change, sadly this doesn't solve our problem.

I added the following code to our handler:

        case WEBSOCKET_EVENT_PONG:
            ESP_LOGI(TAG, "Pong!");
            break;

Sadly after a while, the following still happened:

E (83168) transport_ws: Error read data
E (83168) transport_ws: Error reading payload data
D (83168) client_handler: Received text
D (83178) client_handler: <- 
E (83178) client_handler: text_data_handler(471): Received unexpected text data
W (83258) client_handler: WS unhandled op code 11
I (83258) client_handler: Pong!
I (83498) client_handler: Pong!
I (83498) client_handler: Pong!
I (84148) client_handler: Pong!
I (84248) client_handler: Pong!
I (84258) client_handler: Received binary message
I (85148) client_handler: Received binary message
I (85248) client_handler: Received binary message
W (85248) client_handler: WS unhandled op code 4
W (86158) client_handler: WS unhandled op code 4
W (86408) client_handler: WS unhandled op code 4
W (86408) client_handler: WS unhandled op code 13
W (87158) client_handler: WS unhandled op code 13
W (87278) client_handler: WS unhandled op code 13
W (88258) client_handler: WS unhandled op code 13
I (88258) client_handler: Received continue message
I (89168) client_handler: Received continue message
I (89258) client_handler: Received continue message
I (89258) client_handler: Received close message
W (89268) transport_ws: esp_transport_ws_poll_connection_closed: unexpected data readable on socket=58
W (89278) websocket_client: Connection terminated while waiting for clean TCP close
W (89288) client_handler: WS unhandled event (5)
I (89288) client_handler: Websocket client finished

[Lupindakaas]

I did some investigating

Looking at the implementation i see the line: if (rlen == 0 && client->last_opcode == WS_TRANSPORT_OPCODES_NONE) If this is true we call it a timeout. I think the root cause of this issue is that the client->last_opcode doesn't get set to NONE. I've added a print to the recv() function, this gave me the following log:

E (265569) transport_ws: Error read data
E (265569) transport_ws: Error reading payload data
I (265569) websocket_client: esp_transport_read() returned 0
I (265579) websocket_client: Received opcode: 1

I've changed this line to if (rlen == 0 && (client->last_opcode == WS_TRANSPORT_OPCODES_BINARY || client->last_opcode == WS_TRANSPORT_OPCODES_TEXT)) and now it does at least detect the timeout event:

E (421289) transport_ws: Error read data
E (421289) transport_ws: Error reading payload data
I (421289) websocket_client: esp_transport_read() returned 0
I (421299) websocket_client: Received opcode: 1
E (421299) websocket_client: esp_transport_read timeouts

Proposed solution

It would be nice/prefered if the websocket could be maintained when we have a read timeout. I believe the actual fix for this bug would be to make esp_transport_ws properly handle a timeout error, because this seems to be the reason it starts acting up. After a timeout event this will keep returning weird/unpredictable opcodes, payload lengths and fin flags.

proof: added ESP_LOGI(TAG, "Read opcode=%d, fin=%d, payload_len=%d, rlen=%d", client->last_opcode, client->last_fin, client->payload_len, rlen); to right after where we read the opcode. Normally this is always websocket_client: Read opcode=1, fin=1, payload_len=78, rlen=78 but when it enters this state it goes:

E (262519) transport_ws: Error read data
E (262519) transport_ws: Error reading payload data
I (262519) websocket_client: Read opcode=1, fin=1, payload_len=78, rlen=0
E (262529) websocket_client: esp_transport_read timeouts
I (263909) websocket_client: Read opcode=11, fin=0, payload_len=34, rlen=34
I (263929) websocket_client: Read opcode=10, fin=0, payload_len=123, rlen=40
I (264179) websocket_client: Read opcode=10, fin=0, payload_len=123, rlen=2
I (264199) websocket_client: Read opcode=10, fin=0, payload_len=123, rlen=78
I (264209) websocket_client: Read opcode=10, fin=0, payload_len=123, rlen=2
I (264229) websocket_client: Read opcode=10, fin=0, payload_len=123, rlen=1
I (264239) websocket_client: Read opcode=2, fin=0, payload_len=116, rlen=75

Or, as a workaround, just force a reconnect when we notice a timeout. This is (to us) preffered to the undefined behaviour it currently has. This we can do by changeing the timeout code section to:

        if (rlen == 0 && (client->last_opcode == WS_TRANSPORT_OPCODES_BINARY || client->last_opcode == WS_TRANSPORT_OPCODES_TEXT))
        {
            ESP_LOGE(TAG, "esp_transport_read timeouts");
            esp_websocket_free_buf(client, false); // probably not necessary as we rebuild anyhow
            return ESP_FAIL;
        }