Lora app server experience significant delay in publishing lora node messages

Kim_Chuan_Lim · April 23, 2018, 3:34am

I have all the lora-gateway-bridge, loraserver, and lora-app-server configured and running in the rpi3 (risinghf concentrator), using a arduino node (ABP) to push the message, and started the mosquitto to monitor the mqtt activities

rxhf@rhf2s001:~ $  mosquitto_sub -t "#" -v -u loraroot -P pppppppppppp
gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-3T02:52:08Z","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-3T02:52:38Z","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":3624654795,"frequency":922500000,"channel":2,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-89,"loRaSNR":9.2,"size":21,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAAAABa6BxuohJpaLgANnA"}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":3631977491,"frequency":922900000,"channel":4,"rfChain":1,"crcStatus":1,"codeRate":"4/5","rssi":-89,"loRaSNR":9.2,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAAQABJVD9Sp8="}

Question #1. can i confirm the gateway/#/rx is the lora packet received by the concentrator?

however, after 13 minutes, i only see the first application message published by the lora-app-server

gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-23T03:05:08Z","rxPacketsReceived":4,"rxPacketsReceivedOK":4,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":68472043,"frequency":922300000,"channel":1,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":10.8,"size":21,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAVQABMVdU7sP4MfaDnTVm"}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":75794355,"frequency":922700000,"channel":3,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-85,"loRaSNR":9,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAVgABsP36+LY="}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":83138371,"frequency":922500000,"channel":2,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":10.2,"size":21,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAVwABN6fjiU6JVIthK+Rz"}
gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-23T03:05:38Z","rxPacketsReceived":3,"rxPacketsReceivedOK":3,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":90461539,"frequency":922900000,"channel":4,"rfChain":1,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":9.5,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAWAABdYssWNA="}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":102805699,"frequency":922500000,"channel":2,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":10.5,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAWQABnSJ7rtM="}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":110150515,"frequency":922700000,"channel":3,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":9.8,"size":21,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAWgABsfjd/Ulm0JfzRN6W"}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":117473659,"frequency":922300000,"channel":1,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":10,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAWwABHkuDFGU="}
gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-23T03:06:08Z","rxPacketsReceived":4,"rxPacketsReceivedOK":4,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":124818243,"frequency":922900000,"channel":4,"rfChain":1,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":9.5,"size":21,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAXAABnMH86mER5rbARXHw"}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":132140651,"frequency":922500000,"channel":2,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-87,"loRaSNR":9.5,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAXQABrbdehqQ="}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":144484883,"frequency":922500000,"channel":2,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-89,"loRaSNR":10,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAXgABtQqA6o0="}
gateway/b827ebfffe958375/stats {"mac":"b827ebfffe958375","time":"2018-04-23T03:06:38Z","rxPacketsReceived":3,"rxPacketsReceivedOK":3,"txPacketsReceived":0,"txPacketsEmitted":0}
gateway/b827ebfffe958375/rx {"rxInfo":{"mac":"b827ebfffe958375","timestamp":156829587,"frequency":922700000,"channel":3,"rfChain":0,"crcStatus":1,"codeRate":"4/5","rssi":-90,"loRaSNR":9.8,"size":14,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"board":0,"antenna":0},"phyPayload":"QKRtJQYAXwABc9WBjFM="}
gateway/b827ebfffe958375/tx {"token":57458,"txInfo":{"mac":"b827ebfffe958375","immediately":false,"timestamp":157829587,"frequency":922700000,"power":23,"dataRate":{"modulation":"LORA","spreadFactor":7,"bandwidth":125},"codeRate":"4/5","iPol":null,"board":0,"antenna":0},"phyPayload":"YKRtJQaCXgAIAaCmLOw="}
application/2/node/0004a30b001b5bd8/rx {"applicationID":"2","applicationName":"streetlight","deviceName":"streetlightdevice","devEUI":"0004a30b001b5bd8","rxInfo":[{"mac":"b827ebfffe958375","rssi":-90,"loRaSNR":9.8,"name":"b827ebfffe958375","latitude":0,"longitude":0,"altitude":0}],"txInfo":{"frequency":922700000,"dataRate":{"modulation":"LORA","bandwidth":125,"spreadFactor":7},"adr":false,"codeRate":"4/5"},"fCnt":95,"fPort":1,"data":"AA=="}

Question #2: Is my observation correct?
Question #3: Anything I should do to the lora-app-server to make it immediately publish the application message?

brocaar · April 23, 2018, 8:57am

It is hard to tell what is the issue from the MQTT logs. Please also check the LoRa (App) Server log output. It could be that some of the frames are rejected (e.g. because of a frame-counter mismatch).

Kim_Chuan_Lim · April 23, 2018, 10:52am

Thanks for the quick response.

I noticed at the beginning the lora-app-server is suffering the grpc Unauthenticated error from time “2018-04-23T04:18:25Z” to “2018-04-23T04:19:52Z”. But the application server still not publishing any mqtt message after “2018-04-23T04:19:52Z”.

