LoRa services not starting successful after reboot

Uros_Males · August 1, 2017, 11:30am

I’ve updated the server via apt-get update & apt-get upgrade today.

The LoRa things were also automatically updated (now I have v. 0.11.0).

After the update and reset, the LoRa things were not started correctly.

I manually started mosquitto, loraserver, lora-app-server, lora-gateway-bridge but I got a few errors.

After googling around and checking log files, I’ve added
GW_SERVER_JWT_SECRET=Zysxxxxxxxxx= into /etc/default/loraserver and
JWT_SECRET=Zysxxxxxxxxx= into /etc/default/lora-app-server

After restarting services manually with systemctl, everything started to work.

I rebooted the server and the services did not start automatically.

If after reboot I manually do:
systemctl restart mosquitto
systemctl restart loraserver
systemctl restart lora-app-server
systemctl restart lora-gateway-bridge

then everything works again (log file start at Aug 01 12:19:31 LoraServer30 systemd[1]: Stopped LSB: mosquitto MQTT v3.1 message broker.).

Another interesting thing poping up in the logs: 116.31.116.49 - anyone knows what this is is?

Boot Log:

Aug 01 12:05:00 LoraServer30 systemd[1]: Reached target Login Prompts.
Aug 01 12:05:00 LoraServer30 systemd[1]: Started LoRa Gateway Bridge.
Aug 01 12:05:00 LoraServer30 systemd[1]: Started LoRa Server.
Aug 01 12:05:00 LoraServer30 systemd[1]: Started LSB: Node-RED initialisation.
Aug 01 12:05:00 LoraServer30 systemd[1]: Started Set console scheme.
Aug 01 12:05:00 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:00+02:00" level=info msg="starting LoRa Gateway Bridge" docs="https://docs.loraserver.io/lora-gateway-bridge/" version=2.1.5
Aug 01 12:05:00 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:00+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:05:00 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:00+02:00" level=error msg="could not setup mqtt backend, retry in 2 seconds: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:05:00 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:00+02:00" level=info msg="starting LoRa Server" band="EU_863_870" docs="https://docs.loraserver.io/" net_id=010203 version=0.20.0
Aug 01 12:05:00 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:00+02:00" level=info msg="setup redis connection pool" url="redis://localhost:6379"
Aug 01 12:05:00 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:00+02:00" level=info msg="connecting to postgresql"
Aug 01 12:05:00 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:00+02:00" level=error msg="ping database error, will retry in 2s: pq: the database system is starting up"
Aug 01 12:05:02 LoraServer30 kernel: e1000: ens3 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
Aug 01 12:05:02 LoraServer30 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): ens3: link becomes ready
Aug 01 12:05:02 LoraServer30 systemd[1]: Started PostgreSQL Cluster 9.5-main.
Aug 01 12:05:02 LoraServer30 systemd[1]: Starting PostgreSQL RDBMS...
Aug 01 12:05:02 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:02+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:05:02 LoraServer30 systemd[1]: Started PostgreSQL RDBMS.
Aug 01 12:05:02 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:02+02:00" level=error msg="could not setup mqtt backend, retry in 2 seconds: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:05:02 LoraServer30 systemd[1]: Started LoRa App Server.
Aug 01 12:05:02 LoraServer30 systemd[1]: Reached target Multi-User System.
Aug 01 12:05:02 LoraServer30 systemd[1]: Reached target Graphical Interface.
Aug 01 12:05:02 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:02+02:00" level=info msg="backend/gateway: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:05:02 LoraServer30 loraserver[1252]: time="2017-08-01T12:05:02+02:00" level=error msg="backend/gateway: connecting to mqtt broker failed, will retry in 2s: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:05:02 LoraServer30 systemd[1]: Starting Update UTMP about System Runlevel Changes...
Aug 01 12:05:02 LoraServer30 systemd[1]: Started Update UTMP about System Runlevel Changes.
Aug 01 12:05:02 LoraServer30 systemd[1]: Startup finished in 2.661s (kernel) + 3.682s (userspace) = 6.344s.
Aug 01 12:05:02 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:05:02+02:00" level=info msg="starting LoRa App Server" docs="https://docs.loraserver.io/" version=0.11.0
Aug 01 12:05:02 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:05:02+02:00" level=info msg="connecting to postgresql"
Aug 01 12:05:02 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:05:02+02:00" level=info msg="setup redis connection pool"
Aug 01 12:05:02 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:05:02+02:00" level=info msg="handler/mqtt: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:05:02 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:05:02+02:00" level=error msg="handler/mqtt: connecting to broker error, will retry in 2s: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:05:04 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:04+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:05:04 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:05:04+02:00" level=error msg="could not setup mqtt backend, retry in 2 seconds: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
...
Aug 01 12:19:31 LoraServer30 loraserver[1252]: time="2017-08-01T12:19:31+02:00" level=error msg="backend/gateway: connecting to mqtt broker failed, will retry in 2s: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:19:31 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:31+02:00" level=error msg="handler/mqtt: connecting to broker error, will retry in 2s: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"
Aug 01 12:19:31 LoraServer30 sudo[1537]:     uros : TTY=pts/0 ; PWD=/home/uros/scripts ; USER=root ; COMMAND=./restartLora.sh
Aug 01 12:19:31 LoraServer30 sudo[1537]: pam_unix(sudo:session): session opened for user root by uros(uid=0)
Aug 01 12:19:31 LoraServer30 systemd[1]: Stopping LSB: mosquitto MQTT v3.1 message broker...
Aug 01 12:19:31 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:31+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:19:31 LoraServer30 mosquitto[1541]:  * Stopping network daemon: mosquitto
Aug 01 12:19:31 LoraServer30 mosquitto[1541]: start-stop-daemon: warning: failed to kill 1213: No such process
Aug 01 12:19:31 LoraServer30 mosquitto[1541]:    ...done.
Aug 01 12:19:31 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:31+02:00" level=error msg="could not setup mqtt backend, retry in 2 seconds: Network Error : dial tcp [::1]:1883: getsockopt: connection refused"


