ACK sent on air, acknowledged to NS (in logs), but NS sends next ACK with same FCnt

[jorgeig-space]

• [X] The issue is present in the latest release.
• [X] I have searched the issues of this repository and believe that this is not a duplicate.

What happened?

Received the same UnconfirmedDataDownlink (i.e. with the same FCnt) twice, for two consecutive Uplinks. The end device sees both ACK correctly, and the NS appears to receive the TXACK from the gateway in the logs, but the first ACK is not stored on redis nor shown in the AS interface.

What did you expect?

Receive an ACK with an increased FCnt, and have the previous one stored.

Steps to reproduce this issue

Steps:

1. Join the network
2. Start transmitting confirmed packets, payload is [0,0,0,0,,0]
3. After a few packets, one of the ACKs appears to be "skipped" (no redis storage, not showing on the AS interface), although it is transmitted over the air and TXACK'd by the gateway to the NS
4. On the next uplink, the ACK that would be transmitted from the previous uplink is now transmitted, but it doesn't match the expected FCnt from the end device (because the end device saw the previous ACK that the NS thinks hasn't been transmitted)

I am attaching the app screenshot, end-device application log extract, redis extract (from the gw key) and the network-server log. I am not certain that the problem is in chirpstack because this seems like a very common use case, but looking at redis it looks like a chirpstack issue. Any pointers to where to look next?

These are log extracts from the end-device application, where we can see that the ACKs are correctly received up to UpFCnt 6, where it is the same as UpFCnt 5.

// This is the JoinAccept
7.994411 DEBUG parse_with_factory: bytes: [32, 121, 130, 16, 220, 185, 38, 234, 13, 119, 32, 67, 42, 33, 255, 225, 67]
// For each Uplink with FCnt X
30.455295 TRACE lorawan_response: Uplink with FCnt 0
// We receive an UnconfirmedDataDownlink with an ACK
33.970936 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 0, 0, 176, 219, 212, 191]
60.761542 TRACE lorawan_response: Uplink with FCnt 1
64.276677 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 1, 0, 187, 231, 90, 239]
91.076293 TRACE lorawan_response: Uplink with FCnt 2
94.592112 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 2, 0, 44, 128, 182, 181]
121.395793 TRACE lorawan_response: Uplink with FCnt 3
124.911873 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 3, 0, 33, 107, 63, 180]
151.719372 TRACE lorawan_response: Uplink with FCnt 4
155.236551 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 4, 0, 117, 80, 97, 82]
// This is where the issue manifests
182.041880 TRACE lorawan_response: Uplink with FCnt 5
185.558987 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 5, 0, 56, 146, 35, 134] <--------------
212.366891 TRACE lorawan_response: Uplink with FCnt 6
215.883770 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 5, 0, 56, 146, 35, 134] <--------------

I am not sure whether the issue is in ChirpStack or the RAK2245 forwarder, but I went into the redis stream and found that the ACK is generated at the wrong time, but strangely enough also generated at the right time although it's not in the redis stream:

Note: the duplicated key "2)" is just my translation of the ASCII bytestring into an array of uint_8.

// FCnt 3
 4) 1) "1643198014609-0"
    2) 1) "up"
       2) "\n\x13\x80\xec\xd5\xf4\x01\x00\x03\x00\n\t\"\xc2a\x06u!mv\x9d\x12\x11\b\xd8\xf3\xc6\xce\x01\x1a\t\b}\x10\x0c\x1a\x034/5\x1a>\n\b\xb8'\xeb\xff\xfe\xd7\xe6\xe4(\xfc\xff\xff\xff\xff\xff\xff\xff\xff\x011ffffff,@@\x01Z\x00z\x04\x05\x9b\xa7t\x82\x01\x10\xe2\x0c\xe6d\xe4DE\xbb\xa8\xbeF\x1d}V.\xf8\x88\x01\x02 \x04*\x04\x01\xf4\xd5\xec:\x0c\b\xbe\xec\xc4\x8f\x06\x10\xfb\xf0\xa1\xa0\x02"
       2) [10, 19, 128, 236, 213, 244, 1, 0, 3, 0, 10, 9, 34, 194, 97, 6, 117, 33, 109, 118, 157, 18, 17, 8, 216, 243, 198, 206, 1, 26, 9, 8, 125, 16, 12, 26, 3, 52, 47, 53, 26, 62, 10, 8, 184, 39, 235, 255, 254, 215, 230, 228, 40, 252, 255, 255, 255, 255, 255, 255, 255, 255, 1, 49, 102, 102, 102, 102, 102, 102, 44, 64, 64, 1, 90, 0, 122, 4, 5, 155, 167, 116, 130, 1, 16, 226, 12, 230, 100, 228, 68, 69, 187, 168, 190, 70, 29, 125, 86, 46, 248, 136, 1, 2, 32, 4, 42, 4, 1, 244, 213, 236, 58, 12, 8, 190, 236, 196, 143, 6, 16, 251, 240, 161, 160, 2]
 5) 1) "1643198014931-0"
    2) 1) "down"
       2) "\n\x0c`\xec\xd5\xf4\x01 \x03\x00!k?\xb4\x12$(\xd8\xf3\xc6\xce\x010\n`\x01\x82\x01\x04\x05\x9b\xa7tB\x0b\b}\x10\x0c\x1a\x034/5 \x01r\x04\n\x02\b\x01\x18\xf2\xbb\x02\"\x10\x9d\xf2\xab9\xee6B[\xb8\xc14\x99\x9d0f\b*\b\xb8'\xeb\xff\xfe\xd7\xe6\xe40\x03:\x04\x01\xf4\xd5\xecB\b\xab\xab\xab\xab\xab\xab\xab\xabJ\x0c\b\xbe\xec\xc4\x8f\x06\x10\xef\xb1\xdb\xba\x03"
       2) [10, 12, 96, 236, 213, 244, 1, 32, 3, 0, 33, 107, 63, 180, 18, 36, 40, 216, 243, 198, 206, 1, 48, 10, 96, 1, 130, 1, 4, 5, 155, 167, 116, 66, 11, 8, 125, 16, 12, 26, 3, 52, 47, 53, 32, 1, 114, 4, 10, 2, 8, 1, 24, 242, 187, 2, 34, 16, 157, 242, 171, 57, 238, 54, 66, 91, 184, 193, 52, 153, 157, 48, 102, 8, 42, 8, 184, 39, 235, 255, 254, 215, 230, 228, 48, 3, 58, 4, 1, 244, 213, 236, 66, 8, 171, 171, 171, 171, 171, 171, 171, 171, 74, 12, 8, 190, 236, 196, 143, 6, 16, 239, 177, 219, 186, 3]
