search

louking / tm-csv-connector

Time Machine - CSV Connector - creates CSV file from time machine input, for scoring software to read
Apache License 2.0
1 stars 0 forks source link

some results sent from reader but missed at backend #15

Closed louking closed 10 months ago

louking commented 11 months ago

see

reader

2023-08-19 16:31:38,689 tm-csv-connector DEBUG: async reader started with port COM4
2023-08-19 16:31:44,261 tm-csv-connector ERROR: need to set logging path in logger
2023-08-19 16:32:09,252 tm-csv-connector DEBUG: data received: b'\x19XC 00:00:00.00 \r\n'
2023-08-19 16:32:09,253 tm-csv-connector DEBUG: msg processed: b'\x19XC 00:00:00.00 '
2023-08-19 16:32:31,424 tm-csv-connector DEBUG: data received: b'\x00EVENT 070\r\n'
2023-08-19 16:32:31,424 tm-csv-connector DEBUG: msg processed: b'\x00EVENT 070'
2023-08-19 16:32:31,549 tm-csv-connector DEBUG: data received: b'\x1711 001 0001 00:00:22.17 \r\n'
2023-08-19 16:32:31,549 tm-csv-connector DEBUG: msg processed: b'\x1711 001 0001 00:00:22.17 '
2023-08-19 16:32:31,854 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 1, "time": "0:00:22.17"}
2023-08-19 16:32:36,329 tm-csv-connector DEBUG: data received: b'\x1711 002 0002 00:00:26.92 \r\n'
2023-08-19 16:32:36,329 tm-csv-connector DEBUG: msg processed: b'\x1711 002 0002 00:00:26.92 '
2023-08-19 16:32:36,635 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 2, "time": "0:00:26.92"}
2023-08-19 16:32:36,642 tm-csv-connector DEBUG: data received: b'\x1711 003 0003 00:00:27.08 \r\n\x1711 004 0004 00:00:27.23 \r\n\x1711 005 0005 00:00:27.'
d: b'\x1711 009 0009 00:01:40.49 '
2023-08-19 16:33:50,087 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 8, "time": "0:01:40.35"}
2023-08-19 16:33:50,088 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 9, "time": "0:01:40.49"}
2023-08-19 16:33:50,094 tm-csv-connector DEBUG: data received: b'\x1711 010 0010 00:01:40.64 \r\n\x1711 011 0011 00:01:40.79 \r\n'
2023-08-19 16:33:50,095 tm-csv-connector DEBUG: msg processed: b'\x1711 010 0010 00:01:40.64 '
2023-08-19 16:33:50,095 tm-csv-connector DEBUG: msg processed: b'\x1711 011 0011 00:01:40.79 '
2023-08-19 16:33:50,418 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 10, "time": "0:01:40.64"}
2023-08-19 16:33:50,418 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 11, "time": "0:01:40.79"}
2023-08-19 16:33:50,425 tm-csv-connector DEBUG: data received: b'\x1711 012 0012 00:01:40.95 \r\n\x1711 013 0013 00:01:41.10 \r\n\x1711 014 001'
2023-08-19 16:33:50,426 tm-csv-connector DEBUG: residual: b'\x1711 014 001'
2023-08-19 16:33:50,426 tm-csv-connector DEBUG: msg processed: b'\x1711 012 0012 00:01:40.95 '
2023-08-19 16:33:50,426 tm-csv-connector DEBUG: msg processed: b'\x1711 013 0013 00:01:41.10 '
2023-08-19 16:33:50,744 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 12, "time": "0:01:40.95"}
2023-08-19 16:33:50,744 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 13, "time": "0:01:41.10"}
2023-08-19 16:33:50,749 tm-csv-connector DEBUG: data received: b'4 00:01:41.27 \r\n\x1711 015 0015 00:01:41.42 \r\n'
2023-08-19 16:33:50,749 tm-csv-connector DEBUG: msg processed: b'\x1711 014 0014 00:01:41.27 '
2023-08-19 16:33:50,750 tm-csv-connector DEBUG: msg processed: b'\x1711 015 0015 00:01:41.42 '
2023-08-19 16:33:51,074 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 14, "time": "0:01:41.27"}
2023-08-19 16:33:51,075 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 15, "time": "0:01:41.42"}

