[US915] OTAA JoinAccept not received on node, possible downlink problem

Hi everyone. We’re trying to implement a LoRa network in my college, for which we’re using a Multitech Conduit gateway with the Multi Protocol Packet Forwarder (https://github.com/kersing/packet_forwarder) using the US915 frequency plan, set up to forward packets to a LoRa Server instance we installed in our network, with LoPy and Microchip RN2903 nodes. We were doing some tests with the nodes, trying to make an OTAA Join, but we encountered a problem. We can see the Join Requests at the LoRa Server web log, and also that a Join Accept is generated, but the nodes aren’t receiving the Accept for some reason. Also, when using ABP, and sending a confirmed uplink (tested with the Microchip node), the packet is received but the acknowledgement isn’t generated. We tried running tcpdump at the gateway and we can see that the downlink Join Accept packets are arriving, but they never arrive to the nodes, so we’re suspecting that it can be a problem regarding the frequency channels, but we can’t find where the failure is.
These are the LoRa Server logs:

Gateway Bridge:
feb 08 11:02:59 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:02:59-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/ack”
feb 08 11:03:02 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:02-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:02 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:02-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:07 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:07-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:07 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:07-03:00” level=info msg=“gateway: stat packet received” addr=192.168.1.9:51252 mac=00800000a0001261
feb 08 11:03:07 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:07-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/stats”
feb 08 11:03:07 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:07-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“gateway: rxpk packet received” addr=192.168.1.9:51252 data=“AAEBAQEBAQEB+q8PlEnVs3D2RHYLJUo=” mac=00800000a0001261
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/rx”
feb 08 11:03:13 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:13-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:14 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:14-03:00” level=info msg=“backend: packet received” topic=“gateway/00800000a0001261/tx”
feb 08 11:03:14 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:14-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullResp
feb 08 11:03:14 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:14-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=TXACK
feb 08 11:03:14 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:14-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/ack”
feb 08 11:03:23 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:23-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:23 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:23-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:28 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:28-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:28 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:28-03:00” level=info msg=“gateway: rxpk packet received” addr=192.168.1.9:51252 data=“AAEBAQEBAQEB+q8PlEnVs3DJp8omqLo=” mac=00800000a0001261
feb 08 11:03:28 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:28-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/rx”
feb 08 11:03:28 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:28-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:29 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:29-03:00” level=info msg=“backend: packet received” topic=“gateway/00800000a0001261/tx”
feb 08 11:03:29 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:29-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullResp
feb 08 11:03:29 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:29-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=TXACK
feb 08 11:03:29 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:29-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/ack”
feb 08 11:03:33 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:33-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:33 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:33-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:37 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:37-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:37 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:37-03:00” level=info msg=“gateway: stat packet received” addr=192.168.1.9:51252 mac=00800000a0001261
feb 08 11:03:37 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:37-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/stats”
feb 08 11:03:37 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:37-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“gateway: rxpk packet received” addr=192.168.1.9:51252 data=“AAEBAQEBAQEB+q8PlEnVs3DHoYE60aY=” mac=00800000a0001261
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/rx”
feb 08 11:03:43 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:43-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:44 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:44-03:00” level=info msg=“backend: packet received” topic=“gateway/00800000a0001261/tx”
feb 08 11:03:44 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:44-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullResp
feb 08 11:03:44 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:44-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=TXACK
feb 08 11:03:44 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:44-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/ack”
feb 08 11:03:53 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:53-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullData
feb 08 11:03:53 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:53-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullACK
feb 08 11:03:58 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:58-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushData
feb 08 11:03:58 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:58-03:00” level=info msg=“gateway: rxpk packet received” addr=192.168.1.9:51252 data=“AAEBAQEBAQEB+q8PlEnVs3Ce4taN2J8=” mac=00800000a0001261
feb 08 11:03:58 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:58-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/rx”
feb 08 11:03:58 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:58-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:51252 protocol_version=2 type=PushACK
feb 08 11:03:59 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:59-03:00” level=info msg=“backend: packet received” topic=“gateway/00800000a0001261/tx”
feb 08 11:03:59 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:59-03:00” level=info msg=“gateway: sending udp packet to gateway” addr=192.168.1.9:42724 protocol_version=2 type=PullResp
feb 08 11:03:59 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:59-03:00” level=info msg=“gateway: received udp packet from gateway” addr=192.168.1.9:42724 protocol_version=2 type=TXACK
feb 08 11:03:59 loraserverlcd-VirtualBox lora-gateway-bridge[986]: time=“2018-02-08T11:03:59-03:00” level=info msg=“backend: publishing packet” topic=“gateway/00800000a0001261/ack”

LoRa Server:

– Logs begin at jue 2018-02-08 09:13:27 -03. –
feb 08 11:55:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:55:38-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:55:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:55:38-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:56:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:56:08-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:56:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:56:08-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:56:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:56:38-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:56:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:56:38-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:57:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:57:08-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:57:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:57:08-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:57:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:57:38-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:57:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:57:38-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:58:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:58:08-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:58:08 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:58:08-03:00” level=info msg=“gateway updated” mac=00800000a0001261
feb 08 11:58:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:58:38-03:00” level=info msg=“backend/gateway: gateway stats packet received” mac=00800000a0001261
feb 08 11:58:38 loraserverlcd-VirtualBox loraserver[987]: time=“2018-02-08T11:58:38-03:00” level=info msg=“gateway updated” mac=00800000a0001261

LoRa App Server:
– Logs begin at jue 2018-02-08 09:13:27 -03. –
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=2.799 span.kind=client system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T11:51:39-03:00” grpc.time_ms=6.124 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=2.858 span.kind=client system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T11:51:39-03:00” grpc.time_ms=6.235 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=2.783 span.kind=client system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T11:51:39-03:00” grpc.time_ms=6.193 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=2.888 span.kind=client system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T11:51:39-03:00” grpc.time_ms=6.282 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=2.874 span.kind=client system=grpc
feb 08 11:51:39 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T11:51:39-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T11:51:39-03:00” grpc.time_ms=6.17 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 12:02:04 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T12:02:04-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=Get grpc.service=api.Application grpc.start_time=“2018-02-08T12:02:04-03:00” grpc.time_ms=8.404 peer.address=“127.0.0.1:32834” span.kind=server system=grpc
feb 08 12:02:04 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T12:02:04-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=Get grpc.service=api.Device grpc.start_time=“2018-02-08T12:02:04-03:00” grpc.time_ms=10.098 peer.address=“127.0.0.1:32818” span.kind=server system=grpc
feb 08 12:02:04 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T12:02:04-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=List grpc.service=api.DeviceProfileService grpc.start_time=“2018-02-08T12:02:04-03:00” grpc.time_ms=6.054 peer.address=“127.0.0.1:32832” span.kind=server system=grpc
feb 08 12:02:06 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T12:02:06-03:00” level=info msg=“finished client unary call” grpc.code=OK grpc.method=GetFrameLogsForDevEUI grpc.service=ns.NetworkServer grpc.time_ms=4.652 span.kind=client system=grpc
feb 08 12:02:06 loraserverlcd-VirtualBox lora-app-server[1099]: time=“2018-02-08T12:02:06-03:00” level=info msg=“finished unary call with code OK” grpc.code=OK grpc.method=GetFrameLogs grpc.service=api.Device grpc.start_time=“2018-02-08T12:02:06-03:00” grpc.time_ms=10.631 peer.address=“127.0.0.1:32818” span.kind=server system=grpc

Thanks for reading!

I think the best place is to see if you can get access to the packet-forwarder logs on the gateway. That is the last place between the UDP frames sent by LoRa Gateway Bridge and the actual transmission.

Thanks for the reply brocaar! Here’s the packet-forwarder log from the gateway:

14:13:14  *** Multi Protocol Packet Forwarder for Lora Gateway ***
Version: 3.0.10
14:13:14  *** Lora concentrator HAL library version info ***
Version: 5.0.1; Options: ftdi;
***
14:13:14  INFO: Little endian host
14:13:14  INFO: found global configuration file /var/config/lora/global_conf.json, parsing it
14:13:14  INFO: /var/config/lora/global_conf.json does contain a JSON object named SX1301_conf, parsing SX1301 parameters
14:13:14  INFO: lorawan_public 1, clksrc 0
lgw_board_setconf:437: Note: board configuration; lorawan_public:1, clksrc:0
14:13:14  INFO: no configuration for LBT
14:13:14  INFO: antenna_gain 0 dBi
14:13:14  INFO: Configuring TX LUT with 16 indexes
14:13:14  INFO: radio 0 enabled (type SX1257), center frequency 902700000, RSSI offset -166.000000, tx enabled 1
lgw_rxrf_setconf:486: WARNING: NOT A VALID TX NOTCH FILTER FREQUENCY [126000..250000]Hz
lgw_rxrf_setconf:498: Note: rf_chain 0 configuration; en:1 freq:902700000 rssi_offset:-166.000000 radio_type:2 tx_enable:1 tx_notch_freq:0
14:13:14  INFO: radio 1 enabled (type SX1257), center frequency 903500000, RSSI offset -166.000000, tx enabled 0
lgw_rxrf_setconf:498: Note: rf_chain 1 configuration; en:1 freq:903500000 rssi_offset:-166.000000 radio_type:2 tx_enable:0 tx_notch_freq:0
14:13:14  INFO: Lora multi-SF channel 0>  radio 0, IF -400000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 0 configuration; en:1 freq:-400000 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 1>  radio 0, IF -200000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 1 configuration; en:1 freq:-200000 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 2>  radio 0, IF 0 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 2 configuration; en:1 freq:0 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 3>  radio 0, IF 200000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 3 configuration; en:1 freq:200000 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 4>  radio 1, IF -400000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 4 configuration; en:1 freq:-400000 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 5>  radio 1, IF -200000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 5 configuration; en:1 freq:-200000 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 6>  radio 1, IF 0 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 6 configuration; en:1 freq:0 SF_mask:0x7e
14:13:14  INFO: Lora multi-SF channel 7>  radio 1, IF 200000 Hz, 125 kHz bw, SF 7 to 12
lgw_rxif_setconf:617: Note: LoRa 'multi' if_chain 7 configuration; en:1 freq:200000 SF_mask:0x7e
14:13:14  INFO: Lora std channel> radio 0, IF 300000 Hz, 500000 Hz bw, SF 8
lgw_rxif_setconf:591: Note: LoRa 'std' if_chain 8 configuration; en:1 freq:300000 bw:1 dr:4
14:13:14  INFO: FSK channel 8 disabled
lgw_rxif_setconf:525: Note: if_chain 9 disabled
14:13:14  INFO: /var/config/lora/global_conf.json does contain a JSON object named gateway_conf, parsing gateway parameters
14:13:14  INFO: gateway MAC address is configured to 00800000A0001261
14:13:14  INFO: Found 1 servers in array.
14:13:14  INFO: Server 0 configured to "192.168.1.226"
14:13:14  INFO: downstream keep-alive interval is configured to 10 seconds
14:13:14  INFO: statistics display interval is configured to 30 seconds
14:13:14  INFO: upstream PUSH_DATA time-out is configured to 100 ms
14:13:14  INFO: packets received with a valid CRC will be forwarded
14:13:14  INFO: packets received with a CRC error will NOT be forwarded
14:13:14  INFO: packets received with no CRC will NOT be forwarded
14:13:14  INFO: GPS is disabled
14:13:14  INFO: Upstream data is enabled
14:13:14  INFO: Downstream data is enabled
14:13:14  INFO: Ghoststream data is disabled
14:13:14  INFO: Radiostream data is enabled
14:13:14  INFO: Statusstream data is enabled
14:13:14  INFO: Beacon is disabled
14:13:14  INFO: Monitor is disabled
14:13:14  INFO: Packet logger is disabled
14:13:14  INFO: Flush output after statistic is disabled
14:13:14  INFO: Flush after each line of output is disabled
14:13:14  INFO: Watchdog is disabled
14:13:14  INFO: Platform configured to "MultiTech"
14:13:14  INFO: [Transports] Initializing protocol for 1 servers
14:13:14  INFO: Successfully contacted server 192.168.1.226
14:13:14  INFO: [main] Starting the concentrator
lgw_connect:532: INFO: no FPGA detected or version not supported (v103)
Note: success connecting the concentrator
lgw_setup_sx125x:407: Note: SX125x #0 version register returned 0x21
lgw_setup_sx125x:412: Note: SX125x #0 clock output enabled
lgw_setup_sx125x:469: Note: SX125x #0 PLL start (attempt 1)
lgw_setup_sx125x:407: Note: SX125x #1 version register returned 0x21
lgw_setup_sx125x:415: Note: SX125x #1 clock output disabled
lgw_setup_sx125x:469: Note: SX125x #1 PLL start (attempt 1)
lgw_start:833: Note: calibration started (time: 2300 ms)
lgw_start:854: Note: calibration finished (status = 191)
Info: Initialising AGC firmware...
Info: putting back original RADIO_SELECT value
14:13:19  INFO: [main] concentrator started, radio packets can now be received.
14:13:19  INFO: Disabling GPS mode for concentrator's counter...
14:13:19  INFO: JIT thread activated.
14:13:19  INFO: [up] Thread activated for all servers.
14:13:19  INFO: host/sx1301 time offset=(1518099196s:32055µs) - drift=55587895µs
14:13:19  INFO: Enabling GPS mode for concentrator's counter.

lgw_receive:1165: FIFO content: 1 10 0 5 17
lgw_receive:1184: [8 16]
Note: LoRa packet
Info: packet will be sent without CRC
a6.d3.33.2.96.51.aa.b.0.17.11.16.0.8.0.0.20.f3.c6.c8.1.44.b9.58.5c.7b.ce.8d.13.a0.f3.28.60.end

##### 2018-02-08 14:13:49 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 0
# CRC_OK: 0.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 0 (0 bytes)
# PUSH_DATA datagrams sent: 0 (0 bytes)
# PUSH_DATA acknowledged: 0.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (66.67% acknowledged)
# PULL_RESP(onse) datagrams received: 0 (0 bytes)
# RF packets sent to concentrator: 0 (0 bytes)
# TX errors: 0
### BEACON IS DISABLED! 
### [JIT] ###
# INFO: JIT queue contains 0 packets.
# INFO: JIT queue contains 0 beacons.
### GPS IS DISABLED! 
### [PERFORMANCE] ###
# Upstream radio packet quality: 0.00%.
# Upstream datagram acknowledgment quality for server "192.168.1.226" is 0.00%.
# Downstream heart beat acknowledgment quality for server "192.168.1.226" is 66.67%.
# Downstream datagram content quality for server "192.168.1.226" is 0.00%.
# Downstream radio transmission quality for server "192.168.1.226" is 66.67%.
# Semtech status report send. 
##### END #####
INFO: tx_start_delay=1497 (1497.000000) - (1497, bw_delay=0.000000, notch_delay=0.000000)

##### 2018-02-08 14:14:19 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 1
# CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 1 (23 bytes)
# PUSH_DATA datagrams sent: 2 (415 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (192 bytes)
# RF packets sent to concentrator: 1 (17 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:1, rej:0)
# TX rejected (collision beacon): 0.00% (req:1, rej:0)
# TX rejected (too late): 0.00% (req:1, rej:0)
# TX rejected (too early): 0.00% (req:1, rej:0)
### BEACON IS DISABLED! 
### [JIT] ###
# INFO: JIT queue contains 0 packets.
# INFO: JIT queue contains 0 beacons.
### GPS IS DISABLED! 
### [PERFORMANCE] ###
# Upstream radio packet quality: 100.00%.
# Upstream datagram acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream heart beat acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream datagram content quality for server "192.168.1.226" is 100.00%.
# Downstream radio transmission quality for server "192.168.1.226" is 100.00%.
# Semtech status report send. 
##### END #####
14:14:19  INFO: Disabling GPS mode for concentrator's counter...
14:14:19  INFO: host/sx1301 time offset=(1518099196s:31546µs) - drift=-509µs
14:14:19  INFO: Enabling GPS mode for concentrator's counter.


##### 2018-02-08 14:14:49 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 0
# CRC_OK: 0.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 0 (0 bytes)
# PUSH_DATA datagrams sent: 1 (182 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 0 (0 bytes)
# RF packets sent to concentrator: 0 (0 bytes)
# TX errors: 0
### BEACON IS DISABLED! 
### [JIT] ###
# INFO: JIT queue contains 0 packets.
# INFO: JIT queue contains 0 beacons.
### GPS IS DISABLED! 
### [PERFORMANCE] ###
# Upstream radio packet quality: 0.00%.
# Upstream datagram acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream heart beat acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream datagram content quality for server "192.168.1.226" is 0.00%.
# Downstream radio transmission quality for server "192.168.1.226" is 100.00%.
# Semtech status report send. 
##### END #####

##### 2018-02-08 14:15:19 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 0
# CRC_OK: 0.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 0 (0 bytes)
# PUSH_DATA datagrams sent: 1 (182 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 0 (0 bytes)
# RF packets sent to concentrator: 0 (0 bytes)
# TX errors: 0
### BEACON IS DISABLED! 
### [JIT] ###
# INFO: JIT queue contains 0 packets.
# INFO: JIT queue contains 0 beacons.
### GPS IS DISABLED! 
### [PERFORMANCE] ###
# Upstream radio packet quality: 0.00%.
# Upstream datagram acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream heart beat acknowledgment quality for server "192.168.1.226" is 100.00%.
# Downstream datagram content quality for server "192.168.1.226" is 0.00%.
# Downstream radio transmission quality for server "192.168.1.226" is 100.00%.
# Semtech status report send. 
##### END #####
14:15:19  INFO: Disabling GPS mode for concentrator's counter...
14:15:19  INFO: host/sx1301 time offset=(1518099196s:31026µs) - drift=-520µs
14:15:19  INFO: Enabling GPS mode for concentrator's counter.

@brocaar Any advice on this? We’re still having the same problem, and we can see in the logs that the downlink packet arrives:

### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (192 bytes)
# RF packets sent to concentrator: 1 (17 bytes)

I don’t know and I’m afraid I can’t give any support on this. I see you’re using the multi protocol packet-forwarder. I would recommend to first use the default Semtech packet-forwarder as a starting point and see if that works.

Maybe you can use some SDR and check are those packets visible in the air?
You will see the frequency then.
If you can see packets in the air you can maybe check RX windows timing …