Any kind of connection is tried to be upgraded to WS connection

[winster]

Hello,

I am using both flask router and flash-sockets. That means, my server has both http and websocket end points. After flash-socket integration, any calls to my http router also try to upgrade the request. And getting following error.

Initializing WebSocket Sep 25 04:12:32 surcle app/web.1: Validating WebSocket request Sep 25 04:12:32 surcle app/web.1: Can only upgrade connection if using GET method.

This is how I register blueprint in init.py

from router import router, ws
app.register_blueprint(router)

sockets = Sockets(app)
sockets.register_blueprint(ws)

And in router.py

router = Blueprint('router', __name__)
ws = Blueprint('ws', __name__)
@ws.route('/socket')
def web_socket(socket):
    logging.debug('inside web_socket')
    while not socket.closed:
        message = socket.receive()
        socket.send(message)

@router.route('/status', methods=['POST'])
def status():
    print "inside status"

What went wrong?

[o3bvv]

Hi @winster,

Sorry, I cannot confirm this currently.

I've tried to run this:

from flask import Flask, Blueprint
from flask_sockets import Sockets

router = Blueprint('router', __name__)
ws = Blueprint('ws', __name__)

@ws.route('/socket')
def web_socket(socket):
    app.logger.debug("inside 'web_socket'")
    while not socket.closed:
        message = socket.receive()
        socket.send(message)

@router.route('/status', methods=['POST'])
def status():
    app.logger.debug("inside 'status'")
    return("hello from status\n")

app = Flask(__name__)
app.config['DEBUG'] = True
app.register_blueprint(router)

sockets = Sockets(app)
sockets.register_blueprint(ws)

using Gunicorn:

gunicorn -k flask_sockets.worker --reload flask_sockets_bug_43:app

and tried to POST to /status:

curl -X POST http://127.0.0.1:8000/status

So, I've got in response

hello from status

and here are log messages:

[2016-09-25 19:13:48 +0300] [64046] [INFO] Starting gunicorn 19.3.0
[2016-09-25 19:13:48 +0300] [64046] [INFO] Listening at: http://127.0.0.1:8000 (64046)
[2016-09-25 19:13:48 +0300] [64046] [INFO] Using worker: flask_sockets.worker
[2016-09-25 19:13:48 +0300] [64049] [INFO] Booting worker with pid: 64049

--------------------------------------------------------------------------------
DEBUG in flask_sockets_bug_43 [/tmp/flask_sockets_bug_43.py:19]:
inside 'status'
--------------------------------------------------------------------------------

1. Is this the behaviour you expect?
2. How do you run your app?
3. How do you define it?

P.S.: flask-sockets by name of flask lib, not flash-sockets

Thanks

[winster]

1. This is the expected behavior
2. Running app in Heroku web: gunicorn -k flask_sockets.worker app:app
3. Defining app as usual app = Flask(name)

Can you try first connecting to websocket and then hit the status API?

[o3bvv]

Hi, yes

Here we go to WS:

curl -i -N -H "Connection: Upgrade" -H "Upgrade: websocket" -H "Host: localhost:8000" -H "Origin: http://localhost" -H "Sec-Websocket-Version: 13" -H "Sec-Websocket-Key: y0eGBK40KPi4DQhEo7l02Q==" http://localhost:8000/socket

Output:

HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: XGiCJICR2E3HdufjP/bCXfm3qpM=

And plain HTTP:

curl -XPOST http://127.0.0.1:8000/status

Output:

hello from status

Logs:

[2016-09-26 09:11:56 +0300] [64788] [INFO] Starting gunicorn 19.3.0
[2016-09-26 09:11:56 +0300] [64788] [INFO] Listening at: http://127.0.0.1:8000 (64788)
[2016-09-26 09:11:56 +0300] [64788] [INFO] Using worker: flask_sockets.worker
[2016-09-26 09:11:56 +0300] [64791] [INFO] Booting worker with pid: 64791
--------------------------------------------------------------------------------
DEBUG in flask_sockets_bug_43 [/tmp/flask_sockets_bug_43.py:11]:
inside 'web_socket'
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in flask_sockets_bug_43 [/tmp/flask_sockets_bug_43.py:19]:
inside 'status'
--------------------------------------------------------------------------------

What is your OS, version of Python and libraries? How are you connecting to WS?

Where do those messages

Initializing WebSocket …

come from?

[winster]

I am using Heroku cloud server. Probably it is a Linux distribution, 2.7 I am connecting to websocket using an android library called AsycTask.

'Initializing WebSocket' is not my log. Is it from gevent?

Below another example.

Sep 25 04:57:56 surcle heroku/router:  at=info method=POST path="/v1.0/receipt" host=surcle.herokuapp.com request_id=cda75b77-b174-488d-8176-1799cc331b72 fwd="106.51.142.171" dyno=web.1 connect=0ms service=11ms status=200 bytes=134 
Sep 25 04:57:56 surcle app/web.1:  Initializing WebSocket 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.multiprocess': True, 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.multithread': True, 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.run_once': False, 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.url_scheme': 'http', 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.version': (1, 0), 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.websocket': None, 
Sep 25 04:57:56 surcle app/web.1:   'wsgi.websocket_version': '13'} failed with TypeError 
Sep 25 04:57:56 surcle app/web.1:  Validating WebSocket request 
Sep 25 04:57:56 surcle app/web.1:  Can only upgrade connection if using GET method. 

[o3bvv]