backend

2023-08-19 16:32:31 2023-08-19 20:32:31,855 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 1, 'time': '0:00:22.17'}
2023-08-19 16:32:31 [2023-08-19 20:32:31,855] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 1, 'time': '0:00:22.17'}
2023-08-19 16:32:36 2023-08-19 20:32:36,637 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 2, 'time': '0:00:26.92'}
2023-08-19 16:32:36 [2023-08-19 20:32:36,637] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 2, 'time': '0:00:26.92'}
2023-08-19 16:32:36 [2023-08-19 20:32:36,966] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 3, 'time': '0:00:27.08'}
2023-08-19 16:32:36 2023-08-19 20:32:36,966 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 3, 'time': '0:00:27.08'}
2023-08-19 16:32:37 [2023-08-19 20:32:37,297] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 5, 'time': '0:00:27.38'}
2023-08-19 16:32:37 2023-08-19 20:32:37,297 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 5, 'time': '0:00:27.38'}
2023-08-19 16:33:49 2023-08-19 20:33:49,774 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 7, 'time': '0:01:40.21'}
2023-08-19 16:33:49 [2023-08-19 20:33:49,774] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 7, 'time': '0:01:40.21'}
2023-08-19 16:33:50 [2023-08-19 20:33:50,089] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 8, 'time': '0:01:40.35'}
2023-08-19 16:33:50 2023-08-19 20:33:50,089 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 8, 'time': '0:01:40.35'}
2023-08-19 16:33:50 [2023-08-19 20:33:50,420] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 10, 'time': '0:01:40.64'}
2023-08-19 16:33:50 2023-08-19 20:33:50,420 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 10, 'time': '0:01:40.64'}
2023-08-19 16:33:50 [2023-08-19 20:33:50,746] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 12, 'time': '0:01:40.95'}
2023-08-19 16:33:50 2023-08-19 20:33:50,746 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 12, 'time': '0:01:40.95'}
2023-08-19 16:33:51 2023-08-19 20:33:51,076 tm_csv_connector DEBUG: received {'opcode': 'primary', 'pos': 14, 'time': '0:01:41.27'}
2023-08-19 16:33:51 [2023-08-19 20:33:51,076] DEBUG in websockets_server: received {'opcode': 'primary', 'pos': 14, 'time': '0:01:41.27'}
louking commented 11 months ago

Another instance, another log.

