search

miguelgrinberg / turbo-flask

Integration of Hotwire's Turbo library with Flask.
MIT License
301 stars 35 forks source link

turbo.push Key Error when the server is accessed via the Internet, not when over LAN or local. #49

Closed StableNarwhal closed 8 months ago

StableNarwhal commented 9 months ago

I've got a curious error when serving my Flask application utilizing turbo-flask over the Internet. For testing purposes, I don't have a reverse proxy in front of the Flask application, the application runs inside a docker container on port 8000 which gets mapped to port 80 on the host system. The firewall config opens port 80 to the internet.

I have a flask application that serves different content to different users via the turbo.push() helper method with the optional to argument.

To archive this, I check if a user accessing the first (and only) page served already has a sessionID and if not, create one for him:

@app.route('/')
def index():
    if "sessionID" not in session:       
        session['sessionID'] = uuid4()
        logger.info("new user detected, creating session for user " + str(session['sessionID']))
        .
        .
        .
    userID = str(session['sessionID'])
    user = {'sessionID': userID}
    return render_template('index.html', title='example', user=user)

Following the docs, I defined a function that assigns an id to each connected client, and decorated it with the turbo.user_id decorator:

@turbo.user_id
def get_user_id():
    return str(session['sessionID'])

To push content to individual users, I utillize the turbo.push method:

turbo.push(turbo.replace(render_template('example.html', exampleVariable=actualExampleVariable), 'oldExampleHTML'), to=str(sessionIDtoSendto))

where sessionIDtoSendto is a uuid4() key generated for a user as shown in the /route.

This works great local and in the LAN, but not when accessed via the Internet, it throws a KeyError:



[2023-12-15 21:02:48, 686] ERROR in app: Exception on /panel [POST]
Traceback (most recent call last):
File "/home/lvm/venv/lib/python3.11/site-packages/flask/app.py", line 2190, in wsgi_app 
response = self.full_dispatch_request()
                   ^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/lvm/venv/lib/python3.11/site-packages/flask/app.py", line 1486, in full_dispatch_request
 rv =  self.handle_user_exception(e)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/lvm/venv/lib/python3.11/site-packages/flask/app.py", line 1484, in full_dispatch_request
rv = self.dispatch_request()
       ^^^^^^^^^^^^^^^^^^^^^