// FCnt 4
 6) 1) "1643198044878-0"
    2) 1) "up"
       2) "\n\x13\x80\xec\xd5\xf4\x01\x00\x04\x00\noDO\xa6\x1a;\xda\x84\xeb\xad\x12\x11\b\xd8\xf3\xc6\xce\x01\x1a\t\b}\x10\x0c\x1a\x034/5\x1a>\n\b\xb8'\xeb\xff\xfe\xd7\xe6\xe4(\xfc\xff\xff\xff\xff\xff\xff\xff\xff\x011\x00\x00\x00\x00\x00\x00'@@\x01Z\x00z\x04\ai\xbb\x84\x82\x01\x10-\xaf\xda\xae\x82\rD\xfb\xb7h\xa8\")\x1d\xefO\x88\x01\x02 \x04*\x04\x01\xf4\xd5\xec:\x0c\b\xdc\xec\xc4\x8f\x06\x10\xb0\xff\x85\xa2\x03"
       2) [10, 19, 128, 236, 213, 244, 1, 0, 4, 0, 10, 111, 68, 79, 166, 26, 59, 218, 132, 235, 173, 18, 17, 8, 216, 243, 198, 206, 1, 26, 9, 8, 125, 16, 12, 26, 3, 52, 47, 53, 26, 62, 10, 8, 184, 39, 235, 255, 254, 215, 230, 228, 40, 252, 255, 255, 255, 255, 255, 255, 255, 255, 1, 49, 0, 0, 0, 0, 0, 0, 39, 64, 64, 1, 90, 0, 122, 4, 7, 105, 187, 132, 130, 1, 16, 45, 175, 218, 174, 130, 13, 68, 251, 183, 104, 168, 34, 41, 29, 239, 79, 136, 1, 2, 32, 4, 42, 4, 1, 244, 213, 236, 58, 12, 8, 220, 236, 196, 143, 6, 16, 176, 255, 133, 162, 3]
 7) 1) "1643198045150-0"
    2) 1) "down"
       2) "\n\x0c`\xec\xd5\xf4\x01 \x04\x00uPaR\x12$(\xd8\xf3\xc6\xce\x010\n`\x01\x82\x01\x04\ai\xbb\x84B\x0b\b}\x10\x0c\x1a\x034/5 \x01r\x04\n\x02\b\x01\x18\x9c\xaf\x02\"\x10\x97\x9c\x1f\xa0_\xa0K3\xab\x1bI\x8dP\xd7\x15\xec*\b\xb8'\xeb\xff\xfe\xd7\xe6\xe40\x03:\x04\x01\xf4\xd5\xecB\b\xab\xab\xab\xab\xab\xab\xab\xabJ\x0b\b\xdd\xec\xc4\x8f\x06\x10\xf0\xda\xc8F"
       2) [10, 12, 96, 236, 213, 244, 1, 32, 4, 0, 117, 80, 97, 82, 18, 36, 40, 216, 243, 198, 206, 1, 48, 10, 96, 1, 130, 1, 4, 7, 105, 187, 132, 66, 11, 8, 125, 16, 12, 26, 3, 52, 47, 53, 32, 1, 114, 4, 10, 2, 8, 1, 24, 156, 175, 2, 34, 16, 151, 156, 31, 160, 95, 160, 75, 51, 171, 27, 73, 141, 80, 215, 21, 236, 42, 8, 184, 39, 235, 255, 254, 215, 230, 228, 48, 3, 58, 4, 1, 244, 213, 236, 66, 8, 171, 171, 171, 171, 171, 171, 171, 171, 74, 11, 8, 221, 236, 196, 143, 6, 16, 240, 218, 200, 70]
// FCnt 5 - No ACK seen here but seen on the device!!
 8) 1) "1643198075156-0"
    2) 1) "up"
       2) "\n\x13\x80\xec\xd5\xf4\x01\x00\x05\x00\n\xfb\xa7\xc0\x19O\x9by\xfd\xb0\xc6\x12\x11\b\xd8\xf3\xc6\xce\x01\x1a\t\b}\x10\x0c\x1a\x034/5\x1a>\n\b\xb8'\xeb\xff\xfe\xd7\xe6\xe4(\xfc\xff\xff\xff\xff\xff\xff\xff\xff\x011\x9a\x99\x99\x99\x99\x99%@@\x01Z\x00z\x04\t7\xcdl\x82\x01\x10Y\x82\x14Y-\x15C\xae\x9ddc\x06\xdb\xb0\xf7\xbb\x88\x01\x02 \x04*\x04\x01\xf4\xd5\xec:\x0b\b\xfb\xec\xc4\x8f\x06\x10\xb0\x9d\x85J"
       2) [10, 19, 128, 236, 213, 244, 1, 0, 5, 0, 10, 251, 167, 192, 25, 79, 155, 121, 253, 176, 198, 18, 17, 8, 216, 243, 198, 206, 1, 26, 9, 8, 125, 16, 12, 26, 3, 52, 47, 53, 26, 62, 10, 8, 184, 39, 235, 255, 254, 215, 230, 228, 40, 252, 255, 255, 255, 255, 255, 255, 255, 255, 1, 49, 154, 153, 153, 153, 153, 153, 37, 64, 64, 1, 90, 0, 122, 4, 9, 55, 205, 108, 130, 1, 16, 89, 130, 20, 89, 45, 21, 67, 174, 157, 100, 99, 6, 219, 176, 247, 187, 136, 1, 2, 32, 4, 42, 4, 1, 244, 213, 236, 58, 11, 8, 251, 236, 196, 143, 6, 16, 176, 157, 133, 74]
// FCnt 6
 9) 1) "1643198105460-0"
    2) 1) "up"
       2) "\n\x13\x80\xec\xd5\xf4\x01\x00\x06\x00\n\x14?\xbci #L\xce\x88\x87\x12\x11\b\xd8\xf3\xc6\xce\x01\x1a\t\b}\x10\x0c\x1a\x034/5\x1a>\n\b\xb8'\xeb\xff\xfe\xd7\xe6\xe4(\xfb\xff\xff\xff\xff\xff\xff\xff\xff\x011\x00\x00\x00\x00\x00\x00\"@@\x01Z\x00z\x04\x0b\x05\xdc\xc4\x82\x01\x10\xd7\xf4{\xdd\xffzC\t\x94\x04P\x96O\xd0\x91\x88\x88\x01\x02 \x04*\x04\x01\xf4\xd5\xec:\x0c\b\x99\xed\xc4\x8f\x06\x10\xf8\xd6\xf5\xda\x01"
       2) [10, 19, 128, 236, 213, 244, 1, 0, 6, 0, 10, 20, 63, 188, 105, 32, 35, 76, 206, 136, 135, 18, 17, 8, 216, 243, 198, 206, 1, 26, 9, 8, 125, 16, 12, 26, 3, 52, 47, 53, 26, 62, 10, 8, 184, 39, 235, 255, 254, 215, 230, 228, 40, 251, 255, 255, 255, 255, 255, 255, 255, 255, 1, 49, 0, 0, 0, 0, 0, 0, 34, 64, 64, 1, 90, 0, 122, 4, 11, 5, 220, 196, 130, 1, 16, 215, 244, 123, 221, 255, 122, 67, 9, 148, 4, 80, 150, 79, 208, 145, 136, 136, 1, 2, 32, 4, 42, 4, 1, 244, 213, 236, 58, 12, 8, 153, 237, 196, 143, 6, 16, 248, 214, 245, 218, 1]
// This is the ACK for FCnt 5, but it is generated after the  `up` event and apparently also sent (as seen on the device)
10) 1) "1643198105754-0"
    2) 1) "down"
       2) "\n\x0c`\xec\xd5\xf4\x01 \x05\x008\x92#\x86\x12$(\xd8\xf3\xc6\xce\x010\n`\x01\x82\x01\x04\x0b\x05\xdc\xc4B\x0b\b}\x10\x0c\x1a\x034/5 \x01r\x04\n\x02\b\x01\x18\x89\x9a\x01\"\x10M\t//j\x9aM\x9c\xba\xb9\x97\xac\x0c\xe3\xd5P*\b\xb8'\xeb\xff\xfe\xd7\xe6\xe40\x03:\x04\x01\xf4\xd5\xecB\b\xab\xab\xab\xab\xab\xab\xab\xabJ\x0c\b\x99\xed\xc4\x8f\x06\x10\xd4\xdf\xf9\xe6\x02"
       2) [10, 12, 96, 236, 213, 244, 1, 32, 5, 0, 56, 146, 35, 134, 18, 36, 40, 216, 243, 198, 206, 1, 48, 10, 96, 1, 130, 1, 4, 11, 5, 220, 196, 66, 11, 8, 125, 16, 12, 26, 3, 52, 47, 53, 32, 1, 114, 4, 10, 2, 8, 1, 24, 137, 154, 1, 34, 16, 77, 9, 47, 47, 106, 154, 77, 156, 186, 185, 151, 172, 12, 227, 213, 80, 42, 8, 184, 39, 235, 255, 254, 215, 230, 228, 48, 3, 58, 4, 1, 244, 213, 236, 66, 8, 171, 171, 171, 171, 171, 171, 171, 171, 74, 12, 8, 153, 237, 196, 143, 6, 16, 212, 223, 249, 230, 2]

