[Bug]: Is the upgrade scenario for packets with a higher hop_limit working?

[FilipePortella]

Category

Other/Routing

Hardware

Not Applicable/Irrelevant

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

> v2.7.11.ee68575 ?

Description

This pull request introduces an upgrade scenario, for rebroadcasters with a pending packet in the queue, which then receive a duplicate of said packet with a higher remaining hop_limit. However, I was not able to recreate this scenario, even with artificially high wait times for a rebroadcaster and then inserting a duplicate package with a higher hop_limit. Instead, incoming duplicate packets with a higher hop_limit are ignored.

I'm not 100% sure this is a bug and not me misunderstanding what the upgrade scenario is supposed to do. Hence, the discussion and not a bug report issue. Here's what looks weird/wrong to me:

1. The method shouldFilterReceived(...) in FloodingRouter.cpp``/NextHopRouter.cpp`` handles incoming duplicate messages: Here wasUpgraded is initialized as `false` and then passed to `PacketHistory.cpp` by calling `wasSeenRecently(...)`.

2. In PacketHistory.cpp - wasSeenRecently(...): The upgrade scenario should be handled here. As far as I can tell, up to this point wasUpgraded has not been touched again.

3. Here's what looks weird to me (still in wasSeenRecently(...)): Why is wasUpgraded set to true in line 96, if this branch the code can only execute if wasUpgraded is already true in line 93? I assume wasUpgraded is still false, therefore the upgrade scenario never triggers?

If I am misunderstanding the upgrade scenario an explanation would be appreciated :)

Relevant log output

