[Bug]: MQTT messages sent to secondary channels are always posted in primary channel

[Kollensperger]

Category

Other

Hardware

Rak4631

Firmware Version

2.0.8

Description

When sending a correctly formatted mqtt message to the primary channel, it is displayed correctly and as expected in the primary channel of the iOS app. When sending a message to any secondary channel with mqtt upload and download enabled, the same message does not arrive in the expected secondary channel on iOS, but always in the primary channel.
I have confirmed this behaviour for several secondary channels, and observed the messages in the correct topic using MQTTX.

Example:

Sending a message to mqtt node msh/2/json/Primary/ works as expected: In MQTTX, it appears in msh/2/json/Primary/ and on the iOS app it also appears in the primary channel. So far so good. Now I change the mqtt node to msh/2/json/Secondary/, and as expected, in the MQTTX browser the same messages appear in the channel msh/2/json/Secondary/, but on the iOS app, the messages still appear on msh/2/json/Primary/. In my view since the same message displays fine in the primary channel, and MQTTX is picking up the messages in the correct secondary channel, that would indicate something is wrong in the meshtastic plumbing?

Relevant log output

These are some bits and bobs that may be relevant from the meshtastic node (RAK4631) connected to iOS. This is connected to a t-beam which is connected to the internet. This is a message being sent on the channel "Vær" which lives in the topic msh/2/json/Vær/ but appears in the primary channel. I have also tried secondary channels without the letter "æ", such as "weather"

22:22:26 6130 [Router] Add packet record (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] recentPackets size=73
22:22:26 6130 [Router] recentPackets size=23 (after clearing expired packets)
22:22:26 6130 [Router] Using channel 0 (hash 0x92)
22:22:26 6130 [Router] Using AES256 key!
22:22:26 6130 [Router] Software encrypt fr=d1c801dc, num=5d1c3de, numBytes=184!
22:22:26 6130 [Router] decoded message (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] handleReceived(REMOTE) (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] Module 'text' wantsPacket=1
22:22:26 6130 [Router] Received text msg from=0xd1c801dc, id=0x5d1c3de, msg=Forecast: 2023-01-08T12:00:00Z:  V??r 1h: partlycloudy_day; Temp 1h: 2.4??C ; Nedb??r 1h: 0mm ; Vindretni
22:22:26 6130 [Router] Enter state: ON
22:22:26 6130 [Router] Sending position ping to 0xf7160fca, wantReplies=1
22:22:26 6130 [Router] cancelSending id=0x1a8e7dcb, removed=0
22:22:26 6130 [Router] Providing time to mesh 1673130146
22:22:26 6130 [Router] Position reply: time=1673130146, latI=634219390, lonI=-101256600
22:22:26 6130 [Router] Update DB node 0xafd2da53, rx_time=1673130146
22:22:26 6130 [Router] Add packet record (id=0x1a8e7dcc fr=0x53 to=0xca, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 WANTRESP rxtime=1673130146 priority=10)
22:22:26 6130 [Router] Should encrypt MQTT?: 1
22:22:26 6130 [Router] Using AES256 key!
22:22:26 6130 [Router] Software encrypt fr=afd2da53, num=1a8e7dcc, numBytes=23!
22:22:26 6130 [Router] enqueuing for send (id=0x1a8e7dcc fr=0x53 to=0xca, WantAck=0, HopLim=3 Ch=0x92 encrypted rxtime=1673130146 priority=10)
22:22:26 6130 [Router] txGood=233,rxGood=213,rxBad=0
22:22:26 6130 [Router] Using channel 0 (hash 0x92)
22:22:26 6130 [Router] Using AES256 key!
22:22:26 6130 [Router] Software encrypt fr=afd2da53, num=1a8e7dcc, numBytes=23!
22:22:26 6130 [Router] decoded message (id=0x1a8e7dcc fr=0x53 to=0xca, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 WANTRESP rxtime=1673130146 priority=10)
22:22:26 6130 [Router] showing standard frames
22:22:26 6130 [Router] Showing 0 module frames
22:22:26 6130 [Router] Total frame count: 83
22:22:26 6130 [Router] Added modules.  numframes: 0
22:22:26 6130 [Router] Finished building frames. numframes: 7
22:22:26 6130 [Router] Module 'text' considered
22:22:26 6130 [Router] Module 'canned' wantsPacket=1
22:22:26 6130 [Router] Module 'canned' considered
22:22:26 6130 [Router] Module 'ExternalNotificationModule' wantsPacket=1
22:22:26 6130 [Router] External Notification Module Disabled
22:22:26 6130 [Router] Module 'ExternalNotificationModule' considered
22:22:26 6130 [Router] Module 'routing' wantsPacket=1
22:22:26 6130 [Router] Received routing from=0xd1c801dc, id=0x5d1c3de, portnum=1, payloadlen=179
22:22:26 6130 [Router] Routing sniffing (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] Rebroadcasting received floodmsg to neighbors (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] Should encrypt MQTT?: 1
22:22:26 6130 [Router] Original length - 179 
22:22:26 6130 [Router] Compressed length - 125 
22:22:26 6130 [Router] Original message - Forecast: 2023-01-08T12:00:00Z:  V??r 1h: partlycloudy_day; Temp 1h: 2.4??C ; Nedb??r 1h: 0mm ; Vindretning 1h: S?? ; Vindstyrke: 9.2m/s , 
22:22:26 6130 [Router] Using compressed message.
22:22:26 6130 [Router] Using AES256 key!
22:22:26 6130 [Router] Software encrypt fr=d1c801dc, num=5d1c3de, numBytes=184!
22:22:26 6130 [Router] enqueuing for send (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=2 Ch=0x92 encrypted rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] txGood=233,rxGood=213,rxBad=0
22:22:26 6130 [Router] rx_snr found. hop_limit:2 rx_snr:6.000000
22:22:26 6130 [Router] rx_snr found in packet. Setting tx delay:1092
22:22:26 6130 [Router] FIXME-update-db Sniffing packet
22:22:26 6130 [Router] Delivering rx packet (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] Forwarding to phone (id=0x05d1c3de fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1673130146 rxSNR=6 rxRSSI=1.53492e-154)
22:22:26 6130 [Router] Update DB node 0xd1c801dc, rx_time=1673130146
22:22:26 6130 [Router] Module 'routing' considered