Could you share your log output?

INFO[0001] starting ChirpStack Network Server            band=EU433 docs="https://www.chirpstack.io/" net_id=000000 version=3.15.5
INFO[0001] storage: setting up storage module           
INFO[0001] storage: setting up Redis client             
INFO[0001] storage: connecting to PostgreSQL            
INFO[0001] storage: applying PostgreSQL data migrations 
INFO[0001] gateway/mqtt: connecting to mqtt broker       server="tcp://localhost:1883"
INFO[0001] api: starting network-server api server       bind="0.0.0.0:8000" ca-cert= tls-cert= tls-key=
INFO[0001] backend/gateway: connected to mqtt server    
INFO[0001] gateway/mqtt: subscribing to gateway event topic  qos=0 topic=gateway/+/event/+
INFO[0001] starting downlink device-queue scheduler     
INFO[0001] starting multicast scheduler                 
INFO[0025] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=8da88be5-c80e-46bd-8d78-538294e2583d
INFO[0025] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=faea4360-06df-4ab0-902a-aa57edc36ebe
INFO[0025] storage: gateway state updated                ctx_id=faea4360-06df-4ab0-902a-aa57edc36ebe gateway_id=b827ebfffed7e6e4
INFO[0025] uplink: frame(s) collected                    ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 mtype=JoinRequest uplink_ids="[8da88be5-c80e-46bd-8d78-538294e2583d]"
WARN[0026] creating insecure application-server client   server="localhost:8001"
INFO[0026] finished client unary call                    ctx_id=faea4360-06df-4ab0-902a-aa57edc36ebe grpc.code=OK grpc.ctx_id=110efd52-a3d4-479f-a561-68195c2318ca grpc.duration=194.704948ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0026] lorawan/backend: finished backend api call    message_type=JoinReq protocol_version=1.0 receiver_id=0000000000000000 result_code=Success sender_id=000000 transaction_id=2002198974
INFO[0026] sent uplink meta-data to network-controller   ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 dev_eui=abababababababab
INFO[0026] device-queue flushed                          ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 dev_eui=abababababababab
INFO[0026] device-session saved                          ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0026] device-activation created                     ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 dev_eui=abababababababab id=75
INFO[0026] device updated                                ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 dev_eui=abababababababab
INFO[0026] gateway/mqtt: publishing gateway command      command=down downlink_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0026] storage: downlink-frame saved                 ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 token=29330
INFO[0026] backend/gateway: downlink tx acknowledgement received  downlink_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4 gateway_id=b827ebfffed7e6e4
INFO[0026] sent downlink meta-data to network-controller  ctx_id=a48fc8d4-94b4-456a-8ce2-208dda8a2de4
INFO[0055] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=fd5487b7-4607-4934-8f70-efa5069e0f4a
INFO[0055] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=ac719c26-563a-43f4-9236-cfcc7395326a
INFO[0055] storage: gateway state updated                ctx_id=ac719c26-563a-43f4-9236-cfcc7395326a gateway_id=b827ebfffed7e6e4
INFO[0056] uplink: frame(s) collected                    ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf mtype=ConfirmedDataUp uplink_ids="[fd5487b7-4607-4934-8f70-efa5069e0f4a]"
INFO[0056] sent uplink meta-data to network-controller   ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf dev_eui=abababababababab
INFO[0056] device gateway rx-info meta-data saved        ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf dev_eui=abababababababab
INFO[0056] device-session saved                          ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0056] finished client unary call                    ctx_id=ac719c26-563a-43f4-9236-cfcc7395326a grpc.code=OK grpc.ctx_id=596ee0ff-7ab3-4936-96c9-f933c107de09 grpc.duration=340.829412ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0056] gateway/mqtt: publishing gateway command      command=down downlink_id=638d0521-b4ba-497f-8a71-c95b37cecfcf gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0056] device-session saved                          ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0056] backend/gateway: downlink tx acknowledgement received  downlink_id=638d0521-b4ba-497f-8a71-c95b37cecfcf gateway_id=b827ebfffed7e6e4
INFO[0056] storage: downlink-frame saved                 ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf token=25485
INFO[0056] device-session saved                          ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0056] sent downlink meta-data to network-controller  ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf
INFO[0056] finished client unary call                    ctx_id=638d0521-b4ba-497f-8a71-c95b37cecfcf grpc.code=OK grpc.ctx_id=128c67be-ea0b-47a2-b610-a82041423212 grpc.duration=396.295828ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0085] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=9cfd7467-e42c-4e24-a76d-15c2cd60dbc2
INFO[0085] storage: gateway state updated                ctx_id=9cfd7467-e42c-4e24-a76d-15c2cd60dbc2 gateway_id=b827ebfffed7e6e4
INFO[0086] finished client unary call                    ctx_id=9cfd7467-e42c-4e24-a76d-15c2cd60dbc2 grpc.code=OK grpc.ctx_id=c45680e8-5338-4344-a526-611c4d8634aa grpc.duration=113.516807ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0086] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=1ace32a0-efd8-4cd1-8bd6-ba3ceac2d47f
INFO[0086] uplink: frame(s) collected                    ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda mtype=ConfirmedDataUp uplink_ids="[1ace32a0-efd8-4cd1-8bd6-ba3ceac2d47f]"
INFO[0086] sent uplink meta-data to network-controller   ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda dev_eui=abababababababab
INFO[0086] device gateway rx-info meta-data saved        ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda dev_eui=abababababababab
INFO[0086] device-session saved                          ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0086] finished client unary call                    ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda grpc.code=OK grpc.ctx_id=01ff8b35-7e5a-4801-8566-423a930f0674 grpc.duration=120.347735ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0086] gateway/mqtt: publishing gateway command      command=down downlink_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0086] device-session saved                          ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0086] backend/gateway: downlink tx acknowledgement received  downlink_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda gateway_id=b827ebfffed7e6e4
INFO[0086] storage: downlink-frame saved                 ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda token=61264
INFO[0086] device-session saved                          ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0086] sent downlink meta-data to network-controller  ctx_id=ef50fb3f-1d75-440d-a410-0d4b54e44bda
INFO[0107] finished unary call with code OK              ctx_id=96a1d6d6-962f-4ba1-99e6-c52b72844959 grpc.code=OK grpc.method=GetGateway grpc.service=ns.NetworkServerService grpc.start_time="2022-01-26T11:52:55Z" grpc.time_ms=29.771 peer.address="[::1]:42040" span.kind=server system=grpc
INFO[0115] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=a749a0fb-433b-4713-a0bb-43c39b796416
INFO[0115] storage: gateway state updated                ctx_id=a749a0fb-433b-4713-a0bb-43c39b796416 gateway_id=b827ebfffed7e6e4
INFO[0116] finished client unary call                    ctx_id=a749a0fb-433b-4713-a0bb-43c39b796416 grpc.code=OK grpc.ctx_id=2e56a325-0582-49d3-9c5c-a52f80c68a71 grpc.duration=152.521399ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0116] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=7ce7ea70-555d-4948-b5ca-3ff5552afc83
INFO[0116] uplink: frame(s) collected                    ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 mtype=ConfirmedDataUp uplink_ids="[7ce7ea70-555d-4948-b5ca-3ff5552afc83]"
INFO[0116] sent uplink meta-data to network-controller   ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 dev_eui=abababababababab
INFO[0116] device gateway rx-info meta-data saved        ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 dev_eui=abababababababab
INFO[0116] device-session saved                          ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0116] finished client unary call                    ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 grpc.code=OK grpc.ctx_id=b2ca08a4-b306-4f8f-8ec7-c510408098c3 grpc.duration=145.919468ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0116] gateway/mqtt: publishing gateway command      command=down downlink_id=530f97b8-d582-4068-b610-c5fa6539b535 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0116] device-session saved                          ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0116] backend/gateway: downlink tx acknowledgement received  downlink_id=530f97b8-d582-4068-b610-c5fa6539b535 gateway_id=b827ebfffed7e6e4
INFO[0116] storage: downlink-frame saved                 ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 token=21263
INFO[0116] device-session saved                          ctx_id=530f97b8-d582-4068-b610-c5fa6539b535 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0116] sent downlink meta-data to network-controller  ctx_id=530f97b8-d582-4068-b610-c5fa6539b535
INFO[0118] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=b463d732-ae6c-439e-b98d-4001df5c8135
INFO[0118] uplink: frame(s) collected                    ctx_id=4601ecf9-e0d9-4ea7-8703-70d64edd0930 mtype=UnconfirmedDataDown uplink_ids="[b463d732-ae6c-439e-b98d-4001df5c8135]"
INFO[0126] finished streaming call with code OK          grpc.code=OK grpc.method=StreamFrameLogsForGateway grpc.service=ns.NetworkServerService grpc.start_time="2022-01-26T11:52:57Z" grpc.time_ms=17231.924 peer.address="[::1]:42040" span.kind=server system=grpc
INFO[0136] finished unary call with code OK              ctx_id=9d172b52-48ba-43c0-9c21-96dfbc1eb4c7 grpc.code=OK grpc.method=GetGateway grpc.service=ns.NetworkServerService grpc.start_time="2022-01-26T11:53:24Z" grpc.time_ms=25.747 peer.address="[::1]:42040" span.kind=server system=grpc
INFO[0145] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=851dc34a-95af-43fd-a4dc-a5063eef4eeb
INFO[0145] storage: gateway state updated                ctx_id=851dc34a-95af-43fd-a4dc-a5063eef4eeb gateway_id=b827ebfffed7e6e4
INFO[0146] finished client unary call                    ctx_id=851dc34a-95af-43fd-a4dc-a5063eef4eeb grpc.code=OK grpc.ctx_id=403e0e29-61bd-4b25-80a7-e2441dcd7f16 grpc.duration=77.629186ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0146] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=e20ce664-e444-45bb-a8be-461d7d562ef8
INFO[0146] uplink: frame(s) collected                    ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 mtype=ConfirmedDataUp uplink_ids="[e20ce664-e444-45bb-a8be-461d7d562ef8]"
INFO[0146] sent uplink meta-data to network-controller   ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 dev_eui=abababababababab
INFO[0146] device gateway rx-info meta-data saved        ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 dev_eui=abababababababab
INFO[0147] device-session saved                          ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0147] finished client unary call                    ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 grpc.code=OK grpc.ctx_id=efc13b25-9cab-4c61-9ea2-93cb814a59b3 grpc.duration=141.475517ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0147] gateway/mqtt: publishing gateway command      command=down downlink_id=9df2ab39-ee36-425b-b8c1-34999d306608 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0147] device-session saved                          ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0147] backend/gateway: downlink tx acknowledgement received  downlink_id=9df2ab39-ee36-425b-b8c1-34999d306608 gateway_id=b827ebfffed7e6e4
INFO[0147] storage: downlink-frame saved                 ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 token=40434
INFO[0147] device-session saved                          ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0147] sent downlink meta-data to network-controller  ctx_id=9df2ab39-ee36-425b-b8c1-34999d306608
INFO[0175] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=dc02c80c-72a3-46e0-91fc-e4a3f74cb24f
INFO[0175] storage: gateway state updated                ctx_id=dc02c80c-72a3-46e0-91fc-e4a3f74cb24f gateway_id=b827ebfffed7e6e4
INFO[0176] finished client unary call                    ctx_id=dc02c80c-72a3-46e0-91fc-e4a3f74cb24f grpc.code=OK grpc.ctx_id=5333fd16-5ce0-4167-993f-a8757a10ee2e grpc.duration=81.213149ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0176] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=2dafdaae-820d-44fb-b768-a822291def4f
INFO[0177] uplink: frame(s) collected                    ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec mtype=ConfirmedDataUp uplink_ids="[2dafdaae-820d-44fb-b768-a822291def4f]"
INFO[0177] device gateway rx-info meta-data saved        ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec dev_eui=abababababababab
INFO[0177] device-session saved                          ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0177] sent uplink meta-data to network-controller   ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec dev_eui=abababababababab
INFO[0177] finished client unary call                    ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec grpc.code=OK grpc.ctx_id=8dce86ad-0eac-4a52-a0e7-756fdc332772 grpc.duration=170.179218ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0177] gateway/mqtt: publishing gateway command      command=down downlink_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0177] device-session saved                          ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0177] storage: downlink-frame saved                 ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec token=38812
INFO[0177] backend/gateway: downlink tx acknowledgement received  downlink_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec gateway_id=b827ebfffed7e6e4
INFO[0177] device-session saved                          ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0177] sent downlink meta-data to network-controller  ctx_id=979c1fa0-5fa0-4b33-ab1b-498d50d715ec
INFO[0205] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=85ccadf0-a021-4fbd-aae1-4886c2019ac8
INFO[0205] storage: gateway state updated                ctx_id=85ccadf0-a021-4fbd-aae1-4886c2019ac8 gateway_id=b827ebfffed7e6e4
INFO[0206] finished client unary call                    ctx_id=85ccadf0-a021-4fbd-aae1-4886c2019ac8 grpc.code=OK grpc.ctx_id=5da41920-4e9b-4673-a254-4ee6b425f664 grpc.duration=78.164183ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0207] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=59821459-2d15-43ae-9d64-6306dbb0f7bb
INFO[0207] uplink: frame(s) collected                    ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 mtype=ConfirmedDataUp uplink_ids="[59821459-2d15-43ae-9d64-6306dbb0f7bb]"
INFO[0207] device gateway rx-info meta-data saved        ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 dev_eui=abababababababab
INFO[0207] device-session saved                          ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0207] sent uplink meta-data to network-controller   ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 dev_eui=abababababababab
INFO[0207] finished client unary call                    ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 grpc.code=OK grpc.ctx_id=42804d82-f914-4309-9517-44c96c452ba5 grpc.duration=100.277952ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0207] gateway/mqtt: publishing gateway command      command=down downlink_id=b1286061-6b53-41be-83bc-a514220dc3d6 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0207] backend/gateway: downlink tx acknowledgement received  downlink_id=b1286061-6b53-41be-83bc-a514220dc3d6 gateway_id=b827ebfffed7e6e4
INFO[0207] device-session saved                          ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0207] storage: downlink-frame saved                 ctx_id=b1286061-6b53-41be-83bc-a514220dc3d6 token=45352
INFO[0235] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=f6355712-51ba-4146-aa42-43cc718ac0df
INFO[0235] storage: gateway state updated                ctx_id=f6355712-51ba-4146-aa42-43cc718ac0df gateway_id=b827ebfffed7e6e4
INFO[0236] finished client unary call                    ctx_id=f6355712-51ba-4146-aa42-43cc718ac0df grpc.code=OK grpc.ctx_id=377c3160-f8c5-4c90-86e5-aaaa3c415844 grpc.duration=145.981475ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0237] gateway/mqtt: uplink frame received           gateway_id=b827ebfffed7e6e4 uplink_id=d7f47bdd-ff7a-4309-9404-50964fd09188
INFO[0237] uplink: frame(s) collected                    ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 mtype=ConfirmedDataUp uplink_ids="[d7f47bdd-ff7a-4309-9404-50964fd09188]"
INFO[0237] sent uplink meta-data to network-controller   ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 dev_eui=abababababababab
INFO[0237] device gateway rx-info meta-data saved        ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 dev_eui=abababababababab
INFO[0237] device-session saved                          ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0237] finished client unary call                    ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 grpc.code=OK grpc.ctx_id=5c279e71-32a8-4537-b4fd-ef75eff84524 grpc.duration=127.147672ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
INFO[0238] gateway/mqtt: publishing gateway command      command=down downlink_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
INFO[0238] device-session saved                          ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0238] storage: downlink-frame saved                 ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 token=19721
INFO[0238] backend/gateway: downlink tx acknowledgement received  downlink_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 gateway_id=b827ebfffed7e6e4
INFO[0238] device-session saved                          ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550 dev_addr=01f4d5ec dev_eui=abababababababab
INFO[0238] sent downlink meta-data to network-controller  ctx_id=4d092f2f-6a9a-4d9c-bab9-97ac0ce3d550
INFO[0265] gateway/mqtt: gateway stats packet received   gateway_id=b827ebfffed7e6e4 stats_id=3fed8b65-7588-457c-b210-21de9d457d65
INFO[0265] storage: gateway state updated                ctx_id=3fed8b65-7588-457c-b210-21de9d457d65 gateway_id=b827ebfffed7e6e4
INFO[0266] finished client unary call                    ctx_id=3fed8b65-7588-457c-b210-21de9d457d65 grpc.code=OK grpc.ctx_id=43b2bf5c-f937-4016-8679-d210bd4e6e01 grpc.duration=103.332922ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
^CINFO[0270] signal received                               signal=interrupt
WARN[0270] stopping chirpstack-network-server           
INFO[0270] gateway/mqtt: closing backend                
INFO[0270] gateway/mqtt: unsubscribing from event topic  topic=gateway/+/event/+
INFO[0270] backend/gateway: handling last messages      
INFO[0270] uplink: waiting for pending actions to complete 