reader (missed pos = 12? also some log messages appear to be missing, e.g., data received, msg processed for pos = 13,14

2023-08-19 17:00:06,043 tm-csv-connector DEBUG: data received: b'\x19XC 00:00:00.00 \r\n'
2023-08-19 17:00:06,044 tm-csv-connector DEBUG: msg processed: b'\x19XC 00:00:00.00 '
2023-08-19 17:00:16,685 tm-csv-connector DEBUG: data received: b'\x00EVENT 072\r\n\x1711 001 0001 00:00:10.63 \r\n'
2023-08-19 17:00:16,685 tm-csv-connector DEBUG: msg processed: b'\x00EVENT 072'
2023-08-19 17:00:16,686 tm-csv-connector DEBUG: msg processed: b'\x1711 001 0001 00:00:10.63 '
2023-08-19 17:00:16,728 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 1, "time": "0:00:10.63"}
2023-08-19 17:00:16,763 tm-csv-connector DEBUG: data received: b'\x1711 0'
2023-08-19 17:00:16,764 tm-csv-connector DEBUG: residual: b'\x1711 0'
2023-08-19 17:00:17,066 tm-csv-connector DEBUG: data received: b'02 0002 00:00:10.77 \r\n\x1711 003 0003 00:00:10.93 \r\n\x17'
2023-08-19 17:00:17,067 tm-csv-connector DEBUG: residual: b'\x17'
2023-08-19 17:00:17,067 tm-csv-connector DEBUG: msg processed: b'\x1711 002 0002 00:00:10.77 '
2023-08-19 17:00:17,068 tm-csv-connector DEBUG: msg processed: b'\x1711 003 0003 00:00:10.93 '
2023-08-19 17:00:17,375 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 2, "time": "0:00:10.77"}
2023-08-19 17:00:17,393 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 3, "time": "0:00:10.93"}
2023-08-19 17:00:17,411 tm-csv-connector DEBUG: data received: b'11 004 0004 00:00:11.09 \r\n\x1711 005 0005 00:00:11.24 \r\n\x1711 006 0006 00:00:11.40 \r\n'
2023-08-19 17:00:17,411 tm-csv-connector DEBUG: msg processed: b'\x1711 004 0004 00:00:11.09 '
2023-08-19 17:00:17,412 tm-csv-connector DEBUG: msg processed: b'\x1711 005 0005 00:00:11.24 '
2023-08-19 17:00:17,412 tm-csv-connector DEBUG: msg processed: b'\x1711 006 0006 00:00:11.40 '
2023-08-19 17:00:17,722 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 4, "time": "0:00:11.09"}
2023-08-19 17:00:17,736 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 5, "time": "0:00:11.24"}
2023-08-19 17:00:17,753 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 6, "time": "0:00:11.40"}
2023-08-19 17:00:17,773 tm-csv-connector DEBUG: data received: b'\x1711 007 0007 00:00:11.57 \r\n\x1711 008 0008 00:00:11.74 \r\n'
2023-08-19 17:00:17,773 tm-csv-connector DEBUG: msg processed: b'\x1711 007 0007 00:00:11.57 '
2023-08-19 17:00:17,774 tm-csv-connector DEBUG: msg processed: b'\x1711 008 0008 00:00:11.74 '
2023-08-19 17:00:18,068 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 7, "time": "0:00:11.57"}
2023-08-19 17:00:18,083 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 8, "time": "0:00:11.74"}
2023-08-19 17:00:18,089 tm-csv-connector DEBUG: data received: b'\x1711 009 0009 00:00:11.90 \r\n\x1711 010 0010 00:00:12.06'
2023-08-19 17:00:18,090 tm-csv-connector DEBUG: residual: b'\x1711 010 0010 00:00:12.06'
2023-08-19 17:00:18,090 tm-csv-connector DEBUG: msg processed: b'\x1711 009 0009 00:00:11.90 '
2023-08-19 17:00:18,399 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 9, "time": "0:00:11.90"}
2023-08-19 17:00:18,405 tm-csv-connector DEBUG: data received: b' \r\n\x1711 011 0011 00:00:12.23 \r\n\x1711 012 0012 00:00:12.4'
2023-08-19 17:00:18,406 tm-csv-connector DEBUG: residual: b'\x1711 012 0012 00:00:12.4'
2023-08-19 17:00:18,406 tm-csv-connector DEBUG: msg processed: b'\x1711 010 0010 00:00:12.06 '
2023-08-19 17:00:18,406 tm-csv-connector DEBUG: msg processed: b'\x1711 011 0011 00:00:12.23 '
2023-08-19 17:00:18,728 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 10, "time": "0:00:12.06"}
2023-08-19 17:00:18,742 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 11, "time": "0:00:12.23"}
2023-08-19 17:00:19,088 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 13, "time": "0:00:12.57"}
2023-08-19 17:00:19,105 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 14, "time": "0:00:12.73"}
2023-08-19 17:00:19,112 tm-csv-connector DEBUG: data received: b'\x1711 015 0015 00:00:12.92 \r\n'
2023-08-19 17:00:19,114 tm-csv-connector DEBUG: msg processed: b'\x1711 015 0015 00:00:12.92 '
2023-08-19 17:00:19,435 tm-csv-connector DEBUG: sending: {"opcode": "primary", "pos": 15, "time": "0:00:12.92"}

web server sees all 15

