Random OSError: headers already sent, with gevent_uwsgi

[bigzt]

Hello there,

I began to use Flask-SocketIO today. When i test the example/app.py with uwsgi, I randomly get an OSError: headers already sent

The log is below:

c65db7fdd64742a588366d0782be834e: Received packet MESSAGE data 2/test,["close_room",{"room":"31"}]
c65db7fdd64742a588366d0782be834e: Sending packet MESSAGE data 2/test,["my_response",{"count":3,"data":"Server generated event"}]
[uwsgi-websocket] "GET /socket.io/?EIO=3&transport=websocket&sid=c65db7fdd64742a588366d0782be834e" (192.168.1.133) no PONG received in 3 seconds !!!
Client disconnected c65db7fdd64742a588366d0782be834e
Traceback (most recent call last):
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/flask/app.py", line 2000, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/flask_socketio/__init__.py", line 41, in __call__
    start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/engineio/middleware.py", line 47, in __call__
    return self.engineio_app.handle_request(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/socketio/server.py", line 352, in handle_request
    return self.eio.handle_request(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/engineio/server.py", line 279, in handle_request
    start_response(r['status'], r['headers'] + cors_headers)
OSError: headers already sent
[pid: 30430|app: 0|req: 8/8] 192.168.1.133 () {50 vars in 1258 bytes} [Thu Dec  8 11:57:14 2016] GET /socket.io/?EIO=3&transport=websocket&sid=c65db7fdd64742a588366d0782be834e => generated 643 bytes in 33009 msecs (HTTP/1.1 101) 4 headers in 188 bytes (1 switches on core 999)
605b2357656a4595b56e52488bf1b5c5: Sending packet OPEN data {'pingInterval': 25000, 'upgrades': ['websocket'], 'pingTimeout': 60000, 'sid': '605b2357656a4595b56e52488bf1b5c5'}
605b2357656a4595b56e52488bf1b5c5: Sending packet MESSAGE data 0
[pid: 30430|app: 0|req: 9/9] 192.168.1.133 () {42 vars in 1035 bytes} [Thu Dec  8 11:57:48 2016] GET /socket.io/?EIO=3&transport=polling&t=1481169485617-6 => generated 119 bytes in 0 msecs (HTTP/1.1 200) 4 headers in 195 bytes (3 switches on core 999)
605b2357656a4595b56e52488bf1b5c5: Received request to upgrade to websocket
605b2357656a4595b56e52488bf1b5c5: Sending packet NOOP data None

I test several times, but it seems the Error appears randomly.

The command I used to run the example:
uwsgi --http :8080 --gevent 1000 --http-websockets --master --wsgi-file app_origin.py --callable app -H ~/hospital_server/env_hospital/

[miguelgrinberg]

Is there always a no PONG received in 3 seconds !!! right above the other error? That I think is where the problem is, uwsgi is writing that message, need to investigate why.

[bigzt]

@miguelgrinberg, thank you for your replay. I found that the OSError always appears when the client disconnect the connection.

[miguelgrinberg]

Before you said that the error appeared randomly, though. Are you sure it is only when a client disconnects? The log that you copied above does not suggest the client willingly disconnected, my interpretation is that uWSGI disconnected the user for some reason, so I want to try to figure out what made it break that connection.

[bigzt]

I cant find other error in the log.

Well, I dont know the no PONG received in 3 seconds !!! is from uwsgi or others, but i think it may let the server disconnect the connection because there is no PING signal. I set the web emit my_ping signal in 1s, it also has no PONG received in 3 seconds !!! and the OSerror.
And when i refresh the web, it appears too. The refresh action will let the client disconnect the connection, right? Closing the web has the OSerror too.

179eac6b5b1d4f37a674672386604255: Received packet MESSAGE data 2/test,["my_ping"]
179eac6b5b1d4f37a674672386604255: Sending packet MESSAGE data 2/test,["my_pong",null]
Client disconnected 179eac6b5b1d4f37a674672386604255
Traceback (most recent call last):
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/flask/app.py", line 2000, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/flask_socketio/__init__.py", line 41, in __call__
    start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/engineio/middleware.py", line 47, in __call__
    return self.engineio_app.handle_request(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/socketio/server.py", line 352, in handle_request
    return self.eio.handle_request(environ, start_response)
  File "/home/demo/hospital_server/env_hospital/lib/python3.5/site-packages/engineio/server.py", line 279, in handle_request
    start_response(r['status'], r['headers'] + cors_headers)
OSError: headers already sent
[pid: 14639|app: 0|req: 8/8] 192.168.1.133 () {50 vars in 1257 bytes} [Fri Dec  9 09:42:23 2016] GET /socket.io/?EIO=3&transport=websocket&sid=179eac6b5b1d4f37a674672386604255 => generated 400 bytes in 15453 msecs (HTTP/1.1 101) 4 headers in 188 bytes (1 switches on core 999)

[lbsonix]

I got the same error running a socket io server via uwsgi.
I only get the error when the client disconnects (reload / browser close).

2017-01-04T14:07:56.336012420Z compiled with version: 4.9.2 on 04 January 2017 13:26:53
2017-01-04T14:07:56.336015427Z os: Linux-3.19.0-26-generic #28~14.04.1-Ubuntu SMP Wed Aug 12 14:09:17 UTC 2015
2017-01-04T14:07:56.336017839Z nodename: 5cf4349080cb
2017-01-04T14:07:56.336020064Z machine: x86_64
2017-01-04T14:07:56.336022234Z clock source: unix
2017-01-04T14:07:56.336024470Z detected number of CPU cores: 8
2017-01-04T14:07:56.336026772Z current working directory: /usr/src/app
2017-01-04T14:07:56.336029002Z detected binary path: /usr/local/bin/uwsgi
2017-01-04T14:07:56.336032934Z !!! no internal routing support, rebuild with pcre support !!!
2017-01-04T14:07:56.336035406Z your processes number limit is 524288
2017-01-04T14:07:56.336037549Z your memory page size is 4096 bytes
2017-01-04T14:07:56.336039743Z detected max file descriptor number: 524288
2017-01-04T14:07:56.336041974Z - async cores set to 3000 - fd table size: 524288
2017-01-04T14:07:56.336046010Z lock engine: pthread robust mutexes
2017-01-04T14:07:56.336052677Z thunder lock: disabled (you can enable it with --thunder-lock)
2017-01-04T14:07:56.336055078Z uWSGI http bound on :8080 fd 4
2017-01-04T14:07:56.336057317Z uwsgi socket 0 bound to TCP address 127.0.0.1:45777 (port auto-assigned) fd 3
2017-01-04T14:07:56.336060103Z Python version: 3.5.1 (default, May 24 2016, 06:55:35)  [GCC 4.9.2]
2017-01-04T14:07:56.342754740Z Python main interpreter initialized at 0x1d42950
2017-01-04T14:07:56.342775292Z python threads support enabled
2017-01-04T14:07:56.342778171Z your server socket listen backlog is limited to 100 connections
2017-01-04T14:07:56.342784777Z your mercy for graceful operations on workers is 60 seconds
2017-01-04T14:07:56.345755562Z mapped 61948928 bytes (60497 KB) for 3000 cores
2017-01-04T14:07:56.345786059Z *** Operational MODE: async ***

2017-01-04T15:40:25.003606534Z Traceback (most recent call last):
2017-01-04T15:40:25.003617398Z   File "/usr/local/lib/python3.5/site-packages/engineio/middleware.py", line 47, in __call__
2017-01-04T15:40:25.003707044Z     return self.engineio_app.handle_request(environ, start_response)
2017-01-04T15:40:25.003713272Z   File "/usr/local/lib/python3.5/site-packages/socketio/server.py", line 352, in handle_request
2017-01-04T15:40:25.003831237Z     return self.eio.handle_request(environ, start_response)
2017-01-04T15:40:25.003839909Z   File "/usr/local/lib/python3.5/site-packages/engineio/server.py", line 279, in handle_request
2017-01-04T15:40:25.003932994Z     start_response(r['status'], r['headers'] + cors_headers)
2017-01-04T15:40:25.003940529Z OSError: headers already sent

uwsgi --http :8080 --http-raw-body --gevent 3000 --gevent-monkey-patch --master --http-websockets -w backend.wsgi

[andreatulimiero]

Same for me, when the client disconnect I get the error

  File "/home/tuly/sparks/env/lib/python3.4/site-packages/flask/app.py", line 1994, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/tuly/sparks/env/lib/python3.4/site-packages/flask_socketio/__init__.py", line 42, in __call__
    start_response)
  File "/home/tuly/sparks/env/lib/python3.4/site-packages/engineio/middleware.py", line 47, in __call__
    return self.engineio_app.handle_request(environ, start_response)
  File "/home/tuly/sparks/env/lib/python3.4/site-packages/socketio/server.py", line 350, in handle_request
    return self.eio.handle_request(environ, start_response)
  File "/home/tuly/sparks/env/lib/python3.4/site-packages/engineio/server.py", line 279, in handle_request
    start_response(r['status'], r['headers'] + cors_headers)
OSError: headers already sent
[pid: 8595|app: 0|req: 50/50] 87.16.233.143 () {48 vars in 983 bytes} [Sat Jan 28 18:49:00 2017] GET /socket.io/?EIO=3&transport=websocket&sid=325e475da2774885b5f0ba5eb0b20b49 => generated 195 bytes in 48015 msecs (HTTP/1.1 101) 4 headers in 190 bytes (1 switches on core 999)

The settings I'm using are the ones suggested on the flask_socketio page:
uwsgi --http 0.0.0.0:8080 --gevent 1000 --http-websockets --master --wsgi-file manage.py --callable app

[miguelgrinberg]

@andreatulimiero This is a fairly common problem with WebSocket connections. When the connection ends, the server tries to end the request like a normal HTTP request under WSGI, by sending an HTTP response. But WebSocket works in a different way and the way to end requests is different. The code should have recognized that this was a WebSocket request and handle it appropriately, but apparently it isn't. This should not cause any problems to your application, besides the annoying error every time a client disconnects.

[miguelgrinberg]

Please upgrade package python-engineio and let me know if this problem still occurs. It now works fine for me, so I'm hopeful.

[andreatulimiero]

@miguelgrinberg after the upgrade is working like a charm !