[Bug]: Too many nodeinfo

[FFAMax]

Category

Other

Hardware

Not Applicable

Is this bug report about any UI component firmware like InkHUD or Meshtatic UI (MUI)?

• Meshtastic UI aka MUI colorTFT
• InkHUD ePaper
• OLED slide UI on any display

Firmware Version

xxx

Description

Hello, team. I noticed nodes sending too many nodeinfo, any ideas why?

Another case with CLIENT_MUTE - once it start receiving traffic, seems like the node start responding to everybody heard (on the right side TX util groing along with RX):

This doesn't catch all the packets but here is enough to catch the idea:

So let's investigate and fix the logic of how nodes are working instead of blaming firmware and escape to more 'wide' presets:

Relevant log output

[FFAMax]

• I need remind you ignoring potential bug allowing generate storm [Bug]: Broadcast Storm is possible on 2.7.15.567b8ea #9162

[thebentern]

@FFAMax is it possible your node is browning out or crashing and then rebooting only to send a new nodeinfo packet on boot?

[FFAMax]

@thebentern I have just verified uptime - 30h, so this is not the case.

[thebentern]

Logs for this would be helpful, as well as what firmware the device is running. Otherwise we're flying blind on this issue

[FFAMax]

Trying reproduce on another node, the original one worked on 2.7.14, picked on flasher 2.7.15 2.7.16 but there are a lot of

DEBUG | ??:??:?? 59 [Router] Module 'nodeinfo' wantsPacket=1
INFO  | ??:??:?? 59 [Router] Received nodeinfo from=0xfe4dc246, id=0x37bb58a0, portnum=4, payloadlen=32
ERROR | ??:??:?? 59 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xc8be0
ERROR | ??:??:?? 59 [Router] Error decoding proto module!
ERROR | ??:??:?? 59 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xc8be0
ERROR | ??:??:?? 59 [Router] Error decoding proto module!

That's why we may have no that spam - because node unable decode the origiginal packet in firtst place.

Is there any protection to detect a lot of nodeinfo messages node trying to send?
What will trigger node to send nodeinfo? If peer heard fiirst time? What if node start learning hundreeds of nodes around? What if some of them pushed out from memory and they heard again?

Few more logs:

INFO  | 12:32:05 215 [Router] Received nodeinfo from=0x9b09ed9a, id=0x68a415f6, portnum=4, payloadlen=31
ERROR | 12:32:05 215 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:05 215 [Router] Error decoding proto module!
ERROR | 12:32:05 215 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:05 215 [Router] Error decoding proto module!
DEBUG | 12:32:05 215 [Router] Module 'nodeinfo' considered
DEBUG | 12:32:05 215 [Router] Module 'nodeinfo' handled and skipped other processing
DEBUG | 12:32:06 215 [RadioIf] Corrected frequency offset: 421.406250
DEBUG | 12:32:06 215 [RadioIf] Lora RX (id=0x75c1b4df fr=0xfe4dc246 to=0x9045517a, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:06 215 [RadioIf] Packet RX: 641ms
INFO  | 12:32:06 215 [Router] Packet History - insert: Reusing slot aged 8.173s TRACE MATCHED PACKET
DEBUG | 12:32:06 215 [Router] Ignore dupe incoming msg (id=0x75c1b4df fr=0xfe4dc246 to=0x9045517a, transport = 1, WantAck=1,)
DEBUG | 12:32:06 215 [Router] cancelSending id=0x75c1b4df, removed=0
DEBUG | 12:32:06 215 [Router] Incoming msg was filtered from 0xfe4dc246
DEBUG | 12:32:07 217 [RadioIf] Corrected frequency offset: 419.468719
DEBUG | 12:32:07 217 [RadioIf] Lora RX (id=0xe52e88de fr=0xfe4dc246 to=0x6999ca12, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:07 217 [RadioIf] Packet RX: 641ms
INFO  | 12:32:07 217 [Router] Packet History - insert: Reusing slot aged 8.128s TRACE MATCHED PACKET
DEBUG | 12:32:07 217 [Router] Ignore dupe incoming msg (id=0xe52e88de fr=0xfe4dc246 to=0x6999ca12, transport = 1, WantAck=1,)
DEBUG | 12:32:07 217 [Router] cancelSending id=0xe52e88de, removed=0
DEBUG | 12:32:07 217 [Router] Incoming msg was filtered from 0xfe4dc246
DEBUG | 12:32:14 223 [RadioIf] Corrected frequency offset: 431.093750
DEBUG | 12:32:14 223 [RadioIf] Lora RX (id=0x75c1b4df fr=0xfe4dc246 to=0x9045517a, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:14 223 [RadioIf] Packet RX: 641ms
INFO  | 12:32:14 223 [Router] Packet History - insert: Reusing slot aged 8.212s TRACE MATCHED PACKET
DEBUG | 12:32:14 223 [Router] Ignore dupe incoming msg (id=0x75c1b4df fr=0xfe4dc246 to=0x9045517a, transport = 1, WantAck=1,)
DEBUG | 12:32:14 223 [Router] cancelSending id=0x75c1b4df, removed=0
DEBUG | 12:32:14 223 [Router] Incoming msg was filtered from 0xfe4dc246
DEBUG | 12:32:19 228 [RadioIf] Corrected frequency offset: 371.031219
DEBUG | 12:32:19 228 [RadioIf] Lora RX (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 0, WantAck=0, HopLim=6 Ch=0x8)
DEBUG | 12:32:19 228 [RadioIf] Packet RX: 559ms
INFO  | 12:32:19 228 [Router] Packet History - insert: Using new slot @uptime 228.954s TRACE NEW
DEBUG | 12:32:19 228 [Router] Use channel 0 (hash 0x8)
DEBUG | 12:32:19 228 [Router] Expand short PSK #1
DEBUG | 12:32:19 228 [Router] Use AES128 key!
DEBUG | 12:32:19 229 [Router] decoded message (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 1, WantAck=0, HopLim=6t
DEBUG | 12:32:19 229 [Router] handleReceived(REMOTE) (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 1, WantAck=0, H1
DEBUG | 12:32:19 229 [Router] Module 'DeviceTelemetry' wantsPacket=1
INFO  | 12:32:19 229 [Router] Received DeviceTelemetry from=0x3b46b980, id=0xebdac6fe, portnum=67, payloadlen=23
INFO  | 12:32:19 229 [Router] (Received from ???): air_util_tx=1.834972, channel_utilization=22.286667, battery_level=101, v0
INFO  | 12:32:19 229 [Router] Node database full with 80 nodes and 74192 bytes free. Erasing oldest entry
INFO  | 12:32:19 229 [Router] Adding node to database with 80 nodes and 74192 bytes free!
DEBUG | 12:32:19 229 [Router] updateTelemetry REMOTE node=0x3b46b980 
DEBUG | 12:32:19 229 [Router] Node status update: 12 online, 80 total
DEBUG | 12:32:19 229 [Router] Module 'DeviceTelemetry' considered
DEBUG | 12:32:19 229 [Router] Module 'routing' wantsPacket=1
INFO  | 12:32:19 229 [Router] Received routing from=0x3b46b980, id=0xebdac6fe, portnum=67, payloadlen=23
DEBUG | 12:32:19 229 [Router] Routing sniffing (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 1, WantAck=0, HopLim=S
DEBUG | 12:32:19 229 [Router] No rebroadcast: Role = CLIENT_MUTE or Rebroadcast Mode = NONE
DEBUG | 12:32:19 229 [Router] Delivering rx packet (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 1, WantAck=0, Hop 
DEBUG | 12:32:19 229 [Router] Update DB node 0x3b46b980, rx_time=1771878739
INFO  | 12:32:19 229 [Router] Sort took 4 milliseconds
DEBUG | 12:32:19 229 [Router] Forwarding to phone (id=0xebdac6fe fr=0x3b46b980 to=0xffffffff, transport = 1, WantAck=0, HopLh
DEBUG | 12:32:19 229 [Router] Module 'routing' considered
DEBUG | 12:32:20 230 [RadioIf] Corrected frequency offset: 433.031219
DEBUG | 12:32:20 230 [RadioIf] Lora RX (id=0xfaf114e4 fr=0xfe4dc246 to=0x3b46b980, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:20 230 [RadioIf] Packet RX: 641ms
INFO  | 12:32:20 230 [Router] Packet History - insert: Using new slot @uptime 230.033s TRACE NEW
DEBUG | 12:32:20 230 [Router] Use channel 0 (hash 0x8)
DEBUG | 12:32:20 230 [Router] Expand short PSK #1
DEBUG | 12:32:20 230 [Router] Use AES128 key!
DEBUG | 12:32:21 230 [Router] decoded message (id=0xfaf114e4 fr=0xfe4dc246 to=0x3b46b980, transport = 1, WantAck=1, HopLim=0)
DEBUG | 12:32:21 230 [Router] handleReceived(REMOTE) (id=0xfaf114e4 fr=0xfe4dc246 to=0x3b46b980, transport = 1, WantAck=1, H8
DEBUG | 12:32:21 230 [Router] Module 'nodeinfo' wantsPacket=1
INFO  | 12:32:21 230 [Router] Received nodeinfo from=0xfe4dc246, id=0xfaf114e4, portnum=4, payloadlen=32
ERROR | 12:32:21 230 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:21 230 [Router] Error decoding proto module!
ERROR | 12:32:21 230 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:21 230 [Router] Error decoding proto module!
DEBUG | 12:32:21 230 [Router] Module 'nodeinfo' considered
DEBUG | 12:32:21 230 [Router] Module 'nodeinfo' handled and skipped other processing
DEBUG | 12:32:27 236 [RadioIf] Corrected frequency offset: 363.281250
DEBUG | 12:32:27 236 [RadioIf] Lora RX (id=0xf86465f7 fr=0x9b09ed9a to=0xad5353e1, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:27 236 [RadioIf] Packet RX: 641ms
INFO  | 12:32:27 236 [Router] Packet History - insert: Using new slot @uptime 236.120s TRACE NEW
DEBUG | 12:32:27 236 [Router] Use channel 0 (hash 0x8)
DEBUG | 12:32:27 236 [Router] Expand short PSK #1
DEBUG | 12:32:27 236 [Router] Use AES128 key!
DEBUG | 12:32:27 236 [Router] decoded message (id=0xf86465f7 fr=0x9b09ed9a to=0xad5353e1, transport = 1, WantAck=1, HopLim=0)
DEBUG | 12:32:27 236 [Router] handleReceived(REMOTE) (id=0xf86465f7 fr=0x9b09ed9a to=0xad5353e1, transport = 1, WantAck=1, H4
DEBUG | 12:32:27 236 [Router] Module 'nodeinfo' wantsPacket=1
INFO  | 12:32:27 236 [Router] Received nodeinfo from=0x9b09ed9a, id=0xf86465f7, portnum=4, payloadlen=32
ERROR | 12:32:27 236 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:27 236 [Router] Error decoding proto module!
ERROR | 12:32:27 236 [Router] Can't decode protobuf reason='end-of-stream', pb_msgdesc 0xb4ce4
ERROR | 12:32:27 236 [Router] Error decoding proto module!
DEBUG | 12:32:27 236 [Router] Module 'nodeinfo' considered
DEBUG | 12:32:27 236 [Router] Module 'nodeinfo' handled and skipped other processing
DEBUG | 12:32:29 239 [RadioIf] Corrected frequency offset: 438.843719
DEBUG | 12:32:29 239 [RadioIf] Lora RX (id=0xfaf114e4 fr=0xfe4dc246 to=0x3b46b980, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:29 239 [RadioIf] Packet RX: 641ms
INFO  | 12:32:29 239 [Router] Packet History - insert: Reusing slot aged 9.025s TRACE MATCHED PACKET
DEBUG | 12:32:29 239 [Router] Ignore dupe incoming msg (id=0xfaf114e4 fr=0xfe4dc246 to=0x3b46b980, transport = 1, WantAck=1,)
DEBUG | 12:32:29 239 [Router] cancelSending id=0xfaf114e4, removed=0
DEBUG | 12:32:29 239 [Router] Incoming msg was filtered from 0xfe4dc246
DEBUG | 12:32:34 243 [RadioIf] Corrected frequency offset: 367.156250
DEBUG | 12:32:34 243 [RadioIf] Lora RX (id=0x68a415f6 fr=0x9b09ed9a to=0x97247990, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:34 243 [RadioIf] Packet RX: 641ms
INFO  | 12:32:34 243 [Router] Packet History - insert: Reusing slot aged 28.874s TRACE MATCHED PACKET
DEBUG | 12:32:34 243 [Router] Ignore dupe incoming msg (id=0x68a415f6 fr=0x9b09ed9a to=0x97247990, transport = 1, WantAck=1,)
DEBUG | 12:32:34 243 [Router] cancelSending id=0x68a415f6, removed=0
DEBUG | 12:32:34 243 [Router] Incoming msg was filtered from 0x9b09ed9a
DEBUG | 12:32:35 244 [RadioIf] Corrected frequency offset: 365.218719
DEBUG | 12:32:35 244 [RadioIf] Lora RX (id=0xf86465f7 fr=0x9b09ed9a to=0xad5353e1, transport = 0, WantAck=1, HopLim=0 Ch=0x8)
DEBUG | 12:32:35 244 [RadioIf] Packet RX: 641ms
INFO  | 12:32:35 244 [Router] Packet History - insert: Reusing slot aged 8.699s TRACE MATCHED PACKET
DEBUG | 12:32:35 244 [Router] Ignore dupe incoming msg (id=0xf86465f7 fr=0x9b09ed9a to=0xad5353e1, transport = 1, WantAck=1,)
DEBUG | 12:32:35 244 [Router] cancelSending id=0xf86465f7, removed=0

[FFAMax]

Probably related to packets with want_response.

Aha, here are an options to send at least one nodeinfo every 1 or 5 minutes.

meshtastic_MeshPacket *NodeInfoModule::allocReply()
{
    if (!airTime->isTxAllowedChannelUtil(false)) {
        ignoreRequest = true; // Mark it as ignored for MeshModule
        LOG_DEBUG("Skip send NodeInfo > 40%% ch. util");
        return NULL;
    }
    // If we sent our NodeInfo less than 5 min. ago, don't send it again as it may be still underway.
    if (!shorterTimeout && lastSentToMesh && Throttle::isWithinTimespanMs(lastSentToMesh, 5 * 60 * 1000)) {
        LOG_DEBUG("Skip send NodeInfo since we sent it <5min ago");
        ignoreRequest = true; // Mark it as ignored for MeshModule
        return NULL;
    } else if (shorterTimeout && lastSentToMesh && Throttle::isWithinTimespanMs(lastSentToMesh, 60 * 1000)) {
        LOG_DEBUG("Skip send NodeInfo since we sent it <60s ago");
        ignoreRequest = true; // Mark it as ignored for MeshModule
        return NULL;
    } else {
        ignoreRequest = false; // Don't ignore requests anymore

So yeah, we had at least this protection.
Let's think, why remote node may ask for nodeinfo that often? Can't install record so therefore will never have full node info? Should it give up at some point?
If node has issue with nodeDB, in theory, it may generate a lot of traffic.
Some global counters for nodeinfo sent/requested should help detect malfunction and turn off feature.

[FFAMax]

As an option to make CLIENT_MUTE really mute

meshtastic_MeshPacket *NodeInfoModule::allocReply()
{
if (config.device.role == meshtastic_Config_DeviceConfig_Role_CLIENT_MUTE ||
        config.device.role == meshtastic_Config_DeviceConfig_Role_CLIENT_HIDDEN) {
        return nullptr;
    }

Also I see the current code also will ignore that frequent requests.

meshtastic_MeshPacket *NodeInfoModule::allocReply()
{
    if (suppressReplyForCurrentRequest) {
        LOG_DEBUG("Skip send NodeInfo since we heard the requester <12h ago");
        ignoreRequest = true;
        suppressReplyForCurrentRequest = false;
        return NULL;
    }

LGTM

firmware/src/modules/NodeInfoModule.cpp

Line 119 in 417ca86

meshtastic_MeshPacket *NodeInfoModule::allocReply()

Do we have any protections to make some portions of the code like this solid and stable, untouchable for feature commits? I am surpized to have that old code at the end of 2025 after many years since project was launched. I believe it was already implemented but at some point overwriten/lost.

In my case for infrastructure I'll also add

if (config.device.role == meshtastic_Config_DeviceConfig_Role_ROUTER) {
        return nullptr; 
    }

[FFAMax]

Few more points.
When we have isolated island, for example when router serving area is down, new nodes don't have peers.
Once router restored - new nodes never heard external world starting ectively exchange nodeinfo.
Another factor - NRF52840 with only 80 nodes can fit into the RAM (at least with current constants).
Some online resources in my area showing ~500 nodes on LongFast preset, my x86 client recorded ~800 nodes.
Most of the portable devics will store 200 nodes on ESP32 and the same 80 on NRF52, I think other clients will do about the same.
Once clients come closer to router - they start getting more traffic and generate more traffic.
I understand the idea to know neighbors info, but in large networks 80+ nodes no sense for devices with small RAM even try learn peers because very soon old records will be kicked off.
The only reason to store keys of the peers (and other not needed info) - have intention to open the chat with a peer.
In other cases we don't need that data, so we can store more peers for routing purpose while discarding non-essential data.

Ended up with conclusions:
Mesh networks are too large for current approach (nodes count).
nodeDB is combining 2 type of data: essential network infrastructure data (ids, signal quality, etc) and non-essential user-data (keys, misc info). So need split into a few pieces - forwarding datbase, device database, user database.

By doing that will distinguesh infra data from device/user data, reduce node info traffic significantly.
And somewhere around need think about safe pulic key replacement not causing old key stuck until manually removed.

To make nodes forwarding traffic - they don't need node info. That's the key.