Aug 01 12:19:31 LoraServer30 systemd[1]: Stopped LSB: mosquitto MQTT v3.1 message broker.
Aug 01 12:19:31 LoraServer30 systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...
Aug 01 12:19:31 LoraServer30 mosquitto[1550]:  * Starting network daemon: mosquitto
Aug 01 12:19:31 LoraServer30 mosquitto[1550]:    ...done.
Aug 01 12:19:31 LoraServer30 systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
Aug 01 12:19:32 LoraServer30 systemd[1]: Stopping LoRa Server...
Aug 01 12:19:32 LoraServer30 systemd[1]: Stopped LoRa Server.
Aug 01 12:19:32 LoraServer30 systemd[1]: Started LoRa Server.
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="starting LoRa Server" band="EU_863_870" docs="https://docs.loraserver.io/" net_id=010203 version=0.20.0
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="setup redis connection pool" url="redis://localhost:6379"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="connecting to postgresql"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="backend/gateway: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="connecting to application-server" ca-cert= server="127.0.0.1:8001" tls-cert= tls-key=
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="backend/gateway: connected to mqtt server"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="backend/gateway: subscribing to rx topic" topic="gateway/+/rx"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="backend/gateway: subscribing to stats topic" topic="gateway/+/stats"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="no network-controller configured"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="migrated node-sessions to new format" errors=0 migrated=0
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="applying database migrations"
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="migrations applied" count=0
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="starting api server" bind="0.0.0.0:8000" ca-cert= tls-cert= tls-key=
Aug 01 12:19:32 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:32+02:00" level=info msg="starting gateway api server" bind="0.0.0.0:8002" ca-cert= tls-cert= tls-key=
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="connecting to network-server api" ca-cert= server="127.0.0.1:8000" tls-cert= tls-key=
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="handler/mqtt: connected to mqtt broker"
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="handler/mqtt: subscribling to tx topic" topic="application/+/node/+/tx"
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="applying database migrations"
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="migrations applied" count=0
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="starting application-server api" bind="localhost:8001" ca-cert= tls-cert= tls-key=
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="starting client api server" bind="0.0.0.0:8080" tls-cert="/etc/lora-app-server/certs/http.pem" tls-key="/etc/lora-app-server/certs/http-
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="registering rest api handler and documentation endpoint" path="/api"
Aug 01 12:19:33 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:33+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:19:33 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:33+02:00" level=info msg="gateway: starting gateway udp listener" addr=0.0.0.0:1700
Aug 01 12:19:33 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:33+02:00" level=info msg="backend: connected to mqtt broker"
Aug 01 12:19:33 LoraServer30 systemd[1]: Stopping LoRa App Server...
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=info msg="signal received" signal=terminated
Aug 01 12:19:33 LoraServer30 lora-app-server[1299]: time="2017-08-01T12:19:33+02:00" level=warning msg="stopping lora-app-server"
Aug 01 12:19:33 LoraServer30 systemd[1]: Stopped LoRa App Server.
Aug 01 12:19:33 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:33+02:00" level=info msg="grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:
Aug 01 12:19:33 LoraServer30 systemd[1]: Started LoRa App Server.
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="starting LoRa App Server" docs="https://docs.loraserver.io/" version=0.11.0
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="connecting to postgresql"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="setup redis connection pool"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="handler/mqtt: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="handler/mqtt: connected to mqtt broker"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="handler/mqtt: subscribling to tx topic" topic="application/+/node/+/tx"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="connecting to network-server api" ca-cert= server="127.0.0.1:8000" tls-cert= tls-key=
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="applying database migrations"
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="migrations applied" count=0
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="starting application-server api" bind="localhost:8001" ca-cert= tls-cert= tls-key=
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="starting client api server" bind="0.0.0.0:8080" tls-cert="/etc/lora-app-server/certs/http.pem" tls-key="/etc/lora-app-server/certs/http-
Aug 01 12:19:33 LoraServer30 lora-app-server[1583]: time="2017-08-01T12:19:33+02:00" level=info msg="registering rest api handler and documentation endpoint" path="/api"
Aug 01 12:19:34 LoraServer30 systemd[1]: Stopping LoRa Gateway Bridge...
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:34+02:00" level=info msg="signal received" signal=terminated
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:34+02:00" level=warning msg="shutting down server"
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:34+02:00" level=info msg="gateway: closing gateway backend"
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1248]: time="2017-08-01T12:19:34+02:00" level=info msg="gateway: handling last packets"
Aug 01 12:19:34 LoraServer30 systemd[1]: Stopped LoRa Gateway Bridge.
Aug 01 12:19:34 LoraServer30 systemd[1]: Started LoRa Gateway Bridge.
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="starting LoRa Gateway Bridge" docs="https://docs.loraserver.io/lora-gateway-bridge/" version=2.1.5
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="backend: connecting to mqtt broker" server="tcp://localhost:1883"
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="gateway: starting gateway udp listener" addr=0.0.0.0:1700
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="backend: connected to mqtt broker"
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="backend: subscribing to topic" topic="gateway/7076fffffe0200c0/tx"
Aug 01 12:19:34 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:34+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK
Aug 01 12:19:35 LoraServer30 sudo[1537]: pam_unix(sudo:session): session closed for user root
Aug 01 12:19:38 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:38+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:46586 protocol_version=2 type=PushData
Aug 01 12:19:38 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:38+02:00" level=info msg="gateway: stat packet received" addr=10.0.3.103:46586 mac=7076fffffe0200c0
Aug 01 12:19:38 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:38+02:00" level=info msg="backend: publishing packet" topic="gateway/7076fffffe0200c0/stats"
Aug 01 12:19:38 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:38+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:46586 protocol_version=2 type=PushACK
Aug 01 12:19:38 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:38+02:00" level=info msg="backend/gateway: gateway stats packet received" mac=7076fffffe0200c0
Aug 01 12:19:38 LoraServer30 loraserver[1568]: time="2017-08-01T12:19:38+02:00" level=info msg="gateway updated" mac=7076fffffe0200c0
Aug 01 12:19:45 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:45+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:19:45 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:45+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK
Aug 01 12:19:55 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:55+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:19:55 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:19:55+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK
Aug 01 12:20:00 LoraServer30 systemd[1]: Starting Cleanup of Temporary Directories...
Aug 01 12:20:00 LoraServer30 systemd-tmpfiles[1614]: [/usr/lib/tmpfiles.d/var.conf:14] Duplicate line for path "/var/log", ignoring.
Aug 01 12:20:00 LoraServer30 systemd[1]: Started Cleanup of Temporary Directories.
Aug 01 12:20:05 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:05+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:20:05 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:05+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK
Aug 01 12:20:06 LoraServer30 sshd[1619]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=116.31.116.49  user=root
Aug 01 12:20:08 LoraServer30 sshd[1619]: Failed password for root from 116.31.116.49 port 37231 ssh2
Aug 01 12:20:08 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:08+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:46586 protocol_version=2 type=PushData
Aug 01 12:20:08 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:08+02:00" level=info msg="gateway: stat packet received" addr=10.0.3.103:46586 mac=7076fffffe0200c0
Aug 01 12:20:08 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:08+02:00" level=info msg="backend: publishing packet" topic="gateway/7076fffffe0200c0/stats"
Aug 01 12:20:08 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:08+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:46586 protocol_version=2 type=PushACK
Aug 01 12:20:08 LoraServer30 loraserver[1568]: time="2017-08-01T12:20:08+02:00" level=info msg="backend/gateway: gateway stats packet received" mac=7076fffffe0200c0
Aug 01 12:20:08 LoraServer30 loraserver[1568]: time="2017-08-01T12:20:08+02:00" level=info msg="gateway updated" mac=7076fffffe0200c0
Aug 01 12:20:10 LoraServer30 sshd[1619]: Failed password for root from 116.31.116.49 port 37231 ssh2
Aug 01 12:20:12 LoraServer30 sshd[1619]: Failed password for root from 116.31.116.49 port 37231 ssh2
Aug 01 12:20:12 LoraServer30 sshd[1619]: Received disconnect from 116.31.116.49 port 37231:11:  [preauth]
Aug 01 12:20:12 LoraServer30 sshd[1619]: Disconnected from 116.31.116.49 port 37231 [preauth]
Aug 01 12:20:12 LoraServer30 sshd[1619]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=116.31.116.49  user=root
Aug 01 12:20:15 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:15+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:20:15 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:15+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK
Aug 01 12:20:20 LoraServer30 sudo[1621]:     uros : TTY=pts/0 ; PWD=/home/uros/scripts ; USER=root ; COMMAND=/bin/journalctl -b
Aug 01 12:20:20 LoraServer30 sudo[1621]: pam_unix(sudo:session): session opened for user root by uros(uid=0)
Aug 01 12:20:25 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:25+02:00" level=info msg="gateway: received udp packet from gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullData
Aug 01 12:20:25 LoraServer30 lora-gateway-bridge[1597]: time="2017-08-01T12:20:25+02:00" level=info msg="gateway: sending udp packet to gateway" addr=10.0.3.103:58684 protocol_version=2 type=PullACK