2023-08-19 17:00:16 192.168.0.1 - - [19/Aug/2023:21:00:16 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:17 192.168.0.1 - - [19/Aug/2023:21:00:17 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:17 192.168.0.1 - - [19/Aug/2023:21:00:17 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:17 192.168.0.1 - - [19/Aug/2023:21:00:17 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:17 192.168.0.1 - - [19/Aug/2023:21:00:17 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:17 192.168.0.1 - - [19/Aug/2023:21:00:17 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:18 192.168.0.1 - - [19/Aug/2023:21:00:18 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:18 192.168.0.1 - - [19/Aug/2023:21:00:18 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:18 192.168.0.1 - - [19/Aug/2023:21:00:18 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:18 192.168.0.1 - - [19/Aug/2023:21:00:18 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:18 192.168.0.1 - - [19/Aug/2023:21:00:18 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:19 192.168.0.1 - - [19/Aug/2023:21:00:19 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:19 192.168.0.1 - - [19/Aug/2023:21:00:19 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:19 192.168.0.1 - - [19/Aug/2023:21:00:19 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"
2023-08-19 17:00:19 192.168.0.1 - - [19/Aug/2023:21:00:19 +0000] "GET /tm_reader HTTP/1.1" 101 4 "-" "Python/3.10 websockets/11.0.3"

but app is missing some

2023-08-19 17:00:16 [2023-08-19 21:00:16,730] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 1, "time": "0:00:10.63"}
2023-08-19 17:00:17 [2023-08-19 21:00:17,377] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 2, "time": "0:00:10.77"}
2023-08-19 17:00:17 [2023-08-19 21:00:17,395] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 3, "time": "0:00:10.93"}
2023-08-19 17:00:17 [2023-08-19 21:00:17,739] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 5, "time": "0:00:11.24"}
2023-08-19 17:00:18 [2023-08-19 21:00:18,085] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 8, "time": "0:00:11.74"}
2023-08-19 17:00:18 [2023-08-19 21:00:18,730] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 10, "time": "0:00:12.06"}
2023-08-19 17:00:19 [2023-08-19 21:00:19,090] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 13, "time": "0:00:12.57"}
2023-08-19 17:00:19 [2023-08-19 21:00:19,438] DEBUG in websockets_server: received data {"opcode": "primary", "pos": 15, "time": "0:00:12.92"}
miguelgrinberg commented 10 months ago

I don't really know how to interpret these logs, since there is no code that demonstrates how each side works with the WebSocket. But in any case, there is something that is very strange in which it appears that each message is sent on a separate WebSocket connection. When you say that the web server sees 15 messages and you demonstrate by showing 15 WebSocket connections that is wrong, the correct solution would be a single WebSocket connection receiving all the messages.

louking commented 10 months ago

All of the code is at https://github.com/louking/tm-csv-connector/tree/e114036e6c024eaae4ad1d26f68788655b45b11b

The messages are being sent from https://github.com/louking/tm-csv-connector/blob/e114036e6c024eaae4ad1d26f68788655b45b11b/tm-reader-client/app.py#L134-L158. Originally the loop had 

async with connect(backenduri) as websocket:
    while len(queued_msgs) > 0:

which would be more efficient, but this was an attempt to fix the lost messages. Following your suggestion of "the correct solution" I guess I could move the connection outside the while True loop. Having said that, while inefficient, I'm not sure why the way it's currently coded wouldn't work.

The receiver is at https://github.com/louking/tm-csv-connector/blob/e114036e6c024eaae4ad1d26f68788655b45b11b/app/src/tm_csv_connector/websockets_server.py#L28-L44

miguelgrinberg commented 10 months ago

Why are you sending like this?

            while len(queued_msgs) > 0:
                async with connect(backenduri) as websocket:
                    msg = queued_msgs.pop(0)
                    await send_to_backend(websocket, msg)

This is creating a new connection for each message, and it then closes the connection, possibly before giving time for the message to be sent (which I believe happens in a background task).

As I said before, I continue to believe this is a bug in your client application, not an issue with Flask-Sock or Flask-SocketIO on the server.

louking commented 10 months ago

Ok. I thought the async with connect() would await the connection to be set up before allowing the message to be sent, and that await send_to_backend() would not allow the with block to exit.

Good input, though, and I'll investigate moving the connect outside the while True loop.

louking commented 10 months ago

Yup, that was it. Thanks for your patience and advice @miguelgrinberg.

Fixed with https://github.com/louking/tm-csv-connector/commit/c3da31aed681ee892f4557b59a6f06468438d026

louking commented 10 months ago

I meant to note I also needed to use eventlet, else the flask app would get a worker timeout and restart. Possibly this could have been handled with gunicorn threads as well