RAK7246 repeat packet errors

Issue: I am sending out a single packet and almost every time I get an additional 1,2, or 3 packets which show up as errors because it says the count didn’t increase

Setup: A RAK7246 running the chirpstack OS and acting as its own server. The end point devices are custom RN2903 boards.

Server: The RAK7246

Details:
The “Issue” section above pretty much sums it up. You can kind of see what it looks like here:

Any idea why it would be thinking there are multiple packets? I am sending out a single unconfirmed uplink, so I don’t know why it thinks there are others.

Some detail on the errors would be useful - it’s typical to be able to see the Device Address which may reveal that your gateway is receiving radio signals from other nodes which, either because they aren’t in LoRaWAN format and almost certainly because they are not registered with your NS, cause an error.

1 Like

You are right of course :slight_smile: . Let me also give you a little more info. I have the Gateway on the top floor of my house and the end node in the basement. I am in the US, so I am operating in the 915MHz range. I only have a single end node on at the moment.

This is what I see:


You can see that that second error is occurring pretty quickly after the first.

Here is what the /var/log/messages is showing:

Aug 31 22:49:58 raspberrypi0-wifi authpriv.err getty[7285]: /dev/ttyS0: not a tty
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-concentratord-sx1301[442]: Publishing stats event, stats_id: e4f31c5b-fdb6-41e5-a053-84b0d3c337f7, rx_received: 0, rx_received_ok: 0, tx_received: 0, tx_emitted: 0
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:49:59Z” level=info msg=“backend/concentratord: stats event received” stats_id=e4f31c5b-fdb6-41e5-a053-84b0d3c337f7
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:49:59Z” level=info msg=“integration/mqtt: publishing event” event=stats qos=0 stats_id=e4f31c5b-fdb6-41e5-a053-84b0d3c337f7 topic=gateway/b827ebfffec9e57a/event/stats
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:49:59Z” level=info msg=“gateway/mqtt: gateway stats packet received” gateway_id=b827ebfffec9e57a stats_id=e4f31c5b-fdb6-41e5-a053-84b0d3c337f7
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:49:59Z” level=info msg=“gateway updated” ctx_id=e4f31c5b-fdb6-41e5-a053-84b0d3c337f7 gateway_id=b827ebfffec9e57a
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:49:59Z” level=info msg=“gateway updated” ctx_id=2466eef6-46dc-494e-b23c-6bea98067838 id=b827ebfffec9e57a name=RAK7246
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:49:59Z” level=info msg=“metrics saved” aggregation=“[MINUTE HOUR DAY MONTH]” ctx_id=2466eef6-46dc-494e-b23c-6bea98067838 name=“gw:b827ebfffec9e57a”
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:49:59Z” level=info msg=“finished unary call with code OK” ctx_id=2466eef6-46dc-494e-b23c-6bea98067838 grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServer
Aug 31 22:49:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:49:59Z” level=info msg=“finished client unary call” ctx_id=e4f31c5b-fdb6-41e5-a053-84b0d3c337f7 grpc.code=OK grpc.ctx_id=2466eef6-46dc-494e-b23c-6bea98067838 grpc.duration=81.678174ms
Aug 31 22:50:09 raspberrypi0-wifi authpriv.err getty[7304]: /dev/ttyS0: not a tty
Aug 31 22:50:19 raspberrypi0-wifi daemon.info init: Id “S0” respawning too fast: disabled for 5 minutes
Aug 31 22:50:26 raspberrypi0-wifi user.info chirpstack-concentratord-sx1301[442]: Frame received, uplink_id: 08325e9f-a753-4e26-829b-cca7e13683ea, count_us: 2810800236, freq: 903700000, bw: 125000, mod: LoRa, dr: SF10
Aug 31 22:50:26 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:26Z” level=info msg=“backend/concentratord: uplink event received” uplink_id=08325e9f-a753-4e26-829b-cca7e13683ea
Aug 31 22:50:26 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:26Z” level=info msg=“integration/mqtt: publishing event” event=up qos=0 topic=gateway/b827ebfffec9e57a/event/up uplink_id=08325e9f-a753-4e26-829b-cca7e13683ea
Aug 31 22:50:26 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:26Z” level=info msg=“gateway/mqtt: uplink frame received” gateway_id=b827ebfffec9e57a uplink_id=08325e9f-a753-4e26-829b-cca7e13683ea
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:27Z” level=info msg=“uplink: frame(s) collected” ctx_id=08f1387a-3869-44bc-ab20-20e0c6c77b0d mtype=UnconfirmedDataUp uplink_ids=“[08325e9f-a753-4e26-829b-cca7e13683ea]”
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:27Z” level=info msg=“device gateway rx-info meta-data saved” ctx_id=08f1387a-3869-44bc-ab20-20e0c6c77b0d dev_eui=001e06767b27a920
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:27Z” level=info msg=“sent uplink meta-data to network-controller” ctx_id=08f1387a-3869-44bc-ab20-20e0c6c77b0d dev_eui=001e06767b27a920
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:27Z” level=info msg=“device-session saved” ctx_id=08f1387a-3869-44bc-ab20-20e0c6c77b0d dev_addr=260212b5 dev_eui=001e06767b27a920
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:27Z” level=info msg=“device last-seen and dr updated” ctx_id=d63a7cb8-8664-48bc-bd91-7d68ac926e9d dev_eui=001e06767b27a920
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:27Z” level=info msg=“finished unary call with code OK” ctx_id=d63a7cb8-8664-48bc-bd91-7d68ac926e9d grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline=“2020-08-31T2
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:27Z” level=info msg=“finished client unary call” ctx_id=08f1387a-3869-44bc-ab20-20e0c6c77b0d grpc.code=OK grpc.ctx_id=d63a7cb8-8664-48bc-bd91-7d68ac926e9d grpc.duration=170.941275m
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:27Z” level=info msg=“integration/logger: logging event” ctx_id=d63a7cb8-8664-48bc-bd91-7d68ac926e9d dev_eui=001e06767b27a920 type=up
Aug 31 22:50:27 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:27Z” level=info msg=“integration/mqtt: publishing event” ctx_id=d63a7cb8-8664-48bc-bd91-7d68ac926e9d dev_eui=001e06767b27a920 qos=0 retain=false topic=application/1/device/001e
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-concentratord-sx1301[442]: Publishing stats event, stats_id: 2b90a231-7a90-4c9d-98b2-b6c8c97b4309, rx_received: 1, rx_received_ok: 1, tx_received: 0, tx_emitted: 0
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:29Z” level=info msg=“backend/concentratord: stats event received” stats_id=2b90a231-7a90-4c9d-98b2-b6c8c97b4309
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:29Z” level=info msg=“integration/mqtt: publishing event” event=stats qos=0 stats_id=2b90a231-7a90-4c9d-98b2-b6c8c97b4309 topic=gateway/b827ebfffec9e57a/event/stats
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:29Z” level=info msg=“gateway/mqtt: gateway stats packet received” gateway_id=b827ebfffec9e57a stats_id=2b90a231-7a90-4c9d-98b2-b6c8c97b4309
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:29Z” level=info msg=“gateway updated” ctx_id=2b90a231-7a90-4c9d-98b2-b6c8c97b4309 gateway_id=b827ebfffec9e57a
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:29Z” level=info msg=“gateway updated” ctx_id=41cdbafb-4ef4-47ef-a34f-67751f575972 id=b827ebfffec9e57a name=RAK7246
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:29Z” level=info msg=“metrics saved” aggregation=”[MINUTE HOUR DAY MONTH]" ctx_id=41cdbafb-4ef4-47ef-a34f-67751f575972 name=“gw:b827ebfffec9e57a”
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:29Z” level=info msg=“finished unary call with code OK” ctx_id=41cdbafb-4ef4-47ef-a34f-67751f575972 grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServer
Aug 31 22:50:29 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:29Z” level=info msg=“finished client unary call” ctx_id=2b90a231-7a90-4c9d-98b2-b6c8c97b4309 grpc.code=OK grpc.ctx_id=41cdbafb-4ef4-47ef-a34f-67751f575972 grpc.duration=84.651146ms
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-concentratord-sx1301[442]: Publishing stats event, stats_id: c70fcc3f-e5d3-48f3-9312-8b0b32b01191, rx_received: 0, rx_received_ok: 0, tx_received: 0, tx_emitted: 0
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:59Z” level=info msg=“backend/concentratord: stats event received” stats_id=c70fcc3f-e5d3-48f3-9312-8b0b32b01191
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-gateway-bridge[422]: time=“2020-08-31T22:50:59Z” level=info msg=“integration/mqtt: publishing event” event=stats qos=0 stats_id=c70fcc3f-e5d3-48f3-9312-8b0b32b01191 topic=gateway/b827ebfffec9e57a/event/stats
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:59Z” level=info msg=“gateway/mqtt: gateway stats packet received” gateway_id=b827ebfffec9e57a stats_id=c70fcc3f-e5d3-48f3-9312-8b0b32b01191
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:59Z” level=info msg=“gateway updated” ctx_id=c70fcc3f-e5d3-48f3-9312-8b0b32b01191 gateway_id=b827ebfffec9e57a
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:59Z” level=info msg=“gateway updated” ctx_id=697f2afd-884c-4d7f-8ae4-9f05b02df13c id=b827ebfffec9e57a name=RAK7246
Aug 31 22:50:59 raspberrypi0-wifi local0.notice redis[396]: 100 changes in 60 seconds. Saving…
Aug 31 22:50:59 raspberrypi0-wifi local0.notice redis[396]: Background saving started by pid 7318
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:59Z” level=info msg=“metrics saved” aggregation=“[MINUTE HOUR DAY MONTH]” ctx_id=697f2afd-884c-4d7f-8ae4-9f05b02df13c name=“gw:b827ebfffec9e57a”
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-application-server[304]: time=“2020-08-31T22:50:59Z” level=info msg=“finished unary call with code OK” ctx_id=697f2afd-884c-4d7f-8ae4-9f05b02df13c grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServer
Aug 31 22:50:59 raspberrypi0-wifi user.info chirpstack-network-server[317]: time=“2020-08-31T22:50:59Z” level=info msg=“finished client unary call” ctx_id=c70fcc3f-e5d3-48f3-9312-8b0b32b01191 grpc.code=OK grpc.ctx_id=697f2afd-884c-4d7f-8ae4-9f05b02df13c grpc.duration=96.496028ms