File "/home/lvm/venv/lib/python3.11/site-packages/flask/app.py", line 1469, in dispatch_request
return self.ensure_sync(self.view_functions [rule.endpoint]) (**view_args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/lvm/app/routes.py", line 104, in panel
turbo.push(turbo.replace(render_template('imageFresh.html', imageVariable=imageBase64), 'panelImage'), to=str(sessionIDtoSendto)) File "/home/lvm/venv/lib/python3.11/site-packages/turbo_flask/turbo.py", line 198, in push
for ws in self.clients [recipient]:
               ~~~~~~~~^^^^^^^^^
KeyError: '3b797412-289a-42ce-ada4-ecd6f0e95887'

In my understanding, turbo-flask somehow doesn't recognize a sessionID created over the internet as a valid key present in the internal turbo client ID list. But I honestly have no idea how to go about fixing that, any help would be greatly appreciated.

miguelgrinberg commented 9 months ago

Are your Flask sessions working under your production deployment? As far as I can see the problem here is that your sessions are not working. This package does not do anything different for LAN vs. Internet deployment.

StableNarwhal commented 9 months ago

Thank you for the quick reply!

Yeah, the Sessions are working in my production environment. When I spin up my (production) docker container using eventlet/wsgi 

import eventlet
eventlet.monkey_patch()

from eventlet import wsgi
from app.routes import app

wsgi.server(eventlet.listen(("", 8000)), app)

and access it via LAN or locally, it works. If I access it over the Internet, the mentioned KeyError happens.

miguelgrinberg commented 9 months ago

You are not answering my question though. Are your sessions working? The error indicates that the sessions aren't being preserved. I understand that everything works when you access from LAN, but the question is about the failure case. So let me ask again. Are your sessions working?

The reason I ask is that you are assuming the issue/bug is in this package, but I think the issue or bug is in your set up, which for some reason is not preserving user sessions. Once you fix your user sessions, then this package will work exactly as it does for the LAN users.

StableNarwhal commented 9 months ago

I think I misunderstand your question in that case. I'm very sure that the issue is with my setup instead of this package.

To calrify and hopefully answer your question, the workflow is as follows:

When the user visits the site served by the / route as shown above, he gets assigned a sessionID if one is not already present. This sessionID is passed to another application that generates individual content based on that sessionID. This gets passed back to the individual user via the turbo.push method with the to parameter. The user interacts with the content and the changes are passed back to the other application, it generates new content and so on.

Multiple local/LAN users can interact with this workflow reliably, therefore in my current understanding sessions are working. I'm not sure what I am misunderstanding here, I'd love to learn though!

Any internet user cannot interact with this workflow due to the KeyError.

Update:

Huh, I retested for my sanity and while it works locally, it doesn't work for LAN users as well. It used to at some point. If I visit the website via localhost/127.0.0.1 it works, if I visit it via LAN or the Internet the KeyError is present. I still have no idea what the cause of this could be, but if I understand your answer correctly, this is probably a configuration issue with flask sessions instead of turbo-flask. I'd still very much appreciate any pointer towards a possible solution or towards a better location to ask.

miguelgrinberg commented 9 months ago

Well, I think your problem is that sessions do not work for Internet users. Your application relies on sessions to remember these sessionID values that you create, so non-working sessions would make it impossible for your application to remember what sessionID a user got assigned, and that will create issues as the one you are having, where you are asking this package to send something to a sessionID that this package does not know about.

I do not know why your sessions do not work, but what I'm trying to suggest is that your should debug your use of sessions, as this problem is unrelated to this package and really related to user sessions not working as they should. I mean, you have some logging in your code, right? Isn't a user always detected as a new user, according to your own logs? That means that the session variable is always empty, regardless of what you put in it in the previous request.

StableNarwhal commented 9 months ago

No, users are only detected as new users if a cookie isn't present in the users' browser, e.g. via utilizing a private window.

The workflow as described above (that currently only works for local users, not LAN/Internet users) necessitates the sessions to be working, so at least in the local context sessions are working as expected. So the question seems to be: Why are sessions working for local users but for nobody else?

But yeah, you are right; this seems to be unrelated to this package and after playing around a bit with it myself, I'll head over to the flask github for help. Thank your for your time and attempt to help, Miguel, I truly appreciate it.

miguelgrinberg commented 9 months ago

No, users are only detected as new users if a cookie isn't present in the users' browser, e.g. via utilizing a private window.

I think you don't understand what I'm saying. Here you are describing how your program is supposed to work. But as I suggested above, you should debug your sessions and find proof that this works in the way you believe it works.

You should track every single session ID that is created and when. Then you should correlate that with the session ID that you send to the to argument in turbo.push() and understand how this ID which Turbo-Flask knows nothng about came to appear in your application and end up being used.

I know you are going to say that your applicaton must be working correctly because it works for local users. But that is not the way to go about this. You have an easily reproducible bug, so you should start from that and debug all you can debug. If you do this, you will then have a much better understanding of the issue that you have now, and you'll know who to ask for help if the issue ends up not being in your own application.

StableNarwhal commented 9 months ago

Ah, I don't think I was describing the situation that well.

So currently, LAN and local users work reliably again, Internet users throw the KeyError. Here's an example log of two LAN/local users where one already has a session and the other one doesn't:

2023-12-16 18:18:32,954 - Backend - INFO - new user detected, creating session for user d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:32,954 - Backend - INFO - Sending createsession to tcpIPlayer for user d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:32,955 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 18:18:32,955 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "command": "createsession"}
18:18:32: Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "command": "createsession"}
18:18:32: 127.0.0.1 - - [16/Dec/2023:18:18:32] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
127.0.0.1 - - [16/Dec/2023 18:18:32] "GET / HTTP/1.1" 200 1479 0.003546
127.0.0.1 - - [16/Dec/2023 18:18:33] "GET /static/style.css HTTP/1.1" 200 1482 0.001081
127.0.0.1 - - [16/Dec/2023 18:18:33] "GET /static/scripts.js HTTP/1.1" 200 1736 0.001104
127.0.0.1 - - [16/Dec/2023 18:18:33] "GET /static/favicon.ico HTTP/1.1" 200 15831 0.000836
2023-12-16 18:18:33,238 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:33,241 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:33] "POST /panel HTTP/1.1" 200 240 0.003989
2023-12-16 18:18:36,630 - Backend - INFO - user d0bef5ca-65c4-4467-9d20-6a5698addb4e clicked coordinates, x: 66.33333333333333, y: 453.27777777777777

