benoitc / gunicorn

gunicorn 'Green Unicorn' is a WSGI HTTP Server for UNIX, fast clients and sleepy applications.
http://www.gunicorn.org
Other
9.83k stars 1.75k forks source link

Old bug reproduced:'Response' object has no attribute 'status_code' in wsgi.py with websockets #1852

Open BoWuGit opened 6 years ago

BoWuGit commented 6 years ago

Just like this old issue 1210 said, gunicorn logs error when client disconnects, and my environment is:

Everything works well including clients, except for this error log, two cloud independent production instances both persistently logs,but I can't reproduce it in my develop machine, which is a mac.

Much thanks for your help.

Error handling request /socket.io/?EIO=3&transport=websocket Traceback (most recent call last): File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/workers/async.py", line 56, in handle self.handle_request(listener_name, req, client, addr) File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/workers/async.py", line 116, in handle_request resp.close() File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/http/wsgi.py", line 409, in close self.send_headers() File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/http/wsgi.py", line 325, in send_headers tosend = self.default_headers() File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/http/wsgi.py", line 306, in default_headers elif self.should_close(): File "/opt/apps/lms/virtualenv/lib/python3.4/site-packages/gunicorn/http/wsgi.py", line 229, in should_close if self.status_code < 200 or self.status_code in (204, 304): AttributeError: 'Response' object has no attribute 'status_code'

benoitc commented 6 years ago

do you have any simple example to reproduce it? Also please try with latest master if possible.

BoWuGit commented 6 years ago

Previously I have tried several times in my local development environment,which is the same application code with production environment,but I can't reproduce it.

And I have checked version 19.9.0 release log,not found something related,I'll keep watching this error log,if find something new,I would post here.

mat10tng commented 6 years ago

I too have this problem, specifically when I force all my connection from client to websocket protocol. My settings is the same as BoWuGit. If allow polling protocol before upgrade, this does not show up, but another error : ` [ERROR] Error handling request /socket.io/?EIO=3&transport=polling&t=MPRHUoV&sid=cd64be7c940e474d8728b114c3fb9bbe

Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/async.py", line 56, in handle self.handle_request(listener_name, req, client, addr)

File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/async.py", line 107, in handle_request respiter = self.wsgi(environ, resp.start_response)

File "/usr/local/lib/python3.6/site-packages/flask/app.py", line 1994, in call return self.wsgi_app(environ, start_response)

File "/usr/local/lib/python3.6/site-packages/flask_socketio/init.py", line 43, in call start_response)

File "/usr/local/lib/python3.6/site-packages/engineio/middleware. py", line 47, in call return self.engineio_app.handle_request(environ, start_response)

File "/usr/local/lib/python3.6/site-packages/socketio/server.py", line 360, in handle_request return self.eio.handle_request(environ, start_response)

File "/usr/local/lib/python3.6/site-packages/engineio/server.py", line 279, in handle_request socket = self._get_socket(sid)

File "/usr/local/lib/python3.6/site-packages/engineio/server.py", line 439, in _get_socket raise KeyError('Session is disconnected') ` But I suspect it might have something to do with each other, since I force the connection to be websocket, this error has not been seen again.

Mitalee commented 6 years ago

Having this issue as well with gunicorn 19.9.0 and Flask-socketIO 3.0.2, when using eventlet 0.24.1

AttributeError: 'Response' object has no attribute 'status_code'

insanj commented 5 years ago

Also experiencing this issue with the following requirements:

Flask==1.0.2
gunicorn==19.5.0
python-socketio==2.0.0
eventlet==0.24.1

Error message when closing web browser that has open socket connection:

 Error handling request /socket.io/?EIO=3&transport=websocket&sid=d43ec0ae0bb946debc51f1ca2e5b8a94
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/gunicorn/workers/async.py", line 52, in handle
    self.handle_request(listener_name, req, client, addr)
  File "/usr/lib/python2.7/dist-packages/gunicorn/workers/async.py", line 114, in handle_request
    resp.close()
  File "/usr/lib/python2.7/dist-packages/gunicorn/http/wsgi.py", line 403, in close
    self.send_headers()
  File "/usr/lib/python2.7/dist-packages/gunicorn/http/wsgi.py", line 319, in send_headers
    tosend = self.default_headers()
  File "/usr/lib/python2.7/dist-packages/gunicorn/http/wsgi.py", line 300, in default_headers
    elif self.should_close():
  File "/usr/lib/python2.7/dist-packages/gunicorn/http/wsgi.py", line 233, in should_close
    if self.status_code < 200 or self.status_code in (204, 304):
