Connection problem of gateway-bridge to MQTT server

kurolin · June 19, 2018, 7:25am

Current I am building a LoRa server with CISCO gateway, model IXM-LPWA-900-16-K9.

Everything was fine until it comes to the part of issuing rx packet(I supposed, after reading other posts) from the bridge to server.

As show below, the process got stuck in the loop of pullACK → pullData → pushACK → pushData → received stats:

June 19 15:06:04 kuro-VirtualBox systemd[1]: Stopped LoRa Gateway Bridge.
June 19 15:06:04 kuro-VirtualBox systemd[1]: Started LoRa Gateway Bridge.
June 19 15:06:04 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:06:04+08:00" level=info msg="starting LoRa Gateway Bridge" docs="ht__tps://www.loraserver.io/lora-gateway-bridge/" version=2.4.1
June 19 15:06:04 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:06:04+08:00" level=info msg="backend: TLS config is empty"
June 19 15:06:04 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:06:04+08:00" level=info msg="backend: connecting to mqtt broker" server="tcp://127.0.0.1:1883"
June 19 15:06:04 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:06:04+08:00" level=info msg="gateway: starting gateway udp listener" addr="0.0.0.0:1700"
June 19 15:06:04 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:06:04+08:00" level=info msg="backend: connected to mqtt broker"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:07:16+08:00" level=info msg="signal received" signal=terminated
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:07:16+08:00" level=warning msg="shutting down server"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:07:16+08:00" level=info msg="gateway: closing gateway backend"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30095]: time="2018-06-19T15:07:16+08:00" level=info msg="gateway: handling last packets"
June 19 15:07:16 kuro-VirtualBox systemd[1]: Stopping LoRa Gateway Bridge...
June 19 15:07:16 kuro-VirtualBox systemd[1]: Stopped LoRa Gateway Bridge.
June 19 15:07:16 kuro-VirtualBox systemd[1]: Started LoRa Gateway Bridge.
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:07:16+08:00" level=info msg="starting LoRa Gateway Bridge" docs="ht__tps://www.loraserver.io/lora-gateway-bridge/" version=2.4.1
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:07:16+08:00" level=info msg="backend: TLS config is empty"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:07:16+08:00" level=info msg="backend: connecting to mqtt broker" server="tcp://127.0.0.1:1883"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:07:16+08:00" level=info msg="gateway: starting gateway udp listener" addr="0.0.0.0:1700"
June 19 15:07:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:07:16+08:00" level=info msg="backend: connected to mqtt broker"
June 19 15:09:22 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:22+08:00" level=info msg="gateway: received udp packet from gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullData
June 19 15:09:22 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:22+08:00" level=info msg="backend: subscribing to topic" qos=0 topic=gateway/000070d3798e04b8/tx
June 19 15:09:22 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:22+08:00" level=info msg="backend: subscribing to topic" qos=0 topic=gateway/000070d3798e04b8/config
June 19 15:09:22 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:22+08:00" level=info msg="gateway: sending udp packet to gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullACK
June 19 15:09:31 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:31+08:00" level=info msg="gateway: received udp packet from gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullData
June 19 15:09:31 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:31+08:00" level=info msg="gateway: sending udp packet to gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullACK
June 19 15:09:41 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:41+08:00" level=info msg="gateway: received udp packet from gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullData
June 19 15:09:41 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:41+08:00" level=info msg="gateway: sending udp packet to gateway" addr="192.168.1.3:40302" protocol_version=2 type=PullACK
June 19 15:09:42 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:42+08:00" level=info msg="gateway: received udp packet from gateway" addr="192.168.1.3:48913" protocol_version=2 type=PushData
June 19 15:09:42 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:42+08:00" level=info msg="gateway: stat packet received" addr="192.168.1.3:48913" mac=000070d3798e04b8
June 19 15:09:42 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:42+08:00" level=info msg="backend: publishing packet" qos=0 topic=gateway/000070d3798e04b8/stats
June 19 15:09:42 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:42+08:00" level=info msg="gateway: sending udp packet to gateway" addr="192.168.1.3:48913" protocol_version=2 type=PushACK
June 19 15:09:47 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:47+08:00" level=info msg="gateway: received udp packet from gateway" addr="192.168.1.3:48913" protocol_version=2 type=PushData
June 19 15:09:47 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:47+08:00" level=info msg="gateway: stat packet received" addr="192.168.1.3:48913" mac=000070d3798e04b8
June 19 15:09:47 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:47+08:00" level=info msg="backend: publishing packet" qos=0 topic=gateway/000070d3798e04b8/stats
June 19 15:09:47 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:09:47+08:00" level=info msg="gateway: sending udp packet to gateway" addr="192.168.1.3:48913" protocol_version=2 type=PushACK
June 19 15:11:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:11:16+08:00" level=info msg="backend: unsubscribing from topic" topic=gateway/000070d3798e04b8/tx
June 19 15:11:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:11:16+08:00" level=info msg="backend: unsubscribing from topic" topic=gateway/000070d3798e04b8/config

