Duplicate DOWNLINKs got as UPLINKs

ChirpStack Network Server
1

I’m having strange duplicate DOWNLINKs coming as UPLINKs.

Background: there is an application server, two configured network servers, two configured gateways (currently just one for each network server) with the gateway bridge, three applications.

I don’t think this is an end-device issue because this happens with two different types of end devices (one is using OTAA and one is using ABP).

shot
shot1267×697 121 KB

Here are the logs from the relevant time-frame (with some redactions for privacy):

Application and Network servers:

12:15:27 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:27+04:00" level=info msg="finished unary call with code OK" ctx_id=d71d0ada-5110-4534-a216-0208d4a03ee9 grpc.code=OK grpc.method=Get grpc.service=api.OrganizationService grpc.start_time="2020-05-04T16:15:27+04:00" grpc.time_ms=2.784 peer.address="127.0.0.1:54078" span.kind=server system=grpc
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=83891bed-7afe-4d5d-8b7e-fb41169facaa
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="uplink: frame(s) collected" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 mtype=JoinRequest uplink_ids="[83891bed-7afe-4d5d-8b7e-fb41169facaa]"
12:15:35 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:35+04:00" level=info msg="backend/joinserver: request received" message_type=JoinReq receiver_id=0000000000000000 sender_id=zzzzzz transaction_id=2287457075
12:15:35 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:35+04:00" level=info msg="device-keys updated" ctx_id="<nil>" dev_eui=xxxxxxxxxxxx0001
12:15:35 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:35+04:00" level=info msg="backend/joinserver: sending response" message_type=JoinAns receiver_id=zzzzzz result_code=Success sender_id=0000000000000000 transaction_id=2287457075
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 dev_eui=xxxxxxxxxxxx0001
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="device-queue flushed" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 dev_eui=xxxxxxxxxxxx0001
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="device-session saved" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 dev_addr=d43bbb43 dev_eui=xxxxxxxxxxxx0001
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="device-activation created" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 dev_eui=xxxxxxxxxxxx0001 id=41
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="device updated" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 dev_eui=xxxxxxxxxxxx0001
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=24076a2f-41bb-4fb1-9183-10083e960e07 gateway_id=gggggggggggg0001 qos=0 topic=gateway/ru864/gggggggggggg0001/command/down
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="downlink-frames saved" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07 token=3210
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=24076a2f-41bb-4fb1-9183-10083e960e07 gateway_id=gggggggggggg0001
12:15:35 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:35+04:00" level=info msg="sent downlink meta-data to network-controller" ctx_id=24076a2f-41bb-4fb1-9183-10083e960e07
12:15:41 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:41+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=d9a0b06c-06ef-45dc-b5df-5bb9bc961bf5
12:15:42 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:42+04:00" level=info msg="uplink: frame(s) collected" ctx_id=793df7ea-515a-4f5b-bb3b-f246dd36dd74 mtype=JoinAccept uplink_ids="[d9a0b06c-06ef-45dc-b5df-5bb9bc961bf5]"
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=15b83ff1-dc9c-456b-9ecb-923a8b761764
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="uplink: frame(s) collected" ctx_id=515b72eb-3a73-4f04-a711-46429b4ad20b mtype=UnconfirmedDataUp uplink_ids="[15b83ff1-dc9c-456b-9ecb-923a8b761764]"
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=515b72eb-3a73-4f04-a711-46429b4ad20b dev_eui=xxxxxxxxxxxx0001
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=515b72eb-3a73-4f04-a711-46429b4ad20b dev_eui=xxxxxxxxxxxx0001
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="device-session saved" ctx_id=515b72eb-3a73-4f04-a711-46429b4ad20b dev_addr=d43bbb43 dev_eui=xxxxxxxxxxxx0001
12:15:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:43+04:00" level=info msg="device last-seen and dr updated" ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb dev_eui=xxxxxxxxxxxx0001
12:15:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:43+04:00" level=info msg="device activation updated" ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb dev_addr=d43bbb43 dev_eui=xxxxxxxxxxxx0001
12:15:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:43+04:00" level=info msg="finished unary call with code OK" ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2020-05-04T16:15:44+04:00" grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:15:43+04:00" grpc.time_ms=42.691 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:15:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:43+04:00" level=info msg="finished client unary call" ctx_id=515b72eb-3a73-4f04-a711-46429b4ad20b grpc.code=OK grpc.ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb grpc.duration=45.862677ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:15:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:43+04:00" level=info msg="integration/mqtt: publishing message" ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb qos=0 topic=application/4/device/xxxxxxxxxxxx0001/join
12:15:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:43+04:00" level=info msg="integration/mqtt: publishing message" ctx_id=e82f83ab-680d-4bea-93c8-d4b97e0b0adb qos=0 topic=application/4/device/xxxxxxxxxxxx0001/rx
12:15:47 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:47+04:00" level=info msg="gateway/mqtt: gateway stats packet received" gateway_id=gggggggggggg0001 stats_id=5c031a32-c1f4-4e31-96ca-318dc54cbc34
12:15:47 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:47+04:00" level=info msg="gateway updated" ctx_id=5c031a32-c1f4-4e31-96ca-318dc54cbc34 gateway_id=gggggggggggg0001
12:15:47 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:47+04:00" level=info msg="gateway updated" ctx_id=36f29f9c-9672-420b-a0f0-9aaeb8b1ba63 id=gggggggggggg0001 name=GGGGGG0001
12:15:47 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:47+04:00" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=36f29f9c-9672-420b-a0f0-9aaeb8b1ba63 name="gw:gggggggggggg0001"
12:15:47 app-server chirpstack-application-server[1293]: time="2020-05-04T16:15:47+04:00" level=info msg="finished unary call with code OK" ctx_id=36f29f9c-9672-420b-a0f0-9aaeb8b1ba63 grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:15:47+04:00" grpc.time_ms=17.908 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:15:47 app-server chirpstack-network-server[861]: time="2020-05-04T16:15:47+04:00" level=info msg="finished client unary call" ctx_id=5c031a32-c1f4-4e31-96ca-318dc54cbc34 grpc.code=OK grpc.ctx_id=36f29f9c-9672-420b-a0f0-9aaeb8b1ba63 grpc.duration=18.969047ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=d29d1c3c-ebf8-46e2-9ca7-1b39d89e7c3e
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="uplink: frame(s) collected" ctx_id=ec31d707-785b-4e89-9ac9-1f98e5fb5f24 mtype=UnconfirmedDataUp uplink_ids="[d29d1c3c-ebf8-46e2-9ca7-1b39d89e7c3e]"
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=ec31d707-785b-4e89-9ac9-1f98e5fb5f24 dev_eui=xxxxxxxxxxxx0001
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=ec31d707-785b-4e89-9ac9-1f98e5fb5f24 dev_eui=xxxxxxxxxxxx0001
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="device-session saved" ctx_id=ec31d707-785b-4e89-9ac9-1f98e5fb5f24 dev_addr=d43bbb43 dev_eui=xxxxxxxxxxxx0001
12:16:13 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:13+04:00" level=info msg="device last-seen and dr updated" ctx_id=dbccf4ff-ee64-46f9-9d2a-6b7363ca919c dev_eui=xxxxxxxxxxxx0001
12:16:13 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:13+04:00" level=info msg="finished unary call with code OK" ctx_id=dbccf4ff-ee64-46f9-9d2a-6b7363ca919c grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2020-05-04T16:16:14+04:00" grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:16:13+04:00" grpc.time_ms=28.225 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="finished client unary call" ctx_id=ec31d707-785b-4e89-9ac9-1f98e5fb5f24 grpc.code=OK grpc.ctx_id=dbccf4ff-ee64-46f9-9d2a-6b7363ca919c grpc.duration=30.110363ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:16:13 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:13+04:00" level=info msg="integration/mqtt: publishing message" ctx_id=dbccf4ff-ee64-46f9-9d2a-6b7363ca919c qos=0 topic=application/4/device/xxxxxxxxxxxx0001/rx
12:16:13 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:13+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=ed63e9c0-c6b8-4df2-8226-0bed6553ebd6
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="uplink: frame(s) collected" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 mtype=ConfirmedDataUp uplink_ids="[ed63e9c0-c6b8-4df2-8226-0bed6553ebd6]"
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 dev_eui=xxxxxxxxxxxxxx03
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 dev_eui=xxxxxxxxxxxxxx03
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="device-session saved" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 dev_addr=70388802 dev_eui=xxxxxxxxxxxxxx03
12:16:14 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:14+04:00" level=info msg="device last-seen and dr updated" ctx_id=56eda4db-64eb-4a35-b815-1ef16d1ad0f6 dev_eui=xxxxxxxxxxxxxx03
12:16:14 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:14+04:00" level=info msg="finished unary call with code OK" ctx_id=56eda4db-64eb-4a35-b815-1ef16d1ad0f6 grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2020-05-04T16:16:15+04:00" grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:16:14+04:00" grpc.time_ms=18.081 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="finished client unary call" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 grpc.code=OK grpc.ctx_id=56eda4db-64eb-4a35-b815-1ef16d1ad0f6 grpc.duration=19.799426ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:16:14 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:14+04:00" level=info msg="integration/mqtt: publishing message" ctx_id=56eda4db-64eb-4a35-b815-1ef16d1ad0f6 qos=0 topic=application/1/device/xxxxxxxxxxxxxx03/rx
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="gateway/mqtt: publishing gateway command" command=down downlink_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 gateway_id=gggggggggggg0001 qos=0 topic=gateway/ru864/gggggggggggg0001/command/down
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="device-session saved" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 dev_addr=70388802 dev_eui=xxxxxxxxxxxxxx03
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="downlink-frames saved" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 token=57246
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="backend/gateway: downlink tx acknowledgement received" downlink_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 gateway_id=gggggggggggg0001
12:16:14 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:14+04:00" level=info msg="sent downlink meta-data to network-controller" ctx_id=df9e3f46-3456-480a-a35b-4bbf409bbb11
12:16:15 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:15+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=d3020192-3f4f-49b7-995e-94dec0939138
12:16:16 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:16+04:00" level=info msg="uplink: frame(s) collected" ctx_id=c3af588a-8113-4b93-8700-0d7270f3b9c0 mtype=UnconfirmedDataDown uplink_ids="[d3020192-3f4f-49b7-995e-94dec0939138]"
12:16:17 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:17+04:00" level=info msg="gateway/mqtt: gateway stats packet received" gateway_id=gggggggggggg0001 stats_id=725bcac9-25bc-4188-941b-918ab11fa1ae
12:16:17 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:17+04:00" level=info msg="gateway updated" ctx_id=725bcac9-25bc-4188-941b-918ab11fa1ae gateway_id=gggggggggggg0001
12:16:17 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:17+04:00" level=info msg="gateway updated" ctx_id=b8774c72-ff84-491b-8158-c01d3324e769 id=gggggggggggg0001 name=GGGGGG0001
12:16:17 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:17+04:00" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=b8774c72-ff84-491b-8158-c01d3324e769 name="gw:gggggggggggg0001"
12:16:17 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:17+04:00" level=info msg="finished unary call with code OK" ctx_id=b8774c72-ff84-491b-8158-c01d3324e769 grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:16:17+04:00" grpc.time_ms=17.907 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:16:17 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:17+04:00" level=info msg="finished client unary call" ctx_id=725bcac9-25bc-4188-941b-918ab11fa1ae grpc.code=OK grpc.ctx_id=b8774c72-ff84-491b-8158-c01d3324e769 grpc.duration=18.909007ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:16:42 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:42+04:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=gggggggggggg0001 uplink_id=40d2c5a2-0118-4c40-9815-0f6e1f264f4d
12:16:42 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:42+04:00" level=info msg="uplink: frame(s) collected" ctx_id=b57d5f2a-df54-4272-bfad-56866c54e508 mtype=UnconfirmedDataUp uplink_ids="[40d2c5a2-0118-4c40-9815-0f6e1f264f4d]"
12:16:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:43+04:00" level=info msg="sent uplink meta-data to network-controller" ctx_id=b57d5f2a-df54-4272-bfad-56866c54e508 dev_eui=xxxxxxxxxxxx0001
12:16:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:43+04:00" level=info msg="device gateway rx-info meta-data saved" ctx_id=b57d5f2a-df54-4272-bfad-56866c54e508 dev_eui=xxxxxxxxxxxx0001
12:16:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:43+04:00" level=info msg="device-session saved" ctx_id=b57d5f2a-df54-4272-bfad-56866c54e508 dev_addr=d43bbb43 dev_eui=xxxxxxxxxxxx0001
12:16:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:43+04:00" level=info msg="device last-seen and dr updated" ctx_id=ff1d0845-6d93-4c16-a90c-7e9acc4d3080 dev_eui=xxxxxxxxxxxx0001
12:16:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:43+04:00" level=info msg="integration/mqtt: publishing message" ctx_id=ff1d0845-6d93-4c16-a90c-7e9acc4d3080 qos=0 topic=application/4/device/xxxxxxxxxxxx0001/rx
12:16:43 app-server chirpstack-application-server[1293]: time="2020-05-04T16:16:43+04:00" level=info msg="finished unary call with code OK" ctx_id=ff1d0845-6d93-4c16-a90c-7e9acc4d3080 grpc.code=OK grpc.method=HandleUplinkData grpc.request.deadline="2020-05-04T16:16:44+04:00" grpc.service=as.ApplicationServerService grpc.start_time="2020-05-04T16:16:43+04:00" grpc.time_ms=23.022 peer.address="127.0.0.1:54072" span.kind=server system=grpc
12:16:43 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:43+04:00" level=info msg="finished client unary call" ctx_id=b57d5f2a-df54-4272-bfad-56866c54e508 grpc.code=OK grpc.ctx_id=ff1d0845-6d93-4c16-a90c-7e9acc4d3080 grpc.duration=27.092559ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService span.kind=client system=grpc
12:16:47 app-server chirpstack-network-server[861]: time="2020-05-04T16:16:47+04:00" level=info msg="gateway/mqtt: gateway stats packet received" gateway_id=gggggggggggg0001 stats_id=bed6cd07-6866-4b65-953d-bc8b73eb80e8