Your Environment

Component	Version
Application Server	v3.17.4
Network Server	v3.15.5
Gateway Bridge	v3.13.2
Chirpstack API	N/A
Geolocation	N/A
Concentratord	RAK

RAK lora_pkt_fwd version:

*** Beacon Packet Forwarder for Lora Gateway ***
Version: 4.0.1
*** Lora concentrator HAL library version info ***
Version: 5.0.1;
***

[jorgeig-space]

This might also be the cause of this issue: https://github.com/brocaar/chirpstack-application-server/issues/522

Most stacks will fail silently if they received an invalid frame. In this case the frame is invalid because the MIC will be wrong (as it is for the previous FCnt). The only reason I have the end-node logs above is because I'm also working on the Rust Lorawan stack so I inserted some debug statements.

To clarify, there are no other devices on the network, everything is running on the same host, and the end-device and gateway are in the same room.

[brocaar]

Do you mean that for two confirmed uplinks (FCnt 5 and FCnt 6), the NS responded with exactly the same downlink payload (containing the ACK)?

// This is where the issue manifests
182.041880 TRACE lorawan_response: Uplink with FCnt 5
185.558987 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 5, 0, 56, 146, 35, 134] <--------------
212.366891 TRACE lorawan_response: Uplink with FCnt 6
215.883770 DEBUG parse_with_factory: bytes: [96, 236, 213, 244, 1, 32, 5, 0, 56, 146, 35, 134] <--------------