2023-12-16 18:18:36,632 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 18:18:36,632 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "x": 66.33333333333333, "y": 453.27777777777777}
18:18:36: Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "x": 66.33333333333333, "y": 453.27777777777777}
18:18:36: 127.0.0.1 - - [16/Dec/2023:18:18:36] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
127.0.0.1 - - [16/Dec/2023 18:18:36] "POST / HTTP/1.1" 200 264 0.003327
2023-12-16 18:18:36,900 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:36,905 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:36] "POST /panel HTTP/1.1" 200 240 0.005689
2023-12-16 18:18:36,907 - Backend - INFO - Command NO_COMMAND was sent by MDS to user d0bef5ca-65c4-4467-9d20-6a5698addb4e
127.0.0.1 - - [16/Dec/2023 18:18:36] "POST /command HTTP/1.1" 200 240 0.000885
2023-12-16 18:18:37,027 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:37,030 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:37] "POST /panel HTTP/1.1" 200 240 0.004782
2023-12-16 18:18:40,245 - Backend - INFO - user b101fd0e-5629-4afa-a7d2-bf98c344df90 clicked coordinates, x: 208.00000000000003, y: 396.1999969482422

2023-12-16 18:18:40,246 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 18:18:40,246 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "b101fd0e-5629-4afa-a7d2-bf98c344df90", "x": 208.00000000000003, "y": 396.1999969482422}
18:18:40: Message forwarded via TCP to MDS: {"sessionid": "b101fd0e-5629-4afa-a7d2-bf98c344df90", "x": 208.00000000000003, "y": 396.1999969482422}
18:18:40: 127.0.0.1 - - [16/Dec/2023:18:18:40] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
127.0.0.1 - - [16/Dec/2023 18:18:40] "POST / HTTP/1.1" 200 264 0.002987
2023-12-16 18:18:40,347 - Backend - INFO - MDS gave this sessionID to send an updated panel to: b101fd0e-5629-4afa-a7d2-bf98c344df90
2023-12-16 18:18:40,350 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:40] "POST /panel HTTP/1.1" 200 240 0.003568
(9701) accepted ('127.0.0.1', 38980)
2023-12-16 18:18:40,351 - Backend - INFO - Command NO_COMMAND was sent by MDS to user b101fd0e-5629-4afa-a7d2-bf98c344df90
127.0.0.1 - - [16/Dec/2023 18:18:40] "POST /command HTTP/1.1" 200 240 0.000759
2023-12-16 18:18:40,459 - Backend - INFO - MDS gave this sessionID to send an updated panel to: b101fd0e-5629-4afa-a7d2-bf98c344df90
2023-12-16 18:18:40,461 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:40] "POST /panel HTTP/1.1" 200 240 0.003199
2023-12-16 18:18:46,746 - Backend - INFO - user d0bef5ca-65c4-4467-9d20-6a5698addb4e clicked coordinates, x: 196.7888888888889, y: 276.38888888888886

2023-12-16 18:18:46,747 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 18:18:46,748 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "x": 196.7888888888889, "y": 276.38888888888886}
18:18:46: Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "x": 196.7888888888889, "y": 276.38888888888886}
18:18:46: 127.0.0.1 - - [16/Dec/2023:18:18:46] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
127.0.0.1 - - [16/Dec/2023 18:18:46] "POST / HTTP/1.1" 200 264 0.002813
2023-12-16 18:18:46,891 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:46,894 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:46] "POST /panel HTTP/1.1" 200 240 0.003964
2023-12-16 18:18:46,896 - Backend - INFO - Command NO_COMMAND was sent by MDS to user d0bef5ca-65c4-4467-9d20-6a5698addb4e
127.0.0.1 - - [16/Dec/2023 18:18:46] "POST /command HTTP/1.1" 200 240 0.000688
2023-12-16 18:18:47,036 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e
2023-12-16 18:18:47,038 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
127.0.0.1 - - [16/Dec/2023 18:18:47] "POST /panel HTTP/1.1" 200 240 0.004034

I am tracking the sessionIDs, so for example for the user with the sessionID d0bef5ca-65c4-4467-9d20-6a5698addb4e the sessionID gets forwarded to the other application:

2023-12-16 18:18:32,955 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "command": "createsession"}