sudo journalctl -u lora-app-server -f -n 50

– Logs begin at Mon 2018-04-23 04:17:01 UTC. –
Apr 23 04:18:25 rhf2s001 lora-app-server[724]: time=“2018-04-23T04:18:25Z” level=info msg=“finished streaming call with code Unauthenticated” error=“rpc err or: code = Unauthenticated desc = authentication failed: jwt parse error: token is not valid yet” grpc.code=Unauthenticated grpc.method=StreamFrameLogs grpc .service=api.Gateway grpc.start_time=“2018-04-23T04:18:25Z” grpc.time_ms=0.626 peer.address="[::1]:35398" span.kind=server system=grpc
Apr 23 04:18:25 rhf2s001 lora-app-server[724]: time=“2018-04-23T04:18:25Z” level=info msg=“finished streaming call with code Unauthenticated” error=“rpc err or: code = Unauthenticated desc = authentication failed: jwt parse error: token is not valid yet” grpc.code=Unauthenticated grpc.method=StreamFrameLogs grpc .service=api.Device grpc.start_time=“2018-04-23T04:18:25Z” grpc.time_ms=0.665 peer.address="[::1]:35382" span.kind=server system=grpc
…
…
Apr 23 04:19:52 rhf2s001 lora-app-server[724]: time=“2018-04-23T04:19:52Z” level=info msg=“finished streaming call with code Unauthenticated” error=“rpc error: code = Unauthenticated desc = authentication failed: jwt parse error: token is not valid yet” grpc.code=Unauthenticated grpc.method=StreamFrameLogs grpc.service=api.Gateway grpc.start_time=“2018-04-23T04:19:52Z” grpc.time_ms=1.019 peer.address="[::1]:35398" span.kind=server system=grpc
//end of lora-app-server log

Kim_Chuan_Lim · April 23, 2018, 11:13am

i then restart the lora-app-server with systemctl restart lora-ap-server then the grpc error gone. however, there is still no mqtt message published by the application server. the following is the full restart log.

Apr 23 11:22:26 rhf2s001 systemd[1]: Stopping LoRa App Server...
Apr 23 11:22:26 rhf2s001 lora-app-server[1713]: time="2018-04-23T11:22:26Z" level=info msg="signal received" signal=terminated
Apr 23 11:22:26 rhf2s001 lora-app-server[1713]: time="2018-04-23T11:22:26Z" level=warning msg="stopping lora-app-server"
Apr 23 11:22:26 rhf2s001 systemd[1]: Starting LoRa App Server...
Apr 23 11:22:26 rhf2s001 systemd[1]: Started LoRa App Server.
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="starting LoRa App Server" docs="https://docs.loraserver.io/" version=0.20.1
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="connecting to postgresql"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="setup redis connection pool"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="handler/mqtt: TLS config is empty"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="handler/mqtt: connecting to mqtt broker" server="tcp://localhost:1883"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="applying database migrations"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="handler/mqtt: connected to mqtt broker"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="handler/mqtt: subscribing to tx topic" qos=0 topic=application/+/node/+/tx
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="migrations applied" count=0
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[]" duration=2.683602ms query="select count(*) from network_server"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[]" duration=5.97231ms query="\n\t\tselect\n\t\t\tcount(*)\n\t\tfrom application\n\t\twhere\n\t\t\t$1 = ''\n\t\t\tor ($1 != '' and name ilike $1)"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[]" duration=4.245273ms query="select * from device_queue where pending = false order by id"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[]" duration=1.929068ms query="\n\t\tselect\n\t\t\tcount(*)\n\t\tfrom gateway_profile"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[999 0]" duration=2.956884ms query="\n\t\tselect *\n\t\tfrom network_server\n\t\torder by name\n\t\tlimit $1 offset $2"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=warning msg="creating insecure network-server client" server="localhost:8000"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8000 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1293e1b0, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1293e1b0, READY"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="finished client unary call" grpc.code=OK grpc.method=MigrateChannelConfigurationToGatewayProfile grpc.service=ns.NetworkServer grpc.time_ms=4.059 span.kind=client system=grpc
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="starting application-server api" bind="0.0.0.0:8001" ca-cert= tls-cert= tls-key=
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="starting join-server api" bind="0.0.0.0:8003" ca_cert= tls_cert= tls_key=
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="starting client api server" bind="0.0.0.0:8080" tls-cert=/etc/lora-app-server/certs/http.pem tls-key=/etc/lora-app-server/certs/http-key.pem
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="sql query executed" args="[]" duration=6.46601ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a250, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d790, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1293f0c0, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="dialing to target with scheme: \"\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=info msg="registering rest api handler and documentation endpoint" path=/api
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a530, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a620, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d880, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a720, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a7f0, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a8f0, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ccResolverWrapper: sending new addresses to cc: [{localhost:8080 0  <nil>}]"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a9c0, CONNECTING"
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="ClientConn switching balancer to \"pick_first\""
Apr 23 11:22:26 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:26Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d9d0, CONNECTING"
Apr 23 11:22:27 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:27Z" level=debug msg="sql query executed" args="[]" duration=2.480059ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d880, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a620, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a250, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1293f0c0, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d9d0, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a8f0, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a720, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a530, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1294d790, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a7f0, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="pickfirstBalancer: HandleSubConnStateChange: 0x1270a9c0, READY"
Apr 23 11:22:28 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:28Z" level=debug msg="sql query executed" args="[]" duration=2.583393ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update"
Apr 23 11:22:29 rhf2s001 lora-app-server[1890]: time="2018-04-23T11:22:29Z" level=debug msg="sql query executed" args="[]" duration=2.623654ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update"

