brocaar / chirpstack-application-server

ChirpStack Application Server is an open-source LoRaWAN application-server.
https://www.chirpstack.io
MIT License
501 stars 326 forks source link

Join Request/Accept shown in LoRaWAN Frames but no Join event in Device Data #683

Open harryg-oss opened 2 years ago

harryg-oss commented 2 years ago

What happened?

Many devices (with same hardware and firmware) working happily. Single particular device after a period of hours of working fine disconnects and then sends join request, it appears to be accepted but never allowed network, both request and accept is visible in the 'LORAWAN FRAMES' but in 'DEVICE DATA' there is no 'join' entry.

What did you expect?

There to be a join entry in the 'DEVICE DATA' tab and for the device to connect.

Steps to reproduce this issue

Steps:

  1. Unsure.

Could you share your log output?

Nothing of import. Chosen a time range where I know a join request was sent. Application Server:

time="2022-05-11T07:09:59.710641844Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR
 DAY MONTH]" ctx_id=fb0a466d-9547-4626-8c47-b8ce2da33993 name="gw:GW_ADDR"           
time="2022-05-11T07:09:59.710684308Z" level=info msg="finished unary call with code OK" ctx_id
=fb0a466d-9547-4626-8c47-b8ce2da33993 grpc.code=OK grpc.method=HandleGatewayStats grpc.service
=as.ApplicationServerService grpc.start_time="2022-05-11T07:09:59Z" grpc.time_ms=8.002 peer.ad
dress="127.0.0.1:35574" span.kind=server system=grpc                                          
time="2022-05-11T07:10:29.729019448Z" level=info msg="gateway updated" ctx_id=f7b7d211-898e-4b
61-8ad1-c4f2fcbe1313 id=GW_ADDR name=TrimmingsByDesignGateway                        
time="2022-05-11T07:10:29.730588607Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR
 DAY MONTH]" ctx_id=f7b7d211-898e-4b61-8ad1-c4f2fcbe1313 name="gw:GW_ADDR"           
time="2022-05-11T07:10:29.730633561Z" level=info msg="finished unary call with code OK" ctx_id
=f7b7d211-898e-4b61-8ad1-c4f2fcbe1313 grpc.code=OK grpc.method=HandleGatewayStats grpc.service
=as.ApplicationServerService grpc.start_time="2022-05-11T07:10:29Z" grpc.time_ms=2.802 peer.ad
dress="127.0.0.1:35574" span.kind=server system=grpc                                          
time="2022-05-11T07:10:36.586010317Z" level=info msg="device last-seen and dr updated" ctx_id=
95fd8f76-efa0-4edb-a05c-f9c448c610e6 dev_eui=f0272ef325fe785e                                 
time="2022-05-11T07:10:36.589878218Z" level=info msg="integration/logger: logging event" ctx_i
d=95fd8f76-efa0-4edb-a05c-f9c448c610e6 dev_eui=f0272ef325fe785e type=up                       
time="2022-05-11T07:10:36.590212583Z" level=info msg="integration/mqtt: publishing event" ctx_
id=95fd8f76-efa0-4edb-a05c-f9c448c610e6 dev_eui=f0272ef325fe785e qos=0 retain=false topic=appl
ication/3/device/f0272ef325fe785e/event/up                                                    
time="2022-05-11T07:10:36.590430834Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR
 DAY MONTH]" ctx_id=95fd8f76-efa0-4edb-a05c-f9c448c610e6 name="device:f0272ef325fe785e"       
time="2022-05-11T07:10:36.590477259Z" level=info msg="finished unary call with code OK" ctx_id
=95fd8f76-efa0-4edb-a05c-f9c448c610e6 grpc.code=OK grpc.method=HandleUplinkData grpc.request.d
eadline="2022-05-11T07:10:37Z" grpc.service=as.ApplicationServerService grpc.start_time="2022-
05-11T07:10:36Z" grpc.time_ms=7.86 peer.address="127.0.0.1:35574" span.kind=server system=grpc
time="2022-05-11T07:10:36.59342317Z" level=info msg="integration/influxdb: uplink measurements
 written" ctx_id=95fd8f76-efa0-4edb-a05c-f9c448c610e6 dev_eui=f0272ef325fe785e                
time="2022-05-11T07:10:55.105884123Z" level=info msg="device last-seen and dr updated" ctx_id=
282893d4-f288-4291-9642-9c0c1e57df05 dev_eui=988f1f1970cb47d5                                 
time="2022-05-11T07:10:55.109027848Z" level=info msg="integration/logger: logging event" ctx_i
d=282893d4-f288-4291-9642-9c0c1e57df05 dev_eui=988f1f1970cb47d5 type=up                       
time="2022-05-11T07:10:55.109312368Z" level=info msg="integration/mqtt: publishing event" ctx_
id=282893d4-f288-4291-9642-9c0c1e57df05 dev_eui=988f1f1970cb47d5 qos=0 retain=false topic=appl
ication/3/device/988f1f1970cb47d5/event/up                                                    
time="2022-05-11T07:10:55.109556402Z" level=info msg="metrics saved" aggregation="[MINUTE HOUR
 DAY MONTH]" ctx_id=282893d4-f288-4291-9642-9c0c1e57df05 name="device:988f1f1970cb47d5"       