WARN  | 13:54:57 320 [RadioIf] myLog: RadioInterface::getTxDelayMsecWeighted() ROUTER detected, using fixed delay of 10000ms
INFO  | 13:54:57 320 [Router] Packet History - insert: Reusing slot aged 5.163s TRACE MATCHED PACKET
DEBUG | 13:54:57 320 [Router] Ignore dupe incoming msg (id=0x69e91891 fr=0x55c73900 to=0xffffffff, transport = 1, WantAck=0, HopLim=7 Ch=0x55 encrypted len=26 rxSNR=10 rxRSSI=-38 hopStart=
DEBUG | 13:54:57 320 [Router] Incoming msg was filtered from 0x55c73900
DEBUG | 13:55:07 330 [RadioIf] Started Tx (id=0x69e91891 fr=0x55c73900 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=26 rxtime=1769003691 rxSNR=10.25 rxRSSI=-59 ho
DEBUG | 13:55:07 330 [RadioIf] 0 packets remain in the TX queue
DEBUG | 13:55:07 330 [RadioIf] Packet TX: 35ms
DEBUG | 13:55:07 330 [RadioIf] Completed sending (id=0x69e91891 fr=0x55c73900 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=26 rxtime=1769003691 rxSNR=10.25 rxRSSI

[FilipePortella]

@GUVWAF @h3lix1 @erayd
Since this discussion hasn't had any traction for 3 days, I'm gonna go ahead and tag the three people that seemed to be the most involved in the original issue. I hope that is OK for you. I also asked in discord about this today but my message kinda went under and I didn't get a reply :/

[GUVWAF]

wasUpgraded in the if statement on line 93 is just checking if the pointer exists (i.e. it is not a nullptr), otherwise when trying to set it, things can go wrong. The actual value of it (accessed with *wasUpgraded) is only updated if this if-statement evaluates to true.

The next thing that needs to be true is this in perhapsHandleUpgradedPacket():

firmware/src/mesh/FloodingRouter.cpp

Line 74 in a922751

if (iface->removePendingTXPacket(getFrom(p), p->id, dropThreshold)) {

This only happens when the packet with lower hop limit is still in our Tx queue, waiting to be transmitted. When you are artificially waiting a very long time, chances are high the original packet would have already been transmitted. It was specifically designed not to rebroadcast it again then, as that would result into duplicate packets. Although yes, it might then travel further, but there is always a trade-off here.

[erayd]

Yep, as @GUVWAF said, upgrades are only applicable when the earlier version of the packet is still waiting in the TX queue. This typically occurs when the mesh is quite busy, and is normally a transient condition that will resolve shortly thereafter. It is undesirable for a node to unilaterally rebroadcast the same packet twice, so if it's already been sent, then the second one will simply be ignored, regardless of whether it arrived with a better hop count than the first one.

This whole thing is something of an edge-case optimisation. It applies mostly to ROUTER_LATE, which stores delayed packets in the TX queue while waiting to send them in cases where it overhears other rebroadcasts of that same packet. This is also sensitive to chutil, node density, and modem speed. The higher chutil and node density are, and the lower the modem speed is, then the more likely it is that a packet will still be waiting in the TX queue when a better version arrives via another path.

[erayd]

With all that said, it does seem odd that you aren't able to replicate this given a fixed 10s delay. I'd have expected to see an upgrade message in the log, given those timings. In theory, that first packet should still be in the queue if what your log message claims to be the case is correct.

Are you able to link to the code changes that you made in order to attempt to trigger the upgrade behaviour?

[FilipePortella]

I think I understand my confusion with regard to wasUpgraded: first, its address is passed in wasSeenRecently() –> then, since wasUpgraded exists, if(wasUpgraded) evaluates to true –> finally, the object to which wasUpgraded points to is set to true ?

Unfortunately I can't link to my code since it's a fork in my university's GitLab. But I can explain my setup and if you want to I can recreate it tomorrow and provide further logs.

Disclaimer: I'm on short-fast with rebroadcast-mode set to LOCAL_ONLY in only my own channel, I am using 30dB attenuators, and my setup is indoors. So far I have not seen other nodes, so I hope I'm not disturbing any foreign meshes.

Setup:

• 3 nodes: 1 ROUTER (R), 2 CLIENT (C1, C2)
• All 3 nodes can see each other
• R has a fixed delay of 10s before rebroadcasting – here: delay = 10000;
• C1 is the original broadcaster – without modifications
• C2 has a normal delay, but it sets the hop_limit to 7 before a sending a packet via LoRa – here: txp->hop_limit = 7;

What happens:

1. C1 sends a (channel-)message
2. C2 and R receive at approximately the same time and enqueue for rebroadcast
3. R has 10s of wait time
4. C2 wait time is over, it has heard no rebroadcast and rebroadcasts (setting hop_limit to 7)
5. R still has the original packet in the queue and now receives a duplicate with a higher hop_limit being rebroadcast by C2
6. R ignores the incoming duplicate even though it has a higher hop_limit
7. After the 10s are over, R rebroadcasts the original packet

Since, R is a ROUTER it should always rebroadcast at least once correct? Therefore, this scenario can only trigger for ROUTER or similar roles, if a CLIENT hears a duplicate of a packet in the queue it stops the retransmission. However, if I'm understanding it correctly the upgrade scenario should trigger in step 5 but doesn't. Instead as you can see in my logs above the original packet is rebroadcast (HopLim=2), even though while it was still in the queue a duplicate with a higher hop_limit was received.

[FilipePortella]

And thank you for your responses 👍

[FilipePortella]

Testing Setup

Just reproduced my setup from the original post, with minor tweaks. The issue still persists, you can see in the logs R rebroadcasts the message with the lower hop_limit, C2 also receives the rebroadcast with the lower hop_limit.

The firmware I'm using should be the latest stable release (2.7.15.567b8ea Beta) the last commit is d18f3f7a. Links to code are now specifically to this commit.

• Roles and behavior remain the same:
  • R and C2 are running modified firmware
  • C1 is running unmodified firmware (except for extra logging)
• Except for additional logging the only modified file is src/mesh/RadioLibInterface.cpp:

if(config.device.role == meshtastic_Config_DeviceConfig_Role_ROUTER){
    LOG_WARN("myLog: Testing setup and role is ROUTER, applying 10s transmit delay.");
    if (!txQueue.empty()) {
        notifyLater(10000, TRANSMIT_DELAY_COMPLETED, false);
    }
} else {
    LOG_WARN("myLog: Testing setup and role is not ROUTER, normal behavior.");
    startTransmitTimerRebroadcast(p);
}

Inserted here, replacing startTransmitTimerRebroadcast(p);

if (config.device.role == meshtastic_Config_DeviceConfig_Role_CLIENT)
{
    LOG_WARN("myLog: Testing setup and role is CLIENT, setting hop_limit to 7.");
    txp->hop_limit = 7;
}

Here, before configHardwareForSend();.

Logs

As you can see below I added logs for wasUpgraded and seenRecently here: LOG_WARN("myLog: FloodingRouter::shouldFilterReceived() after wasSeenRecently(); seenRecently=%d, wasUpgraded=%d", seenRecently ? 1 : 0, wasUpgraded ? 1 : 0);. The packet gets handled by FloodingRouter not NextHopRouter as opposed to what I initially assumed in the original post. Interestingly wasUpgraded is not true.

Logs for R:

DEBUG | 13:31:47 270 [RadioIf] Corrected frequency offset: -2667.577393
DEBUG | 13:31:47 270 [RadioIf] Lora RX (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 0, WantAck=0, HopLim=3 Ch=0x55 encrypted len=44 rxSNR=10.75 rxRSSI=-68 hopStart=3 relay=0xd0)
DEBUG | 13:31:47 270 [RadioIf] Packet RX: 51ms
DEBUG | 13:31:47 270 [RadioIf] myLog: Enqueued from radio
WARN  | 13:31:47 270 [RadioIf] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:47 270 [Router] myLog: FloodingRouter::shouldFilterReceived() called
INFO  | 13:31:47 270 [Router] Packet History - insert: Using new slot @uptime 270.630s TRACE NEW
WARN  | 13:31:47 270 [Router] myLog: FloodingRouter::shouldFilterReceived() after wasSeenRecently(); seenRecently=0, wasUpgraded=0
DEBUG | 13:31:47 270 [Router] Use channel 0 (hash 0x55)
DEBUG | 13:31:47 270 [Router] Use AES256 key!
DEBUG | 13:31:47 270 [Router] decoded message (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693507 rxSNR=10.75 rxRSSI=-68 hopSt
DEBUG | 13:31:47 270 [Router] handleReceived(REMOTE) (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693507 rxSNR=10.75 rxRSSI=-6
DEBUG | 13:31:47 270 [Router] uncommentedLog: In call modules
DEBUG | 13:31:47 270 [Router] Module 'text' wantsPacket=1
INFO  | 13:31:47 270 [Router] Received text msg from=0x55c76cd0, id=0x33eaf446, msg=Test: Upgrade Scenario
DEBUG | 13:31:47 270 [Router] Show standard frames
DEBUG | 13:31:47 270 [Router] Show 8 module frames
DEBUG | 13:31:47 270 [Router] Added modules.  numframes: 8
DEBUG | 13:31:47 270 [Router] Finished build frames. numframes: 8
DEBUG | 13:31:47 270 [Router] Module 'text' considered
DEBUG | 13:31:47 270 [Router] Module 'ExternalNotificationModule' wantsPacket=1
INFO  | 13:31:47 270 [Router] External Notification Module Disabled or muted
DEBUG | 13:31:47 270 [Router] Module 'ExternalNotificationModule' considered
DEBUG | 13:31:47 270 [Router] Module 'routing' wantsPacket=1
INFO  | 13:31:47 270 [Router] Received routing from=0x55c76cd0, id=0x33eaf446, portnum=1, payloadlen=22
DEBUG | 13:31:47 270 [Router] Routing sniffing (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693507 rxSNR=10.75 rxRSSI=-68 hopS
INFO  | 13:31:47 270 [Router] Rebroadcast received message coming from d0
INFO  | 13:31:47 270 [Router] Packet History - insert: Reusing slot aged 0.231s TRACE MATCHED PACKET
DEBUG | 13:31:47 270 [Router] myLog: Router::send() Sending packet 0x33eaf446 to 0xffffffff
DEBUG | 13:31:47 270 [Router] Use AES256 key!
DEBUG | 13:31:47 270 [Router] enqueue for send (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxtime=1769693507 rxSNR=10.75 rxRSSI=
DEBUG | 13:31:47 270 [Router] txGood=2,txRelay=1,rxGood=4,rxBad=1
DEBUG | 13:31:47 270 [Router] myLog: Enqueuing packet 0x33eaf446
DEBUG | 13:31:47 270 [Router] myLog: Enqueued packet 0x33eaf446
WARN  | 13:31:47 270 [Router] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:47 270 [Router] setTransmitDelay(); else branch
DEBUG | 13:31:47 270 [Router] rx_snr found. hop_limit:2 rx_snr:10.750000
WARN  | 13:31:47 270 [Router] myLog: Testing setup and role is ROUTER, applying 10s transmit delay.
DEBUG | 13:31:47 270 [Router] Delivering rx packet (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693507 rxSNR=10.75 rxRSSI=-68 
DEBUG | 13:31:48 270 [Router] Update DB node 0x55c76cd0, rx_time=1769693507
INFO  | 13:31:48 270 [Router] Sort took 0 milliseconds
DEBUG | 13:31:48 270 [Router] Forwarding to phone (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693507 rxSNR=10.75 rxRSSI=-68 h
DEBUG | 13:31:48 271 [Router] Module 'routing' considered
DEBUG | 13:31:49 272 [RadioIf] Corrected frequency offset: -4412.407715
DEBUG | 13:31:49 272 [RadioIf] Lora RX (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 0, WantAck=0, HopLim=7 Ch=0x55 encrypted len=44 rxSNR=9.75 rxRSSI=-87 hopStart=3 relay=0x8)
DEBUG | 13:31:49 272 [RadioIf] Packet RX: 51ms
DEBUG | 13:31:49 272 [RadioIf] myLog: Enqueued from radio
WARN  | 13:31:49 272 [RadioIf] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:49 272 [RadioIf] setTransmitDelay(); else branch
DEBUG | 13:31:49 272 [RadioIf] rx_snr found. hop_limit:2 rx_snr:10.750000
WARN  | 13:31:49 272 [RadioIf] myLog: Testing setup and role is ROUTER, applying 10s transmit delay.
WARN  | 13:31:49 272 [Router] myLog: FloodingRouter::shouldFilterReceived() called
INFO  | 13:31:49 272 [Router] Packet History - insert: Reusing slot aged 1.295s TRACE MATCHED PACKET
WARN  | 13:31:49 272 [Router] myLog: FloodingRouter::shouldFilterReceived() after wasSeenRecently(); seenRecently=1, wasUpgraded=0
DEBUG | 13:31:49 272 [Router] Ignore dupe incoming msg (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=7 Ch=0x55 encrypted len=44 rxSNR=9.75 rxRSSI=-87 hopStar
DEBUG | 13:31:49 272 [Router] Incoming msg was filtered from 0x55c76cd0
DEBUG | 13:31:59 282 [RadioIf] Started Tx (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxtime=1769693507 rxSNR=10.75 rxRSSI=-68 ho
DEBUG | 13:31:59 282 [RadioIf] 0 packets remain in the TX queue
DEBUG | 13:31:59 282 [RadioIf] Packet TX: 51ms
DEBUG | 13:31:59 282 [RadioIf] Completed sending (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxtime=1769693507 rxSNR=10.75 rxRSSI
WARN  | 13:31:59 282 [RadioIf] RadioLibInterface::setTransmitDelay()

Logs for C2:

DEBUG | 13:31:48 175 [RadioIf] Corrected frequency offset: 1728.053223
DEBUG | 13:31:48 175 [RadioIf] Lora RX (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 0, WantAck=0, HopLim=3 Ch=0x55 encrypted len=44 rxSNR=10.75 rxRSSI=-69 hopStart=3 relay=0xd0)
DEBUG | 13:31:48 175 [RadioIf] Packet RX: 51ms
DEBUG | 13:31:48 175 [RadioIf] myLog: Enqueued from radio
WARN  | 13:31:48 175 [RadioIf] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:48 175 [Router] myLog: FloodingRouter::shouldFilterReceived() called
INFO  | 13:31:48 175 [Router] Packet History - insert: Using new slot @uptime 175.376s TRACE NEW
WARN  | 13:31:48 175 [Router] myLog: FloodingRouter::shouldFilterReceived() after wasSeenRecently(); seenRecently=0, wasUpgraded=0
DEBUG | 13:31:48 175 [Router] Use channel 0 (hash 0x55)
DEBUG | 13:31:48 175 [Router] Use AES256 key!
DEBUG | 13:31:48 175 [Router] decoded message (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693508 rxSNR=10.75 rxRSSI=-69 hopSt
DEBUG | 13:31:48 175 [Router] handleReceived(REMOTE) (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693508 rxSNR=10.75 rxRSSI=-6
DEBUG | 13:31:48 175 [Router] uncommentedLog: In call modules
DEBUG | 13:31:48 175 [Router] Module 'text' wantsPacket=1
INFO  | 13:31:48 175 [Router] Received text msg from=0x55c76cd0, id=0x33eaf446, msg=Test: Upgrade Scenario
DEBUG | 13:31:48 175 [Router] Show standard frames
DEBUG | 13:31:48 175 [Router] Show 8 module frames
DEBUG | 13:31:48 175 [Router] Added modules.  numframes: 8
DEBUG | 13:31:48 175 [Router] Finished build frames. numframes: 8
DEBUG | 13:31:48 175 [Router] Module 'text' considered
DEBUG | 13:31:48 175 [Router] Module 'ExternalNotificationModule' wantsPacket=1
INFO  | 13:31:48 175 [Router] External Notification Module Disabled or muted
DEBUG | 13:31:48 175 [Router] Module 'ExternalNotificationModule' considered
DEBUG | 13:31:48 175 [Router] Module 'routing' wantsPacket=1
INFO  | 13:31:48 175 [Router] Received routing from=0x55c76cd0, id=0x33eaf446, portnum=1, payloadlen=22
DEBUG | 13:31:48 175 [Router] Routing sniffing (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693508 rxSNR=10.75 rxRSSI=-69 hopS
INFO  | 13:31:48 175 [Router] Rebroadcast received message coming from d0
INFO  | 13:31:48 175 [Router] Packet History - insert: Reusing slot aged 0.231s TRACE MATCHED PACKET
DEBUG | 13:31:48 175 [Router] myLog: Router::send() Sending packet 0x33eaf446 to 0xffffffff
DEBUG | 13:31:48 175 [Router] Use AES256 key!
DEBUG | 13:31:48 175 [Router] enqueue for send (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxtime=1769693508 rxSNR=10.75 rxRSSI=
DEBUG | 13:31:48 175 [Router] txGood=1,txRelay=0,rxGood=3,rxBad=0
DEBUG | 13:31:48 175 [Router] myLog: Enqueuing packet 0x33eaf446
DEBUG | 13:31:48 175 [Router] myLog: Enqueued packet 0x33eaf446
WARN  | 13:31:48 175 [Router] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:48 175 [Router] setTransmitDelay(); else branch
DEBUG | 13:31:48 175 [Router] rx_snr found. hop_limit:2 rx_snr:10.750000
WARN  | 13:31:48 175 [Router] myLog: Testing setup and role is not ROUTER, normal behavior.
DEBUG | 13:31:48 175 [Router] myLog: RadioInterface::getTxDelayMsecWeighted() Calculating delay for packet 0x33eaf446
DEBUG | 13:31:48 175 [Router] myLog: RadioInterface::getCWsize() = 8
DEBUG | 13:31:48 175 [Router] uncommentedLog: rx_snr of 10.750000 so setting CWsize to:8
DEBUG | 13:31:48 175 [Router] myLog: RadioInterface::shouldRebroadcastEarlyLikeRouter() Checking if packet 0x33eaf446 should be rebroadcast early
DEBUG | 13:31:48 175 [Router] rx_snr found in packet. Setting tx delay:1000
DEBUG | 13:31:48 175 [Router] Delivering rx packet (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693508 rxSNR=10.75 rxRSSI=-69 
DEBUG | 13:31:48 175 [Router] Update DB node 0x55c76cd0, rx_time=1769693508
INFO  | 13:31:48 175 [Router] Sort took 0 milliseconds
DEBUG | 13:31:48 175 [Router] Forwarding to phone (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1769693508 rxSNR=10.75 rxRSSI=-69 h
DEBUG | 13:31:48 175 [Router] Module 'routing' considered
WARN  | 13:31:49 176 [RadioIf] myLog: Testing setup and role is CLIENT, setting hop_limit to 7.
DEBUG | 13:31:49 176 [RadioIf] Started Tx (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=7 Ch=0x55 encrypted len=44 rxtime=1769693508 rxSNR=10.75 rxRSSI=-69 ho
DEBUG | 13:31:49 176 [RadioIf] 0 packets remain in the TX queue
DEBUG | 13:31:49 176 [RadioIf] Packet TX: 51ms
DEBUG | 13:31:49 176 [RadioIf] Completed sending (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=7 Ch=0x55 encrypted len=44 rxtime=1769693508 rxSNR=10.75 rxRSSI
WARN  | 13:31:49 176 [RadioIf] RadioLibInterface::setTransmitDelay()
DEBUG | 13:31:54 181 [Power] Battery: usbPower=1, isCharging=0, batMv=4147, batPct=100
DEBUG | 13:31:59 186 [RadioIf] Corrected frequency offset: 4412.407715
DEBUG | 13:31:59 186 [RadioIf] Lora RX (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 0, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxSNR=10 rxRSSI=-87 hopStart=3 relay=0xff)
DEBUG | 13:31:59 186 [RadioIf] Packet RX: 51ms
DEBUG | 13:31:59 186 [RadioIf] myLog: Enqueued from radio
WARN  | 13:31:59 187 [RadioIf] RadioLibInterface::setTransmitDelay()
WARN  | 13:31:59 187 [Router] myLog: FloodingRouter::shouldFilterReceived() called
INFO  | 13:31:59 187 [Router] Packet History - insert: Reusing slot aged 11.405s TRACE MATCHED PACKET
WARN  | 13:31:59 187 [Router] myLog: FloodingRouter::shouldFilterReceived() after wasSeenRecently(); seenRecently=1, wasUpgraded=0
DEBUG | 13:31:59 187 [Router] Ignore dupe incoming msg (id=0x33eaf446 fr=0x55c76cd0 to=0xffffffff, transport = 1, WantAck=0, HopLim=2 Ch=0x55 encrypted len=44 rxSNR=10 rxRSSI=-87 hopStart=
WARN  | 13:31:59 187 [Router] myLog: Router::cancelSending() was called by FloodingRouter::perhapsCancelDupe()
WARN  | 13:31:59 187 [Router] myLog: Router::cancelSending() called
DEBUG | 13:31:59 187 [Router] myLog: Router::cancelSending() Attempting to cancel sending of packet 0x33eaf446
WARN  | 13:31:59 187 [Router] myLog: RadioLibInterface::cancelSending() called
DEBUG | 13:31:59 187 [Router] cancelSending id=0x33eaf446, removed=0
DEBUG | 13:31:59 187 [Router] myLog: Router::cancelSending() Failed to cancel sending of packet 0x33eaf446
DEBUG | 13:31:59 187 [Router] Incoming msg was filtered from 0x55c76cd0

[GUVWAF]

I think I see what's going wrong here, and I have to blame myself.

The PacketRecord hop_limit entry is composed of two hop limits (to save memory):

firmware/src/mesh/PacketHistory.h

Lines 22 to 23 in 5dd06ed

	uint8_t hop_limit; // bit 0-2: Highest hop limit observed for this packet,
	// bit 3-5: our hop limit when we first transmitted it

Hence we shouldn't be checking for found->hop_limit here:

firmware/src/mesh/PacketHistory.cpp

Line 93 in 5dd06ed

if (seenRecently && wasUpgraded && found->hop_limit < p->hop_limit) {

But rather use the getHighestHopLimit() method (or at least I think that makes sense here... will have to think about this some more).

[FilipePortella]

Isn't this scenario only supposed to trigger if the original packet is still in the Tx queue? If so, couldn't one retrieve the original packet, which at that point would still be in the queue, and get the hop_limit from there?

[FilipePortella]

This has been fixed here so I will close this.