search

Links2004 / arduinoWebSockets

arduinoWebSockets
GNU Lesser General Public License v2.1
1.9k stars 555 forks source link

Code 400, bad request syntax with Flask SocketIO and ESP8266 #574

Closed JMANN240 closed 4 years ago

JMANN240 commented 4 years ago

Hello Links2004, I have been trying to figure out what could be going wrong with this for a few hours and I can not seem to get it working. Basically, I have a flask application running on my a Digital Ocean droplet. The flask application uses Flask SocketIO to handle socket connections. The socketio operations work correctly from a webpage, and it receives and sends socketio messages correctly. The problem comes when I try to connect my ESP8266 to my server. It connects, and sometime during the handshake it sends a strange request. I will attach pertinent files and error logs. If you need any more information please let me know and I will be happy to provide it. Any help would be greatly appreciated. Thanks!

Flask File

from flask import Flask, render_template
from flask_socketio import SocketIO, emit

app = Flask(__name__)
socketio = SocketIO(app, engineio_logger=True, logger=True, cors_allowed_origins='*')

@app.route('/')
def index():
    print("index")
    return render_template('index.html')

@socketio.on('on')
def on():
    emit('on')
    print("on")

@socketio.on('off')
def off():
    emit('off')
    print("off")

if __name__ == '__main__':
    socketio.run(app, host='0.0.0.0', debug=True)

HTML File

<!DOCTYPE html>
<html lang="en">

<head>
    <meta charset="UTF-8">
    <title>Internet Lamp</title>
    <link rel="stylesheet" href="{{ url_for('static', filename='css/styles.css') }}" type="text/css">
    <script src="https://cdnjs.cloudflare.com/ajax/libs/socket.io/2.1.1/socket.io.js"></script>
</head>

<body>
    <button id='on' onclick="onFunc()">On</button>
    <button id='off' onclick="offFunc()">Off</button>
    <script type="text/javascript">
        // sending a connect request to the server.
        var socket = io.connect('http://ejrobotics.com:5000');

        // An event handler for a change of value 
        function onFunc() {
            socket.emit('on');
            console.log('Lamp On Func');
        };

        function offFunc() {
            socket.emit('off');
            console.log('Lamp Off Func');
        };

        socket.on('on', function(msg) {
            console.log('Lamp On');
        });

        socket.on('off', function(msg) {
            console.log('Lamp Off');
        });
    </script>
</body>

</html>

Arduino Code (taken from your WebSocketClientSocketIO example)

/*
 * WebSocketClientSocketIO.ino
 *
 *  Created on: 06.06.2016
 *
 */

#include <Arduino.h>

#include <ESP8266WiFi.h>
#include <ESP8266WiFiMulti.h>

#include <ArduinoJson.h>

#include <WebSocketsClient.h>
#include <SocketIOclient.h>

#include <Hash.h>

ESP8266WiFiMulti WiFiMulti;
SocketIOclient socketIO;

#define USE_SERIAL Serial

void socketIOEvent(socketIOmessageType_t type, uint8_t * payload, size_t length) {
    switch(type) {
        case sIOtype_DISCONNECT:
            USE_SERIAL.printf("[IOc] Disconnected!\n");
            break;
        case sIOtype_CONNECT:
            USE_SERIAL.printf("[IOc] Connected to url: %s\n", payload);
            break;
        case sIOtype_EVENT:
            USE_SERIAL.printf("[IOc] get event: %s\n", payload);
            break;
        case sIOtype_ACK:
            USE_SERIAL.printf("[IOc] get ack: %u\n", length);
            hexdump(payload, length);
            break;
        case sIOtype_ERROR:
            USE_SERIAL.printf("[IOc] get error: %u\n", length);
            hexdump(payload, length);
            break;
        case sIOtype_BINARY_EVENT:
            USE_SERIAL.printf("[IOc] get binary: %u\n", length);
            hexdump(payload, length);
            break;
        case sIOtype_BINARY_ACK:
            USE_SERIAL.printf("[IOc] get binary ack: %u\n", length);
            hexdump(payload, length);
            break;
    }
}

