Python socketio Async Client does not work correctly when connection is too long

[jona972]

Hello,

I have a client made in python, it must always be connected, but after a certain time the information does not reach me complete

As can be seen in the image there is information that does not arrive but from others.

In this image you can see that the information was received, but in the @sio.on() event I did not receive any information.

I really don't understand why that happens, the only way I found is by restarting the program and there if I get all the information again. I hope you can help me, thank you very much.

[miguelgrinberg]

I don't understand how to interpret the first image, because those are not logs that come from this package. What does the red rectangle indicate? Can you generate logs from this package for an event that isn't being reported?

[jona972]

log.txt

The red box means that it does not receive information from the @sio.on('sub_gps') event, and the blue box means that it did. The information that I print is in HEX value taken from the event. I attach the log that I have at the time that I do not receive all the information

[miguelgrinberg]

How can I make your HEX values to logged messages? That's the only way I can find what's different about the events for which you don't receive data.

[jona972]

I think that I expressed myself wrong, the data comes to me in json and later I convert it into HEX.

I am using the next libraries
python-socketio==4.6.0 python-engineio==3.13.2

and I enable the logger
sio = socketio.AsyncClient(logger=True, engineio_logger=True, ssl_verify=False, reconnection=True)

and the log prints the following message with correct data
Received packet MESSAGE data 2["sub_gps",{"deviceno":"008802E56D","lat":"-0.131108","lng":"-78.343045","state":1,"speed":0,"direction":331.7,"altitude":2435,"dateTime":"2021-06-03 15:18:16","vid":225,"carlicense":"YA020","groupName":"SAE YARUQUI"}]

But sometimes the log prints empyt data
2021-06-03 10:18:19,335 - Received event "sub_gps" [/]

The problem is that the server always sends information, but I receive empty data.

[miguelgrinberg]

@jona972 you are mixing up two different levels of logging. The Received packet MESSAGE logs are issued by the Engine.IO layer. The Received event logs are issued by the Socket.IO layer, and these do not print the data that is sent to the handler. For each received event, there are two log lines, one from each subsystem.

[jona972]

There is some way to detect when no information arrives in events because the server always sends information and I don't know where it is getting lost. Additionally, when I restart my client, all the information arrives without getting lost.

[miguelgrinberg]

@jona972 you are still not giving me any information I can use to troubleshoot this. I understand that you have found some issue with the data that arrives with events, but now I need to see how this reflects in my logs. As I said, each event that arrives in your client will print two lines in the log:

Received packet MESSAGE data 2["sub_gps",{"deviceno": ...
Received event "sub_gps" [/]

What you haven't shown me yet, is logs that show missing data. All the MESSAGE logs that you have shown me have data with them. You claim that some of the events are invoked with no data, then I need to see those in the log.

[jona972]

I understand you, but sometimes my client receives only the following messages:

Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,306 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,322 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,338 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,353 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,368 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,383 - Received event "sub_gps" [/]
Jun 03 00:19:41 [21734]: Received event "sub_gps" [/]

[miguelgrinberg]

These are all correct. I need to see a log line that starts with Received packet MESSAGE, in which the data is missing.

[jona972]

Oh I got you, I always receive the two logs message but in my code I print the data received:

@sio.on('sub_gps')
async def sub_gps(data):
     device_name = data.get('deviceno')
     logging.info("[%s] HEX: %s" % (device_name, message.hex()))  

message.hex() is the data transformed to hex string

For example:

Jun 03 00:19:41 [21734]: 2021-06-03 00:19:41,257 - [008802E98C] HEX: 0000000000000063520000007b224f5045524154494f4e223a22534f434b4554475053222c22504152414d45544552223a22303038383032453938432c2d302e3136323131312c2d37382e3332313231332c362c323536322c3232372e332c3230323130363033303031393336227d

Also you can see more data printed in the first image, but in the logs that I attached, the data received is not printed (I even waited all day and it didn't print), so I think that my client doesn't receive data. When I restart my client the data are printed normally. I don't know if I need to add a socketio.sleep() or what I have to do?

[miguelgrinberg]

I think I did not interpret the problem correctly. Based on what you reported, my assumption was that your sub_gps handler was being called, but sometimes it was called without data. Your last comment suggests it might not even be called at all. Which of the two is your case?

If the handler isn't being called, then there can be many reasons, like maybe the async application is blocked. I can't really help you address the issue, as it is likely it is something your application is doing to block the asyncio loop.

[jona972]

I think the event is not called because the message is not printed, is there any way to detect when the asyncio loop is blocked?

[miguelgrinberg]

@jona972 if your server does not respond to requests, then it is blocked.

[jona972]

For example, I have two devices A and B, the server always sends information from the two devices, but after a long time my client stops receiving information from device B but from device A if I get information. I need to reboot the system so that I can get back information from both devices. In this case also asyncio loop is blocked or not?

[miguelgrinberg]

@jona972 You are asking me questions that I cannot really answer, as I don't have the whole picture. You are missing some messages, right? You say that the server is sending these messages, but the client isn't receiving them. That is very unlikely, and you haven't provided any confirmation that the server is sending data that the client is not receiving. As I said several times before, this is something that you need to debug on your server and clients, and if you determine that the server is sending data that the client isn't receiving then I can investigate. So far you haven't shown any confirmation of this, or any code that I can use to reproduce the issue or understand your use case better, so I can't really comment any more. I just don't know. Sorry!