search

chirpstack / chirpstack-gateway-bridge

ChirpStack Gateway Bridge abstracts Packet Forwarder protocols into Protobuf or JSON over MQTT.
https://www.chirpstack.io
MIT License
423 stars 270 forks source link

Dequeue-ing, but not transmitting? #47

Closed PhatHub closed 7 years ago

PhatHub commented 7 years ago

This is in reference to brocaar/lora-app-server#114

Symptoms:

Hardware:

The original question asked for debugging guidance and what configuration settings I may be overlooking that might cause this.

Thank you... if you need more information, I'll be happy to provide it. I'll try to get you the log file(s) as soon as possible.

PhatHub commented 7 years ago

Just to update, I do not have any log files in the /var/log/lora* directories. Viewing the MQTT stream for gateways has not shown any "txInfo" JSON structures.

brocaar commented 7 years ago

When your system uses systemd, you can see the logfiles with journalctl -f -n 100 -u lora-gateway-bridge

Please note that when nothing has been published to the gateway/[MAC]/tx MQTT topic, no data (PULL_RESP) will be send to the gateway.

PhatHub commented 7 years ago

I've been queueing via the RESTful web interface, not the MQTT, so I'll look into doing it that way.

(Note: This is with the web interface) I queued a packet, and the below is what journalctl showed from when the packet was queued and when it was approximately de-queued:

Jul 17 12:39:19 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:19-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:39:19 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:19-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:39:31 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:31-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:39:31 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:31-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:39:43 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:43-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:39:43 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:43-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:39:55 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:55-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:39:55 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:39:55-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:40:08 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:08-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:40:08 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:08-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:40:13 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:13-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:34629 protocol_version=1 type=PushData Jul 17 12:40:13 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:13-04:00" level=info msg="gateway: rxpk packet received" addr=10.1.107.251:34629 data=QAQDAgEA6mUB306sYGju mac=fffeb827ebf64bf7 Jul 17 12:40:13 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:13-04:00" level=info msg="backend: publishing packet" topic="gateway/fffeb827ebf64bf7/rx" Jul 17 12:40:13 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:13-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:34629 protocol_version=1 type=PushACK Jul 17 12:40:20 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:20-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullData Jul 17 12:40:20 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:20-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:49053 protocol_version=1 type=PullACK Jul 17 12:40:26 theserver lora-gateway-bridge[7258]: time="2017-07-17T12:40:26-04:00" level=info msg="gateway: received udp packet from gateway" addr=10.1.107.251:34629 protocol_version=1 type=PushData

PhatHub commented 7 years ago

I'm trying to use paho for my client and I created the following:

!/usr/bin/python

import paho.mqtt.client as mqtt mac="fffeb827ebf64bf7" payload='{\ "reference": "abcd1234",\ "confirmed": true,\ "fPort": 1,\ "data": "AAAAA"\ }' client = mqtt.Client() client.connect("127.0.0.1") client.subscribe("gateway/"+mac+"/tx") client.publish("gateway/"+mac+"/tx",payload)

I ran it, but nothing "tx" showed up in the journalctl, mosquitto_sub, or my sniffer logs. :-/ Am I creating the payload correctly?

PhatHub commented 7 years ago

Forgive me, but more mysteries...

Something happened where my python sniffer is now reporting a PullResp:

PUSH_ACK'd PULL_RESP !!!!!! Payload: {"imme":false,"tmst":3335476076,"freq":923.3,"rfch":0,"powe":20,"modu":"LORA","datr":"SF10BW125","codr":"4/5","ipol":true,"size":16,"data":"oAQDAgEQDQABNVfqU5D4DQ=="}}

The journalctl is also showing similar traffic:

[snip] lora-gateway-bridge[7258]: time="2017-07-18T17:20:28-04:00" level=info msg="gateway: rxpk packet received" addr=10.1.107.251:46750 data="QAQDAgEAVxcB/aUg5Ykn" mac=fffeb827ebf64bf7 [snip] lora-gateway-bridge[7258]: time="2017-07-18T17:20:28-04:00" level=info msg="backend: publishing packet" topic="gateway/fffeb827ebf64bf7/rx" [snip] lora-gateway-bridge[7258]: time="2017-07-18T17:20:28-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:46750 protocol_version=1 type=PushACK [snip] lora-gateway-bridge[7258]: time="2017-07-18T17:20:28-04:00" level=info msg="backend: packet received" topic="gateway/fffeb827ebf64bf7/tx" [snip] lora-gateway-bridge[7258]: time="2017-07-18T17:20:28-04:00" level=info msg="gateway: sending udp packet to gateway" addr=10.1.107.251:35634 protocol_version=1 type=PullResp

Not sure what was the cause of this, unfortunately. :( I made a change to the data field in the web interface with a different Base64 value.

~However, also odd is that the web interface API is not showing the queued downlink packets popping out of the queue. So the gateway is getting the same downlink packet over and over again, but the DownlinkQueue is showing that it's not de-queueing. the only way I can get it out is to issue a RESTful delete, and it will stop sending the PullResp packets.~

update: I forced the downlink packet to be "confirmed:true" so that's probably why it didn't get cleared out of the queue... The mote didn't ack, and so the server holds the packet in the queue.

I haven't even tried to see if there's a transmission, but the mDot is still indicating that it's not getting any downlink packets. Maybe there's a parameter in setting up the mDot that's incorrect... :-/

brocaar commented 7 years ago

In case of confirmed: true it is not surprising that the frame gets send over and over again. The node did ACK the frame, so the server sees the transmission as not successful. Please check your frame counters (which could be the reason why the mDot rejects the frame).

PhatHub commented 7 years ago

Ok, I will check the mDot...

Ok! I followed the mDot's uplink/downlink counters. The downlink counter is increasing on the Loraserver UI, but the mDot's downlink is staying "0". I checked the uplink to make sure I was accessing the correct object, and the uplink counter matches the uplink reported in the loraserver UI.

PhatHub commented 7 years ago

@brocaar Another update. I think it's mDot's timing, or a failure to set up correct parameters for receiving the downlink.

I have GQRX looking at 923.3 (as specified for US915 RX2), and it shows that a transmit burst is happening. I'm sending out uplinks with a request for an ACK, and as far as I know, the server is transmitting the ACK. However, the mDot debugging will declare that it didn't receive an ACK, thus "failed to send to gateway", and it also can't read the downlinks, saying that "the [recv] operation timed out". (error #-5)

So I'll close this, but I hope that someone with an mDot has some hints on how to get downlink working with mDot/mbed v5... but as of right now it's not caused by your project.