LoRa module fails receiving packets after unexpected reboot, all fine again after manual reboot

avbentem commented 6 years ago

This is a bug report.

What do you want to do? What do you expect?

After an (unexpected) reboot the gateway's LoRa module should start receiving LoRa packets.

What went wrong? What is missing?

After running version 1.0.3 fine for 7 hours, the gateway ran into FAILMQTT: Sending status failed and MAIN: MQTT error, and rebooted.
It then showed a lot of LORA: UART WRITE ERROR! errors, but eventually reported LORA: Configuration succeeded and LORA: Starting operation.
(It also showed a single LORA: UART TIMEOUT before LORA: Configuration succeeded, but that is also seen in cases where the LoRa module truly starts just fine, and was also seen in version 1.0.1.)
Despite the LORA: Starting operation it was not receiving any LoRa packets at all. (It showed neither any LORA: Accepted packet nor LORA: Packet dropped! Bad CRC.)
After 4 hours, after pressing the Mode button to force another reboot, everything immediately worked just fine again.

The gateway is using ethernet. It seems the same LEDs were on before and after the manual reboot. An LMiC test node is sending many packets on alternating frequencies and spreading factors. That test node was not touched at all when pressing the Mode button, while its packets were received just fine again after that manual intervention. So surely packets should have been received before the manual reboot was triggered.

What firmware is running on your gateway?

Version 1.0.3 beta channel, loaded using an SD card, using the factory bootloader.

As an aside:

I've not used version 1.0.2, as that got me a reboot loop: https://github.com/TheThingsProducts/gateway/issues/1#issuecomment-377886224.
Version 1.0.1 also got me one or two occasions where I'd not get any uplinks in TTN Console, but I'd have to dive into old log files to see if at that point no LoRa packets were received (like now), or if this was caused by some MQTT issue.

What do the logs show?

After an expected reboot today 08:49 UTC (which upgraded from 1.0.1 to 1.0.3), all was fine until a FAILMQTT: Sending status failed at 15:50 UTC (17:50 Amsterdam time; all timestamps added by a Raspberry Pi that monitors the serial output):

[2018-04-02T15:48:49.456Z] LORA: Packet dropped! Bad CRC
[2018-04-02T15:48:49.674Z] LORA: Accepted packet
[2018-04-02T15:48:49.706Z] MQTT: Sending UPLINK OK
[2018-04-02T15:48:55.046Z] MQTT: Sending status packet
[2018-04-02T15:48:55.077Z] MQTT: Sending status succeeded: 836
...
[2018-04-02T15:50:24.958Z] MQTT: Sending status packet
[2018-04-02T15:50:27.457Z] FAILMQTT: Sending status failed
[2018-04-02T15:50:27.464Z]
[2018-04-02T15:50:27.478Z] MAIN: MQTT error
[2018-04-02T15:50:27.485Z]
[2018-04-02T15:50:27.486Z] MAIN: Leaving state 5
[2018-04-02T15:50:36.345Z] SNTP: State change from 0 to 0
[2018-04-02T15:50:36.348Z] SNTP: State change from 0 to 0
[2018-04-02T15:50:36.350Z]
[2018-04-02T15:50:36.350Z]
[2018-04-02T15:50:36.352Z]
[2018-04-02T15:50:36.354Z] **************************
[2018-04-02T15:50:36.355Z] *   The Things Network   *
[2018-04-02T15:50:36.357Z] *      G A T E W A Y     *
[2018-04-02T15:50:36.359Z] **************************
[2018-04-02T15:50:36.368Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252
[2018-04-02T15:50:36.387Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298
[2018-04-02T15:50:36.399Z] Build time: Mar 22 2018 12:21:52
[2018-04-02T15:50:36.401Z] Reboot reason: 0x10

After this reboot it got a network connection, and got as far as:

[2018-04-02T15:51:05.179Z] CNFG: Load online user config state change to 7
[2018-04-02T15:51:05.180Z]
[2018-04-02T15:51:05.182Z] CNFG: Configuring LoRa module
[2018-04-02T15:51:05.184Z] LORA: Changing state from 4 to 6
[2018-04-02T15:51:05.187Z] LORA: Starting reconfiguration
[2018-04-02T15:51:05.194Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.201Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.238Z] LORA: version: 00
[2018-04-02T15:51:05.239Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.245Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.251Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.257Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.262Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.268Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.274Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.335Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.341Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.346Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.352Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.357Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.363Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.369Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.377Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.382Z] LORA: Configuration failed, retry
[2018-04-02T15:51:05.388Z] LORA: Starting reconfiguration
[2018-04-02T15:51:05.398Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.404Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.409Z] LORA: version: 00
[2018-04-02T15:51:05.410Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.468Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.473Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.479Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.484Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.490Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.495Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.501Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.506Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.513Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.519Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.524Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.530Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.535Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.540Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.546Z] LORA: Configuration failed, retry
[2018-04-02T15:51:05.551Z] LORA: Starting reconfiguration
[2018-04-02T15:51:05.555Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.560Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.797Z] LORA: version: 00
[2018-04-02T15:51:05.798Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.806Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.811Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.817Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.822Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.828Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.833Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.838Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.844Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.849Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.855Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.872Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.877Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.882Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.888Z] LORA: UART WRITE ERROR!
[2018-04-02T15:51:05.893Z] LORA: Configuration failed, retry
[2018-04-02T15:51:05.898Z] LORA: RESET MODULE
[2018-04-02T15:51:05.900Z] LORA: Changing state from 6 to 0
[2018-04-02T15:51:06.184Z] LORA: Initialisation complete
[2018-04-02T15:51:06.186Z] LORA: Changing state from 0 to 1
[2018-04-02T15:51:06.629Z] MON: SYS Stack size: 2837
[2018-04-02T15:51:06.630Z] MON: heap usage: 152KB (234KB), free: 187KB
[2018-04-02T15:51:13.002Z] LORA: Wait init complete, check for communication on 115200 baud.
[2018-04-02T15:51:13.005Z] LORA: Changing state from 1 to 2
[2018-04-02T15:51:13.011Z] LORA: Communication on 115200 OK, waiting for application.
[2018-04-02T15:51:13.014Z] LORA: Changing state from 2 to 4
[2018-04-02T15:51:13.016Z] LORA: Changing state from 4 to 6
[2018-04-02T15:51:13.019Z] LORA: Starting reconfiguration
[2018-04-02T15:51:13.024Z] LORA: version: 01
[2018-04-02T15:51:15.066Z] LORA: UART TIMEOUT
[2018-04-02T15:51:15.069Z] LORA: Configuration succeeded
[2018-04-02T15:51:15.075Z] LORA: Starting operation
[2018-04-02T15:51:15.077Z] LORA: Changing state from 6 to 8
[2018-04-02T15:51:16.302Z] MON: SYS Stack size: 2837
[2018-04-02T15:51:16.306Z] MON: heap usage: 152KB (234KB), free: 187KB
[2018-04-02T15:51:21.060Z] LORA: Changing state from 8 to 5
[2018-04-02T15:51:21.062Z] LORA: GOING ASYNC
[2018-04-02T15:51:21.064Z] LORA: Changing state from 5 to 11
[2018-04-02T15:51:21.066Z]
[2018-04-02T15:51:21.069Z] CNFG: Load online user config state change to 9

So, the log shows LORA: Configuration succeeded above, despite all errors that are also logged. It then loads new firmware, but as the SD card with 1.0.3 is still inserted I don't think it would even be using that. Also, it shows it's indeed the same version:

[2018-04-02T15:52:12.272Z] FLASH: Storing FOTA Checksum
[2018-04-02T15:52:12.478Z] FIRM: Finishing writing to storage
[2018-04-02T15:52:12.481Z] FIRM: Downloaded key is the same as current key
[2018-04-02T15:52:12.484Z] MAIN: No new firmware available

All fine. Eventually it gets to:

[2018-04-02T15:52:12.493Z] MQTT: GOT IP: 52.169.76.203
[2018-04-02T15:52:12.496Z] Connecting to: 52.169.76.203
[2018-04-02T15:52:12.528Z] MQTT: Connection Opened: Starting TLS Negotiation
[2018-04-02T15:52:12.532Z] MQTT: Wait for SSL Connect
[2018-04-02T15:52:13.091Z] MQTT: TLS ready: Connect MQTT
[2018-04-02T15:52:13.206Z] RQMQTT: Connected
[2018-04-02T15:52:13.211Z]
[2018-04-02T15:52:13.215Z] *************************
[2018-04-02T15:52:13.216Z] MAIN: Gateway bridging
[2018-04-02T15:52:13.221Z] *************************

After this it simply does not see any LoRa data coming in, not even with bad CRC either. It is sending status messages though, and TTN Console shows it's connected and updates "Last Seen". But the logs just repeat and repeat:

[2018-04-02T15:52:20.987Z] LORA: Kick LoRa module with ACK after not acked it for 60s
[2018-04-02T15:52:26.217Z] MON: SYS Stack size: 2837
[2018-04-02T15:52:26.221Z] MON: heap usage: 266KB (266KB), free: 73KB
[2018-04-02T15:52:36.203Z] MON: SYS Stack size: 2837
[2018-04-02T15:52:36.207Z] MON: heap usage: 266KB (266KB), free: 73KB
[2018-04-02T15:52:43.169Z] MQTT: Sending status packet
[2018-04-02T15:52:43.201Z] MQTT: Sending status succeeded: 1
[2018-04-02T15:52:46.193Z] MON: SYS Stack size: 2837
[2018-04-02T15:52:46.196Z] MON: heap usage: 263KB (266KB), free: 76KB
[2018-04-02T15:52:56.182Z] MON: SYS Stack size: 2837
[2018-04-02T15:52:56.186Z] MON: heap usage: 266KB (266KB), free: 73KB
[2018-04-02T15:53:06.169Z] MON: SYS Stack size: 2837
[2018-04-02T15:53:06.172Z] MON: heap usage: 264KB (266KB), free: 74KB
[2018-04-02T15:53:13.131Z] MQTT: Sending status packet
[2018-04-02T15:53:13.162Z] MQTT: Sending status succeeded: 2
[2018-04-02T15:53:16.156Z] MON: SYS Stack size: 2837
[2018-04-02T15:53:16.159Z] MON: heap usage: 263KB (266KB), free: 76KB

...and every now and then also:

[2018-04-02T16:00:58.349Z] SNTP: State change from 7 to 1
[2018-04-02T16:00:59.444Z] SNTP: State change from 1 to 2
[2018-04-02T16:01:00.541Z] SNTP: State change from 2 to 3
[2018-04-02T16:01:01.638Z] SNTP: State change from 3 to 4
[2018-04-02T16:01:02.737Z] SNTP: State change from 4 to 5
[2018-04-02T16:01:02.764Z] SNTP: State change from 5 to 6
[2018-04-02T16:01:02.767Z] SNTP: State change from 6 to 7

Pressing the mode button to reset the gateway fixes all this.

Any Screenshots or Photos?

willem4ever commented 6 years ago

I upgraded this afternoon to Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1522846485 and see LORA errors, after the first reboot a time-out (never seen this before) not an improvement, actually worse as before ....

2018-04-04 17:45:45.375022 LORA: UART TIMEOUT
2018-04-04 17:45:45.375061 LORA: Configuration succeeded
2018-04-04 17:45:45.375065 LORA: Starting operation
2018-04-04 17:45:45.375068 LORA: Changing state from 6 to 8
2018-04-04 17:45:51.436553 LORA: Changing state from 8 to 5
2018-04-04 17:45:51.436590 LORA: GOING ASYNC
2018-04-04 17:45:51.436594 LORA: Changing state from 5 to 11
2018-04-04 17:46:51.734110 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:47:52.067410 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:48:52.414499 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:49:52.769109 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:50:53.112584 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:51:53.474841 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:52:53.840829 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:53:54.176918 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:54:54.528266 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:55:54.879097 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:56:55.245150 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:57:55.618957 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:58:55.996203 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 17:59:56.358381 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 18:00:56.732491 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 18:01:57.104779 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 18:02:57.456434 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 18:03:57.816745 LORA: Kick LoRa module with ACK after not acked it for 60s
2018-04-04 18:04:58.188847 LORA: Kick LoRa module with ACK after not acked it for 60s

avbentem commented 6 years ago

Today things were not resolved by pressing the Mode button. Instead, it needed a power cycle, after which it started to receive LoRa packets again. Again, the gateway was running just fine until the failure was initiated by a firmware upgrade check. I did not check the LEDs on the board. It's running 1.0.3 (commit: 2c56ce0, timestamp: 1521721252, Build time: Mar 22 2018 12:21:52) from an SD card, as 1.0.4 gives me a reboot loop.

Full logs, all timestamps added by a Raspberry Pi that monitors the serial output:

Running fine, then no LoRa after reboot for firmware upgrade check

```text [2018-05-12T08:46:06.303Z] LORA: Accepted packet [2018-05-12T08:46:06.332Z] MQTT: Sending UPLINK OK [2018-05-12T08:46:13.213Z] LORA: Accepted packet [2018-05-12T08:46:13.240Z] MQTT: Sending UPLINK OK [2018-05-12T08:46:14.750Z] MON: SYS Stack size: 2841 [2018-05-12T08:46:14.754Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:46:21.528Z] LORA: Accepted packet [2018-05-12T08:46:21.565Z] MQTT: Sending UPLINK OK [2018-05-12T08:46:24.749Z] MON: SYS Stack size: 2841 [2018-05-12T08:46:24.753Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:46:28.848Z] MQTT: Sending status packet [2018-05-12T08:46:28.879Z] MQTT: Sending status succeeded: 2871 [2018-05-12T08:46:34.746Z] MON: SYS Stack size: 2841 [2018-05-12T08:46:34.749Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:46:37.869Z] LORA: Packet dropped! Bad CRC [2018-05-12T08:46:37.937Z] LORA: Accepted packet [2018-05-12T08:46:37.965Z] MQTT: Sending UPLINK OK [2018-05-12T08:46:43.579Z] LORA: Accepted packet [2018-05-12T08:46:43.617Z] MQTT: Sending UPLINK OK [2018-05-12T08:46:43.647Z] LORA: Packet dropped! Bad CRC [2018-05-12T08:46:44.745Z] MON: SYS Stack size: 2841 [2018-05-12T08:46:44.748Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:46:54.742Z] MON: SYS Stack size: 2841 [2018-05-12T08:46:54.745Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:46:58.839Z] MQTT: Sending status packet [2018-05-12T08:46:58.867Z] MQTT: Sending status succeeded: 2872 [2018-05-12T08:47:04.739Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:04.743Z] MON: heap usage: 264KB (267KB), free: 74KB [2018-05-12T08:47:12.208Z] LORA: Accepted packet [2018-05-12T08:47:12.234Z] MQTT: Sending UPLINK OK [2018-05-12T08:47:14.740Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:14.743Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:47:17.616Z] LORA: Accepted packet [2018-05-12T08:47:17.653Z] MQTT: Sending UPLINK OK [2018-05-12T08:47:24.740Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:24.744Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:47:25.028Z] LORA: Accepted packet [2018-05-12T08:47:25.056Z] MQTT: Sending UPLINK OK [2018-05-12T08:47:28.836Z] MQTT: Sending status packet [2018-05-12T08:47:28.865Z] MQTT: Sending status succeeded: 2873 [2018-05-12T08:47:34.740Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:34.743Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:47:44.738Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:44.742Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:47:54.736Z] MON: SYS Stack size: 2841 [2018-05-12T08:47:54.739Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:47:58.828Z] MQTT: Sending status packet [2018-05-12T08:47:58.857Z] MQTT: Sending status succeeded: 2874 [2018-05-12T08:48:04.734Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:04.737Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:48:14.732Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:14.736Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:48:24.731Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:24.735Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:48:25.015Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:48:28.821Z] MQTT: Sending status packet [2018-05-12T08:48:28.849Z] MQTT: Sending status succeeded: 2875 [2018-05-12T08:48:30.332Z] LORA: Accepted packet [2018-05-12T08:48:30.363Z] MQTT: Sending UPLINK OK [2018-05-12T08:48:34.729Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:34.732Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:48:36.641Z] LORA: Packet dropped! Bad CRC [2018-05-12T08:48:37.044Z] LORA: Accepted packet [2018-05-12T08:48:37.072Z] MQTT: Sending UPLINK OK [2018-05-12T08:48:44.727Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:44.730Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:48:54.723Z] MON: SYS Stack size: 2841 [2018-05-12T08:48:54.726Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:48:58.813Z] MQTT: Sending status packet [2018-05-12T08:48:58.842Z] MQTT: Sending status succeeded: 2876 [2018-05-12T08:49:04.721Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:04.725Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:49:14.721Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:14.724Z] MON: heap usage: 264KB (267KB), free: 74KB [2018-05-12T08:49:24.720Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:24.723Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:49:28.811Z] MQTT: Sending status packet [2018-05-12T08:49:28.839Z] MQTT: Sending status succeeded: 2877 [2018-05-12T08:49:34.721Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:34.723Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:49:37.037Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:49:44.719Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:44.724Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:49:54.718Z] MON: SYS Stack size: 2841 [2018-05-12T08:49:54.722Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:49:58.806Z] MQTT: Sending status packet [2018-05-12T08:49:58.837Z] MQTT: Sending status succeeded: 2878 [2018-05-12T08:50:04.719Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:04.722Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:50:14.720Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:14.723Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:50:24.722Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:24.725Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:50:28.808Z] MQTT: Sending status packet [2018-05-12T08:50:28.840Z] MQTT: Sending status succeeded: 2879 [2018-05-12T08:50:31.425Z] LORA: Accepted packet [2018-05-12T08:50:31.451Z] MQTT: Sending UPLINK OK [2018-05-12T08:50:34.723Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:34.726Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:50:38.135Z] LORA: Accepted packet [2018-05-12T08:50:38.166Z] MQTT: Sending UPLINK OK [2018-05-12T08:50:44.728Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:44.731Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T08:50:46.550Z] LORA: Accepted packet [2018-05-12T08:50:46.578Z] MQTT: Sending UPLINK OK [2018-05-12T08:50:54.729Z] MON: SYS Stack size: 2841 [2018-05-12T08:50:54.733Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T08:50:56.475Z] [2018-05-12T08:50:56.478Z] MAIN: Rebooting gateway for firmware update check [2018-05-12T08:51:02.875Z] LORA: Accepted packet [2018-05-12T08:51:05.361Z] SNTP: State change from 0 to 0 [2018-05-12T08:51:05.364Z] SNTP: State change from 0 to 0 [2018-05-12T08:51:05.366Z] [2018-05-12T08:51:05.367Z] [2018-05-12T08:51:05.368Z] [2018-05-12T08:51:05.369Z] ************************** [2018-05-12T08:51:05.372Z] * The Things Network * [2018-05-12T08:51:05.374Z] * G A T E W A Y * [2018-05-12T08:51:05.376Z] ************************** [2018-05-12T08:51:05.383Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-05-12T08:51:05.418Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-05-12T08:51:05.420Z] Build time: Mar 22 2018 12:21:52 [2018-05-12T08:51:05.421Z] Reboot reason: 0x10 [2018-05-12T08:51:05.449Z] BOOT: (persisted info) 6F 72 72 65 01 10 83 2C E7 16 0D 49 B2 1A 54 B6 [2018-05-12T08:51:05.450Z] [2018-05-12T08:51:05.450Z] [2018-05-12T08:51:05.451Z] [2018-05-12T08:51:05.451Z] [2018-05-12T08:51:05.452Z] WIFI: Entering state 0 [2018-05-12T08:51:05.453Z] WIFI: Entering SCAN state 0 [2018-05-12T08:51:05.454Z] [2018-05-12T08:51:05.454Z] MAIN: Initialisation complete [2018-05-12T08:51:05.456Z] LORA: Changing state from 0 to 0 [2018-05-12T08:51:05.607Z] [2018-05-12T08:51:05.609Z] MAIN: Leaving state 0 [2018-05-12T08:51:05.611Z] MAIN: Entering state 1 [2018-05-12T08:51:05.619Z] FLASH: Magic bytes found: wifi config present [2018-05-12T08:51:05.625Z] FLASH: Magic bytes found: activation data present [2018-05-12T08:51:05.637Z] FLASH: Magic bytes found: FOTA data present [2018-05-12T08:51:05.638Z] FLASH: Loading Firmware Data [2018-05-12T08:51:05.644Z] CNFG: (Firmware HASH (sha256)) 14 3E 99 52 CC 5B 11 E1 A2 21 8A 04 06 AA 73 1D 1D D8 25 CE FF BD C3 28 34 1E FB 0B B2 AC 9B 56 [2018-05-12T08:51:05.647Z] FLASH: Loading WiFi Data [2018-05-12T08:51:05.650Z] CNFG: WiFi SSID: Palahala [2018-05-12T08:51:05.658Z] CNFG: WiFi key: *** [2018-05-12T08:51:05.660Z] CNFG: WiFi conn_type: 1 [2018-05-12T08:51:05.661Z] CNFG: WiFi sec_type: 4 [2018-05-12T08:51:05.662Z] FLASH: Loading Activation Data [2018-05-12T08:51:05.664Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-05-12T08:51:05.666Z] CNFG: Gateway Key: *** [2018-05-12T08:51:05.671Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-05-12T08:51:05.674Z] CNFG: Locked: true [2018-05-12T08:51:05.676Z] CNFG: Locked first time: false [2018-05-12T08:51:05.678Z] [2018-05-12T08:51:05.680Z] MAIN: Leaving state 1 [2018-05-12T08:51:05.682Z] MAIN: Entering state 2 [2018-05-12T08:51:05.684Z] INET: State change to 0 [2018-05-12T08:51:05.984Z] LORA: Initialisation complete [2018-05-12T08:51:05.987Z] LORA: Changing state from 0 to 1 [2018-05-12T08:51:06.239Z] WIFI: Entering state 1 [2018-05-12T08:51:06.242Z] ETH: IP Address: 0.0.0.0 [2018-05-12T08:51:06.244Z] WIFI: Entering state 4 [2018-05-12T08:51:06.249Z] WIFI: Entering SCAN state 1 [2018-05-12T08:51:07.334Z] SNTP: State change from 0 to 1 [2018-05-12T08:51:07.384Z] INET: Gateway has Ethernet [2018-05-12T08:51:07.386Z] INET: State change to 2 [2018-05-12T08:51:07.393Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-05-12T08:51:08.432Z] SNTP: State change from 1 to 2 [2018-05-12T08:51:08.536Z] Scan is completed successfully [2018-05-12T08:51:08.538Z] WIFI: Entering SCAN state 2 [2018-05-12T08:51:08.546Z] WIFI: Entering SCAN state 5 [2018-05-12T08:51:08.549Z] WIFI: Entering SCAN state 0 [2018-05-12T08:51:08.551Z] WIFI: Entering state 2 [2018-05-12T08:51:08.553Z] WIFI: Disabling modules [2018-05-12T08:51:08.559Z] Head magic match void: trying to free an already freed block, ignore [2018-05-12T08:51:08.562Z] SNTP: State change from 2 to 1 [2018-05-12T08:51:08.565Z] WIFI: Entering state 3 [2018-05-12T08:51:09.431Z] WIFI: Enabling modules for client [2018-05-12T08:51:09.433Z] WIFI: Entering state 6 [2018-05-12T08:51:09.434Z] [2018-05-12T08:51:09.435Z] [2018-05-12T08:51:09.437Z] >WIFI: IP Address: 0.0.0.0 [2018-05-12T08:51:09.531Z] SNTP: State change from 1 to 2 [2018-05-12T08:51:10.430Z] ETH: IP Address: 192.168.0.12 [2018-05-12T08:51:12.384Z] CB: INET: State change to 3 [2018-05-12T08:51:12.387Z] INET: Ping probe [2018-05-12T08:51:12.398Z] INET: Ping response from PIC32INT, set as default [2018-05-12T08:51:12.400Z] INET: State change to 4 [2018-05-12T08:51:12.429Z] WIFI: IP Address: 192.168.178.53 [2018-05-12T08:51:12.988Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-05-12T08:51:12.991Z] LORA: Changing state from 1 to 2 [2018-05-12T08:51:12.997Z] LORA: Communication on 115200 OK, waiting for application. [2018-05-12T08:51:13.000Z] LORA: Changing state from 2 to 4 [2018-05-12T08:51:13.927Z] SNTP: State change from 2 to 3 [2018-05-12T08:51:15.026Z] SNTP: State change from 3 to 4 [2018-05-12T08:51:15.361Z] MON: SYS Stack size: 3959 [2018-05-12T08:51:15.364Z] MON: heap usage: 148KB (157KB), free: 191KB [2018-05-12T08:51:16.126Z] SNTP: State change from 4 to 5 [2018-05-12T08:51:16.136Z] SNTP: State change from 5 to 6 [2018-05-12T08:51:16.138Z] SNTP: State change from 6 to 7 [2018-05-12T08:51:16.141Z] INET: State change to 5 [2018-05-12T08:51:16.143Z] [2018-05-12T08:51:16.145Z] MAIN: Leaving state 2 [2018-05-12T08:51:16.147Z] MAIN: Entering state 3 [2018-05-12T08:51:16.148Z] [2018-05-12T08:51:16.150Z] CNFG: Load online user config state change to 4 [2018-05-12T08:51:16.153Z] HTTP: Close active socket 0 [2018-05-12T08:51:16.155Z] HTTP: Starting connection [2018-05-12T08:51:16.167Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T08:51:16.170Z] HTTP: Wait for TLS Connect [2018-05-12T08:51:16.627Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T08:51:16.660Z] HTTP: Got 1477 bytes [2018-05-12T08:51:18.662Z] HTTP: Connection Closed [2018-05-12T08:51:18.665Z] HTTP: Close active socket 1 [2018-05-12T08:51:18.669Z] CONF: Parsing response token: HTTP/1.1 200 OK [2018-05-12T08:51:18.674Z] CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 [2018-05-12T08:51:18.676Z] [2018-05-12T08:51:18.679Z] CNFG: Load online user config state change to 6 [2018-05-12T08:51:20.672Z] FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 [2018-05-12T08:51:20.675Z] HTTP: Starting connection [2018-05-12T08:51:20.686Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T08:51:20.688Z] HTTP: Wait for TLS Connect [2018-05-12T08:51:21.181Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T08:51:21.192Z] HTTP: Got 1232 bytes [2018-05-12T08:51:23.192Z] HTTP: Connection Closed [2018-05-12T08:51:23.195Z] HTTP: Close active socket 1 [2018-05-12T08:51:23.196Z] [2018-05-12T08:51:23.199Z] CNFG: Load online user config state change to 7 [2018-05-12T08:51:23.201Z] [2018-05-12T08:51:23.202Z] CNFG: Configuring LoRa module [2018-05-12T08:51:23.205Z] LORA: Changing state from 4 to 6 [2018-05-12T08:51:23.208Z] LORA: Starting reconfiguration [2018-05-12T08:51:23.216Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.223Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.258Z] LORA: version: 00 [2018-05-12T08:51:23.263Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.270Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.276Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.282Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.288Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.294Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.301Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.307Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.372Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.378Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.383Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.389Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.394Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.400Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.406Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.411Z] LORA: Configuration failed, retry [2018-05-12T08:51:23.417Z] LORA: Starting reconfiguration [2018-05-12T08:51:23.421Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.426Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.444Z] LORA: version: 00 [2018-05-12T08:51:23.445Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.450Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.459Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.464Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.471Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.477Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.486Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.493Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.500Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.506Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.515Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.522Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.529Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.535Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.542Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.548Z] LORA: Configuration failed, retry [2018-05-12T08:51:23.555Z] LORA: Starting reconfiguration [2018-05-12T08:51:23.559Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.565Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.571Z] LORA: version: 00 [2018-05-12T08:51:23.573Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.580Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.586Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.594Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.600Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.887Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.895Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.900Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.920Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.927Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.935Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.941Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.949Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.956Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.963Z] LORA: UART WRITE ERROR! [2018-05-12T08:51:23.969Z] LORA: Configuration failed, retry [2018-05-12T08:51:23.976Z] LORA: RESET MODULE [2018-05-12T08:51:23.977Z] LORA: Changing state from 6 to 0 [2018-05-12T08:51:24.089Z] LORA: Initialisation complete [2018-05-12T08:51:24.091Z] LORA: Changing state from 0 to 1 [2018-05-12T08:51:25.523Z] MON: SYS Stack size: 2851 [2018-05-12T08:51:25.524Z] MON: heap usage: 152KB (238KB), free: 187KB [2018-05-12T08:51:31.031Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-05-12T08:51:31.036Z] LORA: Changing state from 1 to 2 [2018-05-12T08:51:31.040Z] LORA: Communication on 115200 OK, waiting for application. [2018-05-12T08:51:31.043Z] LORA: Changing state from 2 to 4 [2018-05-12T08:51:31.047Z] LORA: Changing state from 4 to 6 [2018-05-12T08:51:31.051Z] LORA: Starting reconfiguration [2018-05-12T08:51:31.056Z] LORA: version: 01 [2018-05-12T08:51:33.098Z] LORA: UART TIMEOUT [2018-05-12T08:51:33.102Z] LORA: Configuration succeeded [2018-05-12T08:51:33.109Z] LORA: Starting operation [2018-05-12T08:51:33.111Z] LORA: Changing state from 6 to 8 [2018-05-12T08:51:35.362Z] MON: SYS Stack size: 2851 [2018-05-12T08:51:35.366Z] MON: heap usage: 152KB (238KB), free: 187KB [2018-05-12T08:51:39.110Z] LORA: Changing state from 8 to 5 [2018-05-12T08:51:39.112Z] LORA: GOING ASYNC [2018-05-12T08:51:39.113Z] LORA: Changing state from 5 to 11 [2018-05-12T08:51:39.164Z] [2018-05-12T08:51:39.166Z] CNFG: Load online user config state change to 9 [2018-05-12T08:51:39.168Z] [2018-05-12T08:51:39.180Z] MAIN: Leaving state 3 [2018-05-12T08:51:39.181Z] MAIN: Entering state 4 [2018-05-12T08:51:39.182Z] SDCARD: Mounted disk [2018-05-12T08:51:39.184Z] FLASH: Loading FOTA Data [2018-05-12T08:51:39.185Z] FIRM: Requesting key ... [2018-05-12T08:51:39.186Z] HTTP: Starting connection [2018-05-12T08:51:39.187Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T08:51:39.189Z] HTTP: Wait for TLS Connect [2018-05-12T08:51:39.699Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T08:51:39.728Z] HTTP: Got 515 bytes [2018-05-12T08:51:41.730Z] HTTP: Connection Closed [2018-05-12T08:51:41.733Z] HTTP: Close active socket 1 [2018-05-12T08:51:41.735Z] FIRM: Starting download [2018-05-12T08:51:41.737Z] FIRM: available bytes: 79 [2018-05-12T08:51:41.746Z] FIRM: (Downloaded FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T08:51:41.757Z] FIRM: (Stored FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T08:51:41.760Z] FIRM: Firmware is already downloaded [2018-05-12T08:51:41.764Z] MAIN: No new firmware available [2018-05-12T08:51:41.765Z] [2018-05-12T08:51:41.768Z] MAIN: Leaving state 4 [2018-05-12T08:51:41.770Z] MAIN: Entering state 5 [2018-05-12T08:51:41.772Z] MQTT: GOT IP: 52.169.76.203 [2018-05-12T08:51:41.775Z] Connecting to: 52.169.76.203 [2018-05-12T08:51:41.778Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-05-12T08:51:41.781Z] MQTT: Wait for SSL Connect [2018-05-12T08:51:42.340Z] MQTT: TLS ready: Connect MQTT [2018-05-12T08:51:42.447Z] RQMQTT: Connected [2018-05-12T08:51:42.453Z] [2018-05-12T08:51:42.456Z] ************************* [2018-05-12T08:51:42.458Z] MAIN: Gateway bridging [2018-05-12T08:51:42.463Z] ************************* [2018-05-12T08:51:42.464Z] [2018-05-12T08:51:42.467Z] MQTT: Sending status packet [2018-05-12T08:51:42.468Z] MQTT: Report reboot error: 0110 [2018-05-12T08:51:42.472Z] MQTT: Report config error: 0600000080 [2018-05-12T08:51:42.480Z] MQTT: Sending status succeeded: 0 [2018-05-12T08:51:45.360Z] MON: SYS Stack size: 2831 [2018-05-12T08:51:45.364Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:51:55.356Z] MON: SYS Stack size: 2831 [2018-05-12T08:51:55.360Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T08:52:05.355Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:05.358Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:52:12.438Z] MQTT: Sending status packet [2018-05-12T08:52:12.470Z] MQTT: Sending status succeeded: 1 [2018-05-12T08:52:15.351Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:15.354Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T08:52:25.350Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:25.353Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:52:35.347Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:35.351Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:52:39.083Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:52:42.428Z] MQTT: Sending status packet [2018-05-12T08:52:42.459Z] MQTT: Sending status succeeded: 2 [2018-05-12T08:52:45.347Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:45.350Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T08:52:55.346Z] MON: SYS Stack size: 2831 [2018-05-12T08:52:55.348Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:05.345Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:05.348Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:12.423Z] MQTT: Sending status packet [2018-05-12T08:53:12.451Z] MQTT: Sending status succeeded: 3 [2018-05-12T08:53:15.342Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:15.346Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:25.341Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:25.345Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:35.339Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:35.342Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:39.069Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:53:42.418Z] MQTT: Sending status packet [2018-05-12T08:53:42.446Z] MQTT: Sending status succeeded: 4 [2018-05-12T08:53:45.337Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:45.340Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:53:55.335Z] MON: SYS Stack size: 2831 [2018-05-12T08:53:55.338Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:54:05.333Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:05.336Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T08:54:12.412Z] MQTT: Sending status packet [2018-05-12T08:54:12.442Z] MQTT: Sending status succeeded: 5 [2018-05-12T08:54:15.332Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:15.335Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T08:54:25.332Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:25.336Z] MON: heap usage: 264KB (266KB), free: 74KB [2018-05-12T08:54:35.330Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:35.333Z] MON: heap usage: 264KB (266KB), free: 74KB [2018-05-12T08:54:39.058Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:54:42.409Z] MQTT: Sending status packet [2018-05-12T08:54:42.437Z] MQTT: Sending status succeeded: 6 [2018-05-12T08:54:45.330Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:45.333Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:54:55.327Z] MON: SYS Stack size: 2831 [2018-05-12T08:54:55.330Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:55:05.325Z] MON: SYS Stack size: 2831 [2018-05-12T08:55:05.328Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:55:12.398Z] MQTT: Sending status packet [2018-05-12T08:55:12.428Z] MQTT: Sending status succeeded: 7 [2018-05-12T08:55:15.323Z] MON: SYS Stack size: 2831 [2018-05-12T08:55:15.326Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:55:25.323Z] MON: SYS Stack size: 2831 [2018-05-12T08:55:25.326Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:55:35.323Z] MON: SYS Stack size: 2831 [2018-05-12T08:55:35.326Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T08:55:39.047Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T08:55:42.396Z] MQTT: Sending status packet [2018-05-12T08:55:42.426Z] MQTT: Sending status succeeded: 8 ... ... ... [2018-05-12T15:06:11.011Z] MQTT: Sending status packet [2018-05-12T15:06:11.042Z] MQTT: Sending status succeeded: 749 [2018-05-12T15:06:15.467Z] MON: SYS Stack size: 2831 [2018-05-12T15:06:15.470Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T15:06:25.464Z] MON: SYS Stack size: 2831 [2018-05-12T15:06:25.467Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T15:06:35.460Z] MON: SYS Stack size: 2831 [2018-05-12T15:06:35.464Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T15:06:37.650Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T15:06:40.997Z] MQTT: Sending status packet [2018-05-12T15:06:41.026Z] MQTT: Sending status succeeded: 750 [2018-05-12T15:06:45.457Z] MON: SYS Stack size: 2831 [2018-05-12T15:06:45.460Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T15:06:55.452Z] MON: SYS Stack size: 2831 [2018-05-12T15:06:55.456Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T15:07:05.449Z] MON: SYS Stack size: 2831 [2018-05-12T15:07:05.452Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-05-12T15:07:10.983Z] MQTT: Sending status packet [2018-05-12T15:07:11.013Z] MQTT: Sending status succeeded: 751 [2018-05-12T15:07:15.444Z] MON: SYS Stack size: 2831 [2018-05-12T15:07:15.448Z] MON: heap usage: 266KB (267KB), free: 73KB [2018-05-12T15:07:17.049Z] BTN: change to state: 1 [2018-05-12T15:07:17.199Z] BTN: change to state: 2 [2018-05-12T15:07:17.200Z] [2018-05-12T15:07:17.202Z] MAIN: Leaving state 5 [2018-05-12T15:07:17.228Z] MAIN: Ent ```

Pressed Mode button; still no LoRa despite "LORA: Starting operation" and "LORA: GOING ASYNC"

```text [2018-05-12T15:07:17.231Z] *** Application reboot [2018-05-12T15:07:17.265Z] [2018-05-12T15:07:19.451Z] SNTP: State change from 0 to 0 [2018-05-12T15:07:19.453Z] SNTP: State change from 0 to 0 [2018-05-12T15:07:19.455Z] [2018-05-12T15:07:19.456Z] [2018-05-12T15:07:19.456Z] [2018-05-12T15:07:19.459Z] ************************** [2018-05-12T15:07:19.461Z] * The Things Network * [2018-05-12T15:07:19.463Z] * G A T E W A Y * [2018-05-12T15:07:19.465Z] ************************** [2018-05-12T15:07:19.472Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-05-12T15:07:19.503Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-05-12T15:07:19.505Z] Build time: Mar 22 2018 12:21:52 [2018-05-12T15:07:19.507Z] Reboot reason: 0x40 [2018-05-12T15:07:19.535Z] BOOT: (persisted info) 6F 72 72 65 01 40 83 2C E7 16 0D 49 B2 1A 54 B6 [2018-05-12T15:07:19.536Z] [2018-05-12T15:07:19.537Z] [2018-05-12T15:07:19.537Z] [2018-05-12T15:07:19.538Z] [2018-05-12T15:07:19.538Z] WIFI: Entering state 0 [2018-05-12T15:07:19.539Z] WIFI: Entering SCAN state 0 [2018-05-12T15:07:19.540Z] [2018-05-12T15:07:19.541Z] MAIN: Initialisation complete [2018-05-12T15:07:19.542Z] LORA: Changing state from 0 to 0 [2018-05-12T15:07:19.699Z] [2018-05-12T15:07:19.700Z] MAIN: Leaving state 0 [2018-05-12T15:07:19.703Z] MAIN: Entering state 1 [2018-05-12T15:07:19.708Z] FLASH: Magic bytes found: wifi config present [2018-05-12T15:07:19.713Z] FLASH: Magic bytes found: activation data present [2018-05-12T15:07:19.717Z] FLASH: Magic bytes found: FOTA data present [2018-05-12T15:07:19.721Z] FLASH: Loading Firmware Data [2018-05-12T15:07:19.736Z] CNFG: (Firmware HASH (sha256)) 14 3E 99 52 CC 5B 11 E1 A2 21 8A 04 06 AA 73 1D 1D D8 25 CE FF BD C3 28 34 1E FB 0B B2 AC 9B 56 [2018-05-12T15:07:19.738Z] FLASH: Loading WiFi Data [2018-05-12T15:07:19.741Z] CNFG: WiFi SSID: Palahala [2018-05-12T15:07:19.742Z] CNFG: WiFi key: *** [2018-05-12T15:07:19.745Z] CNFG: WiFi conn_type: 1 [2018-05-12T15:07:19.746Z] CNFG: WiFi sec_type: 4 [2018-05-12T15:07:19.748Z] FLASH: Loading Activation Data [2018-05-12T15:07:19.751Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-05-12T15:07:19.754Z] CNFG: Gateway Key: *** [2018-05-12T15:07:19.759Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-05-12T15:07:19.762Z] CNFG: Locked: true [2018-05-12T15:07:19.765Z] CNFG: Locked first time: false [2018-05-12T15:07:19.766Z] [2018-05-12T15:07:19.768Z] MAIN: Leaving state 1 [2018-05-12T15:07:19.771Z] MAIN: Entering state 2 [2018-05-12T15:07:19.773Z] INET: State change to 0 [2018-05-12T15:07:20.073Z] LORA: Initialisation complete [2018-05-12T15:07:20.076Z] LORA: Changing state from 0 to 1 [2018-05-12T15:07:20.323Z] WIFI: Entering state 1 [2018-05-12T15:07:20.326Z] ETH: IP Address: 0.0.0.0 [2018-05-12T15:07:20.329Z] WIFI: Entering state 4 [2018-05-12T15:07:20.331Z] WIFI: Entering SCAN state 1 [2018-05-12T15:07:20.752Z] Scan is completed successfully [2018-05-12T15:07:20.755Z] WIFI: Entering SCAN state 2 [2018-05-12T15:07:20.761Z] WIFI: Entering SCAN state 5 [2018-05-12T15:07:20.764Z] WIFI: Entering SCAN state 0 [2018-05-12T15:07:20.767Z] WIFI: Entering state 2 [2018-05-12T15:07:20.769Z] WIFI: Disabling modules [2018-05-12T15:07:20.774Z] Head magic match void: trying to free an already freed block, ignore [2018-05-12T15:07:20.777Z] WIFI: Entering state 3 [2018-05-12T15:07:21.416Z] SNTP: State change from 0 to 1 [2018-05-12T15:07:21.486Z] INET: Gateway has Ethernet [2018-05-12T15:07:21.489Z] INET: State change to 2 [2018-05-12T15:07:21.495Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-05-12T15:07:21.641Z] WIFI: Enabling modules for client [2018-05-12T15:07:21.643Z] WIFI: Entering state 6 [2018-05-12T15:07:21.645Z] [2018-05-12T15:07:21.646Z] [2018-05-12T15:07:21.648Z] >WIFI: IP Address: 0.0.0.0 [2018-05-12T15:07:22.513Z] SNTP: State change from 1 to 2 [2018-05-12T15:07:24.510Z] CB: ETH: IP Address: 192.168.0.12 [2018-05-12T15:07:26.483Z] INET: State change to 3 [2018-05-12T15:07:26.486Z] INET: Ping probe [2018-05-12T15:07:26.497Z] INET: Ping response from PIC32INT, set as default [2018-05-12T15:07:26.500Z] INET: State change to 4 [2018-05-12T15:07:26.506Z] WIFI: IP Address: 192.168.178.53 [2018-05-12T15:07:27.070Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-05-12T15:07:27.074Z] LORA: Changing state from 1 to 2 [2018-05-12T15:07:27.080Z] LORA: Communication on 115200 OK, waiting for application. [2018-05-12T15:07:27.083Z] LORA: Changing state from 2 to 4 [2018-05-12T15:07:28.002Z] SNTP: State change from 2 to 3 [2018-05-12T15:07:29.100Z] SNTP: State change from 3 to 4 [2018-05-12T15:07:29.439Z] MON: SYS Stack size: 3965 [2018-05-12T15:07:29.443Z] MON: heap usage: 148KB (156KB), free: 191KB [2018-05-12T15:07:30.200Z] SNTP: State change from 4 to 5 [2018-05-12T15:07:30.210Z] SNTP: State change from 5 to 6 [2018-05-12T15:07:30.213Z] SNTP: State change from 6 to 7 [2018-05-12T15:07:30.221Z] INET: State change to 5 [2018-05-12T15:07:30.225Z] [2018-05-12T15:07:30.227Z] MAIN: Leaving state 2 [2018-05-12T15:07:30.230Z] MAIN: Entering state 3 [2018-05-12T15:07:30.231Z] [2018-05-12T15:07:30.232Z] CNFG: Load online user config state change to 4 [2018-05-12T15:07:30.234Z] HTTP: Close active socket 0 [2018-05-12T15:07:30.347Z] HTTP: Starting connection [2018-05-12T15:07:30.361Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:07:30.364Z] HTTP: Wait for TLS Connect [2018-05-12T15:07:30.828Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:07:30.853Z] HTTP: Got 1477 bytes [2018-05-12T15:07:32.853Z] HTTP: Connection Closed [2018-05-12T15:07:32.857Z] HTTP: Close active socket 1 [2018-05-12T15:07:32.860Z] CONF: Parsing response token: HTTP/1.1 200 OK [2018-05-12T15:07:32.864Z] CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 [2018-05-12T15:07:32.867Z] [2018-05-12T15:07:32.869Z] CNFG: Load online user config state change to 6 [2018-05-12T15:07:34.860Z] FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 [2018-05-12T15:07:34.863Z] HTTP: Starting connection [2018-05-12T15:07:34.873Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:07:34.876Z] HTTP: Wait for TLS Connect [2018-05-12T15:07:35.374Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:07:35.390Z] HTTP: Got 1232 bytes [2018-05-12T15:07:37.388Z] HTTP: Connection Closed [2018-05-12T15:07:37.390Z] HTTP: Close active socket 1 [2018-05-12T15:07:37.392Z] [2018-05-12T15:07:37.395Z] CNFG: Load online user config state change to 7 [2018-05-12T15:07:37.397Z] [2018-05-12T15:07:37.399Z] CNFG: Configuring LoRa module [2018-05-12T15:07:37.402Z] LORA: Changing state from 4 to 6 [2018-05-12T15:07:37.404Z] LORA: Starting reconfiguration [2018-05-12T15:07:37.413Z] LORA: version: 01 [2018-05-12T15:07:39.428Z] MON: SYS Stack size: 2870 [2018-05-12T15:07:39.432Z] MON: heap usage: 152KB (238KB), free: 187KB [2018-05-12T15:07:39.448Z] LORA: UART TIMEOUT [2018-05-12T15:07:39.451Z] LORA: Configuration succeeded [2018-05-12T15:07:39.461Z] LORA: Starting operation [2018-05-12T15:07:39.463Z] LORA: Changing state from 6 to 8 [2018-05-12T15:07:45.443Z] LORA: Changing state from 8 to 5 [2018-05-12T15:07:45.447Z] LORA: GOING ASYNC [2018-05-12T15:07:45.451Z] LORA: Changing state from 5 to 11 [2018-05-12T15:07:45.453Z] [2018-05-12T15:07:45.456Z] CNFG: Load online user config state change to 9 [2018-05-12T15:07:45.458Z] [2018-05-12T15:07:45.458Z] MAIN: Leaving state 3 [2018-05-12T15:07:45.462Z] MAIN: Entering state 4 [2018-05-12T15:07:45.463Z] SDCARD: Mounted disk [2018-05-12T15:07:45.464Z] FLASH: Loading FOTA Data [2018-05-12T15:07:45.467Z] FIRM: Requesting key ... [2018-05-12T15:07:45.468Z] HTTP: Starting connection [2018-05-12T15:07:45.481Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:07:45.484Z] HTTP: Wait for TLS Connect [2018-05-12T15:07:46.050Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:07:46.083Z] HTTP: Got 515 bytes [2018-05-12T15:07:48.081Z] HTTP: Connection Closed [2018-05-12T15:07:48.084Z] HTTP: Close active socket 1 [2018-05-12T15:07:48.086Z] FIRM: Starting download [2018-05-12T15:07:48.089Z] FIRM: available bytes: 79 [2018-05-12T15:07:48.100Z] FIRM: (Downloaded FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T15:07:48.109Z] FIRM: (Stored FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T15:07:48.112Z] FIRM: Firmware is already downloaded [2018-05-12T15:07:48.115Z] MAIN: No new firmware available [2018-05-12T15:07:48.117Z] [2018-05-12T15:07:48.119Z] MAIN: Leaving state 4 [2018-05-12T15:07:48.122Z] MAIN: Entering state 5 [2018-05-12T15:07:48.124Z] MQTT: GOT IP: 52.169.76.203 [2018-05-12T15:07:48.127Z] Connecting to: 52.169.76.203 [2018-05-12T15:07:48.129Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-05-12T15:07:48.132Z] MQTT: Wait for SSL Connect [2018-05-12T15:07:48.695Z] MQTT: TLS ready: Connect MQTT [2018-05-12T15:07:48.804Z] RQMQTT: Connected [2018-05-12T15:07:48.811Z] [2018-05-12T15:07:48.815Z] ************************* [2018-05-12T15:07:48.817Z] MAIN: Gateway bridging [2018-05-12T15:07:48.821Z] ************************* [2018-05-12T15:07:48.822Z] [2018-05-12T15:07:49.416Z] MON: SYS Stack size: 2831 [2018-05-12T15:07:49.420Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T15:07:49.422Z] MQTT: Sending status packet [2018-05-12T15:07:49.425Z] MQTT: Report reboot error: 0140 [2018-05-12T15:07:49.448Z] MQTT: Sending status succeeded: 0 [2018-05-12T15:07:59.403Z] MON: SYS Stack size: 2831 [2018-05-12T15:07:59.406Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:08:09.391Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:09.394Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:08:19.377Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:19.380Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:08:19.383Z] MQTT: Sending status packet [2018-05-12T15:08:19.408Z] MQTT: Sending status succeeded: 1 [2018-05-12T15:08:29.367Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:29.373Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T15:08:39.354Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:39.357Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T15:08:45.371Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T15:08:49.343Z] MQTT: Sending status packet [2018-05-12T15:08:49.346Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:49.348Z] MON: heap usage: 264KB (266KB), free: 74KB [2018-05-12T15:08:49.371Z] MQTT: Sending status succeeded: 2 [2018-05-12T15:08:59.337Z] MON: SYS Stack size: 2831 [2018-05-12T15:08:59.341Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:09:09.330Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:09.334Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:09:19.321Z] MQTT: Sending status packet [2018-05-12T15:09:19.326Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:19.331Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T15:09:19.351Z] MQTT: Sending status succeeded: 3 [2018-05-12T15:09:29.322Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:29.325Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:09:39.315Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:39.318Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:09:45.329Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-05-12T15:09:49.303Z] MQTT: Sending status packet [2018-05-12T15:09:49.309Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:49.313Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T15:09:49.333Z] MQTT: Sending status succeeded: 4 [2018-05-12T15:09:59.302Z] MON: SYS Stack size: 2831 [2018-05-12T15:09:59.306Z] MON: heap usage: 266KB (266KB), free: 73KB [2018-05-12T15:10:09.294Z] MON: SYS Stack size: 2831 [2018-05-12T15:10:09.297Z] MON: heap usage: 264KB (266KB), free: 74KB [2018-05-12T15:10:19.276Z] MQTT: Sending status packet [2018-05-12T15:10:19.285Z] MON: SYS Stack size: 2831 [2018-05-12T15:10:19.289Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T15:10:19.305Z] MQTT: Sending status succeeded: 5 [2018-05-12T15:10:29.278Z] MON: SYS Stack size: 2831 [2018-05-12T15:10:29.281Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:10:36.998Z] SNTP: State change from 0 to 0 [2018-05-12T15:10:37.001Z] SNTP: State change from 0 to 0 ```

Power cycled; all fine again

```text [2018-05-12T15:10:37.008Z] ************************** [2018-05-12T15:10:37.009Z] * The Things Network * [2018-05-12T15:10:37.012Z] * G A T E W A Y * [2018-05-12T15:10:37.013Z] ************************** [2018-05-12T15:10:37.020Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-05-12T15:10:37.040Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-05-12T15:10:37.042Z] Build time: Mar 22 2018 12:21:52 [2018-05-12T15:10:37.053Z] Reboot reason: 0x03 [2018-05-12T15:10:37.060Z] BOOT: (persisted info) 6F 72 72 65 01 03 8B 2C E7 16 05 49 B2 3A D8 B6 [2018-05-12T15:10:37.062Z] [2018-05-12T15:10:37.062Z] [2018-05-12T15:10:37.063Z] [2018-05-12T15:10:37.063Z] [2018-05-12T15:10:37.064Z] WIFI: Entering state 0 [2018-05-12T15:10:37.065Z] WIFI: Entering SCAN state 0 [2018-05-12T15:10:37.066Z] [2018-05-12T15:10:37.066Z] MAIN: Initialisation complete [2018-05-12T15:10:37.082Z] LORA: Changing state from 0 to 0 [2018-05-12T15:10:37.243Z] [2018-05-12T15:10:37.245Z] MAIN: Leaving state 0 [2018-05-12T15:10:37.248Z] MAIN: Entering state 1 [2018-05-12T15:10:37.250Z] SDCARD: Mounted disk [2018-05-12T15:10:37.255Z] FLASH: Magic bytes found: wifi config present [2018-05-12T15:10:37.260Z] FLASH: Magic bytes found: activation data present [2018-05-12T15:10:37.265Z] FLASH: Magic bytes found: FOTA data present [2018-05-12T15:10:37.268Z] FLASH: Loading Firmware Data [2018-05-12T15:10:37.280Z] CNFG: (Firmware HASH (sha256)) 14 3E 99 52 CC 5B 11 E1 A2 21 8A 04 06 AA 73 1D 1D D8 25 CE FF BD C3 28 34 1E FB 0B B2 AC 9B 56 [2018-05-12T15:10:37.283Z] FLASH: Loading WiFi Data [2018-05-12T15:10:37.285Z] CNFG: WiFi SSID: Palahala [2018-05-12T15:10:37.288Z] CNFG: WiFi key: *** [2018-05-12T15:10:37.290Z] CNFG: WiFi conn_type: 1 [2018-05-12T15:10:37.293Z] CNFG: WiFi sec_type: 4 [2018-05-12T15:10:37.296Z] FLASH: Loading Activation Data [2018-05-12T15:10:37.298Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-05-12T15:10:37.301Z] CNFG: Gateway Key: *** [2018-05-12T15:10:37.306Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-05-12T15:10:37.309Z] CNFG: Locked: true [2018-05-12T15:10:37.312Z] CNFG: Locked first time: false [2018-05-12T15:10:37.313Z] [2018-05-12T15:10:37.315Z] MAIN: Leaving state 1 [2018-05-12T15:10:37.318Z] MAIN: Entering state 2 [2018-05-12T15:10:37.320Z] INET: State change to 0 [2018-05-12T15:10:37.619Z] LORA: Initialisation complete [2018-05-12T15:10:37.622Z] LORA: Changing state from 0 to 1 [2018-05-12T15:10:37.873Z] WIFI: Entering state 1 [2018-05-12T15:10:37.877Z] ETH: IP Address: 0.0.0.0 [2018-05-12T15:10:37.880Z] WIFI: Entering state 4 [2018-05-12T15:10:37.883Z] WIFI: Entering SCAN state 1 [2018-05-12T15:10:38.966Z] SNTP: State change from 0 to 1 [2018-05-12T15:10:39.036Z] INET: Gateway has Ethernet [2018-05-12T15:10:39.039Z] INET: State change to 2 [2018-05-12T15:10:39.048Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-05-12T15:10:40.063Z] SNTP: State change from 1 to 2 [2018-05-12T15:10:40.172Z] Scan is completed successfully [2018-05-12T15:10:40.175Z] WIFI: Entering SCAN state 2 [2018-05-12T15:10:40.183Z] WIFI: Entering SCAN state 5 [2018-05-12T15:10:40.187Z] WIFI: Entering SCAN state 0 [2018-05-12T15:10:40.190Z] WIFI: Entering state 2 [2018-05-12T15:10:40.194Z] WIFI: Disabling modules [2018-05-12T15:10:40.198Z] Head magic match void: trying to free an already freed block, ignore [2018-05-12T15:10:40.201Z] SNTP: State change from 2 to 1 [2018-05-12T15:10:40.203Z] WIFI: Entering state 3 [2018-05-12T15:10:41.063Z] WIFI: Enabling modules for client [2018-05-12T15:10:41.066Z] WIFI: Entering state 6 [2018-05-12T15:10:41.068Z] [2018-05-12T15:10:41.069Z] [2018-05-12T15:10:41.070Z] >WIFI: IP Address: 0.0.0.0 [2018-05-12T15:10:41.161Z] SNTP: State change from 1 to 2 [2018-05-12T15:10:42.059Z] ETH: IP Address: 192.168.0.12 [2018-05-12T15:10:44.032Z] CB: INET: State change to 3 [2018-05-12T15:10:44.035Z] INET: Ping probe [2018-05-12T15:10:44.046Z] INET: Ping response from PIC32INT, set as default [2018-05-12T15:10:44.050Z] INET: State change to 4 [2018-05-12T15:10:44.056Z] WIFI: IP Address: 192.168.178.53 [2018-05-12T15:10:44.614Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-05-12T15:10:44.618Z] LORA: Changing state from 1 to 2 [2018-05-12T15:10:44.623Z] LORA: Communication on 115200 OK, waiting for application. [2018-05-12T15:10:44.627Z] LORA: Changing state from 2 to 4 [2018-05-12T15:10:45.551Z] SNTP: State change from 2 to 3 [2018-05-12T15:10:46.650Z] SNTP: State change from 3 to 4 [2018-05-12T15:10:46.984Z] MON: SYS Stack size: 3965 [2018-05-12T15:10:46.987Z] MON: heap usage: 148KB (157KB), free: 191KB [2018-05-12T15:10:47.748Z] SNTP: State change from 4 to 5 [2018-05-12T15:10:47.763Z] SNTP: State change from 5 to 6 [2018-05-12T15:10:47.772Z] SNTP: State change from 6 to 7 [2018-05-12T15:10:47.776Z] INET: State change to 5 [2018-05-12T15:10:47.777Z] [2018-05-12T15:10:47.778Z] MAIN: Leaving state 2 [2018-05-12T15:10:47.785Z] MAIN: Entering state 3 [2018-05-12T15:10:47.789Z] [2018-05-12T15:10:47.792Z] CNFG: Load online user config state change to 4 [2018-05-12T15:10:47.794Z] HTTP: Close active socket 0 [2018-05-12T15:10:47.796Z] HTTP: Starting connection [2018-05-12T15:10:47.797Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:10:47.798Z] HTTP: Wait for TLS Connect [2018-05-12T15:10:48.258Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:10:48.287Z] HTTP: Got 1477 bytes [2018-05-12T15:10:50.286Z] HTTP: Connection Closed [2018-05-12T15:10:50.289Z] HTTP: Close active socket 1 [2018-05-12T15:10:50.292Z] CONF: Parsing response token: HTTP/1.1 200 OK [2018-05-12T15:10:50.297Z] CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 [2018-05-12T15:10:50.299Z] [2018-05-12T15:10:50.302Z] CNFG: Load online user config state change to 6 [2018-05-12T15:10:52.293Z] FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 [2018-05-12T15:10:52.297Z] HTTP: Starting connection [2018-05-12T15:10:52.306Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:10:52.308Z] HTTP: Wait for TLS Connect [2018-05-12T15:10:52.810Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:10:52.822Z] HTTP: Got 1232 bytes [2018-05-12T15:10:54.821Z] HTTP: Connection Closed [2018-05-12T15:10:54.824Z] HTTP: Close active socket 1 [2018-05-12T15:10:54.827Z] [2018-05-12T15:10:54.829Z] CNFG: Load online user config state change to 7 [2018-05-12T15:10:54.830Z] [2018-05-12T15:10:54.832Z] CNFG: Configuring LoRa module [2018-05-12T15:10:54.835Z] LORA: Changing state from 4 to 6 [2018-05-12T15:10:54.838Z] LORA: Starting reconfiguration [2018-05-12T15:10:54.845Z] LORA: version: 01 [2018-05-12T15:10:56.884Z] LORA: UART TIMEOUT [2018-05-12T15:10:56.886Z] LORA: Configuration succeeded [2018-05-12T15:10:56.894Z] LORA: Starting operation [2018-05-12T15:10:56.896Z] LORA: Changing state from 6 to 8 [2018-05-12T15:10:56.972Z] MON: SYS Stack size: 2837 [2018-05-12T15:10:56.976Z] MON: heap usage: 152KB (238KB), free: 187KB [2018-05-12T15:11:02.882Z] LORA: Changing state from 8 to 5 [2018-05-12T15:11:02.885Z] LORA: GOING ASYNC [2018-05-12T15:11:02.888Z] LORA: Changing state from 5 to 11 [2018-05-12T15:11:02.889Z] [2018-05-12T15:11:02.892Z] CNFG: Load online user config state change to 9 [2018-05-12T15:11:02.893Z] [2018-05-12T15:11:02.896Z] MAIN: Leaving state 3 [2018-05-12T15:11:02.897Z] MAIN: Entering state 4 [2018-05-12T15:11:02.900Z] FLASH: Loading FOTA Data [2018-05-12T15:11:02.901Z] FIRM: Requesting key ... [2018-05-12T15:11:02.904Z] HTTP: Starting connection [2018-05-12T15:11:02.912Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-05-12T15:11:02.915Z] HTTP: Wait for TLS Connect [2018-05-12T15:11:03.486Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-05-12T15:11:03.612Z] HTTP: Got 515 bytes [2018-05-12T15:11:05.614Z] HTTP: Connection Closed [2018-05-12T15:11:05.617Z] HTTP: Close active socket 1 [2018-05-12T15:11:05.619Z] FIRM: Starting download [2018-05-12T15:11:05.622Z] FIRM: available bytes: 79 [2018-05-12T15:11:05.631Z] FIRM: (Downloaded FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T15:11:05.642Z] FIRM: (Stored FOTA key) 65 0D 50 41 6F 3C 7A 21 B0 6A 61 4A FF BE C3 DD 3F 8A 2C 8F D1 98 70 9F 71 EF C5 53 6A 7D 31 AF [2018-05-12T15:11:05.645Z] FIRM: Firmware is already downloaded [2018-05-12T15:11:05.648Z] MAIN: No new firmware available [2018-05-12T15:11:05.650Z] [2018-05-12T15:11:05.652Z] MAIN: Leaving state 4 [2018-05-12T15:11:05.655Z] MAIN: Entering state 5 [2018-05-12T15:11:05.657Z] MQTT: GOT IP: 52.169.76.203 [2018-05-12T15:11:05.662Z] Connecting to: 52.169.76.203 [2018-05-12T15:11:05.665Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-05-12T15:11:05.667Z] MQTT: Wait for SSL Connect [2018-05-12T15:11:06.226Z] MQTT: TLS ready: Connect MQTT [2018-05-12T15:11:06.965Z] RQMON: SYS Stack size: 2837 [2018-05-12T15:11:06.970Z] MON: heap usage: 266KB (266KB), free: 72KB [2018-05-12T15:11:11.280Z] MQTT: Connection failed [2018-05-12T15:11:11.287Z] [2018-05-12T15:11:11.300Z] MAIN: MQTT error [2018-05-12T15:11:11.307Z] [2018-05-12T15:11:11.307Z] MAIN: Leaving state 5 [2018-05-12T15:11:11.309Z] MAIN: Entering state 6 [2018-05-12T15:11:11.310Z] INET: State change to 0 [2018-05-12T15:11:11.330Z] WIFI: Disabling modules [2018-05-12T15:11:11.331Z] CB: Disconnect [2018-05-12T15:11:11.332Z] Head magic match void: trying to free an already freed block, ignore [2018-05-12T15:11:11.333Z] SNTP: State change from 7 to 1 [2018-05-12T15:11:11.334Z] WIFI: Entering state 3 [2018-05-12T15:11:11.335Z] INET: Gateway has Ethernet [2018-05-12T15:11:11.336Z] INET: State change to 2 [2018-05-12T15:11:11.340Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-05-12T15:11:11.902Z] SNTP: State change from 1 to 2 [2018-05-12T15:11:12.171Z] WIFI: Enabling modules for client [2018-05-12T15:11:12.174Z] WIFI: Entering state 6 [2018-05-12T15:11:12.177Z] WIFI: IP Address: 0.0.0.0 [2018-05-12T15:11:12.999Z] SNTP: State change from 2 to 3 [2018-05-12T15:11:13.859Z] CB: LORA: Accepted packet [2018-05-12T15:11:13.927Z] LORA: Packet dropped! Bad CRC [2018-05-12T15:11:14.098Z] SNTP: State change from 3 to 4 [2018-05-12T15:11:14.454Z] LORA: Packet dropped! Bad CRC [2018-05-12T15:11:14.998Z] WIFI: IP Address: 192.168.178.53 [2018-05-12T15:11:15.195Z] SNTP: State change from 4 to 5 [2018-05-12T15:11:15.702Z] SNTP: State change from 5 to 6 [2018-05-12T15:11:15.705Z] SNTP: State change from 6 to 7 [2018-05-12T15:11:16.286Z] INET: State change to 3 [2018-05-12T15:11:16.288Z] INET: Ping probe [2018-05-12T15:11:16.297Z] INET: Ping response from PIC32INT, set as default [2018-05-12T15:11:16.300Z] INET: State change to 5 [2018-05-12T15:11:16.302Z] [2018-05-12T15:11:16.304Z] MAIN: Leaving state 6 [2018-05-12T15:11:16.306Z] MAIN: Entering state 5 [2018-05-12T15:11:16.308Z] MQTT: GOT IP: 52.169.76.203 [2018-05-12T15:11:16.311Z] Connecting to: 52.169.76.203 [2018-05-12T15:11:16.331Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-05-12T15:11:16.333Z] MQTT: Wait for SSL Connect [2018-05-12T15:11:19.959Z] MON: SYS Stack size: 2837 [2018-05-12T15:11:19.962Z] MON: heap usage: 246KB (266KB), free: 92KB [2018-05-12T15:11:19.965Z] MQTT: TLS ready: Connect MQTT [2018-05-12T15:11:20.954Z] RQLORA: Accepted packet [2018-05-12T15:11:22.459Z] MQTT: Connection failed [2018-05-12T15:11:22.466Z] [2018-05-12T15:11:22.478Z] MAIN: MQTT error [2018-05-12T15:11:22.486Z] [2018-05-12T15:11:22.486Z] MAIN: Leaving state 5 [2018-05-12T15:11:22.487Z] MAIN: Entering state 6 [2018-05-12T15:11:22.488Z] INET: State change to 0 [2018-05-12T15:11:22.509Z] WIFI: Disabling modules [2018-05-12T15:11:22.511Z] CB: Disconnect [2018-05-12T15:11:22.512Z] Head magic match void: trying to free an already freed block, ignore [2018-05-12T15:11:22.513Z] SNTP: State change from 7 to 1 [2018-05-12T15:11:22.513Z] WIFI: Entering state 3 [2018-05-12T15:11:22.514Z] INET: Gateway has Ethernet [2018-05-12T15:11:22.516Z] INET: State change to 2 [2018-05-12T15:11:22.519Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-05-12T15:11:22.881Z] SNTP: State change from 1 to 2 [2018-05-12T15:11:23.345Z] WIFI: Enabling modules for client [2018-05-12T15:11:23.348Z] WIFI: Entering state 6 [2018-05-12T15:11:23.351Z] WIFI: IP Address: 0.0.0.0 [2018-05-12T15:11:23.981Z] SNTP: State change from 2 to 3 [2018-05-12T15:11:25.080Z] CB: SNTP: State change from 3 to 4 [2018-05-12T15:11:25.980Z] WIFI: IP Address: 192.168.178.53 [2018-05-12T15:11:26.177Z] SNTP: State change from 4 to 5 [2018-05-12T15:11:27.365Z] LORA: Accepted packet [2018-05-12T15:11:27.466Z] INET: State change to 3 [2018-05-12T15:11:27.470Z] INET: Ping probe [2018-05-12T15:11:27.497Z] INET: Ping response from MRF24WN, set as default [2018-05-12T15:11:27.501Z] INET: State change to 5 [2018-05-12T15:11:27.504Z] [2018-05-12T15:11:27.507Z] MAIN: Leaving state 6 [2018-05-12T15:11:27.509Z] MAIN: Entering state 5 [2018-05-12T15:11:27.513Z] MQTT: GOT IP: 52.169.76.203 [2018-05-12T15:11:27.514Z] Connecting to: 52.169.76.203 [2018-05-12T15:11:27.534Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-05-12T15:11:27.538Z] MQTT: Wait for SSL Connect [2018-05-12T15:11:28.227Z] MQTT: TLS ready: Connect MQTT [2018-05-12T15:11:28.379Z] RQMQTT: Connected [2018-05-12T15:11:28.390Z] [2018-05-12T15:11:28.395Z] ************************* [2018-05-12T15:11:28.397Z] MAIN: Gateway bridging [2018-05-12T15:11:28.402Z] ************************* [2018-05-12T15:11:28.403Z] [2018-05-12T15:11:28.421Z] MQTT: Sending UPLINK OK [2018-05-12T15:11:28.454Z] MQTT: Sending UPLINK OK [2018-05-12T15:11:28.513Z] MQTT: Sending UPLINK OK [2018-05-12T15:11:28.518Z] MQTT: Sending status packet [2018-05-12T15:11:28.521Z] MQTT: Report reboot error: 0103 [2018-05-12T15:11:28.529Z] MQTT: Report config error: 0600000020 [2018-05-12T15:11:28.546Z] MQTT: Sending status succeeded: 0 [2018-05-12T15:11:29.956Z] MON: SYS Stack size: 2837 [2018-05-12T15:11:29.959Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:11:32.768Z] SNTP: State change from 5 to 6 [2018-05-12T15:11:39.952Z] MON: SYS Stack size: 2837 [2018-05-12T15:11:39.954Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:11:47.048Z] SNTP: State change from 6 to 1 [2018-05-12T15:11:48.145Z] SNTP: State change from 1 to 2 [2018-05-12T15:11:49.247Z] SNTP: State change from 2 to 3 [2018-05-12T15:11:49.944Z] MON: SYS Stack size: 2837 [2018-05-12T15:11:49.947Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:11:50.341Z] SNTP: State change from 3 to 4 [2018-05-12T15:11:51.102Z] LORA: Accepted packet [2018-05-12T15:11:51.131Z] MQTT: Sending UPLINK OK [2018-05-12T15:11:51.440Z] SNTP: State change from 4 to 5 [2018-05-12T15:11:51.448Z] SNTP: State change from 5 to 6 [2018-05-12T15:11:51.452Z] SNTP: State change from 6 to 7 [2018-05-12T15:11:58.015Z] LORA: Accepted packet [2018-05-12T15:11:58.053Z] MQTT: Sending UPLINK OK [2018-05-12T15:11:58.501Z] MQTT: Sending status packet [2018-05-12T15:11:59.540Z] MQTT: Sending status succeeded: 1 [2018-05-12T15:11:59.940Z] MON: SYS Stack size: 2837 [2018-05-12T15:11:59.944Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:12:06.327Z] LORA: Accepted packet [2018-05-12T15:12:06.355Z] MQTT: Sending UPLINK OK [2018-05-12T15:12:09.935Z] MON: SYS Stack size: 2837 [2018-05-12T15:12:09.938Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:12:19.932Z] MON: SYS Stack size: 2837 [2018-05-12T15:12:19.934Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-05-12T15:12:22.753Z] LORA: Accepted packet [2018-05-12T15:12:22.782Z] MQTT: Sending UPLINK OK [2018-05-12T15:12:28.463Z] LORA: Accepted packet [2018-05-12T15:12:28.530Z] MQTT: Sending UPLINK OK [2018-05-12T15:12:28.533Z] MQTT: Sending status packet [2018-05-12T15:12:28.562Z] MQTT: Sending status succeeded: 2 ```

avbentem commented 6 years ago

If my notes don't fail me, then since my May 12th comment I've pressed the Mode button to resolve this problem:

May 15th, 7:25 Amsterdam time
May 22nd, 6:45
May 22nd, 18:25
May 27th, 22:20
June 3rd, 9:08, 9:13, 9:15

So today it was again running fine until it did its daily reboot for a firmware upgrade check, after which the LoRa module just failed to receive any LoRa packets. Today I had to press the Mode button 3 times to get things working again. Regardless wether or not receiving LoRa packets, only the main (power?) LED is illuminated on the card, while during the restart the LED marked "1" (in the row of 5) was on one or two times shortly too.

(Using ethernet though WiFi is configured too. And still running 1.0.3 from an SD card, commit: 2c56ce09, timestamp: 1521721252, Build time: Mar 22 2018 12:21:52, as 1.0.4 is giving me a reboot loop. As an aside, it's not clear to me if 1.0.3 or 1.0.4 is the current stable release if one would not use an SD card.)

avbentem commented 6 years ago

And some more human interventions pressing the Mode button, approximate times again:

June 3rd, 21:35 Amsterdam time
June 6th, 17:25
June 6th, 22:10
June 7th, 23:15 (after running into #47 first)
June 8th, 18:55
June 9th, 12:00 (after an automatic reboot at 11:41 for no apparent reason, Reboot reason: 0x10)

KrishnaIyer commented 6 years ago

This is related to #47 as the gateway controller was unable to maintain UART connection with the LoRa module and is also addressed in 1.0.5. Once again, please feel free to re-open it if the issue persists in 1.0.5.

avbentem commented 6 years ago

I've indeed not run into this issue since I updated to 1.0.5 on July 17th.

(Last occurrence on Monday July 16th, using 1.0.3.)

TheThingsProducts / gateway