AttributeError: 'Response' object has no attribute 'status_code'
Mitalee commented 5 years ago

It looks like this issue has been fixed in the latest version of python-engineio..

BoWuGit commented 5 years ago

Have tested with python-engineio latest version(2.3.2), still not work.

NotSoShaby commented 5 years ago

Any news on this issue? I get the same error when using sentry-python

eazow commented 5 years ago

I have the same issue

eventlet: 0.25.1 flask-socketio: 4.2.1 gunicorn: 19.9.0

image

image

benoitc commented 4 years ago

how to reproduce it? cna you provide a simple example?

sagydr commented 4 years ago

i'm also not sure how to reproduce it, but it happens OFTEN when i refresh a page on my gunicorn app

cowbonlin commented 4 years ago

Encounter the same issue, and my environment is the same as @eazow while gunicorn == 20.0.4. It seems that the issue happened after I installed sentry for bug tracking. The issues can be reproduced by

  1. refreshing the page(not opening a new page)
  2. closing the page

Interestingly, opening a new page won't produce the issue. Not sure why. Thanks!

TheSHEEEP commented 4 years ago

I have the same issue as @cowbonlin . Same gunicorn version, too.

After installing sentry, we're getting crazy amounts of this error. Though I find it hard to tell if this always happened or not - since we didn't track errors before sentry.

While it doesn't seem to influence actual functionality of our server, this is just a ton of spam.

blackmicha commented 4 years ago

We're experiencing the same. Sentry installed but disabled. Any ideas?

Divide-By-0 commented 4 years ago

Same issue with sentry installed.

benoitc commented 4 years ago

Do you hve any example that reproduce it without sentry (disabled or not) ?

Divide-By-0 commented 4 years ago

In addition, instead of a namespace I manually hit /api.

benoitc commented 4 years ago

In addition, instead of a namespace I manually hit /api.

what does it mean ? Is this sentry related?

Divide-By-0 commented 4 years ago

In addition, instead of a namespace I manually hit /api.

what does it mean ? Is this sentry related?

No, this is related to socket.io namespaces. I tried removing them, and even after removing them, I get the error. I get this other error on local machine without gunicorn or nginx however, which may be related.

These are my requirements:

sentry_sdk == 0.14.3
Flask_SocketIO == 4.2.1
eventlet == 0.25.1

This is my flask-socketio code on the server side:

socketio = SocketIO(engineio_logger=True, logger=True, debug=True, cors_allowed_origins="*", path='/socket.io')
...
socketio.init_app(app, async_mode="eventlet")

And this is my React socket io code on the client side:

          this.socket = io.connect(`http://localhost:5000?info=${someInfo}`, {
            transports: ['websocket', 'polling'] // an attempt to keep polling as a fallback but start on websockets
          });

Let me know if this helps. On Ubuntu the error looks like the above one, and locally on Windows it looks like this:


  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 599, in handle_one_response
    write(b'')
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 491, in write
    raise AssertionError("write() before start_response()")