[garthvh]

I have tested this quite a bit and they go to the right places, do your channels have the same indexes on both networks?

[caveman99]

@garthvh The Json stuff is the problem, proto mode works fine. The newly crafted package from the Json translation indeed does not have the correct channel index set.

[Kollensperger]

I have tested this quite a bit and they go to the right places, do your channels have the same indexes on both networks?

@garthvh They should have since I set up one device and then shared via QR code. I also checked on both devices using meshtastic ---info and they both showed the same channels in the same order with the same psk.

To be clear, in this instance the message does not originate in the other network, but from a weatherforecast that is polled on node-red every 6 hours and then transmitted via mqtt into the "weather" channel.
I'm not sure this is relevant because the messages are correctly formatted since they display correctly when sent in the primary channel, and appear in the correct secondary mqtt channel when sent there, but are not picked up by the secondary channel on the devices.

Edit: I was writing this and then saw that that @caveman99 has figured this out now!
Thanks!!

[Kollensperger]

I've now tested with 2.0.13 installed on the devices and the mqtt messages are still showing up in the wrong channel (primary channel) on the iOS interface, but the correct channel in MQTTX. Could it be that I have 4 channels, and only the first three are usable? My weather channel is on index 3, so the fourth channel.

[Kollensperger]

Edit, Ive now moved the messages over to channel index 2, and they are still showing up in the primary channel, but correct, changed channel on MQTTX.

[Kollensperger]

Posting serial output from router node here also for completeness sake

