Skip to content
This repository has been archived by the owner on Apr 29, 2022. It is now read-only.

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

Closed
winster opened this issue Sep 25, 2016 · 11 comments
Closed

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

winster opened this issue Sep 25, 2016 · 11 comments

Comments

@winster
Copy link

winster commented Sep 25, 2016

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
Copy link
Contributor

o3bvv commented Sep 25, 2016

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
Copy link
Author

winster commented Sep 26, 2016

  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
Copy link
Contributor

o3bvv commented Sep 26, 2016

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
Copy link
Author

winster commented Sep 26, 2016

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
Copy link
Contributor

o3bvv commented Sep 26, 2016

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
Copy link
Author

winster commented Sep 27, 2016

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

@o3bvv
Copy link
Contributor

o3bvv commented Sep 27, 2016

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
Copy link
Contributor

o3bvv commented Sep 27, 2016

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 o3bvv changed the title router end points also try to upgrade the request WebSocketHandler tries to upgrade any kind of connection into WS connection Sep 27, 2016
@o3bvv o3bvv changed the title WebSocketHandler tries to upgrade any kind of connection into WS connection Any kind of connection is tried to be upgraded to WS connection Sep 27, 2016
@o3bvv
Copy link
Contributor

o3bvv commented Sep 27, 2016

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
Copy link
Contributor

o3bvv commented Sep 29, 2016

@winster can this issue be closed?

@winster
Copy link
Author

winster commented Sep 29, 2016

closing this

@winster winster closed this as completed Sep 29, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Development

No branches or pull requests

2 participants