Please note that (for LoRaWAN 1.0), the ACK does not contain the frame-counter that was acknowledged. For LoRaWAN 1.1 the ACK uses the uplink frame-counter in the MIC calculation.

Note that the NS increments the downlink frame-counter after receiving a TX ACK from the gateway. In case the gateway does transmit the downlink, but does not send a TXACK (or it did send but it did not reach the NS), the NS will consider the downlink as not transmitted and the downlink frame-counter will not increment and thus will be used again for the next downlink.

This could have happened:

1. Device sends confirmed up with fcnt up: 5
2. NS responds with ACK using fcnt down: 5 (no TX ACK from gateway)
3. Device sends confirmed up with fcnt up: 6
4. NS responds with ACK using fcnt down: 5 (TX ACK from gateway)

In this case the downlink from 2) will not appear in the Redis Stream as it is considered as never been sent by the gateway.

Please note, it is perfectly fine that the confirmed uplink has fcnt 6, and the downlink acknowledgement has fcnt 5. The device receives an ACK, but it does not contain the uplink fcnt to which the ACK relates. That is why in LoRaWAN 1.1 this was included in the MIC validation.

[jorgeig-space]

Many thanks for taking the time to look into this and pointing out the ACK mechanism. That makes things much clearer. Clearly this is not an NS issue.

It appears there is some issue in RAK's lora_pkt_fwd, since the ACK is transmitted (seen by the end-device), but no txack is given back to the NS... I'll close the issue here and post a solution when I find it. If you have any ideas on how to diagnose that, they'll be much appreciated! Thanks.

[jorgeig-space]

Hi, sorry to beat the dead horse with this but I've been taking a closer look at logs and it appears the NS is indeed receiving TX ACK from the gateway. Redis still doesn't show any downlink message right before the problem, and the device is still seeing the "duplicated" ACK.

In this latest test:

• FCnt 0 ConfirmedUplink is received and ACK'd properly (with FCnt_down = 0)
• FCnt 1 ConfirmedUplink is received by the gateway
• Down TX (with an ACK for FCnt 1) is scheduled and the TX ACK is seen by the NS according to logs
• Down ACK with FCnt_down = 1 is transmitted by the radio and seen by the end device (so the device expects FCnt_down = 2 next)
• FCnt 2 up is received by the gateway
• Down TX (with an ACK for FCnt 1) is scheduled and the TX ACK is seen by the NS according to logs
• Down ACK with FCnt_down = 1 is transmitted by the radio and seen by the end device so the device rejects it

The big issue is that the ACK is always correctly transmitted, it's just that the NS doesn't seem to know about it (but the log says otherwise).

Any pointer on where to look? I can only see one difference between the good ACKs and the one that appears to be ignored: at the end of each FCnt block in the NS log, there is a message msg="sent downlink meta-data to network-controller" which is not present for FCnt 1.

The messages storage: downlink-frame saved seem to indicate that we are on the OnError branch of handleDownlinkTXAckTasks, but I see no errors on the AS or anywhere else.

=========== Logs

View on application:

NS Log:

JOIN
ns: time="2022-03-02T03:22:41.287768752Z" level=info msg="gateway/mqtt: uplink frame received" gateway_id=b827ebfffed7e6e4 uplink_id=34d5f339-a1c4-4374-8fb1-1673b2c234d6
ns: time="2022-03-02T03:22:41.506105913Z" level=info msg="uplink: frame(s) collected" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 mtype=JoinRequest uplink_ids="[34d5f339-a1c4-4374-8fb1-1673b2c234d6]"
ns: time="2022-03-02T03:22:41.661447048Z" level=info msg="lorawan/backend: finished backend api call" message_type=JoinReq protocol_version=1.0 receiver_id=0000000000000000 result_code=Success sender_id=000000 transaction_id=187779681
ns: time="2022-03-02T03:22:41.669978781Z" level=info msg="sent uplink meta-data to network-controller" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:41.677317551Z" level=info msg="device-queue flushed" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:41.687746224Z" level=info msg="device-session saved" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:41.705809659Z" level=info msg="device-activation created" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 dev_eui=3236500700160026 id=1063
ns: time="2022-03-02T03:22:41.716904311Z" level=info msg="device updated" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:41.726039025Z" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
ns: time="2022-03-02T03:22:41.745245424Z" level=info msg="storage: downlink-frame saved" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 token=50642
------> ns: time="2022-03-02T03:22:41.761914901Z" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535 gateway_id=b827ebfffed7e6e4
ns: time="2022-03-02T03:22:41.781753280Z" level=info msg="sent downlink meta-data to network-controller" ctx_id=795fcae2-a24a-4f49-b8d3-60e0ca3f0535
FCnt 0
ns: time="2022-03-02T03:22:49.236545186Z" level=info msg="gateway/mqtt: uplink frame received" gateway_id=b827ebfffed7e6e4 uplink_id=3d626ee7-52c4-4e21-95ed-442f665a9918
ns: time="2022-03-02T03:22:49.465267739Z" level=info msg="uplink: frame(s) collected" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd mtype=ConfirmedDataUp uplink_ids="[3d626ee7-52c4-4e21-95ed-442f665a9918]"
ns: time="2022-03-02T03:22:49.569812964Z" level=info msg="sent uplink meta-data to network-controller" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd dev_eui=3236500700160026
ns: time="2022-03-02T03:22:49.581033451Z" level=info msg="device gateway rx-info meta-data saved" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd dev_eui=3236500700160026
ns: time="2022-03-02T03:22:49.602659464Z" level=info msg="device-session saved" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:49.750499711Z" level=info msg="finished client unary call" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd grpc.code=OK grpc.ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f grpc.duration=163.189546ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
ns: time="2022-03-02T03:22:49.776026545Z" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=79cb52e5-294d-4041-bc09-855a5adf21dd gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
ns: time="2022-03-02T03:22:49.813452835Z" level=info msg="device-session saved" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd dev_addr=01f8eea2 dev_eui=3236500700160026
-----> ns: time="2022-03-02T03:22:49.822347429Z" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=79cb52e5-294d-4041-bc09-855a5adf21dd gateway_id=b827ebfffed7e6e4
ns: time="2022-03-02T03:22:49.847309289Z" level=info msg="storage: downlink-frame saved" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd token=31179
ns: time="2022-03-02T03:22:49.862989573Z" level=info msg="device-session saved" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:49.870309238Z" level=info msg="sent downlink meta-data to network-controller" ctx_id=79cb52e5-294d-4041-bc09-855a5adf21dd
FCnt 1
ns: time="2022-03-02T03:22:53.351669109Z" level=info msg="gateway/mqtt: uplink frame received" gateway_id=b827ebfffed7e6e4 uplink_id=a9ee3c59-2088-4786-ab53-cfc00a3d5578
ns: time="2022-03-02T03:22:53.594831415Z" level=info msg="uplink: frame(s) collected" ctx_id=41916195-326e-4f28-9526-13ef4c878933 mtype=ConfirmedDataUp uplink_ids="[a9ee3c59-2088-4786-ab53-cfc00a3d5578]"
ns: time="2022-03-02T03:22:53.652651396Z" level=info msg="device gateway rx-info meta-data saved" ctx_id=41916195-326e-4f28-9526-13ef4c878933 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:53.662736870Z" level=info msg="sent uplink meta-data to network-controller" ctx_id=41916195-326e-4f28-9526-13ef4c878933 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:53.704875670Z" level=info msg="device-session saved" ctx_id=41916195-326e-4f28-9526-13ef4c878933 dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:53.799708719Z" level=info msg="finished client unary call" ctx_id=41916195-326e-4f28-9526-13ef4c878933 grpc.code=OK grpc.ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad grpc.duration=138.318779ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
ns: time="2022-03-02T03:22:53.837449749Z" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=41916195-326e-4f28-9526-13ef4c878933 gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
----> ns: time="2022-03-02T03:22:53.887277148Z" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=41916195-326e-4f28-9526-13ef4c878933 gateway_id=b827ebfffed7e6e4
ns: time="2022-03-02T03:22:53.895231733Z" level=info msg="device-session saved" ctx_id=41916195-326e-4f28-9526-13ef4c878933 dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:53.905574193Z" level=info msg="storage: downlink-frame saved" ctx_id=41916195-326e-4f28-9526-13ef4c878933 token=16785

ns: time="2022-03-02T03:22:56.247231193Z" level=info msg="gateway/mqtt: gateway stats packet received" gateway_id=b827ebfffed7e6e4 stats_id=58654513-85d9-49b2-a7ca-677906cf5b2d
ns: time="2022-03-02T03:22:56.307640759Z" level=info msg="storage: gateway state updated" ctx_id=58654513-85d9-49b2-a7ca-677906cf5b2d gateway_id=b827ebfffed7e6e4
ns: time="2022-03-02T03:22:56.423147194Z" level=info msg="finished client unary call" ctx_id=58654513-85d9-49b2-a7ca-677906cf5b2d grpc.code=OK grpc.ctx_id=fd097867-19e6-4904-8604-2bdc3f5b304c grpc.duration=81.738354ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc

FCnt 2
ns: time="2022-03-02T03:22:56.957286836Z" level=info msg="gateway/mqtt: uplink frame received" gateway_id=b827ebfffed7e6e4 uplink_id=86939234-2e54-4ff9-b193-ce0972f4a705
ns: time="2022-03-02T03:22:57.199717779Z" level=info msg="uplink: frame(s) collected" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f mtype=ConfirmedDataUp uplink_ids="[86939234-2e54-4ff9-b193-ce0972f4a705]"
ns: time="2022-03-02T03:22:57.238074541Z" level=info msg="device gateway rx-info meta-data saved" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f dev_eui=3236500700160026
ns: time="2022-03-02T03:22:57.244401172Z" level=info msg="device-session saved" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:57.248416938Z" level=info msg="sent uplink meta-data to network-controller" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f dev_eui=3236500700160026
ns: time="2022-03-02T03:22:57.408944574Z" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=e158db29-846d-47f0-81c2-b40ff652b89f gateway_id=b827ebfffed7e6e4 qos=0 topic=gateway/b827ebfffed7e6e4/command/down
ns: time="2022-03-02T03:22:57.449817190Z" level=info msg="device-session saved" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f dev_addr=01f8eea2 dev_eui=3236500700160026
----> ns: time="2022-03-02T03:22:57.480867378Z" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=e158db29-846d-47f0-81c2-b40ff652b89f gateway_id=b827ebfffed7e6e4
ns: time="2022-03-02T03:22:57.510334660Z" level=info msg="storage: downlink-frame saved" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f token=57688
ns: time="2022-03-02T03:22:57.515877336Z" level=info msg="finished client unary call" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f grpc.code=OK grpc.ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 grpc.duration=268.411342ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
ns: time="2022-03-02T03:22:57.538397023Z" level=info msg="device-session saved" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f dev_addr=01f8eea2 dev_eui=3236500700160026
ns: time="2022-03-02T03:22:57.545114631Z" level=info msg="sent downlink meta-data to network-controller" ctx_id=e158db29-846d-47f0-81c2-b40ff652b89f

AS log:

JOIN
as: time="2022-03-02T03:22:41.60104294Z" level=info msg="backend/joinserver: request received" message_type=JoinReq receiver_id=0000000000000000 sender_id=000000 transaction_id=187779681
as: time="2022-03-02T03:22:41.645955533Z" level=info msg="device-keys updated" ctx_id="<nil>" dev_eui=3236500700160026
as: time="2022-03-02T03:22:41.649984407Z" level=info msg="backend/joinserver: sending response" dev_eui=3236500700160026 message_type=JoinAns receiver_id=000000 result_code=Success sender_id=0000000000000000 transaction_id=187779681