The application then creates some content and provides that with the sessionID to send to:

2023-12-16 18:18:33,238 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e

Up to this point, it's the same behaviour for local/LAN users and Internet users. I also verified that the sessionIDs provided to and from the background application match the sessions created for the Internet users.

So as long as I'm not still massively misunderstanding something here, the sessions actually work for local/LAN users. Would you have a suggestion on how to go about tracking all the sessions at at the moment turbo.push tries to push an update to a user it doesn't know about?

The issue I'm facing in that regard is that the route (and method) utilized to push the update to a user is used by the application in the background, not a user with a session. It is structured like this:

@app.route('/panel', methods=['POST'])
def panel():
    if request.is_json:

        #uploaded_file = request.files['file']   
        jsonRequest = request.get_json(force=True)

        sessionIDtoSendto = str(jsonRequest['sessionid'])
        logger.info("MDS gave this sessionID to send an updated panel to: " + sessionIDtoSendto)
        imageBase64 = jsonRequest['image']

        turbo.push(turbo.replace(render_template('imageFresh.html', imageVariable=imageBase64), 'panelImage'), to=sessionIDtoSendto)
        logger.info("/panel POST von MDS erhalten und verarbeitet.")
    else:
        logger.info("POST zu /panel war kein JSON, dump request:")
    resp = jsonify(success=True)
    return resp

The background application gets the data as logged above:

2023-12-16 18:18:32,955 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "d0bef5ca-65c4-4467-9d20-6a5698addb4e", "command": "createsession"}

and returns a JSON String with some data and the sessionID to push to by posting to the /panel route:

2023-12-16 18:18:33,238 - Backend - INFO - MDS gave this sessionID to send an updated panel to: d0bef5ca-65c4-4467-9d20-6a5698addb4e

miguelgrinberg commented 9 months ago

I think you need to concentrate on the failing case. You are focused on demonstrating that the local/LAN users can work with your application and this provides nothing useful, since we already know that there are no issues when the application is used in this way.

Why don't you do the same analysis with a remote user? Make sure there is a single user, and track all session IDs that are created. If your application works correctly, there should be only one session ID created for this user, and this should be the session ID that is later used to send an update via push.

StableNarwhal commented 9 months ago

Ok, this is curious. I think I'm finally getting somewhere:

I modified the def get_user_id() function to provide an output when being called:

@turbo.user_id
def get_user_id():
    logger.info("Turbo trying to get a sessionID")
    sessionID = str(session.get('sessionID'))
    logger.info("Turbo got sessionID: " + sessionID)
    return sessionID

and the panel method to output the currently connected turbo clients:

@app.route('/panel', methods=['POST'])
def panel():
    if request.is_json:
        jsonRequest = request.get_json(force=True)

        sessionIDtoSendto = str(jsonRequest['sessionid'])
        logger.info("MDS gave this sessionID to send an updated panel to: " + sessionIDtoSendto)
        imageBase64 = jsonRequest['image']

        logger.info("All currently connected Turbo clients:")
        logger.info(turbo.clients))

        turbo.push(turbo.replace(render_template('imageFresh.html', imageVariable=imageBase64), 'panelImage'), to=sessionIDtoSendto)
        logger.info("/panel POST von MDS erhalten und verarbeitet.")
    else:
        logger.info("POST zu /panel war kein JSON, dump request:")
    resp = jsonify(success=True)
    return resp

and tried to access the Flask application via LAN and remote with 2 different users without an existing sessionID. This is the log:

(1) wsgi starting up on http://0.0.0.0:8000
2023-12-16 22:12:36,555 - TCP Translation Layer - INFO - Accepted connection from ('LOCALIPOFSERVER', 50000)
22:12:36: Accepted connection from ('LOCALIPOFSERVER', 50000)
(1) accepted ('REMOTEIPOFUSERS', 42188)
2023-12-16 22:13:20,310 - Backend - INFO - new user detected, creating session for user 30070a20-8e11-4788-8402-c94394b7dee1
2023-12-16 22:13:20,310 - Backend - INFO - Sending createsession to tcpIPlayer for user 30070a20-8e11-4788-8402-c94394b7dee1
2023-12-16 22:13:20,318 - TCP Translation Layer - INFO - Incoming POST
22:13:20: Incoming POST
2023-12-16 22:13:20,318 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "30070a20-8e11-4788-8402-c94394b7dee1", "command": "createsession"}
22:13:20: Message forwarded via TCP to MDS: {"sessionid": "30070a20-8e11-4788-8402-c94394b7dee1", "command": "createsession"}
22:13:20: 127.0.0.1 - - [16/Dec/2023:22:13:20] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
REMOTEIPOFUSERS - - [16/Dec/2023 22:13:20] "GET / HTTP/1.1" 200 1523 0.031555
REMOTEIPOFUSERS - - [16/Dec/2023 22:13:20] "GET /static/style.css HTTP/1.1" 200 1361 0.003376
(1) accepted ('REMOTEIPOFUSERS', 42196)
REMOTEIPOFUSERS - - [16/Dec/2023 22:13:20] "GET /static/scripts.js HTTP/1.1" 200 1622 0.002210
REMOTEIPOFUSERS - - [16/Dec/2023 22:13:20] "GET /static/favicon.ico HTTP/1.1" 200 15710 0.002411
(1) accepted ('LOCALIPOFSERVER', 35186)
2023-12-16 22:13:20,598 - Backend - INFO - MDS gave this sessionID to send an updated panel to: 30070a20-8e11-4788-8402-c94394b7dee1
2023-12-16 22:13:20,598 - Backend - INFO - All currently connected Turbo clients:
2023-12-16 22:13:20,598 - Backend - INFO - {}
[2023-12-16 22:13:20,602] ERROR in app: Exception on /panel [POST]
Traceback (most recent call last):
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 1455, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 869, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 867, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 852, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/home/lvm/app/routes.py", line 117, in panel
    turbo.push(turbo.replace(render_template('imageFresh.html', imageVariable=imageBase64), 'panelImage'), to=sessionIDtoSendto)
  File "/home/lvm/venv/lib/python3.10/site-packages/turbo_flask/turbo.py", line 198, in push
    for ws in self.clients[recipient]:
KeyError: '30070a20-8e11-4788-8402-c94394b7dee1'
LOCALIPOFSERVER - - [16/Dec/2023 22:13:20] "POST /panel HTTP/1.1" 500 401 0.008091
(1) accepted ('REMOTEIPOFUSERS', 42198)
2023-12-16 22:13:20,625 - Backend - INFO - Turbo trying to get a sessionID
2023-12-16 22:13:20,625 - Backend - INFO - Turbo got sessionID: 30070a20-8e11-4788-8402-c94394b7dee1
(1) accepted ('REMOTEIPOFUSERS', 42136)
2023-12-16 22:15:10,363 - Backend - INFO - new user detected, creating session for user 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,363 - Backend - INFO - Sending createsession to tcpIPlayer for user 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,368 - TCP Translation Layer - INFO - Incoming POST
22:15:10: Incoming POST
2023-12-16 22:15:10,369 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "5062fe48-ba15-4dd8-b8ac-8c282d6170eb", "command": "createsession"}
22:15:10: Message forwarded via TCP to MDS: {"sessionid": "5062fe48-ba15-4dd8-b8ac-8c282d6170eb", "command": "createsession"}
22:15:10: 127.0.0.1 - - [16/Dec/2023:22:15:10] "POST / HTTP/1.1" 200 2 "" "python-requests/2.31.0"
REMOTEIPOFUSERS - - [16/Dec/2023 22:15:10] "GET / HTTP/1.1" 200 1523 0.012157
REMOTEIPOFUSERS - - [16/Dec/2023 22:15:10] "GET /static/style.css HTTP/1.1" 200 1361 0.002405
(1) accepted ('REMOTEIPOFUSERS', 42146)
REMOTEIPOFUSERS - - [16/Dec/2023 22:15:10] "GET /static/scripts.js HTTP/1.1" 200 1622 0.003135
REMOTEIPOFUSERS - - [16/Dec/2023 22:15:10] "GET /static/favicon.ico HTTP/1.1" 200 15710 0.002530
(1) accepted ('REMOTEIPOFUSERS', 42152)
2023-12-16 22:15:10,623 - Backend - INFO - Turbo trying to get a sessionID
2023-12-16 22:15:10,623 - Backend - INFO - Turbo got sessionID: 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
(1) accepted ('LOCALIPOFSERVER', 40730)
2023-12-16 22:15:10,760 - Backend - INFO - MDS gave this sessionID to send an updated panel to: 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,760 - Backend - INFO - All currently connected Turbo clients:
2023-12-16 22:15:10,760 - Backend - INFO - {'30070a20-8e11-4788-8402-c94394b7dee1': [<simple_websocket.ws.Server object at 0x7f05ab689780>], '5062fe48-ba15-4dd8-b8ac-8c282d6170eb': [<simple_websocket.ws.Server object at 0x7f05ab68b700>]}
2023-12-16 22:15:10,770 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
LOCALIPOFSERVER - - [16/Dec/2023 22:15:10] "POST /panel HTTP/1.1" 200 125 0.012773
^Cwsgi exiting
REMOTEIPOFUSERS - - [16/Dec/2023 22:16:55] "GET /turbo-stream HTTP/1.1" 200 0 104.461360
REMOTEIPOFUSERS - - [16/Dec/2023 22:16:55] "GET /turbo-stream HTTP/1.1" 200 0 214.460143
(1) wsgi exited, is_accepting=True