Gateway Bridge and Packet Forwarder

12:15:35 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:35Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=83891bed-7afe-4d5d-8b7e-fb41169facaa
12:15:35 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:35Z" level=info msg="integration/mqtt: downlink frame received" downlink_id=24076a2f-41bb-4fb1-9183-10083e960e07 gateway_id=gggggggggggg0001
12:15:35 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:35Z" level=info msg="integration/mqtt: publishing event" downlink_id=24076a2f-41bb-4fb1-9183-10083e960e07 event=ack qos=0 topic=gateway/ru864/gggggggggggg0001/event/ack
12:15:41 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:41Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=d9a0b06c-06ef-45dc-b5df-5bb9bc961bf5
12:15:43 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:43Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=15b83ff1-dc9c-456b-9ecb-923a8b761764
12:15:47 gateway lora_pkt_fwd[1140]: ### [UPSTREAM] ###
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets received by concentrator: 7
12:15:47 gateway lora_pkt_fwd[1140]: # CRC_OK: 85.71%, CRC_FAIL: 14.29%, NO_CRC: 0.00%
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets forwarded: 6 (84 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # PUSH_DATA datagrams sent: 7 (1295 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # PUSH_DATA acknowledged: 100.00%
12:15:47 gateway lora_pkt_fwd[1140]: ### [DOWNSTREAM] ###
12:15:47 gateway lora_pkt_fwd[1140]: # PULL_DATA sent: 3 (100.00% acknowledged)
12:15:47 gateway lora_pkt_fwd[1140]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets sent to concentrator: 0 (0 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # TX errors: 0
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (collision packet): 0.00% (req:3, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (collision beacon): 0.00% (req:3, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (too late): 0.00% (req:3, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (too early): 0.00% (req:3, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON queued: 0
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON sent so far: 0
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON rejected: 0
12:15:47 gateway lora_pkt_fwd[1140]: ### [JIT] ###
12:15:47 gateway lora_pkt_fwd[1140]: # SX1301 time (PPS): 662432699
12:15:47 gateway lora_pkt_fwd[1140]: src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
12:15:47 gateway lora_pkt_fwd[1140]: ### [GPS] ###
12:15:47 gateway lora_pkt_fwd[1140]: # Invalid time reference (age: 1588594517 sec)
12:15:47 gateway lora_pkt_fwd[1140]: # no valid GPS coordinates available yet
12:15:47 gateway lora_pkt_fwd[1140]: ##### END #####
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"stat":{"time":"2020-05-04 12:15:17 GMT","rxnb":7,"rxok":6,"rxfw":6,"ackr":100.0,"dwnb":0,"txnb":0}}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Received pkt from mote: D43B1C90 (fcnt=13)
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"rxpk":[{"tmst":693654428,"chan":5,"rfch":1,"freq":868.900000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":-13.0,"rssi":-117,"size":14,"data":"=REDACTED-001="}]}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 1 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Received pkt from mote: D43B1C90 (fcnt=14)
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"rxpk":[{"tmst":697969044,"chan":6,"rfch":1,"freq":869.100000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":-12.5,"rssi":-115,"size":14,"data":"=REDACTED-002="}]}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [down] PULL_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [down] PULL_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Received pkt from mote: 00000000 (fcnt=0)
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"rxpk":[{"tmst":710748636,"chan":5,"rfch":1,"freq":868.900000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":-15.2,"rssi":-115,"size":23,"data":"=REDACTED-003="}]}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [down] PULL_RESP received  - token[138:12] :)
12:15:47 gateway lora_pkt_fwd[1140]: JSON down: {"txpk":{"imme":false,"rfch":0,"powe":14,"ant":0,"brd":0,"tmst":715748636,"freq":868.9,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"size":17,"data":"=REDACTED-004="}}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: tx_start_delay=1495 (1495.500000) - (1497, bw_delay=1.500000, notch_delay=0.000000)
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Received pkt from mote: 44A87E8B (fcnt=60771)
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"rxpk":[{"tmst":717067532,"chan":6,"rfch":1,"freq":869.100000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":2.5,"rssi":-111,"size":17,"data":"=REDACTED-004="}]}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 1 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [down] PULL_ACK received in 0 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Received pkt from mote: D43BBB43 (fcnt=1)
12:15:47 gateway lora_pkt_fwd[1140]: JSON up: {"rxpk":[{"tmst":718487548,"chan":5,"rfch":1,"freq":868.900000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":-12.8,"rssi":-117,"size":14,"data":"=REDACTED-005="}]}
12:15:47 gateway lora_pkt_fwd[1140]: INFO: [up] PUSH_ACK received in 1 ms
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Disabling GPS mode for concentrator's counter...
12:15:47 gateway lora_pkt_fwd[1140]: INFO: host/sx1301 time offset=(1588593824s:772088µs) - drift=41µs
12:15:47 gateway lora_pkt_fwd[1140]: INFO: Enabling GPS mode for concentrator's counter.
12:15:47 gateway lora_pkt_fwd[1140]: ##### 2020-05-04 12:15:47 GMT #####
12:15:47 gateway lora_pkt_fwd[1140]: ### [UPSTREAM] ###
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets received by concentrator: 6
12:15:47 gateway lora_pkt_fwd[1140]: # CRC_OK: 83.33%, CRC_FAIL: 16.67%, NO_CRC: 0.00%
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets forwarded: 5 (82 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # PUSH_DATA datagrams sent: 6 (1112 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # PUSH_DATA acknowledged: 100.00%
12:15:47 gateway lora_pkt_fwd[1140]: ### [DOWNSTREAM] ###
12:15:47 gateway lora_pkt_fwd[1140]: # PULL_DATA sent: 3 (100.00% acknowledged)
12:15:47 gateway lora_pkt_fwd[1140]: # PULL_RESP(onse) datagrams received: 1 (194 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # RF packets sent to concentrator: 1 (17 bytes)
12:15:47 gateway lora_pkt_fwd[1140]: # TX errors: 0
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (collision packet): 0.00% (req:4, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (collision beacon): 0.00% (req:4, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (too late): 0.00% (req:4, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # TX rejected (too early): 0.00% (req:4, rej:0)
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON queued: 0
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON sent so far: 0
12:15:47 gateway lora_pkt_fwd[1140]: # BEACON rejected: 0
12:15:47 gateway lora_pkt_fwd[1140]: ### [JIT] ###
12:15:47 gateway lora_pkt_fwd[1140]: # SX1301 time (PPS): 722432917
12:15:47 gateway lora_pkt_fwd[1140]: src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
12:15:47 gateway lora_pkt_fwd[1140]: ### [GPS] ###
12:15:47 gateway lora_pkt_fwd[1140]: # Invalid time reference (age: 1588594547 sec)
12:15:47 gateway lora_pkt_fwd[1140]: # no valid GPS coordinates available yet
12:15:47 gateway lora_pkt_fwd[1140]: ##### END #####
12:15:47 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:15:47Z" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=5c031a32-c1f4-4e31-96ca-318dc54cbc34 topic=gateway/ru864/gggggggggggg0001/event/stats
12:16:13 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:13Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=d29d1c3c-ebf8-46e2-9ca7-1b39d89e7c3e
12:16:13 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:13Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=ed63e9c0-c6b8-4df2-8226-0bed6553ebd6
12:16:14 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:14Z" level=info msg="integration/mqtt: downlink frame received" downlink_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 gateway_id=gggggggggggg0001
12:16:14 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:14Z" level=info msg="integration/mqtt: publishing event" downlink_id=df9e3f46-3456-480a-a35b-4bbf409bbb11 event=ack qos=0 topic=gateway/ru864/gggggggggggg0001/event/ack
12:16:15 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:15Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=d3020192-3f4f-49b7-995e-94dec0939138
12:16:17 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:17Z" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=725bcac9-25bc-4188-941b-918ab11fa1ae topic=gateway/ru864/gggggggggggg0001/event/stats
12:16:42 gateway chirpstack-gateway-bridge[599]: time="2020-05-04T12:16:42Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ru864/gggggggggggg0001/event/up uplink_id=40d2c5a2-0118-4c40-9815-0f6e1f264f4d
12:16:47 gateway lora_pkt_fwd[1140]: JSON up: {"stat":{"time":"2020-05-04 12:15:47 GMT","rxnb":6,"rxok":5,"rxfw":5,"ackr":100.0,"dwnb":1,"txnb":1}}
2

This can happen when your gateways does not use inverted iq polarity for downlinks. I’m not sure if/how server can affect this setting, can you validate proper channel setup on gateways?

3

Thank you for your reply.

Which settings should I validate? There is no mention of polarity neither in global_conf.json nor in chripstack-gateway-bridge.toml on the gateway configuration files.

I’m using this configuration file for the Packet Forwarder, the only difference in the “gateway_conf” section, here’s mine:

"gateway_conf": {
	"gps": true,
	"gps_tty_path": "/dev/ttyAMA0",
	"fake_gps": false,
	"server_address": "localhost",
	"serv_port_up": 1700,
	"serv_port_down": 1700,
	"keepalive_interval": 10,
	"push_timeout_ms": 100,
	"stat_interval": 30,
	"forward_crc_valid": true,
	"forward_crc_error": false,
	"forward_crc_disabled": false
}
4

Right, that looks ok. I see the polarity inversion should be the “ipol”:true option of the txpk, for example:

12:15:47 gateway lora_pkt_fwd[1140]: JSON down: {"txpk":{"imme":false,"rfch":0,"powe":14,"ant":0,"brd":0,"tmst":715748636,"freq":868.9,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"size":17,"data":"=REDACTED-004="}}

So that looks ok too, at least for this log.
I would also check the frame details in frame log then

5

This is the join request UPLINK:

{
  "uplinkFrame": {
    "txInfo": {
      "frequency": 869100000,
      "modulation": "LORA",
      "loRaModulationInfo": {
        "bandwidth": 125,
        "spreadingFactor": 12,
        "codeRate": "4/5",
        "polarizationInversion": false
      }
    },
    "rxInfo": [
      {
        "gatewayID": "=REDACTED-GWID=",
        "time": null,
        "timeSinceGPSEpoch": null,
        "rssi": -115,
        "loRaSNR": -21.2,
        "channel": 6,
        "rfChain": 1,
        "board": 0,
        "antenna": 0,
        "location": {
          "latitude": xx.xxxxx,
          "longitude": xx.xxxxx,
          "altitude": xxx,
          "source": "UNKNOWN",
          "accuracy": 0
        },
        "fineTimestampType": "NONE",
        "context": "f8S6TA==",
        "uplinkID": "dgeOYsYVQy+dSK8nNPUu7w==",
        "crcStatus": "CRC_OK"
      }
    ],
    "phyPayloadJSON": "{\"mhdr\":{\"mType\":\"JoinRequest\",\"major\":\"LoRaWANR1\"},\"macPayload\":{\"joinEUI\":\"0000000000000000\",\"devEUI\":\"xxxxxxxxxxxx0001\",\"devNonce\":1941},\"mic\":\"c4414819\"}"
  }
}

This is the join accept DOWNLINK:

{
  "downlinkFrame": {
    "txInfo": {
      "gatewayID": "=REDACTED-GWID=",
      "frequency": 869100000,
      "power": 14,
      "modulation": "LORA",
      "loRaModulationInfo": {
        "bandwidth": 125,
        "spreadingFactor": 12,
        "codeRate": "4/5",
        "polarizationInversion": true
      },
      "board": 0,
      "antenna": 0,
      "timing": "DELAY",
      "delayTimingInfo": {
        "delay": "5s"
      },
      "context": "f8S6TA=="
    },
    "phyPayloadJSON": "{\"mhdr\":{\"mType\":\"JoinAccept\",\"major\":\"LoRaWANR1\"},\"macPayload\":{\"bytes\":\"cYpwQXC5cpNgrgoR\"},\"mic\":\"61a1e331\"}"
  }
}

This is the duplicate join accept UPLINK:

{
  "uplinkFrame": {
    "txInfo": {
      "frequency": 868900000,
      "modulation": "LORA",
      "loRaModulationInfo": {
        "bandwidth": 125,
        "spreadingFactor": 12,
        "codeRate": "4/5",
        "polarizationInversion": false
      }
    },
    "rxInfo": [
      {
        "gatewayID": "=REDACTED-GWID=",
        "time": null,
        "timeSinceGPSEpoch": null,
        "rssi": -107,
        "loRaSNR": 1.2,
        "channel": 5,
        "rfChain": 1,
        "board": 0,
        "antenna": 0,
        "location": {
          "latitude": xx.xxxxx,
          "longitude": xx.xxxxx,
          "altitude": xxx,
          "source": "UNKNOWN",
          "accuracy": 0
        },
        "fineTimestampType": "NONE",
        "context": "gCUlfA==",
        "uplinkID": "xhZPesmwS+CJ0257d8LDpw==",
        "crcStatus": "CRC_OK"
      }
    ],
    "phyPayloadJSON": "{\"mhdr\":{\"mType\":\"JoinAccept\",\"major\":\"LoRaWANR1\"},\"macPayload\":{\"bytes\":\"cYpwQXC5cpNgrgoR\"},\"mic\":\"61a1e331\"}"
  }
}
6

Ok, not sure what is going on, but some things I noticed:

  • On the first screenshot you provided the duplicate frames are 2 and 7 seconds away from each other, which seems to be quite a long time if that should really be same “physical” (RF) frame.

  • Duplicate frames from last log you provided does not seem to be duplicate on first look (different frequency, inversion…), but then they have same MIC, which is odd.

So the next thing I would look at is what could create such delay and how can same message be decoded with different RF parameters, whether it is network issue or some misconfiguration somewhere.

7

Yes, the duplicate frames come after several seconds (as you noted once it was 2 and once it was 7 seconds in the example above) and they come on different channel. But the contents (macPayload) and the mic are the same, so no doubt that these are duplicates. How, why, and by whom they are being sent, I don’t know.

8

hello. did you find the reason and solved the problem?