FCnt 0
as: time="2022-03-02T03:22:49.639972759Z" level=info msg="device last-seen and dr updated" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_eui=3236500700160026
as: time="2022-03-02T03:22:49.656400009Z" level=info msg="device activation updated" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_addr=01f8eea2 dev_eui=3236500700160026
as: time="2022-03-02T03:22:49.67782403Z" level=info msg="integration/logger: logging event" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_eui=3236500700160026 type=join
as: time="2022-03-02T03:22:49.685525679Z" level=info msg="integration/mqtt: publishing event" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_eui=3236500700160026 qos=0 retain=false topic=application/1/device/3236500700160026/event/join
as: time="2022-03-02T03:22:49.705088785Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f name="device:3236500700160026"
as: time="2022-03-02T03:22:49.70803565Z" level=info msg="finished unary call with code OK" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2022-03-02T03:22:50Z" grpc.service=as.ApplicationServerService grpc.start_time="2022-03-02T03:22:49Z" grpc.time_ms=115.714 peer.address="[::1]:34810" span.kind=server system=grpc
as: time="2022-03-02T03:22:49.737546303Z" level=info msg="integration/mqtt: publishing event" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_eui=3236500700160026 qos=0 retain=false topic=application/1/device/3236500700160026/event/up
as: time="2022-03-02T03:22:49.727159777Z" level=info msg="integration/logger: logging event" ctx_id=8aae7825-2f8c-42ea-8c79-ff4a52488b6f dev_eui=3236500700160026 type=up

FCnt 1
as: time="2022-03-02T03:22:53.733138195Z" level=info msg="device last-seen and dr updated" ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad dev_eui=3236500700160026
as: time="2022-03-02T03:22:53.766436456Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad name="device:3236500700160026"
as: time="2022-03-02T03:22:53.782219632Z" level=info msg="finished unary call with code OK" ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2022-03-02T03:22:54Z" grpc.service=as.ApplicationServerService grpc.start_time="2022-03-02T03:22:53Z" grpc.time_ms=109.813 peer.address="[::1]:34810" span.kind=server system=grpc
as: time="2022-03-02T03:22:53.786225423Z" level=info msg="integration/mqtt: publishing event" ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad dev_eui=3236500700160026 qos=0 retain=false topic=application/1/device/3236500700160026/event/up
as: time="2022-03-02T03:22:53.781796654Z" level=info msg="integration/logger: logging event" ctx_id=91296d51-e78c-481f-b9e4-a2c649fac3ad dev_eui=3236500700160026 type=up
as: time="2022-03-02T03:22:56.371597124Z" level=info msg="gateway updated" ctx_id=fd097867-19e6-4904-8604-2bdc3f5b304c id=b827ebfffed7e6e4 name=local
as: time="2022-03-02T03:22:56.410356921Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=fd097867-19e6-4904-8604-2bdc3f5b304c name="gw:b827ebfffed7e6e4"
as: time="2022-03-02T03:22:56.414622679Z" level=info msg="finished unary call with code OK" ctx_id=fd097867-19e6-4904-8604-2bdc3f5b304c grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService grpc.start_time="2022-03-02T03:22:56Z" grpc.time_ms=66.776 peer.address="[::1]:34810" span.kind=server system=grpc

FCnt 2
as: time="2022-03-02T03:22:57.316915942Z" level=info msg="device last-seen and dr updated" ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 dev_eui=3236500700160026
as: time="2022-03-02T03:22:57.378475351Z" level=info msg="integration/logger: logging event" ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 dev_eui=3236500700160026 type=up
as: time="2022-03-02T03:22:57.430923292Z" level=info msg="integration/mqtt: publishing event" ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 dev_eui=3236500700160026 qos=0 retain=false topic=application/1/device/3236500700160026/event/up
as: time="2022-03-02T03:22:57.478729503Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 name="device:3236500700160026"
as: time="2022-03-02T03:22:57.497619401Z" level=info msg="finished unary call with code OK" ctx_id=247797fc-8d1b-4d52-a02c-1f1bca3734b7 grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2022-03-02T03:22:58Z" grpc.service=as.ApplicationServerService grpc.start_time="2022-03-02T03:22:57Z" grpc.time_ms=245.256 peer.address="[::1]:34810" span.kind=server system=grpc

Redis content for the gateway key, where we can see there is no "down" message for FCnt 1 (although it was acknowledged).

127.0.0.1:6379> XRANGE lora:ns:gw:b827ebfffed7e6e4:stream:frame - +
JOIN
1) 1) "1646191361510-0" 03:22:41
   2) 1) "up"
      2) '0a1700000000000000000026001600075036328e87b64d12ae121108d8f3c6ce011a09087d100c1a03342f351a3e0a08b827ebfffed7e6e428ddffffffffffffffff0131666666666666204040015a007a04987365d482011034d5f339a1c443748fb11673b2c234d6880102320832365007001600263a0c0881c6fb90061082b5d4f201'
2) 1) "1646191361780-0" 03:22:41
   2) 1) "down"
      2) '0a1120f8d984c5e951a5102091324e2be3d389122428d8f3c6ce01300a6001820104987365d4420b087d100c1a03342f35200172040a02080518d28b032210795fcae2a24a4f49b8d360e0ca3f05352a08b827ebfffed7e6e43001420832365007001600264a0c0881c6fb9006108b9892f302'

FCnt 0
3) 1) "1646191369473-0" 03:22:49
   2) 1) "up"
      2) '0a1380a2eef8010000000a6c0e6a840f2297a4293c121108d8f3c6ce011a09087d100c1a03342f351a3e0a08b827ebfffed7e6e428dfffffffffffffffff0131000000000000214040015a007a0498ec81b48201103d626ee752c44e2195ed442f665a991888010220042a0401f8eea23a0c0889c6fb900610b793f3df01'
4) 1) "1646191369869-0" 03:22:49
   2) 1) "down"
      2) '0a0c60a2eef80120000046f8bcdf122428d8f3c6ce01300a600182010498ec81b4420b087d100c1a03342f35200172040a02080118cbf301221079cb52e5294d4041bc09855a5adf21dd2a08b827ebfffed7e6e430033a0401f8eea2420832365007001600264a0c0889c6fb900610d1fcbb9d03'
FCnt 1
      5) 1) "1646191373616-0" 03:22:53
   2) 1) "up"
      2) '0a2180a2eef8010001001435d51141cf38a653cae137ac4cf60f1bbc1549871ec50586121108d8a8dfce011a09087d100c1a03342f351a400a08b827ebfffed7e6e428e4ffffffffffffffff01310000000000002140380240015a007a04992b37c4820110a9ee3c5920884786ab53cfc00a3d557888010220042a0401f8eea23a0c088dc6fb900610b6ff91a502'
FCnt 2
6) 1) "1646191377206-0" 03:22:57 
   2) 1) "up"
      2) '0a1380a2eef8010002000aa8d45602070928821714121108d8f3c6ce011a09087d100c1a03342f351a3e0a08b827ebfffed7e6e428dfffffffffffffffff0131666666666666204040015a007a04996266bc820110869392342e544ff9b193ce0972f4a70588010220042a0401f8eea23a0b0891c6fb90061081e8fe61'
7) 1) "1646191377544-0" 03:22:57
   2) 1) "down"
      2) '0a0c60a2eef8012001009752c094122428d8f3c6ce01300a6001820104996266bc420b087d100c1a03342f35200172040a02080118d8c2032210e158db29846d47f081c2b40ff652b89f2a08b827ebfffed7e6e430033a0401f8eea2420832365007001600264a0c0891c6fb900610f0bca48202'

MQTT output from: mosquitto_sub -t "application/1/device/3236500700160026/#" -t "gateway/b827ebfffed7e6e4/event/#" -T "gateway/b827ebfffed7e6e4/event/stats" -v -F "%I %t %p":

JOIN
2022-03-02T03:22:41+0000 gateway/b827ebfffed7e6e4/event/up 
&P62???M????   }
                4/5<
?'??????(?????????1ffffff @@z?seԂ4??9??Ct??s??4ֈ