void setup() {
    // USE_SERIAL.begin(921600);
    USE_SERIAL.begin(115200);

    //Serial.setDebugOutput(true);
    USE_SERIAL.setDebugOutput(true);

    USE_SERIAL.println();
    USE_SERIAL.println();
    USE_SERIAL.println();

      for(uint8_t t = 4; t > 0; t--) {
          USE_SERIAL.printf("[SETUP] BOOT WAIT %d...\n", t);
          USE_SERIAL.flush();
          delay(1000);
      }

    // disable AP
    if(WiFi.getMode() & WIFI_AP) {
        WiFi.softAPdisconnect(true);
    }

    WiFiMulti.addAP(my SSID, my Passphrase);

    //WiFi.disconnect();
    while(WiFiMulti.run() != WL_CONNECTED) {
        delay(100);
    }

    String ip = WiFi.localIP().toString();
    USE_SERIAL.printf("[SETUP] WiFi Connected %s\n", ip.c_str());

    // server address, port and URL
    socketIO.begin("ejrobotics.com", 5000);

    // event handler
    socketIO.onEvent(socketIOEvent);
}

unsigned long messageTimestamp = 0;
void loop() {
    socketIO.loop();
}

Arduino IDE Serial Log (repeats indefinitely)

[WS-Client] connect ws...
[WS-Client] connected to ejrobotics.com:5000.
[WS-Client][sendHeader] sending header...
[WS-Client][sendHeader] handshake GET /socket.io/?EIO=3&transport=polling HTTP/1.1
Host: ejrobotics.com:5000
Connection: keep-alive
Origin: file://
User-Agent: arduino-WebSocket-Client

[write] n: 158 t: 11576
[WS-Client][sendHeader] sending header... Done (15806us).
[WS-Client][handleHeader] RX: HTTP/1.1 200 OK
[WS-Client][handleHeader] RX: Set-Cookie: io=f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax
[WS-Client][handleHeader] RX: Content-Type: application/octet-stream
[WS-Client][handleHeader] RX: Access-Control-Allow-Origin: file://
[WS-Client][handleHeader] RX: Access-Control-Allow-Credentials: true
[WS-Client][handleHeader] RX: Content-Length: 119
[WS-Client][handleHeader] RX: Date: Mon, 02 Nov 2020 01:41:51 GMT
[WS-Client][handleHeader] RX: Connection: keep-alive
[WS-Client][handleHeader] Header read fin.
[WS-Client][handleHeader] Client settings:
[WS-Client][handleHeader]  - cURL: /socket.io/?EIO=3
[WS-Client][handleHeader]  - cKey: JEUDtaTVkSu0gqZo5Qp0Vw==
[WS-Client][handleHeader] Server header:
[WS-Client][handleHeader]  - cCode: 200
[WS-Client][handleHeader]  - cIsUpgrade: 0
[WS-Client][handleHeader]  - cIsWebsocket: 0
[WS-Client][handleHeader]  - cAccept: 
[WS-Client][handleHeader]  - cProtocol: arduino
[WS-Client][handleHeader]  - cExtensions: 
[WS-Client][handleHeader]  - cVersion: 0
[WS-Client][handleHeader]  - cSessionId: f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax
[WS-Client][handleHeader] still data in buffer (119), clean up.
[WS-Client][sendHeader] sending header...
[WS-Client][sendHeader] handshake GET /socket.io/?EIO=3&transport=websocket&sid=f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax HTTP/1.1
Host: ejrobotics.com:5000
Connection: Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: +AgqxSZjVw7IA+Qcyh4RHw==
Sec-WebSocket-Protocol: arduino
Origin: file://
User-Agent: arduino-WebSocket-Client

[write] n: 341 t: 11741
[WS-Client][sendHeader] sending header... Done (36026us).
[WS-Client][handleHeader] RX: HTTP/1.1 400 Bad request syntax ('GET /socket.io/?EIO=3&transport=websocket&sid=f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax HTTP/1.1')
[WS-Client] connection lost.
[WS-Client] client disconnected.
[IOc] Disconnected!
[wsIOc] Disconnected!

Server Flask Output (repeats indefinitely)