And what does Ms Google say when you ask her about the blatant error message shown?

1 Like

She was being a fickle lady and wasn’t much help which is why I ended up here (though my google skills might have been off off-kilter again…). :slight_smile:

That said, I managed to have great overnight tests. In my code for the RN2903 I set pwridx to 5, which based on Microchip’s documentation, that is 20dBm. This is a bit loud, but my real tests are outside, so I’ll want that oomf. Last night I decided to set pwridx to 10, which should be 10dBm and I only had 13 of the errors over an 8 hour period.

I had wondered if maybe the signal was too loud and I was ending up with some slop in adjacent channels making it look like I transmitted twice, but I thought it unlikely because the reported channels of the errors weren’t adjacent (at least consistently) to the actually transmitted channel. I am re-thinking that based on last night’s test, but am not 100% sold yet.

The interesting thing to me is that the RSSI and LoRaSNR values aren’t terribly different between the two tests. They both seems within the range of possibility (of course both are reasonably high values), I just would have expected the values when pwridx was set to 5 would have shown more of a saturation. Who knows…

Signal strength isn’t relevant - we know your gateway is hearing your device.

Without getting too passive-aggressive, can you not see the detail in the error message screen shot you posted???

You are referring to the uplink framecount re-transmission, right?

Yes, that was what I was looking into. I am only sending the one transmission, so I don’t know why it sometimes sees that. I am doing unconfirmed, so I know that it shouldn’t be re-transmitting on its own, so that was why mentioned that I suspected overpowering the front-end and maybe it was causing some inadvertent signal recovery (that wasn’t actually there) in other channels.