Network Server:

time="2022-05-11T07:09:59.710857195Z" level=info msg="finished client unary call" ctx_id=e47a47
32-789a-4776-8c86-f78d831ce185 grpc.code=OK grpc.ctx_id=fb0a466d-9547-4626-8c47-b8ce2da33993 gr
pc.duration=8.806882ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService
span.kind=client system=grpc
time="2022-05-11T07:10:29.725060855Z" level=info msg="gateway/mqtt: gateway stats packet receiv
ed" gateway_id=GW_ADDR stats_id=4b33dd46-cf48-409c-b0fc-bddb3eaac475
time="2022-05-11T07:10:29.726936495Z" level=info msg="storage: gateway state updated" ctx_id=4b
33dd46-cf48-409c-b0fc-bddb3eaac475 gateway_id=GW_ADDR
time="2022-05-11T07:10:29.730815188Z" level=info msg="finished client unary call" ctx_id=4b33dd
46-cf48-409c-b0fc-bddb3eaac475 grpc.code=OK grpc.ctx_id=f7b7d211-898e-4b61-8ad1-c4f2fcbe1313 gr
pc.duration=3.234069ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService 
span.kind=client system=grpc
time="2022-05-11T07:10:36.379138212Z" level=info msg="gateway/mqtt: uplink frame received" gate
way_id=GW_ADDR uplink_id=fb847d52-3bb7-4b3a-bb1e-46b78f9fd176
time="2022-05-11T07:10:36.580463518Z" level=info msg="uplink: frame(s) collected" ctx_id=c5b005
25-4fea-47c5-ab94-ca5e0ef836a1 mtype=ConfirmedDataUp uplink_ids="[fb847d52-3bb7-4b3a-bb1e-46b78
f9fd176]"
time="2022-05-11T07:10:36.581916727Z" level=info msg="sent uplink meta-data to network-controll
er" ctx_id=c5b00525-4fea-47c5-ab94-ca5e0ef836a1 dev_eui=f0272ef325fe785e
time="2022-05-11T07:10:36.582058255Z" level=info msg="device gateway rx-info meta-data saved" c
tx_id=c5b00525-4fea-47c5-ab94-ca5e0ef836a1 dev_eui=f0272ef325fe785e
time="2022-05-11T07:10:36.582373924Z" level=info msg="device-session saved" ctx_id=c5b00525-4fe
a-47c5-ab94-ca5e0ef836a1 dev_addr=01a6bba2 dev_eui=f0272ef325fe785e
time="2022-05-11T07:10:36.590675576Z" level=info msg="finished client unary call" ctx_id=c5b005
25-4fea-47c5-ab94-ca5e0ef836a1 grpc.code=OK grpc.ctx_id=95fd8f76-efa0-4edb-a05c-f9c448c610e6 gr
pc.duration=8.457132ms grpc.method=HandleUplinkData grpc.service=as.ApplicationServerService sp
an.kind=client system=grpc
time="2022-05-11T07:10:36.684344125Z" level=info msg="gateway/mqtt: publishing gateway command"
 command=down downlink_id=c5b00525-4fea-47c5-ab94-ca5e0ef836a1 gateway_id=GW_ADDR qos=
0 topic=gateway/GW_ADDR/command/down
time="2022-05-11T07:10:36.684820968Z" level=info msg="device-session saved" ctx_id=c5b00525-4fe
a-47c5-ab94-ca5e0ef836a1 dev_addr=01a6bba2 dev_eui=f0272ef325fe785e
time="2022-05-11T07:10:36.684964989Z" level=info msg="storage: downlink-frame saved" ctx_id=c5b
00525-4fea-47c5-ab94-ca5e0ef836a1 token=50608
time="2022-05-11T07:10:36.70342563Z" level=info msg="backend/gateway: downlink tx acknowledgeme
nt received" downlink_id=c5b00525-4fea-47c5-ab94-ca5e0ef836a1 gateway_id=GW_ADDR
time="2022-05-11T07:10:36.704241277Z" level=info msg="device-session saved" ctx_id=c5b00525-4fe
a-47c5-ab94-ca5e0ef836a1 dev_addr=01a6bba2 dev_eui=f0272ef325fe785e
time="2022-05-11T07:10:36.70433296Z" level=info msg="sent downlink meta-data to network-control
ler" ctx_id=c5b00525-4fea-47c5-ab94-ca5e0ef836a1
time="2022-05-11T07:10:54.900171944Z" level=info msg="gateway/mqtt: uplink frame received" gate
way_id=GW_ADDR uplink_id=527453b7-867d-4e4f-908a-ae4fe6e9b240

Your Environment

Component Version
Application Server v3.17.4
Network Server v3.15.5
Gateway Bridge
Chirpstack API
Geolocation
Concentratord

I realise this is a difficult to help issue, but I am struggling to find information about this too but assume that the issue must lie with chirpstack (not entirely sure if the application server or network server) as there is a mismatch between the events as published to the application and the raw LoRaWAN PHYPayload frames as seen by the gateway. Pointers towards where the problem might be would be very useful.