So the first client connects and gets assigned the sessionID 30070a20-8e11-4788-8402-c94394b7dee1:

2023-12-16 22:13:20,310 - Backend - INFO - new user detected, creating session for user 30070a20-8e11-4788-8402-c94394b7dee1

The flask application sends that info to the background application. The background application sends a POSTrequest to the panel method:

2023-12-16 22:13:20,310 - Backend - INFO - Sending createsession to tcpIPlayer for user 30070a20-8e11-4788-8402-c94394b7dee1
2023-12-16 22:13:20,318 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 22:13:20,318 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "30070a20-8e11-4788-8402-c94394b7dee1", "command": "createsession"}
2023-12-16 22:13:20,598 - Backend - INFO - MDS gave this sessionID to send an updated panel to: 30070a20-8e11-4788-8402-c94394b7dee1

Here's where it gets interesting: Now the panel method calls logger.info(turbo.clients), which returns an empty dictionary. This finally explains the KeyError. 

2023-12-16 22:13:20,598 - Backend - INFO - All currently connected Turbo clients:
2023-12-16 22:13:20,598 - Backend - INFO - {}
[2023-12-16 22:13:20,602] ERROR in app: Exception on /panel [POST]
Traceback (most recent call last):
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 1455, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 869, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 867, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/lvm/venv/lib/python3.10/site-packages/flask/app.py", line 852, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/home/lvm/app/routes.py", line 117, in panel
    turbo.push(turbo.replace(render_template('imageFresh.html', imageVariable=imageBase64), 'panelImage'), to=sessionIDtoSendto)
  File "/home/lvm/venv/lib/python3.10/site-packages/turbo_flask/turbo.py", line 198, in push
    for ws in self.clients[recipient]:
KeyError: '30070a20-8e11-4788-8402-c94394b7dee1'
LOCALIPOFSERVER - - [16/Dec/2023 22:13:20] "POST /panel HTTP/1.1" 500 401 0.008091

After that, turbo-flask calls the def get_user_id() function:

2023-12-16 22:13:20,625 - Backend - INFO - Turbo trying to get a sessionID
2023-12-16 22:13:20,625 - Backend - INFO - Turbo got sessionID: 30070a20-8e11-4788-8402-c94394b7dee1

Now I'm trying to replicate this behaviour and open a new remote browser session:

2023-12-16 22:15:10,363 - Backend - INFO - new user detected, creating session for user 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,363 - Backend - INFO - Sending createsession to tcpIPlayer for user 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,368 - TCP Translation Layer - INFO - Incoming POST
2023-12-16 22:15:10,369 - TCP Translation Layer - INFO - Message forwarded via TCP to MDS: {"sessionid": "5062fe48-ba15-4dd8-b8ac-8c282d6170eb", "command": "createsession"}

Now, turbo-flask tries to get the sessionID before trying to push:

2023-12-16 22:15:10,623 - Backend - INFO - Turbo trying to get a sessionID
2023-12-16 22:15:10,623 - Backend - INFO - Turbo got sessionID: 5062fe48-ba15-4dd8-b8ac-8c282d6170eb

and afterwards, the panel method actually seems to execute correctly, at least according to logs:

2023-12-16 22:15:10,760 - Backend - INFO - MDS gave this sessionID to send an updated panel to: 5062fe48-ba15-4dd8-b8ac-8c282d6170eb
2023-12-16 22:15:10,760 - Backend - INFO - All currently connected Turbo clients:
2023-12-16 22:15:10,760 - Backend - INFO - {'30070a20-8e11-4788-8402-c94394b7dee1': [<simple_websocket.ws.Server object at 0x7f05ab689780>], '5062fe48-ba15-4dd8-b8ac-8c282d6170eb': [<simple_websocket.ws.Server object at 0x7f05ab68b700>]}
2023-12-16 22:15:10,770 - Backend - INFO - /panel POST von MDS erhalten und verarbeitet.
LOCALIPOFSERVER - - [16/Dec/2023 22:15:10] "POST /panel HTTP/1.1" 200 125 0.012773

Notice how now the client that previously wasn't in the list is in the list, too. But now the replaced HTML still isn't getting pushed, it simply doesn't log an error.

Interestingly, after Ctrl+Cing the Docker container running the Flask application and a helper application (TCP Translation Layer in the logs), this gets logged:

^Cwsgi exiting
REMOTEIPOFUSERS - - [16/Dec/2023 22:16:55] "GET /turbo-stream HTTP/1.1" 200 0 104.461360
REMOTEIPOFUSERS - - [16/Dec/2023 22:16:55] "GET /turbo-stream HTTP/1.1" 200 0 214.460143
(1) wsgi exited, is_accepting=True

So in conclusion, I still have no idea why this is happening. It looks like some kind of race condition, but I'm not sure how to approach this. Do you have any idea? Thanks again for your patience.

miguelgrinberg commented 9 months ago

This indicates that there are no connected turbo clients, at a time where you think you have two clients connected. How is this possible? You indicated that the two clients at this point are one remote and one LAN, yet neither one is connected via turbo. You see, you think your application is working in some way, but the facts appear to suggest something different. 

2023-12-16 22:13:20,598 - Backend - INFO - All currently connected Turbo clients:
2023-12-16 22:13:20,598 - Backend - INFO - {}
StableNarwhal commented 9 months ago

How is this possible?

Well, that's the question. As you can see in the log, the Flask application correctly sees and serves the clients. The index.html provided by the initial route also displays the clients sessionID, the sessions for all local, LAN and remote users seem work correctly since the logs as well as the clients itself behave as expected apart from flask-turbo. I can refresh the windows and the interactions with Flask (and the background application) work as intended.

I don't have advanced knowledge of the underlying workings of flask-turbo or Flask itself yet, for example when turbo-flask tries to call its helper function (def get_user_id()), why it doesn't execute it before trying to push an update in at least some cases in my code, if and how exactly I should differentiate between regular Flask clients and turbo clients or why it doesn't push an update even when it seems to correctly see all currently corrected clients as is the case with the second user.

miguelgrinberg commented 9 months ago

Unfortunately I cannot debug your application for you. The most reasonable explanation is that your application did not make the Turbo-Flask connection for those two clients. And you are saying that if you refresh the browser then the connection is made and everything works. That to me suggests that your application fails to make a Turbo-Flask connection for new clients, but it does for clients that have a previous session in place.

You can look in your browser's network tab for the WebSocket request to the /turbo-stream URL. When your server shows that Turbo-Flask does not have any connected clients, see if the browser has this connection. I bet it doesn't. This would prove that your front end did not make the Turbo connection.

StableNarwhal commented 9 months ago

And you are saying that if you refresh the browser then the connection is made and everything works.

Only the basic serving of the index.html works, not the turbo-flask part, unfortunately. I saw an upgrade request (101) to /turbo-stream at some point when turbo.push failed, but I'll have to debug/retest it further.

I think at this point i'll write a new, simple Flask application to test the WebSocket connections especially on remote clients without possible interference from other components. If it's OK with you and not considered OT, I'll keep updating this thread in the next few days. Maybe this odyssey will help someone in a similar situation once I find a solution.

Thanks again for your continued help!

StableNarwhal commented 8 months ago

After a lot of testing around how and when turbo-flask updates its internal dictionary and playing around with ways to trigger that manually on my SPA, I found that in its current form it unfortunately isn't completely compatible with my project.

I switched to your awesomeFlask-SocketIO integration and implemented the desired workflow by assigning each client to a SocketIO room with their sessionID and emitting the HTML/JS updates to those rooms while applying those updates manually via JS clientside.

It works reliably now, mainly due to having direct control over how and when a socketIO sid gets associated with a custom sessionID.

I'll mark this issue as closed, I wish you a wonderful holiday season!