AssertionError: write() before start_response()

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 357, in __init__
    self.handle()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 390, in handle
    self.handle_one_request()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 466, in handle_one_request
    self.handle_one_response()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 609, in handle_one_response
    write(err_body)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 538, in write
    wfile.flush()
  File "C:\ProgramData\Anaconda3\lib\socket.py", line 607, in write
    return self._sock.send(b)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\greenio\base.py", line 397, in send
    return self._send_loop(self.fd.send, data, flags)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\greenio\base.py", line 384, in _send_loop
    return send_method(data, *args)
ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\hubs\hub.py", line 461, in fire_timers
    timer()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\hubs\timer.py", line 59, in __call__
    cb(*args, **kw)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\semaphore.py", line 147, in _do_acquire
    waiter.switch()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\greenthread.py", line 221, in main
    result = function(*args, **kwargs)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 818, in process_request
    proto.__init__(conn_state, self)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 359, in __init__
    self.finish()
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\wsgi.py", line 732, in finish
    BaseHTTPServer.BaseHTTPRequestHandler.finish(self)
  File "C:\ProgramData\Anaconda3\lib\socketserver.py", line 784, in finish
    self.wfile.close()
  File "C:\ProgramData\Anaconda3\lib\socket.py", line 607, in write
    return self._sock.send(b)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\greenio\base.py", line 397, in send
    return self._send_loop(self.fd.send, data, flags)
  File "C:\ProgramData\Anaconda3\lib\site-packages\eventlet\greenio\base.py", line 384, in _send_loop
    return send_method(data, *args)
ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine```
Divide-By-0 commented 4 years ago

Can confirm this error disappears when sentry is fully disabled. Would be great if gunicorn was robust enough to deal with this.

Divide-By-0 commented 4 years ago

Bump @benoitc

eelkevdbos commented 4 years ago

Can confirm this error disappears when sentry is fully disabled. Would be great if gunicorn was robust enough to deal with this.

I found that disabling the Sentry's FlaskIntegration also makes the error disappear.

ziddey commented 4 years ago

Seeing similar behavior. Using New Relic in production causes this error with flask-socketio. In development, the werkzeug debugger middleware needs to be loaded before flask-socketio is initialized (so it's not applied to engineio's wsgi app). Problem is production is where I really don't want the errors tripping.

Can't replace the response in gunicorn config's post_request, but I tried forcing a status code onto resp.status_code. It didn't take though.

Canicio commented 4 years ago

This error is reproducible by using Sentry's FlaskIntegration together with Gunicorn and Flask-SocketIO. Is it possible to solve it soon?

blackmicha commented 4 years ago

@Canicio we thought to try that to get rid of the error and even after disabling the integration, the error persists.

Divide-By-0 commented 4 years ago

Does anyone have sharable code/a minimal example for @benoitc to go off of?

ziddey commented 4 years ago

Sure:

import sentry_sdk
from flask import Flask
from flask_socketio import SocketIO
from sentry_sdk.integrations.flask import FlaskIntegration

sentry_sdk.init(
    dsn="https://examplePublicKey@o0.ingest.sentry.io/0",
    integrations=[FlaskIntegration()]
)

app = Flask(__name__)
socketio = SocketIO(app)

@app.route('/')
def index():
    return '''
<script src="https://cdnjs.cloudflare.com/ajax/libs/socket.io/2.2.0/socket.io.js"></script>
<script>
    var socket = io()
</script>

requirements:

gunicorn
flask
sentry-sdk[flask]
flask-socketio
eventlet

example gunicorn config:

bind = '[::]:4444'
worker_class = 'eventlet'
accesslog = '-'

On loading / it'll connect to the websocket. On websocket disconnect (e.g. navigate away, refresh), will produce exception like so:

[2020-09-23 07:24:49 +0000] [16303] [ERROR] Error handling request /socket.io/?EIO=3&transport=websocket&sid=29f4c1adfac343d6bc6db56acf8fd0ee
Traceback (most recent call last):
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/workers/base_async.py", line 55, in handle
    self.handle_request(listener_name, req, client, addr)
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/workers/base_async.py", line 115, in handle_request
    resp.close()
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 402, in close
    self.send_headers()
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 318, in send_headers
    tosend = self.default_headers()
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 299, in default_headers
    elif self.should_close():
  File "/home/ziddey/projects/sentry/venv_sentry/lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 219, in should_close
    if self.status_code < 200 or self.status_code in (204, 304):
AttributeError: 'Response' object has no attribute 'status_code'
2001:470:1f07:7eb:9dd4:254c:35d7:236c - - [23/Sep/2020:07:24:49 +0000] "GET /socket.io/?EIO=3&transport=websocket&sid=29f4c1adfac343d6bc6db56acf8fd0ee HTTP/1.1" 500 0 "-" "-"

Note: I've never actually used sentry myself. This is just from the sentry getting started page. The example dsn works fine for our test.

Commenting integrations=[FlaskIntegration()] will then eliminate the error (of course effectively disabling sentry).

For what it's worth, gevent-websocket can be used instead of eventlet without errors. However, it then seems to handle all requests..

ziddey commented 4 years ago

Ok, did some playing around. Looks like sentry/newrelic wraps the response. Without sentry, we get <eventlet.wsgi._AlreadyHandled object at 0x7fd0f5b1c0d0> as expected and gunicorn's EventletWorker.is_already_handled() will stop iteration.

However, when using sentry, this becomes something like <sentry_sdk.integrations.wsgi._ScopedResponse object at 0x7f30155a5100> instead, failing the check

Instead, we could peek at respiter to see if it's empty. Will look further tomorrow.

ziddey commented 4 years ago

Alright, here's the workaround I've come up with:

eventlet_fix.py: see edit below

And in my gunicorn config.py: worker_class = 'eventlet_fix.EventletWorker.

The issue is that sentry/newrelic wraps the responses, so we can't simply check it against eventlet's ALREADY_HANDLED. Since the nature of an already handled request is that gunicorn's start_response doesn't get called, we can instead check for the presence of a response status.

So I've hijacked the wsgi call to then check for a response status, and hack response values as necessary. This allows the request to still be logged by gunicorn. If instead, it's desired to keep the original behavior, StopIteration can be raised instead.

Hacking the status to 101 is appropriate for our use case here (flask-socketio websocket), but otherwise, leaving it as None works as well since headers_sent and should_close are forced to True.

Again, this makes the assumption that if status isn't set, start_response wasn't called, and therefore the request must have been "already handled" externally.

edit: No good. Will need to reevaluate. If the request takes time to perform, start_response won't be called before resp.status is checked.

edit2: Here's a fixed version with a hacked response iterator:

from functools import wraps

from gunicorn.workers.geventlet import EventletWorker as _EventletWorker

class HackedResponse:
    def __init__(self, respiter, resp):
        self.respiter = iter(respiter)
        self.resp = resp
        if hasattr(respiter, "close"):
            self.close = respiter.close

    def __iter__(self):
        return self

    def __next__(self):
        try:
            return next(self.respiter)
        except StopIteration:
            if not self.resp.status:
                self.resp.status = "101"  # logger derives status code from status instead of using status_code
                self.resp.status_code = 101  # not actually needed since headers_sent/force_close result in status_code not being checked anymore
                self.resp.headers_sent = True
                self.resp.force_close()
            raise

def wsgi_decorator(wsgi):
    @wraps(wsgi)
    def wrapper(environ, start_response):
        respiter = wsgi(environ, start_response)
        resp = start_response.__self__
        return HackedResponse(respiter, resp)

    return wrapper

class EventletWorker(_EventletWorker):
    def load_wsgi(self):
        super().load_wsgi()
        self.wsgi = wsgi_decorator(self.wsgi)

Obviously this is just a monkey patch. The actual fix could potentially go in handle_request in base_async.py. The key may be to (indirectly) check if start_response was called after iterating through respiter, either by checking resp.status (just start_response called) or resp.headers_sent (confirmation that we've actually responded to the request).

Canicio commented 3 years ago

@benoitc @ziddey has found a way to solve the problem.

benoitc commented 3 years ago

@ziddey quick questions for your example (as I am not using sentry).

ziddey commented 3 years ago

@benoitc not able to test currently, but looking at the traceback above https://github.com/benoitc/gunicorn/issues/1852#issuecomment-697189261 and https://github.com/benoitc/gunicorn/blob/4ae2a05c37b332773997f90ba7542713b9bf8274/gunicorn/workers/base_async.py#L107-L140

Normally, is_already_handled would return True and it would just end here.

However, because the response is wrapped, that method doesn't work. Instead, execution progresses, failing at line 115: resp.close() attempts to send headers, but start_response was never called, so there's no status code. Even if it did, it'd still ultimately fail obviously.

This results in an AttributeError that gets reraised and assumedly handled by handle_error. Since the request was already handled externally, there is no harm here other than log spam.

I can't say too much about Sentry-- I'm not using it either.

One detail though: the current already-handled mechanism results in no access logging. I suppose this technically makes sense since there's no way of knowing how it was handled externally. In my hacked response, I force the status code to 101, with headers_sent as True so the handler can proceed and the request still gets access logged.

Checking resp.status is a definitive test for determining if start_response was called.

ziddey commented 3 years ago

@benoitc revisiting this. To more definitively conclude that the request was already handled, environ['gunicorn.socket'] could instead be some sort of proxy for the underlying object. That way, it can be recorded when the socket is accessed directly (e.g. wrapping get_socket() for eventlet), and used for something like is_already_handled

It would still require hacking a response status though if access logging is desired.

lawrenceong commented 3 years ago

Same issue is happening using gthread. Instance started using: gunicorn -w 1 --threads 100 module:app as per https://flask-socketio.readthedocs.io/en/latest/deployment.html. Other than the message, everything looks ok.

[2021-09-06 22:56:33 +0000] [24] [ERROR] Error handling request /socket.io/?EIO=3&transport=websocket
Traceback (most recent call last):
  File "/.../lib/python3.8/site-packages/gunicorn/workers/gthread.py", line 271, in handle
    keepalive = self.handle_request(req, conn)
  File "/.../lib/python3.8/site-packages/gunicorn/workers/gthread.py", line 331, in handle_request
    resp.close()
  File "/.../lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 391, in close
    self.send_headers()
  File "/.../lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 318, in send_headers
    tosend = self.default_headers()
  File "/.../lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 299, in default_headers
    elif self.should_close():
  File "/.../lib/python3.8/site-packages/gunicorn/http/wsgi.py", line 219, in should_close
    if self.status_code < 200 or self.status_code in (204, 304):
AttributeError: 'Response' object has no attribute 'status_code'

Gunicorn 20.1.0 with Python 3.8.12

prav2019 commented 4 months ago

Getting same error after changing worker class to gthread https://github.com/benoitc/gunicorn/issues/1852#issuecomment-913891671. Any updates on this one ?

benoitc commented 2 months ago

@prav2019 whichh version of gunicorn are you using?

prav2019 commented 2 months ago

@prav2019 whichh version of gunicorn are you using?

gunicorn==20.1.0

prav2019 commented 1 month ago

@benoitc Any updates on this one ?

ziddey commented 1 week ago

@prav2019 whichh version of gunicorn are you using?

gunicorn==20.1.0

That's an old version. Should be resolved now. However, upgraded requests go unlogged, and Sentry does not like when simple-websocket raises a StopIteration, so I adapted the earlier eventlet hack into a middleware to handle that. Kind of out of scope here though..

benoitc commented 1 week ago

@ziddey did you opensource it somewhere?

ziddey commented 1 week ago

@benoitc here's the code. It works for using flask-socketio, gunicorn with threads, and sentry, but is lacking guardrails if any other middleware decides to wrap start_response.

from functools import partial

from sentry_sdk.integrations.wsgi import _sentry_start_response

class SIOMiddleware:
    def __init__(self, app):
        self.app = app

    def __call__(self, environ, start_response):
        try:
            return self.app(environ, start_response)
        except StopIteration:
            # python-engineio raises StopIteration when using simple-websocket with gunicorn
            # https://github.com/miguelgrinberg/python-engineio/blob/dce4498122e4ca93fb9237f4bcb43854061e2c7d/src/engineio/async_drivers/_websocket_wsgi.py#L16-L17
            if (
                isinstance(start_response, partial)
                and start_response.func == _sentry_start_response
            ):
                # sentry wraps start_response
                # https://github.com/getsentry/sentry-python/blob/8d4896188802febf5b23a084d2826c70924da9cb/sentry_sdk/integrations/wsgi.py#L130-L138
                resp = start_response.args[0].__self__
            else:
                # warning: assumes start_response is from gunicorn's Response object
                resp = start_response.__self__
            resp.status = "101"
            resp.status_code = 101
            resp.headers_sent = True
            resp.force_close()
            return []

Sentry wraps start_response, so we need to use the original in order to get the gunicorn Response object. We set the status and headers_sent so gunicorn will be able to properly log.

Since sentry will report exceptions, instead of raising StopIteration, we convert to simply returning [], which should result in a StopIteration later on. And since headers_sent is set, gunicorn won't try to do anything.

Obviously if some other middleware is present that wraps start_response, there will likely be breakage. Same if something else raises a StopIteration

Idea is similar to the eventlet hack earlier: https://github.com/benoitc/gunicorn/issues/1852#issuecomment-698057723