brocaar · April 23, 2018, 2:55pm

You might also want to inspect your loraserver logs. Could you please format these logs the next time?

Kim_Chuan_Lim · April 23, 2018, 3:22pm

oops, now i see the error message "“processing rx packet error: get device-session error: device-session does not exist or invalid fcnt or mic” "

anyway, i can manually decrypt[1] the base64 message without any error.

anything i should do to fix the error?

Apr 23 15:16:15 rhf2s001 systemd[1]: Stopping LoRa Server...
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="signal received" signal=terminated
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=warning msg="stopping loraserver"
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: closing backend"
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: unsubscribing from rx topic" topic=gateway/+/rx
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: unsubscribing from stats topic" topic=gateway/+/stats
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: handling last messages"
Apr 23 15:16:15 rhf2s001 loraserver[725]: time="2018-04-23T15:16:15Z" level=info msg="waiting for pending actions to complete"
Apr 23 15:16:15 rhf2s001 systemd[1]: Starting LoRa Server...
Apr 23 15:16:15 rhf2s001 systemd[1]: Started LoRa Server.
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="starting LoRa Server" band=KR_920_923 docs="https://docs.loraserver.io/" net_id=010203 version=0.26.1
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="setup redis connection pool" url="redis://localhost:6379"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="connecting to postgresql"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: TLS config is empty"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: connecting to mqtt broker" server="tcp://localhost:1883"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="configuring join-server client" ca_cert= server="http://localhost:8003" tls_cert= tls_key=
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="no network-controller configured"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="applying database migrations"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: connected to mqtt server"
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: subscribing to rx topic" qos=0 topic=gateway/+/rx
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="backend/gateway: subscribing to stats topic" qos=0 topic=gateway/+/stats
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="migrations applied" count=0
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="starting api server" bind="0.0.0.0:8000" ca-cert= tls-cert= tls-key=
Apr 23 15:16:15 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:15Z" level=info msg="starting downlink device-queue scheduler"
Apr 23 15:16:25 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:25Z" level=info msg="backend/gateway: rx packet received"
Apr 23 15:16:25 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:25Z" level=error msg="processing rx packet error: get device-session error: device-session does not exist or invalid fcnt or mic" data_base64="QKRtJQYA5QEBoOzhD36C6h4="
Apr 23 15:16:31 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:31Z" level=info msg="backend/gateway: gateway stats packet received" mac=b827ebfffe958375
Apr 23 15:16:31 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:31Z" level=info msg="gateway updated" mac=b827ebfffe958375
Apr 23 15:16:32 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:32Z" level=info msg="backend/gateway: rx packet received"
Apr 23 15:16:32 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:32Z" level=error msg="processing rx packet error: get device-session error: device-session does not exist or invalid fcnt or mic" data_base64="QKRtJQYA5gEBtEIVAB0="
Apr 23 15:16:40 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:40Z" level=info msg="backend/gateway: rx packet received"
Apr 23 15:16:40 rhf2s001 loraserver[2428]: time="2018-04-23T15:16:40Z" level=error msg="processing rx packet error: get device-session error: device-session does not exist or invalid fcnt or mic" data_base64="QKRtJQYA5wEBNyN71Kcj1gI="

[1] https://github.com/anthonykirby/lora-packet

brocaar · April 24, 2018, 7:57am

This is what I was expecting, there is a frame-counter mismatch between your device(s) and network-server. Please see: https://forum.loraserver.io/search?q=invalid%20fcnt%20or%20mic

Kim_Chuan_Lim · April 24, 2018, 9:53am

Thanks Brocaar. It is the frame-counter mismatch issue. I managed to resolve it after disable the Disable frame-counter validation as discussed in https://forum.loraserver.io/t/error-node-session-does-not-exist-or-invalid-fcnt-or-mic/379

Praveen_Kumar_R · August 6, 2018, 10:29am

@Kim_Chuan_Lim

Hi even i have disabled frame-counter validation option.But still i am getting the same error.Can you please tell me what might be the issue?

Thanks

Kim_Chuan_Lim · August 6, 2018, 3:18pm

can share your log with us?

Praveen_Kumar_R · August 7, 2018, 4:26am

@Kim_Chuan_Lim

Thanks! issue resolved.

Problem was with incorrect security keys configuration.

Now uplink and downlink works fine.