FYI, below is the log for loraserver:

June 19 15:06:40 kuro-VirtualBox systemd[1]: Stopped LoRa Server.
June 19 15:06:40 kuro-VirtualBox systemd[1]: Started LoRa Server.
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="starting LoRa Server" band=AS_923 docs="https://docs.loraserver.io/" net_id=000000 version=1.0.0
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="setup redis connection pool" url="redis://localhost:6379"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="connecting to postgresql"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="backend/gateway: TLS config is empty"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="backend/gateway: connecting to mqtt broker" server="tcp://localhost:1883"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="configuring join-server client" ca_cert= server="http://localhost:8003" tls_cert= tls_key=
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="no network-controller configured"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="applying database migrations"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="backend/gateway: connected to mqtt server"
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="backend/gateway: subscribing to rx topic" qos=0 topic=gateway/+/rx
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="backend/gateway: subscribing to stats topic" qos=0 topic=gateway/+/stats
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="migrations applied" count=0
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="starting api server" bind="0.0.0.0:8000" ca-cert= tls-cert= tls-key=
June 19 15:06:40 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:06:40+08:00" level=info msg="starting downlink device-queue scheduler"
June 19 15:09:42 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:09:42+08:00" level=info msg="backend/gateway: gateway stats packet received" mac=000070d3798e04b8
June 19 15:09:42 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:09:42+08:00" level=info msg="gateway updated" mac=000070d3798e04b8
June 19 15:09:47 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:09:47+08:00" level=info msg="backend/gateway: gateway stats packet received" mac=000070d3798e04b8
June 19 15:09:47 kuro-VirtualBox loraserver[30111]: time="2018-06-19T15:09:47+08:00" level=info msg="gateway updated" mac=000070d3798e04b8

Please suggest what can I do!! Thanks.

Remark: I am running Ubuntu 18.04 on VirtualBox.

brocaar · June 19, 2018, 7:36am

June 19 15:11:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:11:16+08:00" level=info msg="backend: unsubscribing from topic" topic=gateway/000070d3798e04b8/tx
June 19 15:11:16 kuro-VirtualBox lora-gateway-bridge[30123]: time="2018-06-19T15:11:16+08:00" level=info msg="backend: unsubscribing from topic" topic=gateway/000070d3798e04b8/config

Your gateway stopped sending data to the LoRa Gateway Bridge / LGB stopped receiving data. That is why LoRa Gateway Bridge is unsubscribing from the MQTT topics.

kurolin · June 19, 2018, 8:16am

Yes, this is because we terminated the uplink request.

I just wanted to show the log of the whole process, from starting to ending.

And the problem is not here, but the loop.

brocaar · June 19, 2018, 8:51am

Ah, I think I understand now, looking at the timestamps in the logs. However, I’m not sure if I can help you with this as I can’t see what is going on at your side. I don’t know how to reproduce your issue as I have never experienced it.

kurolin · June 19, 2018, 10:13am

Thanks, will update if there is any new progress.

brocaar · June 19, 2018, 10:35am

Maybe this could help you in your debugging: https://www.loraserver.io/lora-gateway-bridge/install/debug/.

kurolin · June 19, 2018, 10:42am

I have tried the command

tcpdump -AUq -i lo port 1700

and the output was only

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes

kurolin · June 22, 2018, 6:32pm

@brocaar just want to update you that I have got some similar output recently using WireShark regarding the sample output on the doc debugging section