131.123.50.18 - - [02/Nov/2020 01:41:02] "GET /socket.io/?EIO=3&transport=polling HTTP/1.1" 200 409 0.000529
131.123.50.18 - - [02/Nov/2020 01:41:02] code 400, message Bad request syntax ('GET /socket.io/?EIO=3&transport=websocket&sid=a92c5fc589284d288168766e3fd41879; path=/; SameSite=Lax HTTP/1.1')
131.123.50.18 - - [02/Nov/2020 01:41:02] "GET /socket.io/?EIO=3&transport=websocket&sid=a92c5fc589284d288168766e3fd41879; path=/; SameSite=Lax HTTP/1.1" 400 -
(978427) accepted ('131.123.50.18', 49997)
3f61979a37cc4fe1946ee8bde9c10356: Sending packet OPEN data {'sid': '3f61979a37cc4fe1946ee8bde9c10356', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
3f61979a37cc4fe1946ee8bde9c10356: Sending packet MESSAGE data 0

P.S. if you try this on my server it will not work, as I am just running the python file directly for testing purposes rather than using a gateway interface as I usually would. Unless I am logged in and have the file running, my hostname won't connect.

Links2004 commented 4 years ago

looks like the cookie from your server is not correctly parsed 

Set-Cookie: io=f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax

the code needs to extract the f97dbec18c044920b99effd301b9193e but for some reason this fails and we get f97dbec18c044920b99effd301b9193e; path=/; SameSite=Lax

looks like the code here needs a way better parsing method:
https://github.com/Links2004/arduinoWebSockets/blob/4db14451fb8b47ee620e3ef6687fd591ab5f6a30/src/WebSocketsClient.cpp#L707-L713

JMANN240 commented 4 years ago

Alright, so I went ahead and changed the library locally to be this:

            } else if(headerName.equalsIgnoreCase(WEBSOCKETS_STRING("Set-Cookie"))) {
                client->cSessionId = headerValue.substring(headerValue.indexOf('=') + 1, headerValue.indexOf(";"));
            }

which worked, but now I am getting a new error that does not seem to be so easy to recognize.

