Your question
I have created simple chat based on Flask-Socketio, Vue.js and html/css. Application works fine locally, with socketio.run. But upon deployment the application work showing only rendering of html input and button. Background, chat window messages are missing. Could you please help to understand the reason of the application displayed partially upon deployment?
Here is the server-side code:
import os
from os import environ
from dotenv import load_dotenv, find_dotenv
import eventlet
eventlet.monkey_patch()
from flask import Flask, render_template
from flask_socketio import SocketIO, emit, send
from flask import session
load_dotenv(find_dotenv())
app = Flask(__name__)
app.config['SECRET_KEY'] = environ.get('KEY')
socketio = SocketIO(app, manage_session = False)
@app.route('/')
def index():
return render_template('session.html')
@socketio.on('message')
def handle_message(msg):
send(msg, broadcast = True)
@socketio.on('join')
def join_username(username):
emit('message', {'user':'Chat', 'message':username + ' joined this chatroom'}, broadcast = True)
socketio.sleep(0)
if __name__ == '__main__':
socketio.run(app, debug = True)
And heroky.yml:
build:
docker:
web: Dockerfile
run:
web: gunicorn --worker-class eventlet -w 1 chat:app
Logs
2019-11-15T09:46:43.050884+00:00 app[web.1]: return os.sendfile(fdout, fdin, offset, nbytes)
2019-11-15T09:46:43.050887+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/geventlet.py", line 32, in _eventlet_sendfile
2019-11-15T09:46:43.050889+00:00 app[web.1]: return os.sendfile(fdout, fdin, offset, nbytes)
2019-11-15T09:46:43.050891+00:00 app[web.1]: [Previous line repeated 968 more times]
2019-11-15T09:46:43.050893+00:00 app[web.1]: RecursionError: maximum recursion depth exceeded
2019-11-15T09:46:43.908752+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=wuji.herokuapp.com request_id=dbbd986c-7107-45d4-8a76-29ce30a4ec2e fwd="178.133.105.238" dyno=web.1 connect=0ms service=4ms status=404 bytes=385 protocol=https
2019-11-15T10:22:52.352597+00:00 heroku[web.1]: Idling
2019-11-15T10:22:52.356719+00:00 heroku[web.1]: State changed from up to down
2019-11-15T10:22:53.326695+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2019-11-15T10:22:53.415883+00:00 heroku[web.1]: Process exited with status 143
This does not seem to be related to Socket.IO, it's some sort of recursion loop in either eventlet or gunicorn's eventlet worker.
I suggest you try moving the monkey patching above all other imports. If that does not do it, then you may want to try an older eventlet release (assuming you are on the latest one).
I moved eventlet import to the top of imports, updated eventlet version from 0.25.1 to 0.22.1, got the response that eventlet 0.24.0 or higher is needed. So I tried v.0.24.1 but still same result.
But I appreciate very much your help and advice where to look for the solution.
I will try gunicorn version lower than 20.0.0 or will check if switching from eventlet to gevent will help.
Thank you, Miguel!
Which module gave you this message that eventlet 0.24 was needed? I have used eventlet for a long time and never had any issues working with older versions.
First I got error message in CMD "Could not install eventlet packages". Then I checked logs in heroku, here are the logs:
2019-11-15T20:18:45.964778+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/geventlet.py", line 18, in
2019-11-15T20:18:45.964780+00:00 app[web.1]: raise RuntimeError("eventlet worker requires eventlet 0.24.1 or higher")
2019-11-15T20:18:45.964782+00:00 app[web.1]: RuntimeError: eventlet worker requires eventlet 0.24.1 or higher
Okay. This is gunicorn complaining. You may need to also downgrade gunicorn to be able to use older eventlet releases.
Thank you, Miguel. I will check with gunicorn downgrade and will share the result.
Update: gunicorn 19.0.0 failed as well. I will try with gevent or will change the server to uWSGI.
here are the logs for gunicorn 19.0 attempt:
2019-11-16T12:28:13.615706+00:00 app[web.1]: File "
2019-11-16T12:28:13.615707+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/geventlet.py", line 24
2019-11-16T12:28:13.615709+00:00 app[web.1]: from gunicorn.workers.async import AsyncWorker
2019-11-16T12:28:13.615710+00:00 app[web.1]: ^
2019-11-16T12:28:13.615712+00:00 app[web.1]: SyntaxError: invalid syntax
2019-11-16T12:28:13.615713+00:00 app[web.1]: ]
2019-11-16T12:28:13.615715+00:00 app[web.1]:
2019-11-16T12:28:13.666252+00:00 heroku[web.1]: Process exited with status 1
2019-11-16T12:29:06.576390+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/" host=wuji.herokuapp.com request_id=bce8f684-f9dc-4b39-ab25-6a7d00bccc47 fwd="193.194.107.70" dyno= connect= service= status=503 bytes= protocol=https
2019-11-16T12:29:07.223176+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/favicon.ico" host=wuji.herokuapp.com request_id=2d4bd448-7716-46bf-9ced-063b99ba5252 fwd="193.194.107.70" dyno= connect= service= status=503 bytes= protocol=https
thank you again, checking diferent versions helped partially (I used eventlet 25.1 and gunicorn 19.9). Now I am half way closer to the result )) all html forms with css rendered correctly, but it seems that sockets do not work, user is not joined (simple login without registration) and message is not sent.
I've got the logs, but I can not understand the point of the last line with "status=404". I appreciate if you can advice the direction of the probable reason of the error.
2019-11-17T03:16:24.005475+00:00 app[web.1]: [2019-11-17 03:16:24 +0000] [5] [INFO] Starting gunicorn 19.9.0
2019-11-17T03:16:24.007671+00:00 app[web.1]: [2019-11-17 03:16:24 +0000] [5] [INFO] Listening at: http://0.0.0.0:8431 (5)
2019-11-17T03:16:24.007930+00:00 app[web.1]: [2019-11-17 03:16:24 +0000] [5] [INFO] Using worker: eventlet
2019-11-17T03:16:24.023181+00:00 app[web.1]: [2019-11-17 03:16:24 +0000] [8] [INFO] Booting worker with pid: 8
2019-11-17T03:16:44.625935+00:00 heroku[router]: at=info method=GET path="/" host=wuji.herokuapp.com request_id=a4652171-e189-4306-94e5-96c1ffc16d3e fwd="193.194.107.70" dyno=web.1 connect=1ms service=30ms status=200 bytes=3620 protocol=https
2019-11-17T03:16:45.272409+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=wuji.herokuapp.com request_id=ce1aea77-8d53-4c57-80d6-d35ccdb1e83c fwd="193.194.107.70" dyno=web.1 connect=1ms service=4ms status=404 bytes=385 protocol=https
The 404 is for the /favicon.ico URL. This is the browser trying to get your site's favicon. Since you don't have one, the response is 404. You can ignore this.
You may want to enable Socket.IO logs to see if there are any errors there.
Thank you. If I do understand correctly, socket.io logs an be checked only locally (or I am wrong?)
Locally everything works fine. Is there possibility to check socket.io logs on the deployed application?
By default logs go out to the console. Heroku will capture them and show them to you when you use the heroku logs command.
Thank you, Miguel.
Here are the logs. Could you please help to understand the reason of blocking SocketIO:
2019-11-17T11:33:13.224742+00:00 heroku[web.1]: Unidling
2019-11-17T11:33:13.227669+00:00 heroku[web.1]: State changed from down to starting
2019-11-17T11:33:30.105531+00:00 heroku[web.1]: Starting process with command `/bin/sh -c gunicorn\ --worker-class\ eventlet\ -w\ 1\ chat:app`
2019-11-17T11:33:32.540584+00:00 app[web.1]: [2019-11-17 11:33:32 +0000] [5] [INFO] Starting gunicorn 19.9.0
2019-11-17T11:33:32.541423+00:00 app[web.1]: [2019-11-17 11:33:32 +0000] [5] [INFO] Listening at: http://0.0.0.0:36003 (5)
2019-11-17T11:33:32.541508+00:00 app[web.1]: [2019-11-17 11:33:32 +0000] [5] [INFO] Using worker: eventlet
2019-11-17T11:33:32.548225+00:00 app[web.1]: [2019-11-17 11:33:32 +0000] [8] [INFO] Booting worker with pid: 8
2019-11-17T11:33:33.023295+00:00 heroku[web.1]: State changed from starting to up
2019-11-17T11:33:35.333722+00:00 heroku[router]: at=info method=GET path="/" host=wuji.herokuapp.com request_id=452b73d0-90f4-4a50-92fe-84bc5edea673 fwd="193.194.107.70" dyno=web.1 connect=0ms service=9ms status=200 bytes=3620 protocol=https
2019-11-17T11:33:48.671677+00:00 heroku[router]: at=info method=GET path="/" host=wuji.herokuapp.com request_id=71206841-c094-433a-bcf9-4f21b5456f30 fwd="193.194.107.70" dyno=web.1 connect=0ms service=2ms status=200 bytes=3620 protocol=https
2019-11-17T11:33:48.926355+00:00 heroku[router]: at=info method=GET path="/static/css/main.css" host=wuji.herokuapp.com request_id=acf03395-30d2-4daa -a843-9a51ff2fe5a1 fwd="193.194.107.70" dyno=web.1 connect=0ms service=2ms status=200 bytes=3342 protocol=https
2019-11-17T11:33:49.877124+00:00 heroku[router]: sock=backend at=error code=H18 desc="Server Request Interrupted" method=GET path="/static/images/sai lboat.jpg" host=wuji.herokuapp.com request_id=5aa73c6b-f273-4a98-868f-78ad90623854 fwd="193.194.107.70" dyno=web.1 connect=0ms service=13ms status=50 3 bytes= protocol=https
2019-11-17T11:33:49.869692+00:00 app[web.1]: [2019-11-17 11:33:49 +0000] [8] [ERROR] Socket error processing request.
2019-11-17T11:33:49.869724+00:00 app[web.1]: Traceback (most recent call last):
2019-11-17T11:33:49.869727+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/base_async.py", line 66, in handle
2019-11-17T11:33:49.869728+00:00 app[web.1]: six.reraise(*sys.exc_info())
2019-11-17T11:33:49.869731+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/six.py", line 625, in reraise
2019-11-17T11:33:49.869732+00:00 app[web.1]: raise value
2019-11-17T11:33:49.869734+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/base_async.py", line 56, in handle
2019-11-17T11:33:49.869736+00:00 app[web.1]: self.handle_request(listener_name, req, client, addr)
2019-11-17T11:33:49.869738+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/base_async.py", line 129, in handle_reques t
2019-11-17T11:33:49.869739+00:00 app[web.1]: six.reraise(*sys.exc_info())
2019-11-17T11:33:49.869741+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/six.py", line 625, in reraise
2019-11-17T11:33:49.869742+00:00 app[web.1]: raise value
2019-11-17T11:33:49.869744+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/workers/base_async.py", line 112, in handle_reques t
2019-11-17T11:33:49.869746+00:00 app[web.1]: resp.write_file(respiter)
2019-11-17T11:33:49.869747+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/http/wsgi.py", line 403, in write_file
2019-11-17T11:33:49.869749+00:00 app[web.1]: if not self.sendfile(respiter):
2019-11-17T11:33:49.869750+00:00 app[web.1]: File "/usr/local/lib/python3.7/site-packages/gunicorn/http/wsgi.py", line 393, in sendfile
2019-11-17T11:33:49.869752+00:00 app[web.1]: sent += sendfile(sockno, fileno, offset + sent, count)
2019-11-17T11:33:49.869753+00:00 app[web.1]: BlockingIOError: [Errno 11] Resource temporarily unavailable
2019-11-17T11:33:49.972172+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=wuji.herokuapp.com request_id=1a769c1f-a05b-462d-afb5-98 6f13b3a659 fwd="193.194.107.70" dyno=web.1 connect=0ms service=4ms status=404 bytes=385 protocol=https
2019-11-17T11:33:56.210166+00:00 heroku[router]: at=info method=GET path="/" host=wuji.herokuapp.com request_id=bd599fd0-688a-492f-b787-6db50f873f5f fwd="193.194.107.70" dyno=web.1 connect=0ms service=3ms status=200 bytes=3620 protocol=https
2019-11-17T11:33:56.424035+00:00 heroku[router]: at=info method=GET path="/static/css/main.css" host=wuji.herokuapp.com request_id=8f665602-24f3-4ddc -94b0-d410c1111f89 fwd="193.194.107.70" dyno=web.1 connect=0ms service=3ms status=304 bytes=248 protocol=https
2019-11-17T11:33:56.752602+00:00 heroku[router]: at=info method=GET path="/static/images/sailboat.jpg" host=wuji.herokuapp.com request_id=7bb5a7b8-ea 50-4c3a-ac61-55a1c89db803 fwd="193.194.107.70" dyno=web.1 connect=1ms service=43ms status=206 bytes=1667984 protocol=https
I don't see any socket.io logs. Have you enabled logging on the socket.io server?
No, I didn't. Excuse me, I will sort it out and will get back with correct logs.
Here is the way I switched the logger on:
import eventlet
eventlet.monkey_patch()
import os
from os import environ
from dotenv import load_dotenv, find_dotenv
from flask import Flask, render_template
from flask_socketio import SocketIO, emit, send
from flask import session
load_dotenv(find_dotenv())
app = Flask(__name__)
app.config['SECRET_KEY'] = environ.get('KEY')
socketio = SocketIO(app, logger=True, engineio_logger=True, manage_session = False)
But consol (with heroku logs) give only similar info as before:
2019-11-17T14:30:22.657846+00:00 heroku[web.1]: State changed from crashed to starting
2019-11-17T14:30:22.125859+00:00 app[api]: Release v50 created by user vitaly.[email protected]
2019-11-17T14:30:22.000000+00:00 app[api]: Build succeeded
2019-11-17T14:30:22.125859+00:00 app[api]: Deploy d4e93a1d by user vitaly.[email protected]
2019-11-17T14:30:36.114191+00:00 heroku[web.1]: Starting process with command /bin/sh -c gunicorn\ --worker-class\ eventlet\ -w\ 1\ chat:app
2019-11-17T14:30:37.854540+00:00 app[web.1]: [2019-11-17 14:30:37 +0000] [5] [INFO] Starting gunicorn 19.9.0
2019-11-17T14:30:37.855035+00:00 app[web.1]: [2019-11-17 14:30:37 +0000] [5] [INFO] Listening at: http://0.0.0.0:8527 (5)
2019-11-17T14:30:37.855120+00:00 app[web.1]: [2019-11-17 14:30:37 +0000] [5] [INFO] Using worker: eventlet
2019-11-17T14:30:37.861390+00:00 app[web.1]: [2019-11-17 14:30:37 +0000] [8] [INFO] Booting worker with pid: 8
2019-11-17T14:30:38.122664+00:00 app[web.1]: Server initialized for eventlet.
2019-11-17T14:30:38.419599+00:00 heroku[web.1]: State changed from starting to up
2019-11-17T14:30:49.011851+00:00 heroku[router]: at=info method=GET path="/" host=wuji.herokuapp.com request_id=723c717f-b51d-424e-a18c-dbf3fdf42d2c fwd="193.194.107.70" dyno=web.1 connect=0ms service=19ms status=200 bytes=3620 protocol=https
Could you please tell if I did wrong for logs checking?
Unlike the previous log dump, this one has no errors, so it is in fact different. This log looks fine, but I don't see any incoming Socket.IO connections.
If the logger is scripted correctly, the lack of Socket.IO logs gives me the idea that gunicorn doesn't see this part of the application... I will try to downrade gunicorn to older versions.
I think the reason may be in front end part. socketio in my application is linked with Vue.js. As In the application, Vuejs part is used via CDN, it hasn't been mentioned in requirements. I will check, perhaps this is the reason.
Do you see a connection from the side of the client? If you do, then the logging must not be working. If you don't, then you need to ensure that the client connects. Try the application locally to see how the logs look when there is an incoming connection.
Locally everythin works fine, client connects sending following messages to console:
(it works with eventlet as good as with gevent - below are latest result I tried locally)
(env_chat) F:\Programming\Python\Chatroom\chat_root>chat.py
Server initialized for gevent.
My client is connected the following way:
<script src="https://cdnjs.cloudflare.com/ajax/libs/socket.io/2.2.0/socket.io.js"></script>
<script src="https://cdn.jsdelivr.net/npm/vue-chat-scroll/dist/vue-chat-scroll.min.js"></script>
<script type="text/javascript" charset="utf-8">
var socket = io.connect('https://' + document.domain + ':' + location.port);
And I deploy it to heroku with the help of heroku.yml with content:
build:
docker:
web: Dockerfile
run:
web: gunicorn -k gevent -w 1 chat:app
(according to heroku documentation, Procfile is not needed in this case)
When you test it locally, you are testing w/o a container, it seems. Does it work locally as a container?
I just checked as container via heroku local and got the following message:
$ heroku local
[OKAY] Loaded ENV .env File as KEY=VALUE Format
15:37:52 web.1 | "gunicorn" �� ���� ����à¥ï¿½ï¿½ï¿½ ��� ���è¥ï¿½
15:37:52 web.1 | ��������, �ᯮ��塞�� ï¿½à®£à ¬ï¿½ï¿½ï¿½ ��� ������ ä ©ï¿½ï¿½ï¿½.
[DONE] Killing all processes with signal SIGINT
15:37:52 web.1 Exited with exit code null
No idea what is the reason of those garbled messages. Do you know?
I suppose that there are at least two issues causing problems.
1) The last logs above (upon running container locally), I think they are related with dotenv, with secret key stored in a separate .env file. and .env included to dockerignore.
2) Second issue may be related with server port for socketio. I have changed http:// to https://.
The application still loads partially, but with https I got logs seem to be related with socketio^
2019-11-18T14:56:58.971331+00:00 app[web.1]: https://wuji.herokuapp.com is not an accepted origin.
2019-11-18T14:57:00.166534+00:00 heroku[router]: at=info method=GET path="/socket.io/?EIO=3&transport=polling&t=Mv_14MO" host=wuji.herokuapp.com request_id=7171bb12-b286-4481-939b-66dd5b20b9b3 fwd="193.194.107.70" dyno=web.1 connect=1ms service=6ms status=200 bytes=387 protocol=https
2019-11-18T14:57:00.157781+00:00 app[web.1]: 1a4e5e84803c424fbbea34cdbc371fdd: Sending packet OPEN data {'sid': '1a4e5e84803c424fbbea34cdbc371fdd', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
2019-11-18T14:57:00.158640+00:00 app[web.1]: 1a4e5e84803c424fbbea34cdbc371fdd: Sending packet MESSAGE data 0
2019-11-18T14:57:00.590351+00:00 heroku[router]: at=info method=GET path="/socket.io/?EIO=3&transport=websocket&sid=1a4e5e84803c424fbbea34cdbc371fdd" host=wuji.herokuapp.com request_id=2690ff7f-7f3a-476f-ae3d-06f5f6529049 fwd="193.194.107.70" dyno=web.1 connect=0ms service=11ms status=400 bytes=189 protocol=https
2019-11-18T14:57:00.587213+00:00 app[web.1]: https://wuji.herokuapp.com is not an accepted origin.
2019-11-18T14:57:01.731215+00:00 app[web.1]: 2aba0e87774240de946af40c943e8831: Client is gone, closing socket
2019-11-18T14:57:01.732867+00:00 app[web.1]: 2aba0e87774240de946af40c943e8831: Client is gone, closing socket
2019-11-18T14:57:02.183375+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/socket.io/?EIO=3&transport=polling&t=Mv_0zXl&sid=009cb46954bc436c959c8227f39652ff" host=wuji.herokuapp.com request_id=657926d5-319d-43b4-aa27-cda326fed108 fwd="193.194.107.70" dyno=web.1 connect=1ms service=30001ms status=503 bytes=0 protocol=https
Oh, okay. The origin problem is easy to address. Add cors_allowed_origins='https://wuji.herokuapp.com' to your SocketIO() constructor to allow incoming requests from your Heroku app origin.
ho ho ho!! It works!! )))
Three days debugging and now it works... love these moments ))
Miguel, thank you a lot for your assistance and your great help. Trying to find the reason of the problem, I have learned a lot of details, and you know, most of the useful discussions have been found in your conference. Thanks!
Most helpful comment
ho ho ho!! It works!! )))
Three days debugging and now it works... love these moments ))
Miguel, thank you a lot for your assistance and your great help. Trying to find the reason of the problem, I have learned a lot of details, and you know, most of the useful discussions have been found in your conference. Thanks!