11:42:00.114726 IP localhost.34268 > localhost.1700: UDP, length 12
E..(..@.@."................'.....UZ.....
11:42:00.130292 IP localhost.1700 > localhost.34268: UDP, length 4
E.. ..@.@.".....................
11:42:10.204723 IP localhost.34268 > localhost.1700: UDP, length 12
E..(.&@.@..................'.x...UZ.....
11:42:10.206503 IP localhost.1700 > localhost.34268: UDP, length 4
E.. .'@.@....................x..
11:42:10.968420 IP localhost.43827 > localhost.1700: UDP, length 113
E....h@.@............3...y.......UZ.....{"stat":{"time":"2017-09-11 11:42:10 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
11:42:10.970702 IP localhost.1700 > localhost.43827: UDP, length 4
E.. .i@.@..b...........3........
11:42:20.284752 IP localhost.34268 > localhost.1700: UDP, length 12
E..(..@.@..................'.....UZ.....
11:42:20.289256 IP localhost.1700 > localhost.34268: UDP, length 4
E.. ..@.@.......................
11:42:30.364780 IP localhost.34268 > localhost.1700: UDP, length 12
E..( .@.@..................'.S7..UZ.....
11:42:30.366310 IP localhost.1700 > localhost.34268: UDP, length 4
E..  .@.@....................S7.

Do you have any clue why it cannot return any data from the bridge to the gateway?

PS: I will try to provide the WireShark capture next time if necessary

yusuf3650 · July 29, 2019, 3:00pm

We’re having same error.

-- Reboot --
jul 29 16:44:14 diplom-e18 systemd[1]: Started LoRa Gateway Bridge.
jul 29 16:44:15 diplom-e18 lora-gateway-bridge[977]: time="2019-07-29T16:44:15+02:00" level=info msg="starting LoRa Gateway Bridge" docs="https://www.loraserver.io/lora-gateway-bridge/" version=3.0.1
jul 29 16:44:15 diplom-e18 lora-gateway-bridge[977]: time="2019-07-29T16:44:15+02:00" level=info msg="backend/semtechudp: starting gateway udp listener" addr="0.0.0.0:1700"
jul 29 16:44:15 diplom-e18 lora-gateway-bridge[977]: time="2019-07-29T16:44:15+02:00" level=info msg="integration/mqtt: connected to mqtt broker"
jul 29 16:54:09 diplom-e18 lora-gateway-bridge[977]: time="2019-07-29T16:54:09+02:00" level=info msg="signal received" signal=terminated
jul 29 16:54:09 diplom-e18 lora-gateway-bridge[977]: time="2019-07-29T16:54:09+02:00" level=warning msg="shutting down server"

When we’re running following command:

mosquitto_sub -v -t “gateway/#” --cafile /etc/mosquitto/ca_certificates/ca.crt --cert /etc/mosquitto/certs/client.crt --key /etc/mosquitto/certs/client.key -d -h HOSTNAME -p 8883

We can see that the broker is receiving data from the gateway:

Client mosq/3SZs3GoEbR7u2hQuR6 received PUBLISH (d0, q0, r0, m0, 'gateway/{ID OF GATEWAY}/stats', ... (181 bytes))

gateway/{ID OF GATEWAY}/stats {"mac":"{ID OF GATEWAY}","time":"2019-07-29T14:58:48Z","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"customData":{"ip":"{IP OF GATEWAY}"}}

Unfortunately, our lora-gateway-bridge is not retrieving the data as it should, and the gateway wont transmit og receive frames in our web-interface. Do you know what to do here?

It’s important for us to fix this, as we want our gateway to work ASAP

cstratton · July 29, 2019, 6:45pm

Are you sure you have any actual LoRaWan traffic that should be triggering a downlink transmission?

The single MQTT message from the gateway which you quote is a stats one, those are sent all the time even in the absence of any radio traffic, and in fact that one you quote shows no radio traffic during that period (though obviously there could have been some just before or just after, the stats periods are quite brief)

Key questions would be:

Do you actually see raw uplinks, both as gateway/xxxx/rx in MQTT and in the LoRaServer console
Do these decode to valid node messages?
Does the console show downlinks being sent
Do you see downlink messages on the gateway/xxxxx/topics in MQTT when you continue that command line mosquitto test?

yusuf3650 · July 30, 2019, 10:09am

We dont have any traffic at the moment. Our top priority is to make the gateway work, before we set up any devices. Before we encrypted MQTT, it would atleast tell us when it was last seen and not just ‘invalid date’

The only message i see when running the, mosquitto test, command line is the following:

 Client mosq/oSunsXcGbZdb0RaiGW received PUBLISH (d0, q0, r0, m0, 'gateway/xxx/stats', ... (181 bytes))
    gateway/xxx/stats {"mac":"xxx","time":"2019-07-30T10:13:50Z","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"customData":{"ip":"xxx"}}

cstratton · July 30, 2019, 10:41am

Then you cannot expect a gateway to do anything but send stats messages.

To get any more “interesting” behavior you will have to have some node traffic for the gateway to hear, report in, and perhaps be requested to transmit replies to.