DEBUG | 09:18:30 67 [Router] Ignoring incoming msg, because we've already seen it (id=0x342dd7cc fr=0xdc to=0xff, WantAck=0, HopLim=2 Ch=0x92 encrypted rxSNR=12.25 rxRSSI=2.65242e-314)
DEBUG | 09:18:30 67 [Router] Incoming message was filtered 0xd1c801dc
DEBUG | 09:18:46 82 [Power] Battery: usbPower=1, isCharging=1, batMv=3562, batPct=9
INFO  | 09:18:54 90 [mqtt] JSON Received on MQTT, parsing..
DEBUG | 09:18:54 90 [mqtt] Looking for Channel name: Vær
DEBUG | 09:18:54 90 [mqtt] Found Channel name: Home (Index 0)
INFO  | 09:18:54 90 [mqtt] JSON payload Forecast: 2023-01-19T11:00:00Z:  Vær 1h: cloudy; Temp 1h: -5.2°C ; Nedbør 1h: 0mm ; Vindretning 1h: VSV ; Vindstyrke: 2.3m/s , i kastene 3.5m/
DEBUG | 09:18:54 90 [mqtt] Update DB node 0xd1c801dc, rx_time=1674119934
DEBUG | 09:18:54 90 [mqtt] handleReceived(LOCAL) (id=0x342dd7cd fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1674119934)
DEBUG | 09:18:54 90 [mqtt] No modules interested in portnum=1, src=LOCAL
DEBUG | 09:18:54 90 [mqtt] Add packet record (id=0x342dd7cd fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1674119934)
INFO  | 09:18:54 90 [mqtt] Should encrypt MQTT?: 0
DEBUG | 09:18:54 90 [mqtt] publish msh/2/c/Home/!d1c801dc, 226 bytes
DEBUG | 09:18:54 91 [mqtt] got text message of size 171
INFO  | 09:18:54 91 [mqtt] text message payload is of type plaintext
INFO  | 09:18:54 91 [mqtt] serialized json message: {"channel":0,"from":-775421476,"id":875419597,"payload":{"text":"Forecast: 2023-01-19T11:00:00Z:  V\u0000\u0000r 1h: cloudy; Temp 1h:
INFO  | 09:18:54 91 [mqtt] JSON publish message to msh/2/json/Home/!d1c801dc, 347 bytes: {"channel":0,"from":-775421476,"id":875419597,"payload":{"text":"Forecast: 2023-01-19T11:00
DEBUG | 09:18:54 91 [mqtt] Original length - 171 
DEBUG | 09:18:54 91 [mqtt] Compressed length - 121 
DEBUG | 09:18:54 91 [mqtt] Original message - Forecast: 2023-01-19T11:00:00Z:  Vær 1h: cloudy; Temp 1h: -5.2°C ; Nedbør 1h: 0mm ; Vindretning 1h: VSV ; Vindstyrke: 2.3m/s , i kastene
DEBUG | 09:18:54 91 [mqtt] Using compressed message.
DEBUG | 09:18:54 91 [mqtt] Using AES256 key!
DEBUG | 09:18:54 91 [mqtt] ESP32 crypt fr=d1c801dc, num=342dd7cd, numBytes=176!
DEBUG | 09:18:54 91 [mqtt] enqueuing for send (id=0x342dd7cd fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxtime=1674119934)
DEBUG | 09:18:54 91 [mqtt] txGood=4,rxGood=6,rxBad=0
INFO  | 09:18:54 91 [mqtt] Ignoring downlink message we originally sent.
INFO  | 09:18:54 91 [mqtt] JSON Received on MQTT, parsing..
DEBUG | 09:18:54 91 [mqtt] Looking for Channel name: Home
DEBUG | 09:18:54 91 [mqtt] Found Channel name: Home (Index 0)
ERROR | 09:18:54 91 [mqtt] JSON Received payload on MQTT but not a valid envelope
DEBUG | 09:18:54 91 [RadioIf] Starting low level send (id=0x342dd7cd fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxtime=1674119934 priority=64)
DEBUG | 09:18:54 91 [RadioIf] (bw=250, sf=11, cr=4/8) packet symLen=8 ms, payloadSize=192, time 2656 ms
DEBUG | 09:18:54 91 [RadioIf] AirTime - Packet transmitted : 2656ms
DEBUG | 09:18:58 94 [RadioIf] Completed sending (id=0x342dd7cd fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxtime=1674119934 priority=64)
DEBUG | 09:19:06 102 [Power] Battery: usbPower=1, isCharging=1, batMv=3566, batPct=9
DEBUG | 09:19:12 109 [RadioIf] (bw=250, sf=11, cr=4/8) packet symLen=8 ms, payloadSize=37, time 804 ms
DEBUG | 09:19:12 109 [RadioIf] Lora RX (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:12 109 [RadioIf] AirTime - Packet received : 804ms
DEBUG | 09:19:12 109 [Router] Add packet record (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:12 109 [Router] Using channel 0 (hash 0x92)
DEBUG | 09:19:12 109 [Router] Using AES256 key!
DEBUG | 09:19:12 109 [Router] ESP32 crypt fr=afd2da53, num=11b40a2c, numBytes=21!
DEBUG | 09:19:12 109 [Router] decoded message (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:12 109 [Router] handleReceived(REMOTE) (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:13 109 [Router] Module 'position' wantsPacket=1
INFO  | 09:19:13 109 [Router] Received position from=0xafd2da53, id=0x11b40a2c, portnum=3, payloadlen=17
INFO  | 09:19:13 109 [Router] POSITION node=afd2da53 l=17 LAT LON MSL TIME 
INFO  | 09:19:13 109 [Router] updatePosition REMOTE node=0xafd2da53 time=1674119953, latI=632325571, lonI=112661365
DEBUG | 09:19:13 109 [Router] Node status update: 2 online, 5 total
DEBUG | 09:19:13 109 [Router] Module 'position' considered
DEBUG | 09:19:13 109 [Router] Module 'routing' wantsPacket=1
INFO  | 09:19:13 109 [Router] Received routing from=0xafd2da53, id=0x11b40a2c, portnum=3, payloadlen=17
DEBUG | 09:19:13 109 [Router] Routing sniffing (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
INFO  | 09:19:13 109 [Router] Rebroadcasting received floodmsg to neighborsShould encrypt MQTT?: 0
DEBUG | 09:19:13 109 [Router] publish msh/2/c/Home/!d1c801dc, 85 bytes
INFO  | 09:19:13 109 [Router] serialized json message: {"channel":0,"from":-1345136045,"id":297011756,"payload":{"altitude":68,"latitude_i":632325571,"longitude_i":112661365,"time":1674119
INFO  | 09:19:13 109 [Router] JSON publish message to msh/2/json/Home/!d1c801dc, 208 bytes: {"channel":0,"from":-1345136045,"id":297011756,"payload":{"altitude":68,"latitude_i": 632325
DEBUG | 09:19:13 109 [Router] Using AES256 key!
DEBUG | 09:19:13 109 [Router] ESP32 crypt fr=afd2da53, num=11b40a2c, numBytes=21!
DEBUG | 09:19:13 109 [Router] enqueuing for send (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=2 Ch=0x92 encrypted rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:13 109 [Router] txGood=5,rxGood=7,rxBad=0
DEBUG | 09:19:13 109 [Router] rx_snr found. hop_limit:2 rx_snr:12.500000
DEBUG | 09:19:13 109 [Router] rx_snr found in packet. Setting tx delay:4662
DEBUG | 09:19:13 109 [Router] Delivering rx packet (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:13 109 [Router] Forwarding to phone (id=0x11b40a2c fr=0x53 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 rxtime=1674119952 rxSNR=12.5 rxRSSI=2.65242e-314)
DEBUG | 09:19:13 109 [Router] Update DB node 0xafd2da53, rx_time=1674119952
DEBUG | 09:19:13 109 [Router] Module 'routing' considered
INFO  | 09:19:13 109 [mqtt] Ignoring downlink message we originally sent.
INFO  | 09:19:13 109 [mqtt] JSON Received on MQTT, parsing..
DEBUG | 09:19:13 109 [mqtt] Looking for Channel name: Home
DEBUG | 09:19:13 109 [mqtt] Found Channel name: Home (Index 0)
ERROR | 09:19:13 109 [mqtt] JSON Received payload on MQTT but not a valid envelope
INFO  | 09:19:14 110 [mqtt] JSON Received on MQTT, parsing..
DEBUG | 09:19:14 110 [mqtt] Looking for Channel name: Vær
DEBUG | 09:19:14 110 [mqtt] Found Channel name: Home (Index 0)
INFO  | 09:19:14 110 [mqtt] JSON payload Forecast: 2023-01-19T14:00:00Z:  Vær 1h: cloudy; Temp 1h: -2.6°C ; Nedbør 1h: 0mm ; Vindretning 1h: SSV ; Vindstyrke: 2.7m/s , i kastene 4.2m/
DEBUG | 09:19:14 110 [mqtt] Update DB node 0xd1c801dc, rx_time=1674119954
DEBUG | 09:19:14 110 [mqtt] handleReceived(LOCAL) (id=0x342dd7ce fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1674119954)
DEBUG | 09:19:14 110 [mqtt] No modules interested in portnum=1, src=LOCAL
DEBUG | 09:19:14 110 [mqtt] Add packet record (id=0x342dd7ce fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=1 rxtime=1674119954)
INFO  | 09:19:14 110 [mqtt] Should encrypt MQTT?: 0
DEBUG | 09:19:14 110 [mqtt] publish msh/2/c/Home/!d1c801dc, 228 bytes
DEBUG | 09:19:14 110 [mqtt] got text message of size 173
INFO  | 09:19:14 110 [mqtt] text message payload is of type plaintext
INFO  | 09:19:14 110 [mqtt] serialized json message: {"channel":0,"from":-775421476,"id":875419598,"payload":{"text":"Forecast: 2023-01-19T14:00:00Z:  V\u0000\u0000r 1h: cloudy; Temp 1h:
INFO  | 09:19:14 111 [mqtt] JSON publish message to msh/2/json/Home/!d1c801dc, 349 bytes: {"channel":0,"from":-775421476,"id":875419598,"payload":{"text":"Forecast: 2023-01-19T14:00
DEBUG | 09:19:14 111 [mqtt] Original length - 173 
DEBUG | 09:19:14 111 [mqtt] Compressed length - 121 
DEBUG | 09:19:14 111 [mqtt] Original message - Forecast: 2023-01-19T14:00:00Z:  Vær 1h: cloudy; Temp 1h: -2.6°C ; Nedbør 1h: 0mm ; Vindretning 1h: SSV ; Vindstyrke: 2.7m/s , i kastene
DEBUG | 09:19:14 111 [mqtt] Using compressed message.
DEBUG | 09:19:14 111 [mqtt] Using AES256 key!
DEBUG | 09:19:14 111 [mqtt] ESP32 crypt fr=d1c801dc, num=342dd7ce, numBytes=178!
DEBUG | 09:19:14 111 [mqtt] enqueuing for send (id=0x342dd7ce fr=0xdc to=0xff, WantAck=0, HopLim=3 Ch=0x92 encrypted rxtime=1674119954)
DEBUG | 09:19:14 111 [mqtt] txGood=5,rxGood=7,rxBad=0
DEBUG | 09:19:14 111 [mqtt] rx_snr found. hop_limit:2 rx_snr:12.500000
DEBUG | 09:19:14 111 [mqtt] rx_snr found in packet. Setting tx delay:4704
INFO  | 09:19:14 111 [mqtt] Ignoring downlink message we originally sent.
INFO  | 09:19:14 111 [mqtt] JSON Received on MQTT, parsing..
DEBUG | 09:19:14 111 [mqtt] Looking for Channel name: Home
DEBUG | 09:19:14 111 [mqtt] Found Channel name: Home (Index 0)