Failing to upgrade to websocket connection #175
Comments
The current version of Flask-SocketIO does not force Werkzeug when you are in debug mode. If you have eventlet or gevent installed, those will be used, and WebSocket will be enabled.
Do you have a link for this Socket.IO client? |
Ok, that makes sense (though the docs are a bit inconsistent). If that's the case, though, there's an issue with the HTML/JavaScript client upgrading the connection.
I added a link to it - it's unfortunately only commercially available on the Unity assetstore, though it does come with source. |
What version of the Javascript client are you using for this test? It's odd that gevent-websocket complains about the upgrade request being != 'GET', that suggests the problem is on the client side. Do you get the same problem if you use the example application from this repository? Regarding the BestHTTP Socket.IO support, do you know what version is their implementation compatible with? Socket.IO went through major changes at the 1.0 release. From looking at the file listing (the only thing I can see without making a purchase) it isn't clear if they align with pre or post 1.0. |
I'll try with a cleaner/smaller setup and let you know.
http://forum.unity3d.com/threads/best-http-released.200006/ and |
|
Hi. BestHTTP developer is here. My Socket.IO implementation supports the post v1 line. The WebSocket implementation is also written by me against the official RFC, and it shouldn't switch to a non-GET method. Also, using an intermediate proxy (like https://www.charlesproxy.com/) to see and share the logs what requests the plugin really sent out would be good too. |
|
Okay, I tried with the app in You can try the exact same environment by dropping this Dockerfile into the FROM jprjr/ubuntu-base:14.04
RUN apt-get update && apt-get install \
python python-dev python-distribute python-pip python-gevent-websocket
RUN pip install Flask
ADD ./flask_socketio /app/flask_socketio
ADD ./setup.py /app/setup.py
WORKDIR /app
RUN python setup.py install
ADD . /app
EXPOSE 5000
WORKDIR /app/example
ENTRYPOINT []
CMD ["/app/example/app.py"]And in that same directory: % docker build -t flaskio-example .
% docker run -p 5000:5000 docker run flaskio-example |
|
@Benedicht you can get the Flask-SocketIO server up-and-running by doing this after installing docker: git clone https://github.com/miguelgrinberg/Flask-SocketIO/
cd Flask-SocketIO
# put the above Dockerfile into this directory
docker build -t flaskio-example .
docker run -p 5000:5000 docker run flaskio-exampleThe logs from the server look like this: though you have to add this to the top of the import logging
logging.basicConfig(level='DEBUG') |
|
Thank you both for helping to troubleshoot this!!! @Benedicht The POST log entry is from me running the |
|
@beorn Thanks, i will try to set it up. |
|
Okay, here's a log from Charles capturing BestHTTP trying to connect to the Flask-SocketIO example app: CharlesLog.txt Here's a slightly longer session: CharlesLog2.txt |
|
It looks that the WebSocket upgrade is successfully done, no "Can only upgrade connection if using GET method." error in your previous log, but the server immediately closed the connection by sending a Close frame. (Docker doesn't like my win10 rig, now i try to install on my mac.) |
|
@beorn Okay, I am seeing an issue that is probably what you are seeing. When using gevent+gevent-websocket and the server is in debug mode, the WebSocket connection is not established. But I do get a WebSocket connection up when I use Some component in the stack must be causing some interference and prevents the upgrade request from ever reaching the Socket.IO server. Your log does not show any of these entries, which are expected during the WebSocket upgrade: INFO:engineio:42831cd38f664e53bcafbe91bf595f2e: Received request to upgrade to websocket Can I ask you to try using I need to debug this problem to figure out why these upgrade requests are lost, I'll update this bug once I have figured it out. |
I’ll dump the logs from Charles and the Flask server for BestHTTP and the socket.io web chat example a bit later.
Ok. |
|
Here are the Flask server & Charles HTTP proxy logs from running the example chat app and a BestHTTP app, with chat http trace |
|
Okay, this is looking much much better. Now the upgrade request is received, but it appears the handshake isn't what the server expects. The handshake the server expects goes like this:
According to the BestHTTP logs you just posted, step 3 does not occur. Server logs do not say what packet the client sent, but it clearly isn't the UPGRADE packet. Relevant code is here. @Benedicht Maybe you can help with the handshake part? Either by explaining how you expect the exchange to go from your side, or by letting me take a peek at the code? Thanks! |
|
Now I was able to set up an environment to test it too. The websocket upgrade/handshake process is the same as expected. WebSocket packets captured by charles:
The relevant code: case TransportEventTypes.Pong:
// Answer for a Ping Probe.
if (packet.Payload == "probe")
{
HTTPManager.Logger.Information("WebSocketTransport", "\"probe\" packet received, sending Upgrade packet");
// We will send an Upgrade("52") packet.
Send(new Packet(TransportEventTypes.Upgrade, SocketIOEventTypes.Event, "/", string.Empty));
}
goto default;The packet is present in the charles log, and the info log is also logged into the Unity console. |
|
Just so I'm clear, so the client does send the upgrade packet, but the server detects/handles it? |
|
@beorn Yes. Also I modified the socket.py a little: self.server.logger.info(
'%s: Failed websocket upgrade, no UPGRADE packet: %s',
self.sid, pkt)Now, it logs out the following:
So it receives it, but it's not identified as an upgrade packet. |
|
Changing my code to send only update("5") without the event("2") event type works now: Send(new Packet(TransportEventTypes.Upgrade, SocketIOEventTypes.Unknown, "/", string.Empty)); |
|
@beorn Sent a modified WebSocketTransport.cs in mail that you can try out. |
|
@Benedicht Thanks for the detailed analysis. Basically, the problem is that my way of checking for the upgrade packet is too strict, I expect the packet will have no data in it. Your client is sending a payload of "2" in the packet, so my test fails. I will go ahead and relax my checking to allow any payloads in the upgrade packet, but what is the "2"? Is there some meaning to it? Edit: I guess the "2" is just an empty event packet at the socketio level. I'll go ahead and change my server to ignore anything that comes with the upgrade packet, I think that should work. |
|
@miguelgrinberg Yes, it was meant for an event packet, but now I can't recall why it's there. I think when I started my implementation I saw this sending the js client... Anyway, thank you for your help! Changed my implementation, and if @beorn will verify that it's working, then it will be released with the next update. |
|
I have also relaxed the criteria to accept the upgrade packet in my python-engineio package, so this should now work even without the modified BestHTTP. I'm going to close this issue and open a separate one for the problem with debug mode and gevent. Debug mode issue: #177 |
|
@miguelgrinberg @Benedicht I've applied the WebSocket.cs patch (don't have Flask-SocketIO patch), but it still seems like it doesn't detect the packet: |
|
You can try my patch by running: On Wed, Dec 2, 2015, 6:58 PM Bjørn Stabell [email protected] wrote:
|
|
@miguelgrinberg Ok, I'm using the latest python-engineio (0.8.1) with the latest patched BestHTTP, but the upgrade still doesn't work. |
|
@beorn Do you have updated logs? |
(There's some of our own code in there - please ignore. We're also adding some stuff to the query_strings, but that shouldn't matter.) |
|
@beorn Do you get the same log output if you use the original BaseHTTP client code? Also, I assume you are still running with debug mode disabled on the server? |
|
Yes, looks exactly the same. |
|
I just pushed Flask-SocketIO 1.2 to pypi, with the fix for the debug mode WebSocket connection. |
|
Okay, I added some more logging information to The relevantly instrumented parts of def handle_get_request(self, environ, start_response):
"""Handle a long-polling GET request from the client."""
self.server.logger.debug('%s: Received GET request %s', self.sid, dict(environ))
connections = [
s.strip()
for s in environ.get('HTTP_CONNECTION', '').lower().split(',')]
transport = environ.get('HTTP_UPGRADE', '').lower()
if 'upgrade' in connections and transport in self.upgrade_protocols:
self.server.logger.info('%s: Received request to upgrade to %s',
self.sid, transport)
return getattr(self, '_upgrade_' + transport)(environ,
start_response)
try:
packets = self.poll()
except IOError as e:
self.close(wait=False)
raise e
return packets
def handle_post_request(self, environ):
"""Handle a long-polling POST request from the client."""
self.server.logger.debug('%s: Received POST request %s', self.sid, dict(environ))
length = int(environ.get('CONTENT_LENGTH', '0'))
if length > self.server.max_http_buffer_size:
raise ValueError()
else:
body = environ['wsgi.input'].read(length)
p = payload.Payload(encoded_payload=body)
for pkt in p.packets:
self.receive(pkt)
def close(self, wait=True, abort=False):
"""Close the socket connection."""
self.server._trigger_event('disconnect', self.sid)
if not abort:
self.send(packet.Packet(packet.CLOSE))
self.closed = True
if wait:
self.queue.join()
def _upgrade_websocket(self, environ, start_response):
"""Upgrade the connection from polling to websocket."""
self.server.logger.debug('%s: Upgrading websocket %s', self.sid, dict(environ))
if self.upgraded:
raise IOError('Socket has been upgraded already')
websocket_class = getattr(self.server.async['websocket'],
self.server.async['websocket_class'])
ws = websocket_class(self._websocket_handler)
return ws(environ, start_response)
def _websocket_handler(self, ws):
"""Engine.IO handler for websocket transport."""
self.server.logger.debug('%s: _websocket_handler - ws: %s', self.sid, ws)
if self.connected:
self.server.logger.debug('%s: _websocket_handler - connected => upgrade', self.sid)
# the socket was already connected, so this is an upgrade
self.queue.join() # flush the queue first
self.server.logger.debug('%s: _websocket_handler - flushed queue, waiting for pkt', self.sid)
pkt = ws.wait()
if pkt != packet.Packet(packet.PING,
data=six.text_type('probe')).encode(
always_bytes=False):
self.server.logger.info(
'%s: Failed websocket upgrade, no PING packet', self.sid)
return
self.server.logger.debug('%s: _websocket_handler - got pkt, sending PONG', self.sid)
ws.send(packet.Packet(
packet.PONG,
data=six.text_type('probe')).encode(always_bytes=False))
self.server.logger.debug('%s: _websocket_handler - got pkt, sending NOOP', self.sid)
self.send(packet.Packet(packet.NOOP))
self.server.logger.debug('%s: _websocket_handler - waiting for pkt', self.sid)
pkt = ws.wait()
decoded_pkt = packet.Packet(encoded_packet=pkt)
self.server.logger.debug('%s: _websocket_handler - decoded_pkt: %s', self.sid, decoded_pkt)
if decoded_pkt.packet_type != packet.UPGRADE:
self.upgraded = False
self.server.logger.info(
('%s: Failed websocket upgrade, expected UPGRADE packet, '
'received %s instead.'),
self.sid, pkt)
return
self.server.logger.debug('%s: _websocket_handler - upgraded=True', self.sid)
self.upgraded = True
else:
self.server.logger.debug('%s: _websocket_handler - !connected => upgraded=connected=True', self.sid)
self.connected = True
self.upgraded = True |
|
@beorn what I don't understand is how come this worked before. The problems that you had a couple of days ago were past the queue join. Did anything else change? The message queue should empty eventually, assuming the client continues to use the polling transport to get messages flowing. Here is where stuff gets out of the queue, in the GET request handler. |
|
I'm not sure, could it be that the client just keeps sending GET requests before the previous ones have finished? I don't see it continuing past the It seems the client sends to GET requests in rapid sequence - one with transport polling, then with websocket. I guess that's normal? I'm attaching the entire log from unity/besthttp and flask. |
|
The GET request that starts the WebSocket connection is never going to finish (well, it will when the client goes away, but other than that it is not going to end). Before and while the WebSocket connection is being established, the client must continue to use long-polling. Do you see new GET and POST requests coming in to the server? These would have to be regular requests, not WebSocket upgrade requests. I suspect for some reason those requests are not being sent, so any messages that got stuck in the queue are never delivered. Do you have any issues with my example app? At this point it should work just fine in all configurations, even in debug mode. |
Hi,
We're using BestHTTP for Unity3d, and I'm running into two problems:
(1) flask-socketio advertises websockets as an upgrade option even if we run it in develop=True => using werkzeug
or is should websockets be supported in this mode?
(2) If I run in non-develop mode, the websocket succeeds against the stock chat HTML/JavaScript client, but fails against the BestHTTP socketio client that we want to use. I know the issue might be with BestHTTP, but maybe you could let me know how to troubleshoot it better? Here's the log:
And on the BestHTTP side it appears to send a ping probe and wait for the response of that, which it never gets:
BestHTTP link: https://www.assetstore.unity3d.com/en/#!/content/10872
BestHTTP docs: https://docs.google.com/document/d/181l8SggPrVF1qRoPMEwobN_1Fn7NXOu-VtfjE6wvokg/edit
The text was updated successfully, but these errors were encountered: