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

[Bug]: fromRadioQueue is full #5152

Closed
hb9hha opened this issue Oct 26, 2024 · 3 comments
Closed

[Bug]: fromRadioQueue is full #5152

hb9hha opened this issue Oct 26, 2024 · 3 comments
Assignees
@GUVWAF
Labels
bug Something isn't working

Comments

@hb9hha
Copy link

hb9hha commented Oct 26, 2024

Category

BLE

Hardware

T-Echo

Firmware Version

2.5.7.f77c87d

Description

Hello meshtastic team !

I have a tricky bug with my t-echo.

Background:
I am using a T-Echo with my android phone using BLE. A personal MQTT server is configured with the "Proxy to client enabled" turned ON. I am using the default LongFast EU_868 modem settings. Node list is at the max 100 nodes and ChUtil is around 20%. Traffic is somewhat intense.

Symptoms:
The T-Echo stop working after a few hours. Android app says connected to a radio but last transmit time is not "now" but minutes/hours ago. Messages are not received any more. The blinking heartbeat blue LED is not blinking. The T-echo seems dead. A reset with the RST button solve the issue for a while.

Relevant logs:
First, all go smoothly for a few hours. I included standard logs from received packets and MQTT traffic.
Then, I think the e-paper screen is doing a FULL refresh.
Soon after that, we are seeing BUG logs:
DEBUG | 12:37:05 9726 [Screen] BUG! fromRadioQueue is full! Discarding! (id=0x55b78200 fr=0xe8 to=0xff, WantAck=0, HopLim=4 Ch=0x1 Portnum=67 rxtime=1729946226 rxSNR=-8.25 rxRSSI=-109 via M

And then the logs loops for the next 15 minutes.

I am not sure where to look. Is that a MQTT related problem? Is that a problem with the e-paper display? Do I have too much traffic to process? I do not have such behaviours with the T3S3 nor with the T-Beam connected with Wi-Fi and MQTT. T-echo users from my area are seeing similar behaviour with their t-echo. It seems persistent with this model.

Let me know if I can dig deeper and get some more debug logs.

Thanks for the great work !

73 de HB9HHA

Relevant log output

DEBUG | 12:36:50 9711 New ToRadio packet
INFO  | 12:36:50 9711 Got MqttClientProxy message
INFO  | 12:36:50 9711 Received MQTT topic msh/EU_868/2/e/LongFast/!7c5a4724, len=129
DEBUG | 12:36:50 9711 Using channel 1 (hash 0x8)
DEBUG | 12:36:50 9711 Expanding short PSK #1
DEBUG | 12:36:50 9711 Using AES128 key!
DEBUG | 12:36:50 9711 decoded message (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart=3)
INFO  | 12:36:50 9711 toRadioWriteCb data 0x20021c4a, len 147

DEBUG | 12:36:50 9711 New ToRadio packet
INFO  | 12:36:50 9711 Got MqttClientProxy message
INFO  | 12:36:50 9711 Received MQTT topic msh/EU_868/2/e/LongFast/!da585fa8, len=107
DEBUG | 12:36:50 9711 Using channel 1 (hash 0x8)
DEBUG | 12:36:50 9711 Expanding short PSK #1
DEBUG | 12:36:50 9711 Using AES128 key!
DEBUG | 12:36:50 9711 decoded message (id=0x7eb074d5 fr=0xa8 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946212 via MQTT hopStart=2 priority=70)

DEBUG | 12:36:50 9711 [Router] recentPackets size=95
DEBUG | 12:36:50 9711 [Router] recentPackets size=95 (after clearing expired packets)
DEBUG | 12:36:50 9711 [Router] Add packet record (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart=3)
DEBUG | 12:36:50 9711 [Router] recentPackets size=96
DEBUG | 12:36:50 9711 [Router] recentPackets size=96 (after clearing expired packets)
DEBUG | 12:36:50 9711 [Router] handleReceived(REMOTE) (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopSta
DEBUG | 12:36:50 9711 [Router] Module 'nodeinfo' wantsPacket=1
INFO  | 12:36:50 9711 [Router] Received nodeinfo from=0x8b9eefc, id=0x4ff2408d, portnum=4, payloadlen=56
DEBUG | 12:36:50 9711 [Router] old user IAPC La Barillette Router/ARBA, channel=1
DEBUG | 12:36:50 9711 [Router] updating changed=0 user IAPC La Barillette Router/ARBA, channel=1
INFO  | 12:36:50 9711 [Router] sending owner !329b8ad5/HB9HHA Samuel/HHA
DEBUG | 12:36:50 9711 [Router] Partially randomized packet id 2516211125
INFO  | 12:36:50 9711 [Router] Asked module 'nodeinfo' to send a response
DEBUG | 12:36:50 9711 [Router] Module 'routing' wantsPacket=1
INFO  | 12:36:50 9711 [Router] Received routing from=0x8b9eefc, id=0x4ff2408d, portnum=4, payloadlen=56
DEBUG | 12:36:50 9711 [Router] Routing sniffing (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart=3)
INFO  | 12:36:50 9711 [Router] Rebroadcasting received floodmsg
DEBUG | 12:36:50 9711 [Router] Expanding short PSK #1
DEBUG | 12:36:50 9711 [Router] Using AES128 key!
DEBUG | 12:36:50 9711 [Router] enqueuing for send (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=2 Ch=0x8 encrypted rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart=3 priority
DEBUG | 12:36:50 9711 [Router] txGood=829,txRelay=770,rxGood=507,rxBad=0
DEBUG | 12:36:50 9711 [Router] rx_snr found. hop_limit:6 rx_snr:-12.000000
DEBUG | 12:36:50 9711 [Router] rx_snr found in packet. Setting tx delay:1540
DEBUG | 12:36:50 9711 [Router] Delivering rx packet (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart
DEBUG | 12:36:50 9711 [Router] Update DB node 0x8b9eefc, rx_time=1729946210
DEBUG | 12:36:50 9711 [Router] Forwarding to phone (id=0x4ff2408d fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=4 WANTRESP rxtime=1729946210 rxSNR=-7.75 rxRSSI=-115 via MQTT hopStart=
DEBUG | 12:36:50 9711 [Router] Module 'routing' considered
DEBUG | 12:36:50 9711 [Router] Sending response (id=0x95fa55b5 fr=0xd5 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946210 priority=70)
DEBUG | 12:36:50 9711 [Router] Update DB node 0x329b8ad5, rx_time=1729946210
DEBUG | 12:36:50 9711 [Router] Add packet record (id=0x95fa55b5 fr=0xd5 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946210 priority=70)
DEBUG | 12:36:50 9711 [Router] recentPackets size=97
DEBUG | 12:36:50 9711 [Router] recentPackets size=97 (after clearing expired packets)
DEBUG | 12:36:50 9711 [Router] Expanding short PSK #1
DEBUG | 12:36:50 9711 [Router] Using AES128 key!
DEBUG | 12:36:51 9712 [Router] MQTT onSend - Publishing
DEBUG | 12:36:51 9712 [Router] encrypted message
DEBUG | 12:36:51 9712 [Router] MQTT Publish msh/EU_868/2/e/LongFast/!329b8ad5, 139 bytes
DEBUG | 12:36:51 9712 [Router] Sending mqtt message on topic 'msh/EU_868/2/e/LongFast/!329b8ad5' to client for proxy
DEBUG | 12:36:51 9712 [Router] enqueuing for send (id=0x95fa55b5 fr=0xd5 to=0xfc, WantAck=0, HopLim=2 Ch=0x8 encrypted rxtime=1729946210 hopStart=2 priority=70)
DEBUG | 12:36:51 9712 [Router] txGood=829,txRelay=770,rxGood=507,rxBad=0
DEBUG | 12:36:51 9712 [Router] rx_snr found. hop_limit:6 rx_snr:-12.000000
DEBUG | 12:36:51 9712 [Router] rx_snr found in packet. Setting tx delay:1540
DEBUG | 12:36:51 9712 [Router] recentPackets size=97
DEBUG | 12:36:51 9712 [Router] recentPackets size=97 (after clearing expired packets)
DEBUG | 12:36:51 9712 [Router] Add packet record (id=0x7eb074d5 fr=0xa8 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946212 via MQTT hopStart=2 priority=70)
DEBUG | 12:36:51 9712 [Router] recentPackets size=98
DEBUG | 12:36:51 9712 [Router] recentPackets size=98 (after clearing expired packets)
DEBUG | 12:36:51 9712 [Router] handleReceived(REMOTE) (id=0x7eb074d5 fr=0xa8 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946211 via MQTT hopStart=2 priority=
DEBUG | 12:36:51 9712 [Router] Module 'nodeinfo' wantsPacket=1
INFO  | 12:36:51 9712 [Router] Received nodeinfo from=0xda585fa8, id=0x7eb074d5, portnum=4, payloadlen=45
DEBUG | 12:36:51 9712 [Router] old user HB9Y Plaine Morte/PLM, channel=1
DEBUG | 12:36:51 9712 [Router] updating changed=0 user HB9Y Plaine Morte/PLM, channel=1
DEBUG | 12:36:51 9712 [Router] Module 'nodeinfo' considered
DEBUG | 12:36:51 9712 [Router] Module 'routing' wantsPacket=1
INFO  | 12:36:51 9712 [Router] Received routing from=0xda585fa8, id=0x7eb074d5, portnum=4, payloadlen=45
DEBUG | 12:36:51 9712 [Router] Routing sniffing (id=0x7eb074d5 fr=0xa8 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946211 via MQTT hopStart=2 priority=70)
DEBUG | 12:36:51 9712 [Router] Rxd an ACK/reply not for me, cancel rebroadcast.
DEBUG | 12:36:51 9712 [Router] cancelSending id=0x4ff2408d, removed=1
INFO  | 12:36:51 9712 [Router] Rebroadcasting received floodmsg
DEBUG | 12:36:51 9712 [Router] Expanding short PSK #1
DEBUG | 12:36:51 9712 [Router] Using AES128 key!
DEBUG | 12:36:51 9712 [Router] enqueuing for send (id=0x7eb074d5 fr=0xa8 to=0xfc, WantAck=0, HopLim=1 Ch=0x8 encrypted rxtime=1729946211 via MQTT hopStart=2 priority=70)
DEBUG | 12:36:51 9712 [Router] txGood=829,txRelay=770,rxGood=507,rxBad=0
DEBUG | 12:36:51 9712 [Router] rx_snr found. hop_limit:6 rx_snr:-12.000000
DEBUG | 12:36:51 9712 [Router] rx_snr found in packet. Setting tx delay:1309
DEBUG | 12:36:51 9712 [Router] Module 'routing' considered

INFO  | 12:36:51 9712 [Screen] Turning on screen
DEBUG | 12:36:51 9712 [Screen] Screen: Joined: IAPC La Barillette Router
INFO  | 12:36:51 9712 [Screen] toRadioWriteCb data 0x20021c4a, len 175
DEBUG | 12:36:51 9712 [Screen] New ToRadio packet
DEBUG | 12:36:51 9712 [Screen] Joining an async refresh in progress
DEBUG | 12:36:51 9712 [Screen] Refresh complete
DEBUG | 12:36:51 9712 [Screen] Drawing screensaver overlay
DEBUG | 12:36:51 9712 [Screen] haveGlyphs=1
DEBUG | 12:36:51 9712 [Screen] determineMode():
DEBUG | 12:36:51 9712 [Screen] refresh=FULL, reason=FLAGGED_COSMETIC, frameFlags=0x7
DEBUG | 12:36:51 9712 [Screen] Updating E-Paper
DEBUG | 12:36:51 9712 [Screen] Async full-refresh complete
DEBUG | 12:36:51 9712 [Screen] determineMode():
DEBUG | 12:36:51 9712 [Screen] Updating E-Paper
DEBUG | 12:36:52 9713 [Screen] done
DEBUG | 12:36:52 9713 [Screen] Async full-refresh begins (dropping frames)
DEBUG | 12:36:52 9713 [Screen] showing standard frames
DEBUG | 12:36:52 9713 [Screen] Showing 0 module frames
DEBUG | 12:36:52 9713 [Screen] Total frame count: 103
DEBUG | 12:36:52 9713 [Screen] Added modules.  numframes: 0
DEBUG | 12:36:52 9713 [Screen] Finished building frames. numframes: 7
INFO  | 12:36:52 9713 [Screen] Turning off screen
INFO  | 12:36:52 9713 [Screen] Got MqttClientProxy message
INFO  | 12:36:52 9713 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!4d6e573d, len=134
DEBUG | 12:36:52 9713 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:36:52 9713 [Screen] Expanding short PSK #1
DEBUG | 12:36:52 9713 [Screen] Using AES128 key!
DEBUG | 12:36:52 9713 [Screen] decoded message (id=0x5fcce291 fr=0x3d to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946209 via MQTT hopStart=2 priority=70)
INFO  | 12:36:52 9713 [Screen] toRadioWriteCb data 0x20021c4a, len 183
DEBUG | 12:36:52 9713 [Screen] New ToRadio packet
INFO  | 12:36:52 9713 [Screen] Got MqttClientProxy message
INFO  | 12:36:52 9713 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!c4d67a99, len=142
DEBUG | 12:36:52 9713 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:36:52 9713 [Screen] Expanding short PSK #1
DEBUG | 12:36:52 9713 [Screen] Using AES128 key!
DEBUG | 12:36:52 9713 [Screen] decoded message (id=0x51bef394 fr=0x99 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946211 via MQTT hopStart=2 priority=70)
INFO  | 12:36:55 9716 [Screen] toRadioWriteCb data 0x20021c4a, len 191
DEBUG | 12:36:55 9716 [Screen] New ToRadio packet
INFO  | 12:36:55 9716 [Screen] Got MqttClientProxy message
INFO  | 12:36:55 9716 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!9c62576b, len=150
DEBUG | 12:36:55 9716 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:36:55 9716 [Screen] Expanding short PSK #1
DEBUG | 12:36:55 9716 [Screen] Using AES128 key!
DEBUG | 12:36:55 9716 [Screen] decoded message (id=0x1a8dc115 fr=0x6b to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=4 requestId=4ff2408d rxtime=1729946203 via MQTT hopStart=2 priority=70)
INFO  | 12:37:05 9726 [Screen] toRadioWriteCb data 0x20021c4a, len 50
DEBUG | 12:37:05 9726 [Screen] New ToRadio packet
DEBUG | 12:37:05 9726 [Screen] PACKET FROM PHONE (id=0xf0346ad9 fr=0x00 to=0xd5, WantAck=0, HopLim=5 Ch=0x0 Portnum=3 priority=10)
DEBUG | 12:37:05 9726 [Screen] Enqueued local (id=0xf0346ad9 fr=0x00 to=0xd5, WantAck=0, HopLim=5 Ch=0x0 Portnum=3 rxtime=1729946225 priority=10)
INFO  | 12:37:05 9726 [Screen] toRadioWriteCb data 0x20021c4a, len 140

DEBUG | 12:37:05 9726 [Screen] New ToRadio packet
INFO  | 12:37:05 9726 [Screen] Got MqttClientProxy message
INFO  | 12:37:05 9726 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!c4d67a99, len=100
DEBUG | 12:37:05 9726 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:37:05 9726 [Screen] Expanding short PSK #1
DEBUG | 12:37:05 9726 [Screen] Using AES128 key!
DEBUG | 12:37:05 9726 [Screen] decoded message (id=0x55b78200 fr=0xe8 to=0xff, WantAck=0, HopLim=4 Ch=0x1 Portnum=67 rxtime=1729946226 rxSNR=-8.25 rxRSSI=-109 via MQTT hopStart=5)
DEBUG | 12:37:05 9726 [Screen] BUG! fromRadioQueue is full! Discarding! (id=0x55b78200 fr=0xe8 to=0xff, WantAck=0, HopLim=4 Ch=0x1 Portnum=67 rxtime=1729946226 rxSNR=-8.25 rxRSSI=-109 via M
INFO  | 12:37:13 9734 [Screen] toRadioWriteCb data 0x20021c4a, len 122

DEBUG | 12:37:13 9734 [Screen] New ToRadio packet
INFO  | 12:37:13 9734 [Screen] Got MqttClientProxy message
INFO  | 12:37:13 9734 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!7c5a4724, len=83
DEBUG | 12:37:13 9734 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:37:13 9734 [Screen] Expanding short PSK #1
DEBUG | 12:37:13 9734 [Screen] Using AES128 key!
DEBUG | 12:37:13 9734 [Screen] decoded message (id=0x5aa096ae fr=0x24 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=3 requestId=2692788f rxtime=1729946233 via MQTT hopStart=2 priority=70)
DEBUG | 12:37:13 9734 [Screen] BUG! fromRadioQueue is full! Discarding! (id=0x5aa096ae fr=0x24 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=3 requestId=2692788f rxtime=1729946233 via MQTT ho
INFO  | 12:37:13 9734 [Screen] toRadioWriteCb data 0x20021c4a, len 128

DEBUG | 12:37:13 9734 [Screen] New ToRadio packet
INFO  | 12:37:13 9734 [Screen] Got MqttClientProxy message
INFO  | 12:37:13 9734 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!7c5a4724, len=89
DEBUG | 12:37:13 9734 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:37:13 9734 [Screen] Expanding short PSK #1
DEBUG | 12:37:13 9734 [Screen] Using AES128 key!
DEBUG | 12:37:13 9734 [Screen] decoded message (id=0x2692788f fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 WANTRESP rxtime=1729946233 rxSNR=-13 rxRSSI=-115 via MQTT hopStart=3)
DEBUG | 12:37:13 9734 [Screen] BUG! fromRadioQueue is full! Discarding! (id=0x2692788f fr=0xfc to=0xff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 WANTRESP rxtime=1729946233 rxSNR=-13 rxRSSI=-115
INFO  | 12:37:13 9734 [Screen] toRadioWriteCb data 0x20021c4a, len 122

DEBUG | 12:37:13 9734 [Screen] New ToRadio packet
INFO  | 12:37:13 9734 [Screen] Got MqttClientProxy message
INFO  | 12:37:13 9734 [Screen] Received MQTT topic msh/EU_868/2/e/LongFast/!da585550, len=83
DEBUG | 12:37:13 9734 [Screen] Using channel 1 (hash 0x8)
DEBUG | 12:37:13 9734 [Screen] Expanding short PSK #1
DEBUG | 12:37:13 9734 [Screen] Using AES128 key!
DEBUG | 12:37:13 9734 [Screen] decoded message (id=0xe05883a4 fr=0x50 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=3 requestId=2692788f rxtime=1729946233 via MQTT hopStart=2 priority=70)
DEBUG | 12:37:13 9734 [Screen] BUG! fromRadioQueue is full! Discarding! (id=0xe05883a4 fr=0x50 to=0xfc, WantAck=0, HopLim=2 Ch=0x1 Portnum=3 requestId=2692788f rxtime=1729946233 via MQTT ho
INFO  | 12:37:13 9734 [Screen] toRadioWriteCb data 0x20021c4a, len 122
@hb9hha hb9hha added the bug Something isn't working label Oct 26, 2024
@hb9hha
Copy link
Author

hb9hha commented Oct 27, 2024

Found this code asking for a fix in Router.cpp :)

/**
 * RadioInterface calls this to queue up packets that have been received from the radio.  The router is now responsible for
 * freeing the packet
 */
void Router::enqueueReceivedMessage(meshtastic_MeshPacket *p)
{
    if (fromRadioQueue.enqueue(p, 0)) { // NOWAIT - fixme, if queue is full, delete older messages

        // Nasty hack because our threading is primitive.  interfaces shouldn't need to know about routers FIXME
        setReceivedMessage();
    } else {
        printPacket("BUG! fromRadioQueue is full! Discarding!", p);
        packetPool.release(p);
    }
}

@GUVWAF GUVWAF self-assigned this Oct 31, 2024
@GUVWAF GUVWAF mentioned this issue Nov 1, 2024
Merged
@GUVWAF
Copy link
Member

GUVWAF commented Nov 1, 2024

Thanks for the report, that’s indeed a tricky bug. It should be fixed by #5212, I tested it by faking the same behavior you were seeing.

@hb9hha
Copy link
Author

hb9hha commented Nov 1, 2024

Thank you @GUVWAF for your time and for the fix! Dropping oldest traffic should prevent the router from being locked out when the queue is full. It should fail safe and not crash any more. I will test it when the new firmware is out and report if needed.

Thanks again ! 👍

@hb9hha hb9hha closed this as completed Nov 1, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@GUVWAF GUVWAF

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@GUVWAF @hb9hha