Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

some results sent from reader but missed at backend #15

Closed
louking opened this issue Aug 19, 2023 · 7 comments
Closed

some results sent from reader but missed at backend #15

louking opened this issue Aug 19, 2023 · 7 comments
Labels
bug Something isn't working

Comments

@louking
Copy link
Owner

louking commented Aug 19, 2023 •
edited
Loading

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 louking added the bug Something isn't working label Aug 19, 2023
@louking
Copy link
Owner Author

louking commented Aug 19, 2023 •
edited
Loading

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"}

@louking louking mentioned this issue Aug 21, 2023
Closed
@miguelgrinberg
Copy link

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
Copy link
Owner Author

louking commented Aug 23, 2023 •
edited
Loading

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

The messages are being sent from

tm-csv-connector/tm-reader-client/app.py

Lines 134 to 158 in e114036

async def reader(port, logging_path):
log.debug(f'async reader started with port {port}')
readloop = get_event_loop()
transport, protocol = await create_serial_connection(readloop, InputChunkProtocol, port)
protocol.set_logging_path(logging_path)
while True:
global stop_reader
if stop_reader:
log.debug('reader stopped')
stop_reader = False
transport.close()
break
await sleep(0.3)
# send any queued messages
global queued_msgs
if queued_msgs:
while len(queued_msgs) > 0:
async with connect(backenduri) as websocket:
msg = queued_msgs.pop(0)
await send_to_backend(websocket, msg)
protocol.resume_reading()
. 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

tm-csv-connector/app/src/tm_csv_connector/websockets_server.py

Lines 28 to 44 in e114036

@_websockets.route('/tm_reader')
def tm_reader(ws):
while True:
data = ws.receive()
current_app.logger.debug(f'received data {data}')
msg = loads(data)
# current_app.logger.debug(f'received msg {msg}')
# write to database
result = Result()
result.bibno = msg['bibno'] if 'bibno' in msg else None
result.tmpos = msg['pos']
result.time = timesecs(msg['time'])
# TODO: fix this to get from msg
result.race_id = 3
db.session.add(result)
db.session.commit()

@miguelgrinberg
Copy link

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
Copy link
Owner Author

louking commented Aug 23, 2023

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 added a commit that referenced this issue Aug 23, 2023
@louking
tm-reader-client: create websockets connection once for each reader t…
c3da31a 
…hread (#15)
@louking
Copy link
Owner Author

louking commented Aug 23, 2023

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

Fixed with c3da31a

@louking louking closed this as completed Aug 23, 2023
@louking
Copy link
Owner Author

louking commented Aug 23, 2023

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
@louking's tm-csv-connector
Status: Closed
Milestone
No milestone
Development

No branches or pull requests
2 participants
@louking @miguelgrinberg