This is indeed something that happens when the receiver front end is overloaded.

The key would be that the duplicate packets would have different frequency but almost identical timestamps, as they are the same transmission. The duplicates are also likely to have much weaker RSSI, and some may have CRC errors (typically a packet forwarder will only log or count CRC error packets locally and not pass them to the network server, though that is configurable)

Wheras a re-transmission due to something like a missed confirmed uplink ACK (which you pointed out you were not using) or even a node firmware bug would have to be at least a message duration different in time stamp, ie, tens to hundreds of milliseconds later, often multiple seconds as an actual retry would not occur until both receive windows had passed.

1 Like

And see, this is where I confused myself. Because I would have expected the times to be within a second for an overloaded front end, but some of these errors could be as much as 5ish seconds from the original message (at least as reported by the web browser). Plus, I would have expected the splashover to be the first adjacent channel, but sometimes it was more than a channel over without the channel in between being “active.”

You should SSH into the pi and look at the raw packet forwarder log, specifically the hardware timestamp which is a rolling 32-bit counter. Or else look at the raw gateway traffic view in chirpstack

If there are really multiple seconds between these packets (as indeed, your first screenshot appears to show) and that is confirmed at the level of raw concentrator counter timestamps, then it’s not a gateway or server problem, it’s a case of the node re-transmitting. If you’re not using confirmed uplink, then you have a node firmware bug.

That’s not necessarily proof that overloading did not occur.

However, the apparent difference in timestamps would be.

1 Like

Where does this log get written to? It seems like almost everything goes to /var/log/messages (which can be a mess to debug through. I am wondering if I need to change a log level value somewhere (they are all set to default).

I am guessing that what you are looking for is the same hardware timestamp in both packets? That would indicate that it is truly the same single transmission multiple times?

quick edit
And of course I roll back my node to use the older pwridx value (that was causing me issues) and it hasn’t caused any problems in the last 30 mins… I’ll keep it running and hope I can get one of the errors and can see what the values say.

Can you add some logging to your node to tell when it actually transmits?

Yes. Using a UART I can see that it is only transmitting the one time.

Are you sure it is only actually transmitting once? You may only be giving one request to the module, but do you know it has not decided on its own to retry for some reason?

In terms of the packet forwarder logs, trying using grep on them to find actual receive events

Good call. If I can ever get it back into that mode, I will look into what the module has to say.