2022-03-02T03:22:41+0000 gateway/b827ebfffed7e6e4/event/ack 
?'??????ҋ"y_??JOI??`???5*

FCnt 0 UP (gateway)
2022-03-02T03:22:49+0000 gateway/b827ebfffed7e6e4/event/up 
????
lj?"??)????    }
                4/5<
?'??????(?????????1!@@z?쁴?=bn?R?N!??D/fZ??
2022-03-02T03:22:49+0000 application/1/device/3236500700160026/event/join {"applicationID":"1","applicationName":"MuninSensing","deviceName":"Nucleo-1","devEUI":"MjZQBwAWACY=","devAddr":"Afjuog==","rxInfo":[{"gatewayID":"uCfr//7X5uQ=","time":null,"timeSinceGPSEpoch":null,"rssi":-33,"loRaSNR":8.5,"channel":0,"rfChain":1,"board":0,"antenna":0,"location":{"latitude":0,"longitude":0,"altitude":0,"source":"UNKNOWN","accuracy":0},"fineTimestampType":"NONE","context":"mOyBtA==","uplinkID":"PWJu51LETiGV7UQvZlqZGA==","crcStatus":"CRC_OK"}],"txInfo":{"frequency":433175000,"modulation":"LORA","loRaModulationInfo":{"bandwidth":125,"spreadingFactor":12,"codeRate":"4/5","polarizationInversion":false}},"dr":0,"tags":{},"publishedAt":"2022-03-02T03:22:49.660025843Z"}

FCnt 0 UP (from AS)
2022-03-02T03:22:49+0000 application/1/device/3236500700160026/event/up {"applicationID":"1","applicationName":"MuninSensing","deviceName":"Nucleo-1","devEUI":"MjZQBwAWACY=","rxInfo":[{"gatewayID":"uCfr//7X5uQ=","time":null,"timeSinceGPSEpoch":null,"rssi":-33,"loRaSNR":8.5,"channel":0,"rfChain":1,"board":0,"antenna":0,"location":{"latitude":0,"longitude":0,"altitude":0,"source":"UNKNOWN","accuracy":0},"fineTimestampType":"NONE","context":"mOyBtA==","uplinkID":"PWJu51LETiGV7UQvZlqZGA==","crcStatus":"CRC_OK"}],"txInfo":{"frequency":433175000,"modulation":"LORA","loRaModulationInfo":{"bandwidth":125,"spreadingFactor":12,"codeRate":"4/5","polarizationInversion":false}},"adr":false,"dr":0,"fCnt":0,"fPort":10,"data":"zuIeYgEA","objectJSON":"{\"fPort\":10,\"frame_number\":1,\"size\":0,\"timestamp\":0}","tags":{},"confirmedUplink":true,"devAddr":"Afjuog==","publishedAt":"2022-03-02T03:22:49.692630354Z","deviceProfileID":"8917dda4-c938-4449-a5d1-45e5bcfda112","deviceProfileName":"Munin Sensor"}

FCnt 0 ACK to NS
2022-03-02T03:22:49+0000 gateway/b827ebfffed7e6e4/event/ack 
?'????????"y?R?)M@A?    ?ZZ?!?*

FCnt 1 UP (gateway)
2022-03-02T03:22:53+0000 gateway/b827ebfffed7e6e4/event/up 
!????5?A?8?S??7?L?I??ب??       }
                                4/5>
?'??????(?????????1!@8@z?+7Ă??<Y ?G??S??
=Ux?

FCnt 1 UP (AS)
2022-03-02T03:22:53+0000 application/1/device/3236500700160026/event/up {"applicationID":"1","applicationName":"MuninSensing","deviceName":"Nucleo-1","devEUI":"MjZQBwAWACY=","rxInfo":[{"gatewayID":"uCfr//7X5uQ=","time":null,"timeSinceGPSEpoch":null,"rssi":-28,"loRaSNR":8.5,"channel":2,"rfChain":1,"board":0,"antenna":0,"location":{"latitude":0,"longitude":0,"altitude":0,"source":"UNKNOWN","accuracy":0},"fineTimestampType":"NONE","context":"mSs3xA==","uplinkID":"qe48WSCIR4arU8/ACj1VeA==","crcStatus":"CRC_OK"}],"txInfo":{"frequency":433575000,"modulation":"LORA","loRaModulationInfo":{"bandwidth":125,"spreadingFactor":12,"codeRate":"4/5","polarizationInversion":false}},"adr":false,"dr":0,"fCnt":1,"fPort":20,"data":"zuIeYgIHDwsHBZgFlwPaBVkFTwA=","objectJSON":"{\"fPort\":20,\"frame_number\":2,\"size\":7,\"timestamp\":0}","tags":{},"confirmedUplink":true,"devAddr":"Afjuog==","publishedAt":"2022-03-02T03:22:53.752886164Z","deviceProfileID":"8917dda4-c938-4449-a5d1-45e5bcfda112","deviceProfileName":"Munin Sensor"}

FCnt 1 ACK to NS
2022-03-02T03:22:53+0000 gateway/b827ebfffed7e6e4/event/ack 
?'????????"A?a?2nO(?&?L??3*

FCnt 2 UP (gateway)
2022-03-02T03:22:56+0000 gateway/b827ebfffed7e6e4/event/up 
????
??V (????  }
                4/5<
?'??????(?????????1ffffff @@z?bf?????4.TO????   r???

FCnt 2 UP (AS)
2022-03-02T03:22:57+0000 application/1/device/3236500700160026/event/up {"applicationID":"1","applicationName":"MuninSensing","deviceName":"Nucleo-1","devEUI":"MjZQBwAWACY=","rxInfo":[{"gatewayID":"uCfr//7X5uQ=","time":null,"timeSinceGPSEpoch":null,"rssi":-33,"loRaSNR":8.2,"channel":0,"rfChain":1,"board":0,"antenna":0,"location":{"latitude":0,"longitude":0,"altitude":0,"source":"UNKNOWN","accuracy":0},"fineTimestampType":"NONE","context":"mWJmvA==","uplinkID":"hpOSNC5UT/mxk84JcvSnBQ==","crcStatus":"CRC_OK"}],"txInfo":{"frequency":433175000,"modulation":"LORA","loRaModulationInfo":{"bandwidth":125,"spreadingFactor":12,"codeRate":"4/5","polarizationInversion":false}},"adr":false,"dr":0,"fCnt":2,"fPort":10,"data":"1uIeYgMA","objectJSON":"{\"fPort\":10,\"frame_number\":3,\"size\":0,\"timestamp\":0}","tags":{},"confirmedUplink":true,"devAddr":"Afjuog==","publishedAt":"2022-03-02T03:22:57.349608035Z","deviceProfileID":"8917dda4-c938-4449-a5d1-45e5bcfda112","deviceProfileName":"Munin Sensor"}

FCnt 2 ACK to NS (although the Down command now contains FCnt_Down 1, as if the previous one wasn't ACK'd)
2022-03-02T03:22:57+0000 gateway/b827ebfffed7e6e4/event/ack 
?'????????"?X?)?mG??´?R??*

[jorgeig-space]

Updated title and description to match the problem more closely.

[jorgeig-space]

I've also just tried using the Chirpstack OS image (full) for Raspberry Pi Zero W. The problem still persists using the Chirpstack OS image, configured for EU433, with all the rest as default (no RAK forwarder, or any other application installed).

[jorgeig-space]

It turns out this only happens when running the full chirpstack stack in a Pi Zero W. When the same stack runs on a separate computer, with the RPi running the packet forwarder, everything works normally. Also tried with TTN and everything worked.

I am closing the issue, as it's not a bug per se, but if you have some free time I'll be happy to dig with you as to why this happens without any error messages. If you need a RPi Zero let me know :)