Well, Initializing WebSocket message comes from gevent-websocket.

Due to code, it is expected to see Validating WebSocket request message immediately after Initializing WebSocket.

However, your log contains a part of traceback interweaved between those messages. This is very suspicious:

1. seems like there are simultaneous requests to your service;
2. take a look at 'wsgi.websocket_version': '13'} failed with TypeError: there's something wrong in your WS endpoint;

I also have a service deployed to Heroku which has both HTTP endpoints and WS endpoints. I make POST requests before and after connecting to WS and there is nothing similar to your messages:

2016-09-26T13:30:26.631914+00:00 heroku[web.1]: Unidling
2016-09-26T13:30:26.632764+00:00 heroku[web.1]: State changed from down to starting
2016-09-26T13:30:31.178397+00:00 heroku[web.1]: Starting process with command `gunicorn -k flask_sockets.worker -w 3 --reload project.app:app --log-file -`
2016-09-26T13:30:34.137806+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [3] [INFO] Starting gunicorn 19.3.0
2016-09-26T13:30:34.138475+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [3] [INFO] Listening at: http://0.0.0.0:56280 (3)
2016-09-26T13:30:34.138614+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [3] [INFO] Using worker: flask_sockets.worker
2016-09-26T13:30:34.157143+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [11] [INFO] Booting worker with pid: 11
2016-09-26T13:30:34.207789+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [12] [INFO] Booting worker with pid: 12
2016-09-26T13:30:34.252224+00:00 app[web.1]: [2016-09-26 13:30:34 +0000] [13] [INFO] Booting worker with pid: 13
2016-09-26T13:30:34.905720+00:00 heroku[web.1]: State changed from starting to up
2016-09-26T13:30:37.268048+00:00 heroku[router]: at=info method=POST path="/api/difficulty/toggle_parameter" host=il2fb-demo-services.herokuapp.com request_id=19f3f15a-4cce-488b-ae19-941804468573 fwd="195.160.235.251" dyno=web.1 connect=1ms service=81ms status=200 bytes=147
2016-09-26T13:38:42.424203+00:00 heroku[router]: at=info method=GET path="/api/events-parser/parse" host=il2fb-demo-services.herokuapp.com request_id=a93f09fc-32fc-40bf-ad2b-bc9650eaf493 fwd="195.160.235.251" dyno=web.1 connect=0ms service=60517ms status=101 bytes=129
2016-09-26T14:13:42.754401+00:00 heroku[router]: at=info method=POST path="/api/difficulty/toggle_parameter" host=il2fb-demo-services.herokuapp.com request_id=c8df6420-085b-4529-afe9-327937aea830 fwd="195.160.235.251" dyno=web.1 connect=0ms service=89ms status=200 bytes=147

AsyncTask is used for managing execution flow by running tiny subtasks in background. It's not related to connections. How are you connecting to web sockets and how are you using them? Java WebSockets maybe?

Have you tried to make bare requests to your services from console or special tools?

It's hard to give a vivid answer without seeing implementation of both server and client.

Thanks

[winster]

I understand. Let me dig more. The same client worked with NodeJS websocket.

[o3bvv]

I confirm this issue.

I do not know, why nothing is put into logs, but yes, WebSocketHandler.run_application() is called for every request: both HTTP and WS.

[o3bvv]

And here's log for POST request:

--------------------------------------------------------------------------------
DEBUG in handler [/home/alex/.virtualenvs/py2/local/lib/python2.7/site-packages/geventwebsocket/handler.py:69]:
Initializing WebSocket
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in handler [/home/alex/.virtualenvs/py2/local/lib/python2.7/site-packages/geventwebsocket/handler.py:101]:
Validating WebSocket request
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in handler [/home/alex/.virtualenvs/py2/local/lib/python2.7/site-packages/geventwebsocket/handler.py:105]:
Can only upgrade connection if using GET method.
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
DEBUG in flask_sockets_bug_43 [./flask_sockets_bug_43.py:22]:
inside 'status'
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
INFO in handler [/home/alex/.virtualenvs/py2/local/lib/python2.7/site-packages/geventwebsocket/handler.py:237]:
127.0.0.1 - - [2016-09-27 13:13:31] "POST /status HTTP/1.1" 200 134 0.000922
--------------------------------------------------------------------------------

[o3bvv]

So, WebSocketHandler from gevent-websocket library tries to upgrade any kind of connection into WS connection.

This is a valid logic, since a web server listens for all incoming connections on a single socket. Hence, all connections are passed through same logic: handler checks whether connection is a websocket connection or not. And there are vivid messages for that:

if self.environ.get('REQUEST_METHOD', '') != 'GET':
    # This is not a websocket request, so we must not handle it
    self.logger.debug('Can only upgrade connection if using GET method.')
    return

if upgrade == 'websocket':
    ...
else:
    # This is not a websocket request, so we must not handle it
    return

So, your messages

Initializing WebSocket Sep 25 04:12:32 surcle app/web.1: Validating WebSocket request Sep 25 04:12:32 surcle app/web.1: Can only upgrade connection if using GET method.

are not errors, they are just debug messages. Nothing goes wrong.

I agree that they are confusing and the only thing you can do is to open an issue in gevent-websocket and to ask to write more correct messages to logs.

Other thing you can do is set up a logging handler for a logger named geventwebsocket.server and ignore debug messages coming from it.

Does this answer your question?

[o3bvv]

@winster can this issue be closed?

[winster]

closing this