Unstable endNode date receiving

msadeghz · August 17, 2021, 1:19pm

Hi,
In my own private network using official semtech packet forwarder on the gateway and official chirpstack servers, I have seen a strange event.
I have seen three different log from network server for three uplink from one endnode.

1-the first uplink (fnct=2)
in the first uplink I get get device-session error: object does not exist error!
packet forwarder log:

Aug 17 12:44:37 Linkap lgw[3588]: INFO: Received pkt from mote: 07340CAF (fcnt=2)
Aug 17 12:44:37 Linkap lgw[3588]: JSON up: {"rxpk":[{"tmst":140025244,"chan":5,"rfch":0,"freq":867.500000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":6.5,"rssi":-60,"size$
Aug 17 12:44:37 Linkap lgw[3588]: INFO: [up] PUSH_ACK received in 37 ms

gateway bridge log:

Aug 17 12:44:38 srv35074 chirpstack-gateway-bridge[25532]: time="2021-08-17T12:44:38.719566271+02:00" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ffffff0000210106/event/up uplink_id=361a9cd9-1aa7-4458-9315-4f0d9a953881

network server log:

Aug 17 12:44:38 srv35074 chirpstack-network-server[25135]: time="2021-08-17T12:44:38.721009813+02:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=ffffff0000210106 uplink_id=361a9cd9-1aa7-4458-9315-4f0d9a953881
Aug 17 12:44:38 srv35074 chirpstack-network-server[25135]: time="2021-08-17T12:44:38.924340252+02:00" level=info msg="uplink: frame(s) collected" ctx_id=670d0614-1d7f-485a-a94d-87bbe443cbef mtype=UnconfirmedDataUp uplink_ids="[361a9cd9-1aa7-4458-9315-4f0d9a953881]"
Aug 17 12:44:38 srv35074 chirpstack-network-server[25135]: time="2021-08-17T12:44:38.925647839+02:00" level=error msg="uplink: processing uplink frame error" ctx_id=670d0614-1d7f-485a-a94d-87bbe443cbef error="get device-session error: object does not exist"

application server log:
------- get nothing

2-the first uplink (fnct=3)
but for the next uplink all things are OK:

packet forwarder log:

Aug 17 13:45:37 Linkap lgw[3588]: INFO: Received pkt from mote: 07340CAF (fcnt=3)
Aug 17 13:45:37 Linkap lgw[3588]: JSON up: {"rxpk":[{"tmst":3745459804,"chan":4,"rfch":0,"freq":867.300000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":8.5,"rssi":-59,"siz$
Aug 17 13:45:37 Linkap lgw[3588]: INFO: [up] PUSH_ACK received in 9 ms

gateway bridge log:

Aug 17 13:45:37 srv35074 chirpstack-gateway-bridge[25532]: time="2021-08-17T13:45:37.697827418+02:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=3878768c-0428-4c02-a552-91703caabbe1 topic=gateway/ffffff0000210106/event/stats

network server log:

Aug 17 13:45:37 srv35074 chirpstack-network-server[25135]: time="2021-08-17T13:45:37.699304+02:00" level=info msg="gateway/mqtt: gateway stats packet received" gateway_id=ffffff0000210106 stats_id=3878768c-0428-4c02-a552-91703caabbe1
Aug 17 13:45:37 srv35074 chirpstack-network-server[25135]: time="2021-08-17T13:45:37.704623434+02:00" level=info msg="storage: gateway state updated" ctx_id=3878768c-0428-4c02-a552-91703caabbe1 gateway_id=ffffff0000210106
Aug 17 13:45:37 srv35074 chirpstack-network-server[25135]: time="2021-08-17T13:45:37.716843742+02:00" level=info msg="finished client unary call" ctx_id=3878768c-0428-4c02-a552-91703caabbe1 grpc.code=OK grpc.ctx_id=d733652f-28c2-48ce-9562-63708f07050b grpc.duration=10.750662ms grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService span.kind=client system=grpc

application server log:

Aug 17 13:45:37 srv35074 chirpstack-application-server[734]: time="2021-08-17T13:45:37.710822827+02:00" level=info msg="gateway updated" ctx_id=d733652f-28c2-48ce-9562-63708f07050b id=ffffff0000210106 name=Ribbon
Aug 17 13:45:37 srv35074 chirpstack-application-server[734]: time="2021-08-17T13:45:37.71628552+02:00" level=info msg="metrics saved" aggregation="[MINUTE HOUR DAY MONTH]" ctx_id=d733652f-28c2-48ce-9562-63708f07050b name="gw:ffffff0000210106"
Aug 17 13:45:37 srv35074 chirpstack-application-server[734]: time="2021-08-17T13:45:37.71635824+02:00" level=info msg="finished unary call with code OK" ctx_id=d733652f-28c2-48ce-9562-63708f07050b grpc.code=OK grpc.method=HandleGatewayStats grpc.service=as.ApplicationServerService grpc.start_time="2021-08-17T13:45:37+02:00" grpc.time_ms=8.936 peer.address="127.0.0.1:56590" span.kind=server system=grpc

3-the third uplink (fnct=4)
and for the next uplink I don’t get any error:!

packet forwarder log:

Aug 17 14:44:54 Linkap lgw[3588]: INFO: Received pkt from mote: 07340CAF (fcnt=4)
Aug 17 14:44:54 Linkap lgw[3588]: JSON up: {"rxpk":[{"tmst":3055927892,"chan":1,"rfch":1,"freq":868.300000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":8.5,"rssi":-63,"siz$
Aug 17 14:44:54 Linkap lgw[3588]: INFO: [up] PUSH_ACK received in 29 ms

gateway bridge log:

Aug 17 14:44:54 srv35074 chirpstack-gateway-bridge[25532]: time="2021-08-17T14:44:54.627084273+02:00" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/ffffff0000210106/event/up uplink_id=6b39a81c-aa55-4f9e-833c-c7426321124c

network server log:

Aug 17 14:44:54 srv35074 chirpstack-network-server[25135]: time="2021-08-17T14:44:54.628900937+02:00" level=info msg="gateway/mqtt: uplink frame received" gateway_id=ffffff0000210106 uplink_id=6b39a81c-aa55-4f9e-833c-c7426321124c

application server log:
------------ get nothing

I just get the second uplink (with fcnt=3) in chirpstack device data tab.
what’s the reason? how can I find the issue source?

msadeghz · August 20, 2021, 9:44am

@brocaar , can you help me? is it possible that some network server logs don’t be shown on jounalctl?

msadeghz · August 20, 2021, 11:38am

I’ve gotten below error in network server each a few minutes.
is it related to above issue?

Aug 20 13:36:46 srv35074 ns[2562]: time=“2021-08-20T13:36:46.990708702+02:00” level=error msg=“finished client unary call” ctx_id=698399e6-d707-4503-b707-74daab237b61 error=“rpc error: code = Internal desc = handle received ping error: get ping lookup error: get ping lookup error: redis: nil” grpc.code=Internal grpc.ctx_id=63637a58-8773-4f66-9c15-13e4e3decfc6 grpc.duration=2.249343ms grpc.method=HandleProprietaryUplink grpc.service=as.ApplicationServerService span.kind=client system=grpc

Aug 20 13:36:46 srv35074 ns[2562]: time=“2021-08-20T13:36:46.991098992+02:00” level=error msg=“handle proprietary up error” ctx_id=698399e6-d707-4503-b707-74daab237b61 error=“rpc error: code = Internal desc = handle received ping error: get ping lookup error: get ping lookup error: redis: nil”

and the corresponding log in application server:

Aug 20 13:36:46 srv35074 as[2576]: time=“2021-08-20T13:36:46.989485545+02:00” level=error msg=“handle received ping error: get ping lookup error: get ping lookup error: redis: nil”

Aug 20 13:36:46 srv35074 as[2576]: time=“2021-08-20T13:36:46.98964623+02:00” level=error msg=“finished unary call with code Internal” ctx_id=63637a58-8773-4f66-9c15-13e4e3decfc6 error=“rpc error: code = Internal desc = handle received ping error: get ping lookup error: get ping lookup error: redis: nil” grpc.code=Internal grpc.method=HandleProprietaryUplink grpc.service=as.ApplicationServerService grpc.start_time=“2021-08-20T13:36:46+02:00” grpc.time_ms=0.581 peer.address=“127.0.0.1:40909” span.kind=server system=grpc

msadeghz · August 20, 2021, 1:04pm

you can see the device data tab vs lorawan frames tab data is not normal. a few uplinks are missed in device data tab.

extra info if needed:
1- the devise profile is ABP class A.
2- I’m using multiple chirpstack network servers and gateway bridges on single 2-cores machine. but I’ve provided independent toml config files and ports

msadeghz · November 3, 2021, 9:43am

I think I found the problem.
I have used several network servers and application servers on single machine and single redis-server. I think the received packets data leakage between the servers leads to this issue. I have launched dedicated redis-server on dedicated port for each networks and the issue is resolved.