brocaar · August 1, 2017, 11:44am

Are you sure Mosquitto is started at boottime? When the services can’t connect to Mosquitto, they will end up in a retry loop. Best would be to check which services are up after a reboot (e.g. ps aux).

The 116.31.116.49 in your logs is probably somebody trying to break into your instance. You could use the fail2ban package for this (apt-get install fail2ban should be enough). It will detect these failed login attempts and block these IP addresses in the firewall (temporarily).

Uros_Males · August 1, 2017, 11:54am

Mosquitto was starting fine before the apt-get upgrade. You’re right, now it does not restart automatically anymore. I’ll have to take a look at that. Thanks for quick reply.

In the boot log I can see: Aug 01 13:50:00 LoraServer30 systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
but I cant find any mosquitto process with the ps aux.

IP, yes, it seems to be some chinese bot… it’s never wise to open up default ssh port on the friewall

Uros_Males · August 1, 2017, 12:02pm

Interesting, this says that it’s running (running systemctl status after reboot):

uros@LoraServer30:~$ sudo systemctl status mosquitto
● mosquitto.service - LSB: mosquitto MQTT v3.1 message broker
Loaded: loaded (/etc/init.d/mosquitto; bad; vendor preset: enabled)
Active: active (running) since Tue 2017-08-01 14:01:13 CEST; 53s ago
Docs: man:systemd-sysv-generator(8)
Process: 1165 ExecStart=/etc/init.d/mosquitto start (code=exited, status=0/SUCCESS)
Tasks: 1
Memory: 2.5M
CPU: 219ms
CGroup: /system.slice/mosquitto.service
└─1205 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
Aug 01 14:01:13 LoraServer30 systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker…
Aug 01 14:01:13 LoraServer30 mosquitto[1165]: * Starting network daemon: mosquitto
Aug 01 14:01:13 LoraServer30 mosquitto[1165]: …done.
Aug 01 14:01:13 LoraServer30 systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
uros@LoraServer30:~$

I tried to reboot the server 2 times, and everything started up just fine. Now I’m really confused. I’ll keep watching this and if the problem occurs again, I’ll post it here.

brocaar · August 1, 2017, 12:07pm

Are you using the mosquitto-auth-plug plugin? If so, you might be interested in following the progress of this issue: https://github.com/jpmens/mosquitto-auth-plug/issues/269.

If that is the case, you could see if you can change the mosquitto.service file so that it restarts on failure.

Uros_Males · August 1, 2017, 12:10pm

Yes, I am using it. Thanks for the link, I’ll follow.