First message to a room node after login always fails

[neutralinsomniac]

Issue is kinda strange. If I have a room node that is idle (no messages being sent to it) for several hours or so, login to the room works fine, but the first message I try to send to it always reaches max re-transmission and fails. Re-sending the message always succeeds. Seen with both a RAK 4631 and a LilyGo T-Echo.

[marrold]

Out of curiosity, what happens if you reset the path to force a flood, before sending each message?

[neutralinsomniac]

OK so I tested it further. It doesn't seem to matter if I attempt a direct message or a flood message. The first message after logging in to a room always fails. I can log in, send message (direct) and it fails. I can log in, reset path, send message (flood) and it fails. In both scenarios if I send another message without re-logging in to the room, it works.

[fishingdev5]

Is room server node clock synced? I have observed DM failures if clock is not synced on room server.

[neutralinsomniac]

Yes, the clock is synced. Just re-synced to be sure. Same behavior.

[neutralinsomniac]

I reflashed my T1000 (client) to the latest dev build and I can't reproduce the issue anymore.

[neutralinsomniac]

Apparently I spoke too soon. I'm seeing this issue again.

[neutralinsomniac]

To rule out the T1000, I've been using the T114 as my client. I'm seeing this issue there too. It only happens after the client has been running for a while (say 8+ hours). Then the issue is 100% reproducible until I reboot the client, at which point everything works fine again until 8+ or so hours passes again.

[neutralinsomniac]

This is still happening on v1.10. I've found that this only happens if I log in to the room node with a password. Using a blank password allows me to immediately send a message after login. And this is still only after the client has been up for a couple days or more. Doesn't matter how long the server is up. If I reboot the client, the issue disappears completely (I can successfully send a message directly after password logins) until a day or two has passed again.

[neutralinsomniac]

Oh and here's a log of a failure (from the client log) followed by a success (after waiting for all the retries to fail out):

[07:58:29] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:30] [Connection] onFrameReceived: responseCode=136, length=25
[07:58:30] [Connection] onFrameReceived: responseCode=129, length=33
[07:58:30] [Connection] onFrameReceived: responseCode=133, length=14
[07:58:30] [Connection] onFrameReceived: responseCode=3, length=148
[07:58:32] [Connection] onFrameReceived: responseCode=13, length=80
[07:58:33] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:33] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=65, expectedAckCode=1692275924
[07:58:36] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:36] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=65, expectedAckCode=2459405779
[07:58:39] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:39] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=65, expectedAckCode=445732474
[07:58:41] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:41] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=65, expectedAckCode=3292392328
[07:58:44] [Connection] onFrameReceived: responseCode=0, length=1
[07:58:44] [Connection] onFrameReceived: responseCode=3, length=148
[07:58:44] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:44] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=65, expectedAckCode=1692275924
[07:58:48] [Database] setMessageFailedById: id=65
[07:58:50] [Connection] onFrameReceived: responseCode=13, length=80
[07:58:50] [Connection] onFrameReceived: responseCode=6, length=10
[07:58:50] [AckCodeManager] rememberContactMessageAckCode: contactMessageId=66, expectedAckCode=3927448717
[07:58:51] [Connection] onFrameReceived: responseCode=136, length=9
[07:58:51] [Connection] onFrameReceived: responseCode=130, length=9
[07:58:51] [Database] setMessageDeliveredByAckCode: ackCode=3927448717 contactMessageId=66
[07:58:53] [Connection] onFrameReceived: responseCode=5, length=60
[07:58:53] [ConnectionManager] setCurrentSelfInfo: 9S
[07:58:53] [Connection] onFrameReceived: responseCode=13, length=80
[07:58:53] [Connection] onFrameReceived: responseCode=12, length=11
[07:59:11] [Connection] onFrameReceived: responseCode=12, length=11

[oltaco]

Sorry that this has slipped through the cracks. Do you have any logs from the room server side? The room server would need to be compiled with MESH_DEBUG and possibly MESH_PACKET_LOGGING flags.

[neutralinsomniac]

Hey sorry it took me so long to get back again. Life got in the way. Here is a packet log on the room server showing the failed message, followed by the successful one after waiting for the 5 retries failure:

10:57:40 - 15/5/2024 U: RX, len=53 (type=7, route=D, payload_len=51) SNR=12 RSSI=-13 score=1000 # login
10:57:41 - 15/5/2024 U: TX, len=22 (type=1, route=D, payload_len=20) [CE -> E7] # login ack
10:57:43 - 15/5/2024 U: RX, len=22 (type=2, route=D, payload_len=20) SNR=12 RSSI=-13 score=1000 [E7 -> CE] # message 1/5
10:57:46 - 15/5/2024 U: RX, len=22 (type=2, route=D, payload_len=20) SNR=11 RSSI=-13 score=1000 [E7 -> CE] # message 2/5
10:57:49 - 15/5/2024 U: RX, len=22 (type=2, route=D, payload_len=20) SNR=11 RSSI=-13 score=1000 [E7 -> CE] # message 3/5
10:57:51 - 15/5/2024 U: RX, len=22 (type=2, route=D, payload_len=20) SNR=12 RSSI=-13 score=1000 [E7 -> CE] # message 4/5
10:57:54 - 15/5/2024 U: RX, len=22 (type=2, route=F, payload_len=20) SNR=12 RSSI=-13 score=1000 [E7 -> CE] # message 5/5
10:58:00 - 15/5/2024 U: RX, len=22 (type=2, route=F, payload_len=20) SNR=12 RSSI=-13 score=1000 [E7 -> CE] # send message again
10:58:01 - 15/5/2024 U: TX, len=6 (type=3, route=D, payload_len=4) # ack!

I'm not sure how to get the serial console logs off of the room server.

[neutralinsomniac]

I have repeat set to ON but it happens with repeat disabled as well.