Here is the new Arduino IDE Serial log (I added a few debugs for my own purposes, so if you see some you don't recognize I put it there)

[WS-Client] connect ws...
[WS-Client] connected to ejrobotics.com:5000.
[WS-Client][sendHeader] sending header...
[SID]=
[WS-Client][sendHeader] handshake GET /socket.io/?EIO=3&transport=polling HTTP/1.1
Host: ejrobotics.com:5000
Connection: keep-alive
Origin: file://
User-Agent: arduino-WebSocket-Client

[write] n: 158 t: 10419
[WS-Client][sendHeader] sending header... Done (16293us).
[WS-Client][handleHeader] RX: HTTP/1.1 200 OK
[WS-Client][handleHeader] RX: Set-Cookie: io=5620d102378f4a13a96a568e10664084; path=/; SameSite=Lax
[WS-Client][handleHeader] RX: Content-Type: application/octet-stream
[WS-Client][handleHeader] RX: Access-Control-Allow-Origin: file://
[WS-Client][handleHeader] RX: Access-Control-Allow-Credentials: true
[WS-Client][handleHeader] RX: Content-Length: 119
[WS-Client][handleHeader] RX: Date: Mon, 02 Nov 2020 15:23:34 GMT
[WS-Client][handleHeader] RX: Connection: keep-alive
[WS-Client][handleHeader] Header read fin.
[WS-Client][handleHeader] Client settings:
[WS-Client][handleHeader]  - cURL: /socket.io/?EIO=3
[WS-Client][handleHeader]  - cKey: plrBBZ/cITMZZUJ9TTQMQQ==
[WS-Client][handleHeader] Server header:
[WS-Client][handleHeader]  - cCode: 200
[WS-Client][handleHeader]  - cIsUpgrade: 0
[WS-Client][handleHeader]  - cIsWebsocket: 1
[WS-Client][handleHeader]  - cAccept: 
[WS-Client][handleHeader]  - cProtocol: arduino
[WS-Client][handleHeader]  - cExtensions: 
[WS-Client][handleHeader]  - cVersion: 0
[WS-Client][handleHeader]  - cSessionId: 5620d102378f4a13a96a568e10664084
[WS-Client][handleHeader] still data in buffer (119), clean up.
[WS-Client][sendHeader] sending header...
[SID]=5620d102378f4a13a96a568e10664084
[WS-Client][sendHeader] handshake GET /socket.io/?EIO=3&transport=websocket&sid=5620d102378f4a13a96a568e10664084 HTTP/1.1
Host: ejrobotics.com:5000
Connection: Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: 1mP585MEX9hkrynXC/E5WQ==
Sec-WebSocket-Protocol: arduino
Origin: file://
User-Agent: arduino-WebSocket-Client

[write] n: 319 t: 10585
[WS-Client][sendHeader] sending header... Done (36845us).
[WS-Client][handleHeader] RX: HTTP/1.1 101 Switching Protocols
[WS-Client][handleHeader] RX: Upgrade: websocket
[WS-Client][handleHeader] RX: Connection: Upgrade
[WS-Client][handleHeader] RX: Sec-WebSocket-Accept: TVd/jwyCS3W2CmtGbd7iaPzTzWY=
[WS-Client][handleHeader] Header read fin.
[WS-Client][handleHeader] Client settings:
[WS-Client][handleHeader]  - cURL: /socket.io/?EIO=3
[WS-Client][handleHeader]  - cKey: 1mP585MEX9hkrynXC/E5WQ==
[WS-Client][handleHeader] Server header:
[WS-Client][handleHeader]  - cCode: 101
[WS-Client][handleHeader]  - cIsUpgrade: 1
[WS-Client][handleHeader]  - cIsWebsocket: 1
[WS-Client][handleHeader]  - cAccept: TVd/jwyCS3W2CmtGbd7iaPzTzWY=
[WS-Client][handleHeader]  - cProtocol: arduino
[WS-Client][handleHeader]  - cExtensions: 
[WS-Client][handleHeader]  - cVersion: 0
[WS-Client][handleHeader]  - cSessionId: 5620d102378f4a13a96a568e10664084
[WS-Client][handleHeader] Websocket connection init done.
[WS][0][headerDone] Header Handling Done.
[wsIOc] Connected to url: /socket.io/?EIO=3
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 1 headerToPayload: 1
[WS][0][sendFrame] text: 5
[write] n: 7 t: 10713
[WS][0][sendFrame] sending Frame Done (4177us).
[IOc] Connected to url: /socket.io/?EIO=3
[WS-Client] connection lost.
[WS-Client] client disconnected.
[IOc] Disconnected!
[wsIOc] Disconnected!

And here is what the server log is saying now

131.123.50.18 - - [02/Nov/2020 15:23:34] "GET /socket.io/?EIO=3&transport=polling HTTP/1.1" 200 409 0.000968
5775d2e240d24e28aa71937179b4620a: Received request to upgrade to websocket
5775d2e240d24e28aa71937179b4620a: Failed websocket upgrade, no PING packet
131.123.50.18 - - [02/Nov/2020 15:23:35] "GET /socket.io/?EIO=3&transport=websocket&sid=5775d2e240d24e28aa71937179b4620a HTTP/1.1" 200 0 0.126044
(983171) accepted ('131.123.50.18', 59832)
357c86ef11bd42408a193bbe01858b89: Sending packet OPEN data {'sid': '357c86ef11bd42408a193bbe01858b89', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
357c86ef11bd42408a193bbe01858b89: Sending packet MESSAGE data 0
Links2004 commented 4 years ago

looks like the server does not like the text "5", part of the engine.io protocol (socket.io uses engine.io as transport layer)

can you search for

 Failed websocket upgrade, no PING packet

in the server code?

the big question is does the server wait for a websocket opcode "PING" or a engine.io ping.

last time I checked the engine.io spec the first packed needed is a 5 which is a UPGRADE message (see links below)

the 5 is send here: https://github.com/Links2004/arduinoWebSockets/blob/master/src/SocketIOclient.cpp#L168

ref: https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.h#L231-L240 https://github.com/Links2004/arduinoWebSockets/blob/master/src/SocketIOclient.h#L18-L36

JMANN240 commented 4 years ago

Alright, so the flask-socketio library I am using does use engineio. The line which produces the error log is here and it looks like the opcodes are defined here The opcode for PING is 2 and the opcode for UPGRADE is 5

Taking a look at the code in the first link, it seems like it is waiting for a ping first and then wants the upgrade packet later. Does this mean that the ESP8266 must send a ping before the upgrade?

Links2004 commented 4 years ago

yes for this Implementation of the engineio protocol its seems needed. but why makes no sense to me. the nodejs version does not need this. you can try to send the 'PING' with probe first.

 WebSocketsClient::sendTXT("2probe");
 WebSocketsClient::sendTXT(eIOtype_UPGRADE);
JMANN240 commented 4 years ago

Great! That fixed the issue, thank you for all of your help and guidance!