Heroku Problems with Gevent (Request Timeout + Polling Hanging)

[kaimou1357]

IMPORTANT: If you have a question, or you are not sure if you have found a bug in this package, then you are in the wrong place. Hit back in your web browser, and then open a GitHub Discussion instead. Likewise, if you are unable to provide the information requested below, open a discussion to troubleshoot your issue.

Describe the bug
I have a NextJS app on one domain (xxxxx.com) and the Flask server on another (api.xxxxx.com). Locally, it works fine but when I use eventlet/gevent, there seems to be some problems around request timeouts.

The exact stacktrace from the server is here.

2023-12-29T09:54:21.580912+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Sending packet OPEN data {'sid': 'Z00VvgzdNSSsfDydAAAA', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
2023-12-29T09:54:21.581337+00:00 app[web.1]: 10.1.62.47 - - [29/Dec/2023:09:54:21 +0000] "GET /socket.io/?EIO=4&transport=polling&t=Ooq_mLB HTTP/1.1" 200 97 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:21.585339+00:00 app[web.1]: 10.1.83.225 - - [29/Dec/2023:09:54:21 +0000] "OPTIONS /api/projects HTTP/1.1" 200 0 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:21.668891+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Received packet MESSAGE data 0/api/,
2023-12-29T09:54:21.668960+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Sending packet MESSAGE data 4/api/,"Unable to connect"
2023-12-29T09:54:21.669237+00:00 app[web.1]: 10.1.62.47 - - [29/Dec/2023:09:54:21 +0000] "POST /socket.io/?EIO=4&transport=polling&t=Ooq_mPZ&sid=Z00VvgzdNSSsfDydAAAA HTTP/1.1" 200 2 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:21.746055+00:00 app[web.1]: 10.1.62.47 - - [29/Dec/2023:09:54:21 +0000] "GET /socket.io/?EIO=4&transport=polling&t=Ooq_mPa&sid=Z00VvgzdNSSsfDydAAAA HTTP/1.1" 200 27 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:21.669428+00:00 heroku[router]: at=info method=POST path="/socket.io/?EIO=4&transport=polling&t=Ooq_mPZ&sid=Z00VvgzdNSSsfDydAAAA" host=api.goiterative.com request_id=6d6f9c94-e585-4288-a294-36113fcb322b fwd="99.92.210.17" dyno=web.1 connect=0ms service=0ms status=200 bytes=257 protocol=https
2023-12-29T09:54:21.746259+00:00 heroku[router]: at=info method=GET path="/socket.io/?EIO=4&transport=polling&t=Ooq_mPa&sid=Z00VvgzdNSSsfDydAAAA" host=api.goiterative.com request_id=d9cdbe76-e8c7-4e91-b589-6ccc70d6a6f9 fwd="99.92.210.17" dyno=web.1 connect=0ms service=1ms status=200 bytes=298 protocol=https
2023-12-29T09:54:21.831943+00:00 heroku[router]: at=info method=GET path="/socket.io/?EIO=4&transport=websocket&sid=Z00VvgzdNSSsfDydAAAA" host=api.goiterative.com request_id=9db57958-f420-484a-988c-c7335172f354 fwd="99.92.210.17" dyno=web.1 connect=0ms service=1ms status=101 bytes=202 protocol=https
2023-12-29T09:54:21.831339+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Received request to upgrade to websocket
2023-12-29T09:54:21.832735+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Failed websocket upgrade, no PING packet
2023-12-29T09:54:21.833275+00:00 app[web.1]: 10.1.90.245 - - [29/Dec/2023:09:54:21 +0000] "GET /socket.io/?EIO=4&transport=websocket&sid=Z00VvgzdNSSsfDydAAAA HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:46.834902+00:00 heroku[router]: at=info method=GET path="/socket.io/?EIO=4&transport=polling&t=Ooq_mS7&sid=Z00VvgzdNSSsfDydAAAA" host=api.goiterative.com request_id=56a31965-9ca8-4eb0-b014-0199ab43afb0 fwd="99.92.210.17" dyno=web.1 connect=0ms service=25002ms status=200 bytes=271 protocol=https
2023-12-29T09:54:46.834200+00:00 app[web.1]: Z00VvgzdNSSsfDydAAAA: Sending packet PING data None
2023-12-29T09:54:46.834734+00:00 app[web.1]: 10.1.62.47 - - [29/Dec/2023:09:54:46 +0000] "GET /socket.io/?EIO=4&transport=polling&t=Ooq_mS7&sid=Z00VvgzdNSSsfDydAAAA HTTP/1.1" 200 1 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"
2023-12-29T09:54:46.835295+00:00 app[web.1]: Traceback (most recent call last):
2023-12-29T09:54:46.835400+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.11/site-packages/eventlet/queue.py", line 118, in switch
2023-12-29T09:54:46.835400+00:00 app[web.1]:     self.greenlet.switch(value)
2023-12-29T09:54:46.835410+00:00 app[web.1]:   File "src/gevent/greenlet.py", line 912, in gevent._gevent_cgreenlet.Greenlet.run
2023-12-29T09:54:46.835419+00:00 app[web.1]:   File "src/gevent/greenlet.py", line 877, in gevent._gevent_cgreenlet.Greenlet._Greenlet__report_result
2023-12-29T09:54:46.835428+00:00 app[web.1]:   File "src/gevent/_gevent_cgreenlet.pxd", line 62, in gevent._gevent_cgreenlet.get_my_hub
2023-12-29T09:54:46.835446+00:00 app[web.1]: TypeError: Cannot convert greenlet.greenlet to gevent._gevent_c_greenlet_primitives.SwitchOutGreenletWithLoop
2023-12-29T09:54:51.443919+00:00 app[web.1]: [2023-12-29 09:54:51 +0000] [2] [CRITICAL] WORKER TIMEOUT (pid:52)
2023-12-29T09:54:51.444383+00:00 app[web.1]: [2023-12-29 09:54:51 +0000] [52] [INFO] Worker exiting (pid: 52)
2023-12-29T09:54:51.665127+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/api/projects" host=api.goiterative.com request_id=24626cb6-690c-481d-a5bb-9ccaf2a1b538 fwd="99.92.210.17" dyno=web.1 connect=0ms service=30000ms status=503 bytes=0 protocol=https
2023-12-29T09:54:51.833026+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/socket.io/?EIO=4&transport=polling&t=Ooq_mS8&sid=Z00VvgzdNSSsfDydAAAA" host=api.goiterative.com request_id=c574fd3b-b30b-452c-8987-33b0d963575b fwd="99.92.210.17" dyno=web.1 connect=0ms service=30000ms status=503 bytes=0 protocol=https
2023-12-29T09:54:51.799160+00:00 app[web.1]: [2023-12-29 09:54:51 +0000] [2] [ERROR] Worker (pid:52) exited with code 1
2023-12-29T09:54:51.799218+00:00 app[web.1]: [2023-12-29 09:54:51 +0000] [2] [ERROR] Worker (pid:52) exited with code 1.
2023-12-29T09:54:51.801553+00:00 app[web.1]: [2023-12-29 09:54:51 +0000] [55] [INFO] Booting worker with pid: 55
2023-12-29T09:54:53.626663+00:00 app[web.1]: Server initialized for eventlet.
2023-12-29T09:54:53.627778+00:00 app[web.1]: Invalid session Z00VvgzdNSSsfDydAAAA (further occurrences of this error will be logged with level INFO)
2023-12-29T09:54:53.628181+00:00 app[web.1]: 10.1.21.64 - - [29/Dec/2023:09:54:53 +0000] "POST /socket.io/?EIO=4&transport=polling&t=Ooq_mS8&sid=Z00VvgzdNSSsfDydAAAA HTTP/1.1" 400 17 "https://www.goiterative.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36"

In fact - you can go to the website itself goiterative.com/tool and see that it seems that websocket upgrade fails then client switches to long polling. However, for some reason - this seems to be very resource intensive or the request times outs for whatever reason.

From the client side: 886-e67588dd3a7e1252.js:3 WebSocket connection to 'wss://api.goiterative.com/socket.io/?EIO=4&transport=websocket&sid=CGtn1SbayJ79n3LAAAAA' failed: WebSocket is closed before the connection is established. - I routinely see something like this and the actual GET/POST requests to the /socket.io endpoints are constantly hanging and the requests never finish.

This only happens on Heroku.

My Procfile: web: gunicorn -k gevent -w 1 "app:create_app()"

Flask create_app() code itself.

def create_app():
    app = Flask(__name__)
    app.config.from_object(os.environ.get("APP_SETTINGS"))
    
    # Initialize Flask extensions here
    session = Session(app)
    migrate = Migrate(app, db)
    bcrypt = Bcrypt(app)
    db.init_app(app)
    CORS(app, resources={r"/*": {"origins": app.config['CORS_ORIGINS']}}, supports_credentials=True)
  
    celery_init_app(app)

    # Register blueprints here
    from app.main import bp as main_bp
    from app.projects import bp as project_bp
    from app.settings import bp as settings_bp
    from app.core import bp as core_bp
    from app.deployments import bp as deployments_bp
    app.register_blueprint(main_bp)
    app.register_blueprint(project_bp)
    app.register_blueprint(settings_bp)
    app.register_blueprint(core_bp)
    app.register_blueprint(deployments_bp)

    socketio.init_app(app, cors_allowed_origins="*", logger=True, engineio_logger=True)
    return app

My client side JS code that interacts with Socket:

let socket: Socket<DefaultEventsMap, DefaultEventsMap> = io(SOCKET_IO_URL);;

export default function Tool() {
  const {
    loading,
    setLoading,
    setProjectStates,
    projectStates,
    reactCode,
    setReactCode,
    recommendations,
    setRecommendations,
    resetProject,
    setOpenProjectModal,
  } = useToolStore();

  const { projectId, setProjectId, setProjectName, projectName } =
    useProjectStore();
  const [isLoading, setIsLoading] = useState<boolean>(false);

  const { user } = useStytchUser();
  useEffect(() => {
    socket.on("server_recommendation", onServerResponse);
    socket.on("server_code", onServerCode);
    socket.on("project_id", onProjectId);
    return () => {
      socket.disconnect();
    };
    // eslint-disable-next-line react-hooks/exhaustive-deps
  }, []);