MQTT Bridge Reconnection after Network Outage or Network Setup Changes

xflash · January 14, 2021, 3:38pm

Issue: MQTT Bridge does not reconnect after network outage or network setup changes

Setup: Firmware V1.1.0063_Release_r205

LoRa® Server: OFF

Details:
I’m using MQTT bridge connected to external Chirpstack network server through OpenVPN connection. The gateway uses 4G LTE as main backhaul and when ethernet plugged in, it will automatically switch to ethernet, and the network/openvpn will be restarted. I write scripts to check the connection (ping) on VPN (tun0) interface, 4G LTE (wwan0) and use ping-watchdog on the ethernet (wan). The problem is that sometimes, when the network and openvpn has been restarted, the loragwbridge cannot connect to the target server and no reconnection when this happen. Sometimes, the loragwbridge started when openvpn has not been connected completely.

Here is the script:

#!/bin/sh

# Check if tunnel interface exist
iface=tun0
ip a show $iface up >> /dev/null
rc=$?
if [[ ! $rc -eq 0 ]]; then
   exit
fi

# Check ping
count=3
while [[ $count -ne 0 ]] ; do
    ping -I $iface -c 1 8.8.8.8 > /dev/null
    rc=$?
    if [[ $rc -eq 0 ]] ; then
        count=1
    fi
    count=$((count-1))
done

# Restart ovpn 
if [[ ! $rc -eq 0 ]] ; then
    logger -t check_vpn "No vpn connection, restarting vpn"
    /etc/init.d/network restart
    sleep 20
    /etc/init.d/openvpn restart
    sleep 20
    /etc/init.d/loragwbridge restart
fi

PS: when using mqtt bridge json v3, no location data sent on stats

xflash · January 14, 2021, 3:39pm

Here is the log when reconnection success:

Tue Jan 12 17:36:30 2021 user.notice check_vpn: No vpn connection, restarting vpn
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'alias' is now down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'lan' is now down
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.020000] br-lan: port 2(ra0) entered disabled state
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.030000] br-lan: port 1(eth0.1) entered disabled state
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.040000] device eth0.1 left promiscuous mode
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.050000] device eth0 left promiscuous mode
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.060000] br-lan: port 1(eth0.1) entered disabled state
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.080000] device ra0 left promiscuous mode
Tue Jan 12 17:36:30 2021 kern.info kernel: [ 5576.090000] br-lan: port 2(ra0) entered disabled state
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'lan' is disabled
Tue Jan 12 17:36:30 2021 daemon.notice netifd: VLAN 'eth0.1' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Bridge 'br-lan' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'lan' has link connectivity loss
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'loopback' is now down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'loopback' is disabled
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Network device 'lo' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'loopback' has link connectivity loss
Tue Jan 12 17:36:30 2021 user.notice ping-watchdog: alias  ifdown
Tue Jan 12 17:36:30 2021 daemon.notice netifd: wan (1508): Received SIGTERM
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wan' is now down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wan' is disabled
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'alias' is disabled
Tue Jan 12 17:36:30 2021 daemon.warn dnsmasq[1813]: no servers found in /tmp/resolv.conf.auto, will retry
Tue Jan 12 17:36:30 2021 daemon.notice netifd: VLAN 'eth0.2' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wan' has link connectivity loss
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'alias' has link connectivity loss
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Network device 'eth0' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: wwan (4020): Received SIGTERM
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wwan' is now down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wwan' is disabled
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Network device 'wwan0' link is down
Tue Jan 12 17:36:30 2021 daemon.notice netifd: Interface 'wwan' has link connectivity loss
Tue Jan 12 17:36:31 2021 user.notice ping-watchdog: lan  ifdown
Tue Jan 12 17:36:33 2021 daemon.err openvpn(miota)[1677]: event_wait : Interrupted system call (code=4)
Tue Jan 12 17:36:33 2021 daemon.warn openvpn(miota)[1677]: ERROR: Linux route delete command failed: external program exited with error status: 1
Tue Jan 12 17:36:33 2021 daemon.notice openvpn(miota)[1677]: /sbin/ifconfig tun0 0.0.0.0
Tue Jan 12 17:36:33 2021 daemon.notice openvpn(miota)[1677]: SIGTERM[hard,] received, process exiting
Tue Jan 12 17:36:34 2021 daemon.info loraSrv[3994]: Handler for termination caught signal 15
Tue Jan 12 17:36:34 2021 daemon.info loraSrv[3994]: Exiting...
Tue Jan 12 17:36:34 2021 daemon.info loraSrv[3995]: Handler for termination caught signal 15
Tue Jan 12 17:36:34 2021 daemon.info loraSrv[3995]: Exiting...
Tue Jan 12 17:36:34 2021 daemon.info evloop[3995]: LEAVE evloopRun
Tue Jan 12 17:36:34 2021 daemon.info bufrd[3995]: ENTER bufrdDestroy `gwbridge-rd'
Tue Jan 12 17:36:34 2021 daemon.info loraSrv[3994]: child process 3995 exited with status 0
Tue Jan 12 17:36:34 2021 user.notice root: drv_ralink_cleanup
Tue Jan 12 17:36:34 2021 daemon.notice openvpn(miota)[4355]: OpenVPN 2.4.3 mipsel-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
Tue Jan 12 17:36:34 2021 daemon.notice openvpn(miota)[4355]: library versions: OpenSSL 1.0.2j  26 Sep 2016, LZO 2.08
Tue Jan 12 17:36:34 2021 daemon.err openvpn(miota)[4355]: RESOLVE: Cannot resolve host address: vpn.xxxxxx:1194 (Name or service not known)
Tue Jan 12 17:36:34 2021 daemon.err openvpn(miota)[4355]: RESOLVE: Cannot resolve host address: vpn.xxxxxx:1194 (Name or service not known)
Tue Jan 12 17:36:34 2021 daemon.warn openvpn(miota)[4355]: Could not determine IPv4/IPv6 protocol
Tue Jan 12 17:36:34 2021 daemon.notice openvpn(miota)[4355]: SIGUSR1[soft,init_instance] received, process restarting
Tue Jan 12 17:36:34 2021 kern.info kernel: [ 5580.000000] device eth0.1 entered promiscuous mode
Tue Jan 12 17:36:34 2021 kern.info kernel: [ 5580.010000] device eth0 entered promiscuous mode
Tue Jan 12 17:36:34 2021 kern.info kernel: [ 5580.020000] br-lan: port 1(eth0.1) entered forwarding state
Tue Jan 12 17:36:34 2021 kern.info kernel: [ 5580.030000] br-lan: port 1(eth0.1) entered forwarding state
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'lan' is enabled
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'lan' is setting up now
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'lan' is now up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wan' is enabled
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'alias' is enabled
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'alias' is setting up now
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'alias' is now up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'loopback' is enabled
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'loopback' is setting up now
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'loopback' is now up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wwan' is enabled
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Bridge 'br-lan' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'lan' has link connectivity 
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Network device 'eth0' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: VLAN 'eth0.1' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: VLAN 'eth0.2' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wan' has link connectivity 
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wan' is setting up now
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'alias' has link connectivity 
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Network device 'lo' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'loopback' has link connectivity 
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Network device 'wwan0' link is up
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wwan' has link connectivity 
Tue Jan 12 17:36:34 2021 daemon.notice netifd: Interface 'wwan' is setting up now
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wwan (4444): udhcpc: option -h NAME is deprecated, use -x hostname:NAME
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wwan (4444): udhcpc (v1.23.2) started
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wan (4447): udhcpc: option -h NAME is deprecated, use -x hostname:NAME
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wan (4447): udhcpc (v1.23.2) started
Tue Jan 12 17:36:35 2021 user.notice ping-watchdog: lan br-lan ifup
Tue Jan 12 17:36:35 2021 daemon.notice netifd: radio0 (4395): Interface doesn't accept private ioctl...
Tue Jan 12 17:36:35 2021 daemon.notice netifd: radio0 (4395): set (8BE2): Invalid argument
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wan (4447): Sending discover...
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wwan (4444): Sending discover...
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wwan (4444): Sending select for 10.10.99.106...
Tue Jan 12 17:36:35 2021 daemon.notice netifd: wwan (4444): Lease of 10.10.99.106 obtained, lease time 7200
Tue Jan 12 17:36:35 2021 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Tue Jan 12 17:36:35 2021 daemon.info loraSrv[4495]: Initializing signal handlers
Tue Jan 12 17:36:35 2021 daemon.notice netifd: Interface 'wwan' is now up
Tue Jan 12 17:36:35 2021 daemon.info dnsmasq[1813]: reading /tmp/resolv.conf.auto
Tue Jan 12 17:36:35 2021 daemon.info dnsmasq[1813]: using nameserver 8.8.4.4#53
Tue Jan 12 17:36:35 2021 daemon.info dnsmasq[1813]: using nameserver 8.8.8.8#53
Tue Jan 12 17:36:35 2021 daemon.info dnsmasq[1813]: using local addresses only for domain lan
Tue Jan 12 17:36:35 2021 daemon.info dnsmasq[1813]: using nameserver 192.168.134.30#53
Tue Jan 12 17:36:35 2021 daemon.info evloop[4506]: evloopInit Done.
Tue Jan 12 17:36:36 2021 daemon.info md[4506]: mdInit Done.
Tue Jan 12 17:36:36 2021 daemon.info mqttEv[4506]: mqttEvInit Done.
Tue Jan 12 17:36:36 2021 daemon.info unknown[4506]: gwManagerInit: Init gateway Manager
Tue Jan 12 17:36:36 2021 daemon.info bufrd[4506]: bufrdInit Done.
Tue Jan 12 17:36:36 2021 daemon.info bufrd[4506]: ENTER bufrdCreate `gwbridge-rd'
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: MQTT Init Start
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - version 3.1.1
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - Client ID rak_xxxxxxxxxxxxxxx
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - Retain 0
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - Clean Session 1
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - Qos 1
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Mqtt - keepalive 10
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: CA CERT File null
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: CA PATH /etc/ssl/certs/
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Client CERT File null
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: Client Key File null
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: TLS Version : tlsv1.2
Tue Jan 12 17:36:36 2021 daemon.info mqttEv[4506]: mqttEvRegister : Register mosquitto event [gwBridgeS Mqtt Client]
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: MQTT Init Done
Tue Jan 12 17:36:36 2021 daemon.info evloop[4506]: ENTER evloopRun
Tue Jan 12 17:36:36 2021 daemon.notice netifd: Network device 'ra0' link is up
Tue Jan 12 17:36:36 2021 kern.info kernel: [ 5581.610000] device ra0 entered promiscuous mode
Tue Jan 12 17:36:36 2021 kern.info kernel: [ 5581.620000] br-lan: port 2(ra0) entered forwarding state
Tue Jan 12 17:36:36 2021 kern.info kernel: [ 5581.630000] br-lan: port 2(ra0) entered forwarding state
Tue Jan 12 17:36:36 2021 daemon.info gwBridge[4506]: mosqConnectCB: Mqtt Connect Success ...
Tue Jan 12 17:36:36 2021 daemon.info mqttEv[4506]: [gwBridgeS Mqtt Client] subscribe gateway/xxxxxxxxxxxxxxx/command/down - QOS 1
Tue Jan 12 17:36:36 2021 kern.info kernel: [ 5582.030000] br-lan: port 1(eth0.1) entered forwarding state
Tue Jan 12 17:36:37 2021 user.notice ping-watchdog: alias eth0.2 ifup
Tue Jan 12 17:36:37 2021 user.notice firewall: Reloading firewall due to ifup of alias (eth0.2)
Tue Jan 12 17:36:38 2021 kern.info kernel: [ 5583.630000] br-lan: port 2(ra0) entered forwarding state
Tue Jan 12 17:36:38 2021 daemon.notice netifd: wan (4447): Sending discover...
Tue Jan 12 17:36:39 2021 user.notice ping-watchdog: loopback lo ifup
Tue Jan 12 17:36:39 2021 daemon.notice openvpn(miota)[4355]: TCP/UDP: Preserving recently used remote address: [AF_INET]xx.xx.xx.xx:1194
Tue Jan 12 17:36:39 2021 daemon.notice openvpn(miota)[4355]: UDP link local: (not bound)
Tue Jan 12 17:36:39 2021 daemon.notice openvpn(miota)[4355]: UDP link remote: [AF_INET]xx.xx.xx.xx:1194
Tue Jan 12 17:36:40 2021 daemon.warn openvpn(miota)[4355]: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1541', remote='link-mtu 1542'
Tue Jan 12 17:36:40 2021 daemon.warn openvpn(miota)[4355]: WARNING: 'comp-lzo' is present in remote config but missing in local config, remote='comp-lzo'
Tue Jan 12 17:36:40 2021 daemon.notice openvpn(miota)[4355]: [vpn.xxxxxx] Peer Connection Initiated with [AF_INET]xx.xx.xx.xx:1194
Tue Jan 12 17:36:40 2021 user.notice ping-watchdog: wwan wwan0 ifup
Tue Jan 12 17:36:40 2021 user.notice firewall: Reloading firewall due to ifup of wwan (wwan0)
Tue Jan 12 17:36:41 2021 daemon.notice netifd: wan (4447): Sending discover...
Tue Jan 12 17:36:41 2021 daemon.err openvpn(miota)[4355]: Options error: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:1: block-outside-dns (2.4.3)
Tue Jan 12 17:36:41 2021 daemon.notice openvpn(miota)[4355]: TUN/TAP device tun0 opened
Tue Jan 12 17:36:41 2021 daemon.notice openvpn(miota)[4355]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Tue Jan 12 17:36:41 2021 daemon.notice openvpn(miota)[4355]: /sbin/ifconfig tun0 192.168.255.70 pointopoint 192.168.255.69 mtu 1500
Tue Jan 12 17:36:41 2021 daemon.warn openvpn(miota)[4355]: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Tue Jan 12 17:36:41 2021 daemon.notice openvpn(miota)[4355]: Initialization Sequence Completed
Tue Jan 12 17:36:46 2021 daemon.info gwManager[4506]: create_gateway: Create Gateway xxxxxxxxxxxxxxx
Tue Jan 12 17:36:48 2021 daemon.info gwBridge[4506]: Stats : {"gatewayID":"xxxxxxxxxx","ip":"xx.xx.xx.xx","time":"2021-01-12T10:36:48Z","location":null,"configVersion":"unknown","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"metaData":{},"statsID":"ZPc8wckAR025Bc60t8sRpw=="}
Tue Jan 12 17:37:00 2021 cron.info crond[1427]: USER root pid 4911 cmd /root/checkvpn.sh

xflash · January 14, 2021, 3:40pm

and here when it fails:

Wed Jan 13 12:08:30 2021 user.notice check_vpn: No vpn connection, restarting vpn
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'alias' is now down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'lan' is now down
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.110000] br-lan: port 2(ra0) entered disabled state
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.120000] br-lan: port 1(eth0.1) entered disabled state
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.130000] device eth0.1 left promiscuous mode
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.140000] device eth0 left promiscuous mode
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.150000] br-lan: port 1(eth0.1) entered disabled state
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.160000] device ra0 left promiscuous mode
Wed Jan 13 12:08:30 2021 kern.info kernel: [72296.170000] br-lan: port 2(ra0) entered disabled state
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'lan' is disabled
Wed Jan 13 12:08:30 2021 daemon.notice netifd: VLAN 'eth0.1' link is down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Bridge 'br-lan' link is down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'lan' has link connectivity loss
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'loopback' is now down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'loopback' is disabled
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Network device 'lo' link is down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'loopback' has link connectivity loss
Wed Jan 13 12:08:30 2021 user.notice ping-watchdog: alias  ifdown
Wed Jan 13 12:08:30 2021 daemon.notice netifd: wan (10336): Received SIGTERM
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'wan' is now down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'wan' is disabled
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'alias' is disabled
Wed Jan 13 12:08:30 2021 daemon.notice netifd: VLAN 'eth0.2' link is down
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'wan' has link connectivity loss
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Interface 'alias' has link connectivity loss
Wed Jan 13 12:08:30 2021 daemon.notice netifd: Network device 'eth0' link is down
Wed Jan 13 12:08:30 2021 daemon.warn dnsmasq[1813]: no servers found in /tmp/resolv.conf.auto, will retry
Wed Jan 13 12:08:31 2021 daemon.notice netifd: wwan (10356): Received SIGTERM
Wed Jan 13 12:08:31 2021 daemon.notice netifd: Interface 'wwan' is now down
Wed Jan 13 12:08:31 2021 daemon.notice netifd: Interface 'wwan' is disabled
Wed Jan 13 12:08:31 2021 daemon.notice netifd: Network device 'wwan0' link is down
Wed Jan 13 12:08:31 2021 daemon.notice netifd: Interface 'wwan' has link connectivity loss
Wed Jan 13 12:08:31 2021 user.notice ping-watchdog: lan  ifdown
Wed Jan 13 12:08:32 2021 daemon.err openvpn(miota)[10265]: event_wait : Interrupted system call (code=4)
Wed Jan 13 12:08:32 2021 daemon.warn openvpn(miota)[10265]: ERROR: Linux route delete command failed: external program exited with error status: 1
Wed Jan 13 12:08:32 2021 daemon.notice openvpn(miota)[10265]: /sbin/ifconfig tun0 0.0.0.0
Wed Jan 13 12:08:32 2021 daemon.notice openvpn(miota)[10265]: SIGTERM[hard,] received, process exiting
Wed Jan 13 12:08:33 2021 daemon.notice openvpn(miota)[20901]: OpenVPN 2.4.3 mipsel-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
Wed Jan 13 12:08:33 2021 daemon.notice openvpn(miota)[20901]: library versions: OpenSSL 1.0.2j  26 Sep 2016, LZO 2.08
Wed Jan 13 12:08:33 2021 daemon.err openvpn(miota)[20901]: RESOLVE: Cannot resolve host address: vpn.lora.miota.id:1194 (Name or service not known)
Wed Jan 13 12:08:33 2021 daemon.err openvpn(miota)[20901]: RESOLVE: Cannot resolve host address: vpn.lora.miota.id:1194 (Name or service not known)
Wed Jan 13 12:08:33 2021 daemon.warn openvpn(miota)[20901]: Could not determine IPv4/IPv6 protocol
Wed Jan 13 12:08:33 2021 daemon.notice openvpn(miota)[20901]: SIGUSR1[soft,init_instance] received, process restarting
Wed Jan 13 12:08:33 2021 daemon.info loraSrv[16291]: Handler for termination caught signal 15
Wed Jan 13 12:08:33 2021 daemon.info loraSrv[16291]: Exiting...
Wed Jan 13 12:08:33 2021 daemon.info loraSrv[16292]: Handler for termination caught signal 15
Wed Jan 13 12:08:33 2021 daemon.info loraSrv[16292]: Exiting...
Wed Jan 13 12:08:33 2021 daemon.info evloop[16292]: LEAVE evloopRun
Wed Jan 13 12:08:33 2021 daemon.info bufrd[16292]: ENTER bufrdDestroy `gwbridge-rd'
Wed Jan 13 12:08:33 2021 daemon.info loraSrv[16291]: child process 16292 exited with status 0
Wed Jan 13 12:08:33 2021 user.notice root: drv_ralink_cleanup
Wed Jan 13 12:08:33 2021 kern.info kernel: [72299.060000] device eth0.1 entered promiscuous mode
Wed Jan 13 12:08:33 2021 kern.info kernel: [72299.070000] device eth0 entered promiscuous mode
Wed Jan 13 12:08:33 2021 kern.info kernel: [72299.100000] br-lan: port 1(eth0.1) entered forwarding state
Wed Jan 13 12:08:33 2021 kern.info kernel: [72299.110000] br-lan: port 1(eth0.1) entered forwarding state
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'lan' is enabled
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'lan' is setting up now
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'lan' is now up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wan' is enabled
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'alias' is enabled
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'alias' is setting up now
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'alias' is now up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'loopback' is enabled
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'loopback' is setting up now
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'loopback' is now up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wwan' is enabled
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Bridge 'br-lan' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'lan' has link connectivity 
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Network device 'eth0' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: VLAN 'eth0.1' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: VLAN 'eth0.2' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wan' has link connectivity 
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wan' is setting up now
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'alias' has link connectivity 
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Network device 'lo' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'loopback' has link connectivity 
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Network device 'wwan0' link is up
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wwan' has link connectivity 
Wed Jan 13 12:08:33 2021 daemon.notice netifd: Interface 'wwan' is setting up now
Wed Jan 13 12:08:34 2021 user.notice ping-watchdog: lan br-lan ifup
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wan (20989): udhcpc: option -h NAME is deprecated, use -x hostname:NAME
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wan (20989): udhcpc (v1.23.2) started
Wed Jan 13 12:08:34 2021 daemon.notice netifd: radio0 (20942): Interface doesn't accept private ioctl...
Wed Jan 13 12:08:34 2021 daemon.notice netifd: radio0 (20942): set (8BE2): Invalid argument
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wwan (21000): udhcpc: option -h NAME is deprecated, use -x hostname:NAME
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wwan (21000): udhcpc (v1.23.2) started
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wan (20989): Sending discover...
Wed Jan 13 12:08:34 2021 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wwan (21000): Sending discover...
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wwan (21000): Sending select for xx.xx.xx.xx...
Wed Jan 13 12:08:34 2021 daemon.notice netifd: wwan (21000): Lease of xx.xx.xx.xx obtained, lease time 7200
Wed Jan 13 12:08:35 2021 daemon.info loraSrv[21057]: Initializing signal handlers
Wed Jan 13 12:08:35 2021 daemon.info evloop[21059]: evloopInit Done.
Wed Jan 13 12:08:35 2021 daemon.info md[21059]: mdInit Done.
Wed Jan 13 12:08:35 2021 daemon.info mqttEv[21059]: mqttEvInit Done.
Wed Jan 13 12:08:35 2021 daemon.info unknown[21059]: gwManagerInit: Init gateway Manager
Wed Jan 13 12:08:35 2021 daemon.info bufrd[21059]: bufrdInit Done.
Wed Jan 13 12:08:35 2021 daemon.info bufrd[21059]: ENTER bufrdCreate `gwbridge-rd'
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: MQTT Init Start
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - version 3.1.1
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - Client ID rak_xxxxxxxxxxxxxxx
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - Retain 0
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - Clean Session 1
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - Qos 1
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Mqtt - keepalive 10
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: CA CERT File null
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: CA PATH /etc/ssl/certs/
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Client CERT File null
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: Client Key File null
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: TLS Version : tlsv1.2
Wed Jan 13 12:08:35 2021 daemon.err mqttEv[21059]: mqttEvConnectStart: [[gwBridgeS Mqtt Client]] Unable to connect
Wed Jan 13 12:08:35 2021 daemon.info gwBridge[21059]: MQTT Init Done
Wed Jan 13 12:08:35 2021 daemon.info evloop[21059]: ENTER evloopRun
Wed Jan 13 12:08:35 2021 daemon.notice netifd: Interface 'wwan' is now up
Wed Jan 13 12:08:35 2021 daemon.info dnsmasq[1813]: reading /tmp/resolv.conf.auto
Wed Jan 13 12:08:35 2021 daemon.info dnsmasq[1813]: using nameserver 8.8.4.4#53
Wed Jan 13 12:08:35 2021 daemon.info dnsmasq[1813]: using nameserver 8.8.8.8#53
Wed Jan 13 12:08:35 2021 daemon.info dnsmasq[1813]: using local addresses only for domain lan
Wed Jan 13 12:08:35 2021 daemon.info dnsmasq[1813]: using nameserver 192.168.134.30#53
Wed Jan 13 12:08:35 2021 daemon.notice netifd: Network device 'ra0' link is up
Wed Jan 13 12:08:35 2021 kern.info kernel: [72300.690000] device ra0 entered promiscuous mode
Wed Jan 13 12:08:35 2021 kern.info kernel: [72300.700000] br-lan: port 2(ra0) entered forwarding state
Wed Jan 13 12:08:35 2021 kern.info kernel: [72300.710000] br-lan: port 2(ra0) entered forwarding state
Wed Jan 13 12:08:35 2021 kern.info kernel: [72301.110000] br-lan: port 1(eth0.1) entered forwarding state
Wed Jan 13 12:08:36 2021 user.notice ping-watchdog: alias eth0.2 ifup
Wed Jan 13 12:08:36 2021 user.notice firewall: Reloading firewall due to ifup of alias (eth0.2)
Wed Jan 13 12:08:37 2021 kern.info kernel: [72302.710000] br-lan: port 2(ra0) entered forwarding state
Wed Jan 13 12:08:37 2021 daemon.notice netifd: wan (20989): Sending discover...
Wed Jan 13 12:08:38 2021 daemon.info mqttEv[21059]: mqttEvRegister : Register mosquitto event [gwBridgeS Mqtt Client]
Wed Jan 13 12:08:38 2021 user.notice ping-watchdog: loopback lo ifup
Wed Jan 13 12:08:38 2021 daemon.info gwManager[21059]: create_gateway: Create Gateway xxxxxxxxxxxxxxx
Wed Jan 13 12:08:39 2021 user.notice ping-watchdog: wwan wwan0 ifup
Wed Jan 13 12:08:39 2021 user.notice firewall: Reloading firewall due to ifup of wwan (wwan0)
Wed Jan 13 12:08:40 2021 daemon.notice netifd: wan (20989): Sending discover...
Wed Jan 13 12:08:43 2021 daemon.notice openvpn(miota)[20901]: TCP/UDP: Preserving recently used remote address: [AF_INET]xx.xx.xx.xx:1194
Wed Jan 13 12:08:43 2021 daemon.notice openvpn(miota)[20901]: UDP link local: (not bound)
Wed Jan 13 12:08:43 2021 daemon.notice openvpn(miota)[20901]: UDP link remote: [AF_INET]xx.xx.xx.xx:1194
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: 
##### 2021-01-13 05:08:50 UTC #####
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: ### [UPSTREAM] ###
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets received by concentrator: 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # CRC_OK: 0.00, CRC_FAIL: 0.00, NO_CRC: 0.00
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets forwarded: 0 (0 bytes)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA datagrams sent: 1 (179 bytes)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA acknowledged: 100.00
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: ### [DOWNSTREAM] ###
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # PULL_DATA sent: 6 (83.33 acknowledged)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets sent to concentrator: 0 (0 bytes)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # TX errors: 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # TX rejected (collision packet): 13.21 (req:159, rej:21)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # TX rejected (collision beacon): 0.00 (req:159, rej:0)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # TX rejected (too late): 0.63 (req:159, rej:1)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # TX rejected (too early): 66.67 (req:159, rej:106)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # BEACON queued: 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # BEACON sent so far: 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # BEACON rejected: 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: ### [JIT] ###
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # SX1301 time (PPS): 3538112076, offset us 0
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: ### [GPS] ###
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # Valid time reference (age: 1 sec)
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: # GPS coordinates: latitude -2.32104, longitude 103.90712, altitude 236 m
Wed Jan 13 12:08:51 2021 user.notice lora_pkt_fwd[1632]: ##### END #####
Wed Jan 13 12:08:51 2021 daemon.info gwBridge[21059]: Stats : {"gatewayID":"xxxxxxxxxx","ip":"xx.xx.xx.xx","time":"2021-01-13T05:08:51Z","location":null,"configVersion":"unknown","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"metaData":{},"statsID":"gNGZnNJLQsmm2GcpCyI9kw=="}
Wed Jan 13 12:09:00 2021 cron.info crond[1427]: USER root pid 21449 cmd /root/checkvpn.sh
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: 
##### 2021-01-13 05:09:21 UTC #####
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: ### [UPSTREAM] ###
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets received by concentrator: 2
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # CRC_OK: 0.00, CRC_FAIL: 100.00, NO_CRC: 0.00
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets forwarded: 0 (0 bytes)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA datagrams sent: 1 (179 bytes)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA acknowledged: 100.00
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: ### [DOWNSTREAM] ###
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # PULL_DATA sent: 6 (100.00 acknowledged)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets sent to concentrator: 0 (0 bytes)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: ### [JIT] ###
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # SX1301 time (PPS): 3568112088, offset us 0
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: ### [GPS] ###
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # Valid time reference (age: 1 sec)
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: # GPS coordinates: latitude -2.32105, longitude 103.90714, altitude 234 m
Wed Jan 13 12:09:21 2021 user.notice lora_pkt_fwd[1632]: ##### END #####
Wed Jan 13 12:09:21 2021 daemon.info gwBridge[21059]: Stats : {"gatewayID":"xxxxxxxxxx","ip":"xx.xx.xx.xx","time":"2021-01-13T05:09:21Z","location":null,"configVersion":"unknown","rxPacketsReceived":2,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"metaData":{},"statsID":"lQe4ZrHuQ/iT+2bt/zUKQA=="}
Wed Jan 13 12:09:43 2021 daemon.err openvpn(miota)[20901]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Wed Jan 13 12:09:43 2021 daemon.err openvpn(miota)[20901]: TLS Error: TLS handshake failed
Wed Jan 13 12:09:43 2021 daemon.notice openvpn(miota)[20901]: SIGUSR1[soft,tls-error] received, process restarting
Wed Jan 13 12:09:49 2021 daemon.notice openvpn(miota)[20901]: TCP/UDP: Preserving recently used remote address: [AF_INET]xx.xx.xx.xx:1194
Wed Jan 13 12:09:49 2021 daemon.notice openvpn(miota)[20901]: UDP link local: (not bound)
Wed Jan 13 12:09:49 2021 daemon.notice openvpn(miota)[20901]: UDP link remote: [AF_INET]xx.xx.xx.xx:1194
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: 
##### 2021-01-13 05:09:51 UTC #####
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: ### [UPSTREAM] ###
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets received by concentrator: 1
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # CRC_OK: 0.00, CRC_FAIL: 100.00, NO_CRC: 0.00
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets forwarded: 0 (0 bytes)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA datagrams sent: 1 (179 bytes)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA acknowledged: 100.00
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: ### [DOWNSTREAM] ###
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # PULL_DATA sent: 5 (100.00 acknowledged)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # RF packets sent to concentrator: 0 (0 bytes)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # SX1301 time (PPS): 3598112101, offset us 0
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: ### [GPS] ###
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # Valid time reference (age: 1 sec)
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: # GPS coordinates: latitude -2.32108, longitude 103.90712, altitude 233 m
Wed Jan 13 12:09:51 2021 user.notice lora_pkt_fwd[1632]: ##### END #####
Wed Jan 13 12:09:51 2021 daemon.info gwBridge[21059]: Stats : {"gatewayID":"xxxxxxxxxx","ip":"xx.xx.xx.xx","time":"2021-01-13T05:09:51Z","location":null,"configVersion":"unknown","rxPacketsReceived":1,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"metaData":{},"statsID":"Dy7oZ4S1RTyy6FMb7ALlhA=="}
Wed Jan 13 12:09:55 2021 daemon.warn openvpn(miota)[20901]: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1541', remote='link-mtu 1542'
Wed Jan 13 12:09:55 2021 daemon.warn openvpn(miota)[20901]: WARNING: 'comp-lzo' is present in remote config but missing in local config, remote='comp-lzo'
Wed Jan 13 12:09:55 2021 daemon.notice openvpn(miota)[20901]: [vpn.xxxx] Peer Connection Initiated with [AF_INET]xx.xx.xx.xx:1194
Wed Jan 13 12:09:56 2021 daemon.err openvpn(miota)[20901]: Options error: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:1: block-outside-dns (2.4.3)
Wed Jan 13 12:09:56 2021 daemon.notice openvpn(miota)[20901]: TUN/TAP device tun0 opened
Wed Jan 13 12:09:56 2021 daemon.notice openvpn(miota)[20901]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Wed Jan 13 12:09:56 2021 daemon.notice openvpn(miota)[20901]: /sbin/ifconfig tun0 192.168.255.70 pointopoint 192.168.255.69 mtu 1500
Wed Jan 13 12:09:56 2021 daemon.warn openvpn(miota)[20901]: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Wed Jan 13 12:09:56 2021 daemon.notice openvpn(miota)[20901]: Initialization Sequence Completed
Wed Jan 13 12:10:00 2021 cron.info crond[1427]: USER root pid 21477 cmd /root/checkvpn.sh
Wed Jan 13 12:10:00 2021 cron.info crond[1427]: USER root pid 21478 cmd /root/checkmodem.sh
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: 
##### 2021-01-13 05:10:21 UTC #####
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: ### [UPSTREAM] ###
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets received by concentrator: 0
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # CRC_OK: 0.00, CRC_FAIL: 0.00, NO_CRC: 0.00
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets forwarded: 0 (0 bytes)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA datagrams sent: 1 (179 bytes)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # PUSH_DATA acknowledged: 100.00
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: ### [DOWNSTREAM] ###
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # PULL_DATA sent: 6 (100.00 acknowledged)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # RF packets sent to concentrator: 0 (0 bytes)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # SX1301 time (PPS): 3628112114, offset us 0
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: ### [GPS] ###
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # Valid time reference (age: 1 sec)
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: # GPS coordinates: latitude -2.32110, longitude 103.90711, altitude 233 m
Wed Jan 13 12:10:21 2021 user.notice lora_pkt_fwd[1632]: ##### END #####
Wed Jan 13 12:10:21 2021 daemon.info gwBridge[21059]: Stats : {"gatewayID":"xxxxxxxxxx","ip":"xx.xx.xx.xx","time":"2021-01-13T05:10:21Z","location":null,"configVersion":"unknown","rxPacketsReceived":0,"rxPacketsReceivedOK":0,"txPacketsReceived":0,"txPacketsEmitted":0,"metaData":{},"statsID":"fP2FExSQQByRAkYK3r504A=="}

cstratton · January 14, 2021, 4:28pm

I recall seeing behavior like this with a similarly older version of the gateway bridge running on an armbian platform, and believe there was a known issue corrected at some point later in the project evolution.

One simple dodge would be to run the UDP protocol out of the gateway box, and run a more recent version of the gateway bridge in the same infrastructure as your chirpstack server.

Another idea, since you seem to be running some custom scripts on the gateway anyway, would be to force-restart the gateway bridge if you feel it is not acting appropriately.

I started down that path with an independent component that subscribed to the gateway’s own stats topic to make sure it was regularly received, proving round trip connectivity between the gateway and the cloud MQTT broker, if not it would progressively restart pieces of the system.

Ultimately I ended up doing a custom replacement of the gateway bridge - and then eventually a custom replacement of the network server too, but that’s a bit drastic and was as much about adding unique application-required features as solving these specific issues.

xflash · January 14, 2021, 5:16pm

Hi @cstratton,

Agree, just as I thought, a simple solution is to use UDP through VPN tunneling (for security and remote access) and put the mqtt bridge on the same infrastructure. But, it seems that using 2-way UDP like in Semtech legacy packet forwarder is not as reliable as MQTT (QOS 1 or 2). For this legacy packet forwarder, when an uplink packet is not received by the server, will there be a retransmission? This of course will cost you more latency, but as most of the packets sent are unconfirmed, we need to make sure that the packets are successfully received. I think the latency will affect less as we only send few downlink/ack.

In the meantime, I will wait for the next major firmware update, hope that RAK team will update their MQTT bridge soon. Thanks.

cstratton · January 14, 2021, 6:42pm

It’s not clear the UDP over your VPN would be unreliable - eg, it’s not clear that it’s still “UDP” in practice through the tunnel, vs just being UDP on the local loopback or equivalent at ingress/egress. Keep in mind that even with the gateway bridge on the gateway, the communication between the packet forwarder and the gateway bridge is still UDP on the loopback.

Uplinks reports are not retried; in a practical sense that wouldn’t work very well unless the RX delays of the network are increased.

I think the latency will affect less as we only send few downlink/ack.

If the latency is such that you miss downlink windows, it doesn’t matter how frequently or infrequently you try to downlink

xflash · January 14, 2021, 6:53pm

Thanks for replying. Just heard about basic station, is it worth to try? I found basicmac repo discontinued, and back to loramac-node. Hopefully, not for this basic station, I guess.