TheThingsProducts / gateway

The Things Kickstarter Gateway
https://www.thethingsindustries.com/docs/gateways/models/thethingskickstartergateway
54 stars 20 forks source link

Boot stops in non-working state when failing to get configuration (LoRa module and bridging not enabled) #47

Closed avbentem closed 5 years ago

avbentem commented 6 years ago

This is a bug report.

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

I want/expect my gateway to run all day without any human intervention.

What steps did you take? (Give as many details as possible so that we can reproduce it)

Gateway was running just fine...

What went wrong? What is missing?

...until it suddenly rebooted for no apparent reason, and during the boot could not get a configuration but reported CONF: ERROR REQUEST, CNFG: Downloading gateway configuration failed and CNFG: Communication ERROR. (For this, network problems seem unlikely as it was reporting through MQTT just fine before the reboot? Maybe the remote server was down?)

After that it did not properly finish its boot. Like: it never even tried to get the configuration again, nor continued with its existing configuration. So, it was just not operational at all and did not bother to resolve that.

What firmware is running on your gateway?

Loaded from an SD card:

AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 Build time: Mar 22 2018 12:21:52

Connected through Ziggo ethernet, while XS4ALL WiFi is configured too.

What do the logs show?

All timestamps in UTC (as added by my own monitor).

First, I've no clue why it even restarted, but that happens more often so is likely unrelated to this issue:

[2018-06-07T04:39:16.060Z] LORA: Accepted packet
[2018-06-07T04:39:16.090Z] MQTT: Sending UPLINK OK
[2018-06-07T04:39:16.450Z] MQTT: Received DOWNLINK
[2018-06-07T04:39:25.346Z] SNTP: State change from 0 to 0
[2018-06-07T04:39:25.350Z] SNTP: State change from 0 to 0
[2018-06-07T04:39:25.352Z] 
[2018-06-07T04:39:25.353Z] 
[2018-06-07T04:39:25.354Z] 
[2018-06-07T04:39:25.356Z] **************************
[2018-06-07T04:39:25.358Z] *   The Things Network   *
[2018-06-07T04:39:25.361Z] *      G A T E W A Y     *
[2018-06-07T04:39:25.363Z] **************************
[2018-06-07T04:39:25.369Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252
[2018-06-07T04:39:25.405Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298
[2018-06-07T04:39:25.407Z] Build time: Mar 22 2018 12:21:52
[2018-06-07T04:39:25.408Z] Reboot reason: 0x10
[2018-06-07T04:39:25.419Z] BOOT: (persisted info) 6F 72 72 65 01 10 83 2C E7 16 09 49 92 3A 51 B7 

A bit later, it successfully gets a network connection:

[2018-06-07T04:39:30.402Z] CB: ETH: IP Address: 192.168.0.12 
[2018-06-07T04:39:32.373Z] INET: State change to 3
[2018-06-07T04:39:32.376Z] INET: Ping probe
[2018-06-07T04:39:32.386Z] INET: Ping response from PIC32INT, set as default
[2018-06-07T04:39:32.389Z] INET: State change to 4
[2018-06-07T04:39:32.398Z] WIFI: IP Address: 192.168.178.53 
[2018-06-07T04:39:32.961Z] LORA: Wait init complete, check for communication on 115200 baud.
[2018-06-07T04:39:32.964Z] LORA: Changing state from 1 to 2
[2018-06-07T04:39:32.970Z] LORA: Communication on 115200 OK, waiting for application.
[2018-06-07T04:39:32.973Z] LORA: Changing state from 2 to 4
[2018-06-07T04:39:33.892Z] SNTP: State change from 2 to 3
[2018-06-07T04:39:34.990Z] SNTP: State change from 3 to 4
[2018-06-07T04:39:35.329Z] MON: SYS Stack size: 3965
[2018-06-07T04:39:35.332Z] MON: heap usage: 148KB (156KB), free: 191KB
[2018-06-07T04:39:36.093Z] SNTP: State change from 4 to 5
[2018-06-07T04:39:36.135Z] SNTP: State change from 5 to 6
[2018-06-07T04:39:36.139Z] SNTP: State change from 6 to 7
[2018-06-07T04:39:36.142Z] INET: State change to 5
[2018-06-07T04:39:36.144Z] 
[2018-06-07T04:39:36.146Z] MAIN: Leaving state 2
[2018-06-07T04:39:36.148Z] MAIN: Entering state 3
[2018-06-07T04:39:36.150Z] 

...but after that the boot process fails:

[2018-06-07T04:39:36.152Z] CNFG: Load online user config state change to 4
[2018-06-07T04:39:36.154Z] HTTP: Close active socket 0
[2018-06-07T04:39:38.134Z] CONF: ERROR REQUEST
[2018-06-07T04:39:38.143Z] 
[2018-06-07T04:39:38.156Z] CNFG: Downloading gateway configuration failed
[2018-06-07T04:39:38.166Z] 
[2018-06-07T04:39:38.167Z] CNFG: Load online user config state change to 8
[2018-06-07T04:39:38.169Z] 
[2018-06-07T04:39:38.191Z] CNFG: Communication ERROR
[2018-06-07T04:39:38.199Z] 
[2018-06-07T04:39:38.200Z] MAIN: Leaving state 3
[2018-06-07T04:39:38.203Z] MAIN: Entering state 2
[2018-06-07T04:39:38.204Z] INET: State change to 0
[2018-06-07T04:39:38.206Z] WIFI: Disabling modules
[2018-06-07T04:39:38.207Z] CB: Disconnect
[2018-06-07T04:39:38.209Z] Head magic match void: trying to free an already freed block, ignore
[2018-06-07T04:39:38.210Z] SNTP: State change from 7 to 1
[2018-06-07T04:39:38.211Z] WIFI: Entering state 3
[2018-06-07T04:39:38.213Z] INET: Gateway has Ethernet
[2018-06-07T04:39:38.214Z] INET: State change to 2
[2018-06-07T04:39:38.229Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping
[2018-06-07T04:39:38.315Z] SNTP: State change from 1 to 2
[2018-06-07T04:39:39.018Z] WIFI: Enabling modules for client
[2018-06-07T04:39:39.021Z] WIFI: Entering state 6
[2018-06-07T04:39:39.024Z] WIFI: IP Address: 0.0.0.0 
[2018-06-07T04:39:39.380Z] SNTP: State change from 2 to 3
[2018-06-07T04:39:40.478Z] SNTP: State change from 3 to 4
[2018-06-07T04:39:41.576Z] CB: SNTP: State change from 4 to 5
[2018-06-07T04:39:41.624Z] SNTP: State change from 5 to 6
[2018-06-07T04:39:41.628Z] SNTP: State change from 6 to 7
[2018-06-07T04:39:43.136Z] INET: State change to 3
[2018-06-07T04:39:43.139Z] INET: Ping probe
[2018-06-07T04:39:43.151Z] INET: Ping response from PIC32INT, set as default
[2018-06-07T04:39:43.154Z] INET: State change to 5
[2018-06-07T04:39:43.156Z] 
[2018-06-07T04:39:43.158Z] MAIN: Leaving state 2
[2018-06-07T04:39:43.160Z] MAIN: Entering state 3
[2018-06-07T04:39:43.162Z] 
[2018-06-07T04:39:43.164Z] CNFG: Load online user config state change to 4
[2018-06-07T04:39:43.166Z] HTTP: Starting connection
[2018-06-07T04:39:45.317Z] MON: SYS Stack size: 3959
[2018-06-07T04:39:45.320Z] MON: heap usage: 152KB (158KB), free: 187KB
[2018-06-07T04:39:45.368Z] WIFI: IP Address: 192.168.178.53 
[2018-06-07T04:39:55.304Z] MON: SYS Stack size: 3959
[2018-06-07T04:39:55.307Z] MON: heap usage: 154KB (158KB), free: 185KB
[2018-06-07T04:40:05.292Z] MON: SYS Stack size: 3959
...
... repeated forever, with an occasional SNTP: State change ...
...

...and after this there is no mention of LORA: in the log at all (so also no LORA: GOING ASYNC that is usually seen, even when the LoRa module actually still fails to receive anything like in #29), nor anything like MAIN: Gateway bridging.

I only got home at 10 PM, so it did not recover itself in 16 hours. Also, after pressing the Mode button it ran into #29, but that seems unrelated. Pressing the Mode button again 45 minutes later finally got the gateway operational again.

Just for reference, the EXPECTED boot for that last part above ## The expected output, as NOT seen due to this very issue ```text CNFG: Load online user config state change to 4 HTTP: Close active socket 0 HTTP: Starting connection HTTPS: Connection Opened: Starting TLS Negotiation HTTP: Wait for TLS Connect HTTP: TLS Connection Opened: Starting Clear Text Communication HTTP: Got 1477 bytes HTTP: Connection Closed HTTP: Close active socket 1 CONF: Parsing response token: HTTP/1.1 200 OK CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 CNFG: Load online user config state change to 6 FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 HTTP: Starting connection HTTPS: Connection Opened: Starting TLS Negotiation HTTP: Wait for TLS Connect HTTP: TLS Connection Opened: Starting Clear Text Communication HTTP: Got 1232 bytes HTTP: Connection Closed HTTP: Close active socket 1 CNFG: Load online user config state change to 7 ```
Full log ## Full log, all timestamps in UTC (as added by my own monitor) ```text [2018-06-07T04:39:16.060Z] LORA: Accepted packet [2018-06-07T04:39:16.090Z] MQTT: Sending UPLINK OK [2018-06-07T04:39:16.450Z] MQTT: Received DOWNLINK [2018-06-07T04:39:25.346Z] SNTP: State change from 0 to 0 [2018-06-07T04:39:25.350Z] SNTP: State change from 0 to 0 [2018-06-07T04:39:25.352Z] [2018-06-07T04:39:25.353Z] [2018-06-07T04:39:25.354Z] [2018-06-07T04:39:25.356Z] ************************** [2018-06-07T04:39:25.358Z] * The Things Network * [2018-06-07T04:39:25.361Z] * G A T E W A Y * [2018-06-07T04:39:25.363Z] ************************** [2018-06-07T04:39:25.369Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-06-07T04:39:25.405Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-06-07T04:39:25.407Z] Build time: Mar 22 2018 12:21:52 [2018-06-07T04:39:25.408Z] Reboot reason: 0x10 [2018-06-07T04:39:25.419Z] BOOT: (persisted info) 6F 72 72 65 01 10 83 2C E7 16 09 49 92 3A 51 B7 [2018-06-07T04:39:25.420Z] [2018-06-07T04:39:25.421Z] [2018-06-07T04:39:25.422Z] [2018-06-07T04:39:25.423Z] [2018-06-07T04:39:25.424Z] WIFI: Entering state 0 [2018-06-07T04:39:25.448Z] WIFI: Entering SCAN state 0 [2018-06-07T04:39:25.449Z] [2018-06-07T04:39:25.450Z] MAIN: Initialisation complete [2018-06-07T04:39:25.451Z] LORA: Changing state from 0 to 0 [2018-06-07T04:39:25.592Z] [2018-06-07T04:39:25.594Z] MAIN: Leaving state 0 [2018-06-07T04:39:25.597Z] MAIN: Entering state 1 [2018-06-07T04:39:25.604Z] FLASH: Magic bytes found: wifi config present [2018-06-07T04:39:25.610Z] FLASH: Magic bytes found: activation data present [2018-06-07T04:39:25.614Z] FLASH: Magic bytes found: FOTA data present [2018-06-07T04:39:25.617Z] FLASH: Loading Firmware Data [2018-06-07T04:39:25.629Z] 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-06-07T04:39:25.632Z] FLASH: Loading WiFi Data [2018-06-07T04:39:25.636Z] CNFG: WiFi SSID: [2018-06-07T04:39:25.639Z] CNFG: WiFi key: *** [2018-06-07T04:39:25.641Z] CNFG: WiFi conn_type: 1 [2018-06-07T04:39:25.644Z] CNFG: WiFi sec_type: 4 [2018-06-07T04:39:25.646Z] FLASH: Loading Activation Data [2018-06-07T04:39:25.649Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-06-07T04:39:25.652Z] CNFG: Gateway Key: *** [2018-06-07T04:39:25.655Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-06-07T04:39:25.658Z] CNFG: Locked: true [2018-06-07T04:39:25.662Z] CNFG: Locked first time: false [2018-06-07T04:39:25.664Z] [2018-06-07T04:39:25.666Z] MAIN: Leaving state 1 [2018-06-07T04:39:25.668Z] MAIN: Entering state 2 [2018-06-07T04:39:25.671Z] INET: State change to 0 [2018-06-07T04:39:25.968Z] LORA: Initialisation complete [2018-06-07T04:39:25.972Z] LORA: Changing state from 0 to 1 [2018-06-07T04:39:26.218Z] WIFI: Entering state 1 [2018-06-07T04:39:26.223Z] ETH: IP Address: 0.0.0.0 [2018-06-07T04:39:26.226Z] WIFI: Entering state 4 [2018-06-07T04:39:26.228Z] WIFI: Entering SCAN state 1 [2018-06-07T04:39:26.640Z] Scan is completed successfully [2018-06-07T04:39:26.643Z] WIFI: Entering SCAN state 2 [2018-06-07T04:39:26.655Z] WIFI: Entering SCAN state 5 [2018-06-07T04:39:26.658Z] WIFI: Entering SCAN state 0 [2018-06-07T04:39:26.661Z] WIFI: Entering state 2 [2018-06-07T04:39:26.664Z] WIFI: Disabling modules [2018-06-07T04:39:26.669Z] Head magic match void: trying to free an already freed block, ignore [2018-06-07T04:39:26.672Z] WIFI: Entering state 3 [2018-06-07T04:39:27.311Z] SNTP: State change from 0 to 1 [2018-06-07T04:39:27.381Z] INET: Gateway has Ethernet [2018-06-07T04:39:27.384Z] INET: State change to 2 [2018-06-07T04:39:27.390Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-06-07T04:39:27.534Z] WIFI: Enabling modules for client [2018-06-07T04:39:27.537Z] WIFI: Entering state 6 [2018-06-07T04:39:27.539Z] [2018-06-07T04:39:27.541Z] [2018-06-07T04:39:27.543Z] >WIFI: IP Address: 0.0.0.0 [2018-06-07T04:39:28.407Z] SNTP: State change from 1 to 2 [2018-06-07T04:39:30.402Z] CB: ETH: IP Address: 192.168.0.12 [2018-06-07T04:39:32.373Z] INET: State change to 3 [2018-06-07T04:39:32.376Z] INET: Ping probe [2018-06-07T04:39:32.386Z] INET: Ping response from PIC32INT, set as default [2018-06-07T04:39:32.389Z] INET: State change to 4 [2018-06-07T04:39:32.398Z] WIFI: IP Address: 192.168.178.53 [2018-06-07T04:39:32.961Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-06-07T04:39:32.964Z] LORA: Changing state from 1 to 2 [2018-06-07T04:39:32.970Z] LORA: Communication on 115200 OK, waiting for application. [2018-06-07T04:39:32.973Z] LORA: Changing state from 2 to 4 [2018-06-07T04:39:33.892Z] SNTP: State change from 2 to 3 [2018-06-07T04:39:34.990Z] SNTP: State change from 3 to 4 [2018-06-07T04:39:35.329Z] MON: SYS Stack size: 3965 [2018-06-07T04:39:35.332Z] MON: heap usage: 148KB (156KB), free: 191KB [2018-06-07T04:39:36.093Z] SNTP: State change from 4 to 5 [2018-06-07T04:39:36.135Z] SNTP: State change from 5 to 6 [2018-06-07T04:39:36.139Z] SNTP: State change from 6 to 7 [2018-06-07T04:39:36.142Z] INET: State change to 5 [2018-06-07T04:39:36.144Z] [2018-06-07T04:39:36.146Z] MAIN: Leaving state 2 [2018-06-07T04:39:36.148Z] MAIN: Entering state 3 [2018-06-07T04:39:36.150Z] [2018-06-07T04:39:36.152Z] CNFG: Load online user config state change to 4 [2018-06-07T04:39:36.154Z] HTTP: Close active socket 0 [2018-06-07T04:39:38.134Z] CONF: ERROR REQUEST [2018-06-07T04:39:38.143Z] [2018-06-07T04:39:38.156Z] CNFG: Downloading gateway configuration failed [2018-06-07T04:39:38.166Z] [2018-06-07T04:39:38.167Z] CNFG: Load online user config state change to 8 [2018-06-07T04:39:38.169Z] [2018-06-07T04:39:38.191Z] CNFG: Communication ERROR [2018-06-07T04:39:38.199Z] [2018-06-07T04:39:38.200Z] MAIN: Leaving state 3 [2018-06-07T04:39:38.203Z] MAIN: Entering state 2 [2018-06-07T04:39:38.204Z] INET: State change to 0 [2018-06-07T04:39:38.206Z] WIFI: Disabling modules [2018-06-07T04:39:38.207Z] CB: Disconnect [2018-06-07T04:39:38.209Z] Head magic match void: trying to free an already freed block, ignore [2018-06-07T04:39:38.210Z] SNTP: State change from 7 to 1 [2018-06-07T04:39:38.211Z] WIFI: Entering state 3 [2018-06-07T04:39:38.213Z] INET: Gateway has Ethernet [2018-06-07T04:39:38.214Z] INET: State change to 2 [2018-06-07T04:39:38.229Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-06-07T04:39:38.315Z] SNTP: State change from 1 to 2 [2018-06-07T04:39:39.018Z] WIFI: Enabling modules for client [2018-06-07T04:39:39.021Z] WIFI: Entering state 6 [2018-06-07T04:39:39.024Z] WIFI: IP Address: 0.0.0.0 [2018-06-07T04:39:39.380Z] SNTP: State change from 2 to 3 [2018-06-07T04:39:40.478Z] SNTP: State change from 3 to 4 [2018-06-07T04:39:41.576Z] CB: SNTP: State change from 4 to 5 [2018-06-07T04:39:41.624Z] SNTP: State change from 5 to 6 [2018-06-07T04:39:41.628Z] SNTP: State change from 6 to 7 [2018-06-07T04:39:43.136Z] INET: State change to 3 [2018-06-07T04:39:43.139Z] INET: Ping probe [2018-06-07T04:39:43.151Z] INET: Ping response from PIC32INT, set as default [2018-06-07T04:39:43.154Z] INET: State change to 5 [2018-06-07T04:39:43.156Z] [2018-06-07T04:39:43.158Z] MAIN: Leaving state 2 [2018-06-07T04:39:43.160Z] MAIN: Entering state 3 [2018-06-07T04:39:43.162Z] [2018-06-07T04:39:43.164Z] CNFG: Load online user config state change to 4 [2018-06-07T04:39:43.166Z] HTTP: Starting connection [2018-06-07T04:39:45.317Z] MON: SYS Stack size: 3959 [2018-06-07T04:39:45.320Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:39:45.368Z] WIFI: IP Address: 192.168.178.53 [2018-06-07T04:39:55.304Z] MON: SYS Stack size: 3959 [2018-06-07T04:39:55.307Z] MON: heap usage: 154KB (158KB), free: 185KB [2018-06-07T04:40:05.292Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:05.295Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:40:15.278Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:15.282Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:40:25.268Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:25.271Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:40:35.257Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:35.261Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:40:45.248Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:45.251Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:40:55.239Z] MON: SYS Stack size: 3959 [2018-06-07T04:40:55.242Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:41:05.230Z] MON: SYS Stack size: 3959 [2018-06-07T04:41:05.233Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:41:15.219Z] MON: SYS Stack size: 3959 [2018-06-07T04:41:15.222Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T04:41:25.208Z] MON: SYS Stack size: 3959 [2018-06-07T04:41:25.211Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:41:35.194Z] MON: SYS Stack size: 3959 [2018-06-07T04:41:35.197Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:41:45.179Z] MON: SYS Stack size: 3959 [2018-06-07T04:41:45.182Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:41:55.163Z] MON: SYS Stack size: 3959 ... ... many more, with an occasional: ... [2018-06-07T04:49:34.477Z] MON: SYS Stack size: 3959 [2018-06-07T04:49:34.479Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:49:41.770Z] SNTP: State change from 7 to 1 [2018-06-07T04:49:42.867Z] SNTP: State change from 1 to 2 [2018-06-07T04:49:43.965Z] SNTP: State change from 2 to 3 [2018-06-07T04:49:44.460Z] MON: SYS Stack size: 3959 [2018-06-07T04:49:44.464Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T04:49:45.062Z] SNTP: State change from 3 to 4 [2018-06-07T04:49:46.159Z] SNTP: State change from 4 to 5 [2018-06-07T04:49:46.171Z] SNTP: State change from 5 to 6 [2018-06-07T04:49:46.174Z] SNTP: State change from 6 to 7 [2018-06-07T04:49:54.445Z] MON: SYS Stack size: 3959 [2018-06-07T04:49:54.448Z] MON: heap usage: 152KB (158KB), free: 187KB ... ... until Mode button pressed: ... [2018-06-07T20:29:45.686Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T20:29:55.670Z] MON: SYS Stack size: 3959 [2018-06-07T20:29:55.673Z] MON: heap usage: 155KB (158KB), free: 184KB [2018-06-07T20:30:05.658Z] MON: SYS Stack size: 3959 [2018-06-07T20:30:05.661Z] MON: heap usage: 152KB (158KB), free: 187KB [2018-06-07T20:30:14.066Z] BTN: change to state: 1 [2018-06-07T20:30:14.202Z] BTN: change to sta [2018-06-07T20:30:14.204Z] *** Application reboot [2018-06-07T20:30:14.212Z] [2018-06-07T20:30:16.422Z] SNTP: State change from 0 to 0 [2018-06-07T20:30:16.425Z] SNTP: State change from 0 to 0 [2018-06-07T20:30:16.427Z] [2018-06-07T20:30:16.429Z] [2018-06-07T20:30:16.430Z] [2018-06-07T20:30:16.434Z] ************************** [2018-06-07T20:30:16.436Z] * The Things Network * [2018-06-07T20:30:16.440Z] * G A T E W A Y * [2018-06-07T20:30:16.442Z] ************************** [2018-06-07T20:30:16.445Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-06-07T20:30:16.463Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-06-07T20:30:16.467Z] Build time: Mar 22 2018 12:21:52 [2018-06-07T20:30:16.479Z] Reboot reason: 0x40 [2018-06-07T20:30:16.486Z] BOOT: (persisted info) 6F 72 72 65 01 10 83 2C E7 16 09 49 92 3A 51 B7 [2018-06-07T20:30:16.488Z] [2018-06-07T20:30:16.490Z] [2018-06-07T20:30:16.491Z] [2018-06-07T20:30:16.492Z] [2018-06-07T20:30:16.492Z] WIFI: Entering state 0 [2018-06-07T20:30:16.494Z] WIFI: Entering SCAN state 0 [2018-06-07T20:30:16.495Z] [2018-06-07T20:30:16.496Z] MAIN: Initialisation complete [2018-06-07T20:30:16.509Z] LORA: Changing state from 0 to 0 [2018-06-07T20:30:16.668Z] [2018-06-07T20:30:16.670Z] MAIN: Leaving state 0 [2018-06-07T20:30:16.674Z] MAIN: Entering state 1 [2018-06-07T20:30:16.682Z] FLASH: Magic bytes found: wifi config present [2018-06-07T20:30:16.686Z] FLASH: Magic bytes found: activation data present [2018-06-07T20:30:16.693Z] FLASH: Magic bytes found: FOTA data present [2018-06-07T20:30:16.696Z] FLASH: Loading Firmware Data [2018-06-07T20:30:16.705Z] 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-06-07T20:30:16.708Z] FLASH: Loading WiFi Data [2018-06-07T20:30:16.711Z] CNFG: WiFi SSID: [2018-06-07T20:30:16.715Z] CNFG: WiFi key: *** [2018-06-07T20:30:16.717Z] CNFG: WiFi conn_type: 1 [2018-06-07T20:30:16.720Z] CNFG: WiFi sec_type: 4 [2018-06-07T20:30:16.722Z] FLASH: Loading Activation Data [2018-06-07T20:30:16.725Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-06-07T20:30:16.728Z] CNFG: Gateway Key: *** [2018-06-07T20:30:16.731Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-06-07T20:30:16.734Z] CNFG: Locked: true [2018-06-07T20:30:16.738Z] CNFG: Locked first time: false [2018-06-07T20:30:16.740Z] [2018-06-07T20:30:16.742Z] MAIN: Leaving state 1 [2018-06-07T20:30:16.744Z] MAIN: Entering state 2 [2018-06-07T20:30:16.747Z] INET: State change to 0 [2018-06-07T20:30:17.044Z] LORA: Initialisation complete [2018-06-07T20:30:17.047Z] LORA: Changing state from 0 to 1 [2018-06-07T20:30:17.299Z] WIFI: Entering state 1 [2018-06-07T20:30:17.302Z] ETH: IP Address: 0.0.0.0 [2018-06-07T20:30:17.306Z] WIFI: Entering state 4 [2018-06-07T20:30:17.309Z] WIFI: Entering SCAN state 1 [2018-06-07T20:30:18.392Z] SNTP: State change from 0 to 1 [2018-06-07T20:30:18.452Z] INET: Gateway has Ethernet [2018-06-07T20:30:18.455Z] INET: State change to 2 [2018-06-07T20:30:18.461Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-06-07T20:30:19.490Z] SNTP: State change from 1 to 2 [2018-06-07T20:30:19.595Z] Scan is completed successfully [2018-06-07T20:30:19.599Z] WIFI: Entering SCAN state 2 [2018-06-07T20:30:19.602Z] WIFI: Entering SCAN state 5 [2018-06-07T20:30:19.605Z] WIFI: Entering SCAN state 0 [2018-06-07T20:30:19.608Z] WIFI: Entering state 2 [2018-06-07T20:30:19.611Z] WIFI: Disabling modules [2018-06-07T20:30:19.616Z] Head magic match void: trying to free an already freed block, ignore [2018-06-07T20:30:19.619Z] SNTP: State change from 2 to 1 [2018-06-07T20:30:19.622Z] WIFI: Entering state 3 [2018-06-07T20:30:20.486Z] WIFI: Enabling modules for client [2018-06-07T20:30:20.488Z] WIFI: Entering state 6 [2018-06-07T20:30:20.490Z] [2018-06-07T20:30:20.491Z] [2018-06-07T20:30:20.493Z] >WIFI: IP Address: 0.0.0.0 [2018-06-07T20:30:20.589Z] SNTP: State change from 1 to 2 [2018-06-07T20:30:21.488Z] ETH: IP Address: 192.168.0.12 [2018-06-07T20:30:23.450Z] CB: INET: State change to 3 [2018-06-07T20:30:23.453Z] INET: Ping probe [2018-06-07T20:30:23.464Z] INET: Ping response from PIC32INT, set as default [2018-06-07T20:30:23.467Z] INET: State change to 4 [2018-06-07T20:30:24.043Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-06-07T20:30:24.046Z] LORA: Changing state from 1 to 2 [2018-06-07T20:30:24.053Z] LORA: Communication on 115200 OK, waiting for application. [2018-06-07T20:30:24.056Z] LORA: Changing state from 2 to 4 [2018-06-07T20:30:24.483Z] WIFI: IP Address: 192.168.178.53 [2018-06-07T20:30:24.981Z] SNTP: State change from 2 to 3 [2018-06-07T20:30:26.080Z] SNTP: State change from 3 to 4 [2018-06-07T20:30:26.414Z] MON: SYS Stack size: 3959 [2018-06-07T20:30:26.418Z] MON: heap usage: 148KB (157KB), free: 191KB [2018-06-07T20:30:27.179Z] SNTP: State change from 4 to 5 [2018-06-07T20:30:27.187Z] SNTP: State change from 5 to 6 [2018-06-07T20:30:27.190Z] SNTP: State change from 6 to 7 [2018-06-07T20:30:27.193Z] INET: State change to 5 [2018-06-07T20:30:27.196Z] [2018-06-07T20:30:27.198Z] MAIN: Leaving state 2 [2018-06-07T20:30:27.200Z] MAIN: Entering state 3 [2018-06-07T20:30:27.202Z] [2018-06-07T20:30:27.204Z] CNFG: Load online user config state change to 4 [2018-06-07T20:30:27.207Z] HTTP: Close active socket 0 [2018-06-07T20:30:27.209Z] HTTP: Starting connection [2018-06-07T20:30:27.218Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T20:30:27.221Z] HTTP: Wait for TLS Connect [2018-06-07T20:30:27.679Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T20:30:27.707Z] HTTP: Got 1477 bytes [2018-06-07T20:30:29.709Z] HTTP: Connection Closed [2018-06-07T20:30:29.712Z] HTTP: Close active socket 1 [2018-06-07T20:30:29.715Z] CONF: Parsing response token: HTTP/1.1 200 OK [2018-06-07T20:30:29.720Z] CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 [2018-06-07T20:30:29.722Z] [2018-06-07T20:30:29.725Z] CNFG: Load online user config state change to 6 [2018-06-07T20:30:31.718Z] FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 [2018-06-07T20:30:31.721Z] HTTP: Starting connection [2018-06-07T20:30:31.729Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T20:30:31.732Z] HTTP: Wait for TLS Connect [2018-06-07T20:30:32.230Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T20:30:32.245Z] HTTP: Got 1232 bytes [2018-06-07T20:30:34.246Z] HTTP: Connection Closed [2018-06-07T20:30:34.249Z] HTTP: Close active socket 1 [2018-06-07T20:30:34.251Z] [2018-06-07T20:30:34.253Z] CNFG: Load online user config state change to 7 [2018-06-07T20:30:34.255Z] [2018-06-07T20:30:34.258Z] CNFG: Configuring LoRa module [2018-06-07T20:30:34.261Z] LORA: Changing state from 4 to 6 [2018-06-07T20:30:34.264Z] LORA: Starting reconfiguration [2018-06-07T20:30:34.269Z] LORA: version: 01 [2018-06-07T20:30:36.309Z] LORA: UART TIMEOUT [2018-06-07T20:30:36.313Z] LORA: Configuration succeeded [2018-06-07T20:30:36.322Z] LORA: Starting operation [2018-06-07T20:30:36.324Z] LORA: Changing state from 6 to 8 [2018-06-07T20:30:36.407Z] MON: SYS Stack size: 2843 [2018-06-07T20:30:36.411Z] MON: heap usage: 152KB (238KB), free: 187KB [2018-06-07T20:30:42.306Z] LORA: Changing state from 8 to 5 [2018-06-07T20:30:42.307Z] LORA: GOING ASYNC [2018-06-07T20:30:42.310Z] LORA: Changing state from 5 to 11 [2018-06-07T20:30:42.312Z] [2018-06-07T20:30:42.315Z] CNFG: Load online user config state change to 9 [2018-06-07T20:30:42.316Z] [2018-06-07T20:30:42.317Z] MAIN: Leaving state 3 [2018-06-07T20:30:42.319Z] MAIN: Entering state 4 [2018-06-07T20:30:42.321Z] SDCARD: Mounted disk [2018-06-07T20:30:42.323Z] FLASH: Loading FOTA Data [2018-06-07T20:30:42.325Z] FIRM: Requesting key ... [2018-06-07T20:30:42.328Z] HTTP: Starting connection [2018-06-07T20:30:42.340Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T20:30:42.342Z] HTTP: Wait for TLS Connect [2018-06-07T20:30:42.904Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T20:30:42.937Z] HTTP: Got 515 bytes [2018-06-07T20:30:44.937Z] HTTP: Connection Closed [2018-06-07T20:30:44.940Z] HTTP: Close active socket 1 [2018-06-07T20:30:44.943Z] FIRM: Starting download [2018-06-07T20:30:44.946Z] FIRM: available bytes: 79 [2018-06-07T20:30:44.954Z] 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-06-07T20:30:44.966Z] 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-06-07T20:30:44.969Z] FIRM: Firmware is already downloaded [2018-06-07T20:30:44.972Z] MAIN: No new firmware available [2018-06-07T20:30:44.974Z] [2018-06-07T20:30:44.977Z] MAIN: Leaving state 4 [2018-06-07T20:30:44.979Z] MAIN: Entering state 5 [2018-06-07T20:30:44.982Z] MQTT: GOT IP: 52.169.76.203 [2018-06-07T20:30:44.984Z] Connecting to: 52.169.76.203 [2018-06-07T20:30:44.987Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-06-07T20:30:44.990Z] MQTT: Wait for SSL Connect [2018-06-07T20:30:45.541Z] MQTT: TLS ready: Connect MQTT [2018-06-07T20:30:45.652Z] RQMQTT: Connected [2018-06-07T20:30:45.658Z] [2018-06-07T20:30:45.661Z] ************************* [2018-06-07T20:30:45.663Z] MAIN: Gateway bridging [2018-06-07T20:30:45.668Z] ************************* [2018-06-07T20:30:45.670Z] [2018-06-07T20:30:46.400Z] MON: SYS Stack size: 2837 [2018-06-07T20:30:46.402Z] MON: heap usage: 266KB (267KB), free: 72KB [2018-06-07T20:30:46.405Z] MQTT: Sending status packet [2018-06-07T20:30:46.410Z] MQTT: Report reboot error: 0110 [2018-06-07T20:30:46.428Z] MQTT: Sending status succeeded: 0 [2018-06-07T20:30:56.393Z] MON: SYS Stack size: 2837 [2018-06-07T20:30:56.396Z] MON: heap usage: 263KB (267KB), free: 75KB [2018-06-07T20:31:06.387Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:06.391Z] MON: heap usage: 263KB (267KB), free: 75KB [2018-06-07T20:31:16.382Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:16.385Z] MON: heap usage: 263KB (267KB), free: 75KB [2018-06-07T20:31:16.388Z] MQTT: Sending status packet [2018-06-07T20:31:16.411Z] MQTT: Sending status succeeded: 1 [2018-06-07T20:31:26.376Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:26.380Z] MON: heap usage: 266KB (267KB), free: 72KB [2018-06-07T20:31:36.372Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:36.375Z] MON: heap usage: 266KB (267KB), free: 72KB [2018-06-07T20:31:42.275Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-06-07T20:31:46.367Z] MQTT: Sending status packet [2018-06-07T20:31:46.370Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:46.376Z] MON: heap usage: 263KB (267KB), free: 75KB [2018-06-07T20:31:46.397Z] MQTT: Sending status succeeded: 2 [2018-06-07T20:31:56.366Z] MON: SYS Stack size: 2837 [2018-06-07T20:31:56.370Z] MON: heap usage: 266KB (267KB), free: 72KB [2018-06-07T20:32:06.364Z] MON: SYS Stack size: 2837 [2018-06-07T20:32:06.368Z] MON: heap usage: 264KB (267KB), free: 74KB [2018-06-07T20:32:16.357Z] MQTT: Sending status packet [2018-06-07T20:32:16.361Z] MON: SYS Stack size: 2837 [2018-06-07T20:32:16.365Z] MON: heap usage: 263KB (267KB), free: 75KB [2018-06-07T20:32:16.387Z] MQTT: Sending status succeeded: 3 [2018-06-07T20:32:26.357Z] MON: SYS Stack size: 2837 [2018-06-07T20:32:26.361Z] MON: heap usage: 266KB (267KB), free: 72KB [2018-06-07T20:32:36.353Z] MON: SYS Stack size: 2837 [2018-06-07T20:32:36.356Z] MON: heap usage: 264KB (267KB), free: 74KB [2018-06-07T20:32:42.250Z] LORA: Kick LoRa module with ACK after not acked it for 60s [2018-06-07T20:32:46.343Z] MQTT: Sending status packet ... ... many more until Mode button pressed again (see bug #29) ... [2018-06-07T21:16:04.792Z] MON: heap usage: 263KB (267KB), free: 76KB [2018-06-07T21:16:05.213Z] BTN: change to state: 1 [2018-06-07T21:16:05.856Z] BTN: change to state: 2 [2018-06-07T21:16:05.858Z] [2018-06-07T21:16:05.860Z] MAIN: Leaving state 5 [2018-06-07T21:16:05.885Z] MAIN: Ent [2018-06-07T21:16:05.889Z] *** Application reboot [2018-06-07T21:16:05.895Z] [2018-06-07T21:16:08.106Z] SNTP: State change from 0 to 0 [2018-06-07T21:16:08.109Z] SNTP: State change from 0 to 0 [2018-06-07T21:16:08.112Z] [2018-06-07T21:16:08.113Z] [2018-06-07T21:16:08.114Z] [2018-06-07T21:16:08.116Z] ************************** [2018-06-07T21:16:08.118Z] * The Things Network * [2018-06-07T21:16:08.121Z] * G A T E W A Y * [2018-06-07T21:16:08.123Z] ************************** [2018-06-07T21:16:08.129Z] Firmware name: AmazingAckermann, type: 0, version: 1.0.3, commit: 2c56ce09, timestamp: 1521721252 [2018-06-07T21:16:08.147Z] Bootloader revision: 1, commit: 7167873a, timestamp: 1496411298 [2018-06-07T21:16:08.150Z] Build time: Mar 22 2018 12:21:52 [2018-06-07T21:16:08.163Z] Reboot reason: 0x40 [2018-06-07T21:16:08.171Z] BOOT: (persisted info) 6F 72 72 65 01 40 83 2C E7 16 09 49 92 3A 51 B7 [2018-06-07T21:16:08.173Z] [2018-06-07T21:16:08.174Z] [2018-06-07T21:16:08.174Z] [2018-06-07T21:16:08.175Z] [2018-06-07T21:16:08.176Z] WIFI: Entering state 0 [2018-06-07T21:16:08.178Z] WIFI: Entering SCAN state 0 [2018-06-07T21:16:08.179Z] [2018-06-07T21:16:08.180Z] MAIN: Initialisation complete [2018-06-07T21:16:08.195Z] LORA: Changing state from 0 to 0 [2018-06-07T21:16:08.352Z] [2018-06-07T21:16:08.354Z] MAIN: Leaving state 0 [2018-06-07T21:16:08.357Z] MAIN: Entering state 1 [2018-06-07T21:16:08.364Z] FLASH: Magic bytes found: wifi config present [2018-06-07T21:16:08.369Z] FLASH: Magic bytes found: activation data present [2018-06-07T21:16:08.374Z] FLASH: Magic bytes found: FOTA data present [2018-06-07T21:16:08.378Z] FLASH: Loading Firmware Data [2018-06-07T21:16:08.389Z] 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-06-07T21:16:08.393Z] FLASH: Loading WiFi Data [2018-06-07T21:16:08.397Z] CNFG: WiFi SSID: [2018-06-07T21:16:08.399Z] CNFG: WiFi key: *** [2018-06-07T21:16:08.402Z] CNFG: WiFi conn_type: 1 [2018-06-07T21:16:08.404Z] CNFG: WiFi sec_type: 4 [2018-06-07T21:16:08.406Z] FLASH: Loading Activation Data [2018-06-07T21:16:08.410Z] CNFG: Gateway ID: arjanvanb-gw-1 [2018-06-07T21:16:08.412Z] CNFG: Gateway Key: *** [2018-06-07T21:16:08.415Z] CNFG: Account Server URL: https://account.thethingsnetwork.org [2018-06-07T21:16:08.418Z] CNFG: Locked: true [2018-06-07T21:16:08.421Z] CNFG: Locked first time: false [2018-06-07T21:16:08.424Z] [2018-06-07T21:16:08.426Z] MAIN: Leaving state 1 [2018-06-07T21:16:08.428Z] MAIN: Entering state 2 [2018-06-07T21:16:08.430Z] INET: State change to 0 [2018-06-07T21:16:08.728Z] LORA: Initialisation complete [2018-06-07T21:16:08.731Z] LORA: Changing state from 0 to 1 [2018-06-07T21:16:08.983Z] WIFI: Entering state 1 [2018-06-07T21:16:08.986Z] ETH: IP Address: 0.0.0.0 [2018-06-07T21:16:08.989Z] WIFI: Entering state 4 [2018-06-07T21:16:08.992Z] WIFI: Entering SCAN state 1 [2018-06-07T21:16:10.077Z] SNTP: State change from 0 to 1 [2018-06-07T21:16:10.242Z] INET: Gateway has Ethernet [2018-06-07T21:16:10.245Z] INET: State change to 2 [2018-06-07T21:16:10.251Z] INET: Connected to a network, waiting for DHCP lease, checking validity with ping [2018-06-07T21:16:11.251Z] Scan is completed successfully [2018-06-07T21:16:11.254Z] WIFI: Entering SCAN state 2 [2018-06-07T21:16:11.261Z] WIFI: Entering SCAN state 5 [2018-06-07T21:16:11.264Z] WIFI: Entering SCAN state 0 [2018-06-07T21:16:11.267Z] WIFI: Entering state 2 [2018-06-07T21:16:11.270Z] WIFI: Disabling modules [2018-06-07T21:16:11.275Z] Head magic match void: trying to free an already freed block, ignore [2018-06-07T21:16:11.282Z] SNTP: State change from 1 to 1 [2018-06-07T21:16:11.285Z] WIFI: Entering state 3 [2018-06-07T21:16:12.146Z] WIFI: Enabling modules for client [2018-06-07T21:16:12.149Z] WIFI: Entering state 6 [2018-06-07T21:16:12.151Z] [2018-06-07T21:16:12.152Z] [2018-06-07T21:16:12.154Z] >WIFI: IP Address: 0.0.0.0 [2018-06-07T21:16:12.273Z] SNTP: State change from 1 to 2 [2018-06-07T21:16:13.172Z] ETH: IP Address: 192.168.0.12 [2018-06-07T21:16:15.169Z] CB: WIFI: IP Address: 192.168.178.53 [2018-06-07T21:16:15.240Z] INET: State change to 3 [2018-06-07T21:16:15.243Z] INET: Ping probe [2018-06-07T21:16:15.255Z] INET: Ping response from PIC32INT, set as default [2018-06-07T21:16:15.259Z] INET: State change to 4 [2018-06-07T21:16:15.728Z] LORA: Wait init complete, check for communication on 115200 baud. [2018-06-07T21:16:15.731Z] LORA: Changing state from 1 to 2 [2018-06-07T21:16:15.737Z] LORA: Communication on 115200 OK, waiting for application. [2018-06-07T21:16:15.741Z] LORA: Changing state from 2 to 4 [2018-06-07T21:16:17.765Z] SNTP: State change from 2 to 3 [2018-06-07T21:16:18.099Z] MON: SYS Stack size: 3965 [2018-06-07T21:16:18.103Z] MON: heap usage: 149KB (157KB), free: 190KB [2018-06-07T21:16:18.864Z] SNTP: State change from 3 to 4 [2018-06-07T21:16:19.962Z] SNTP: State change from 4 to 5 [2018-06-07T21:16:19.972Z] SNTP: State change from 5 to 6 [2018-06-07T21:16:19.975Z] SNTP: State change from 6 to 7 [2018-06-07T21:16:19.978Z] INET: State change to 5 [2018-06-07T21:16:19.981Z] [2018-06-07T21:16:19.983Z] MAIN: Leaving state 2 [2018-06-07T21:16:19.985Z] MAIN: Entering state 3 [2018-06-07T21:16:19.986Z] [2018-06-07T21:16:19.989Z] CNFG: Load online user config state change to 4 [2018-06-07T21:16:19.992Z] HTTP: Close active socket 0 [2018-06-07T21:16:19.994Z] HTTP: Starting connection [2018-06-07T21:16:19.997Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T21:16:20.000Z] HTTP: Wait for TLS Connect [2018-06-07T21:16:20.447Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T21:16:20.484Z] HTTP: Got 1477 bytes [2018-06-07T21:16:22.483Z] HTTP: Connection Closed [2018-06-07T21:16:22.487Z] HTTP: Close active socket 1 [2018-06-07T21:16:22.490Z] CONF: Parsing response token: HTTP/1.1 200 OK [2018-06-07T21:16:22.497Z] CONF: ROUTER URL: mqtts://bridge.eu.thethings.network:8883 [2018-06-07T21:16:22.499Z] [2018-06-07T21:16:22.501Z] CNFG: Load online user config state change to 6 [2018-06-07T21:16:24.493Z] FREQ: APP_URL_Buffer: https://account.thethingsnetwork.org/api/v2/frequency-plans/EU_863_870 [2018-06-07T21:16:24.496Z] HTTP: Starting connection [2018-06-07T21:16:24.506Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T21:16:24.509Z] HTTP: Wait for TLS Connect [2018-06-07T21:16:24.991Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T21:16:25.005Z] HTTP: Got 1232 bytes [2018-06-07T21:16:27.006Z] HTTP: Connection Closed [2018-06-07T21:16:27.009Z] HTTP: Close active socket 1 [2018-06-07T21:16:27.012Z] [2018-06-07T21:16:27.014Z] CNFG: Load online user config state change to 7 [2018-06-07T21:16:27.016Z] [2018-06-07T21:16:27.018Z] CNFG: Configuring LoRa module [2018-06-07T21:16:27.021Z] LORA: Changing state from 4 to 6 [2018-06-07T21:16:27.024Z] LORA: Starting reconfiguration [2018-06-07T21:16:27.029Z] LORA: version: 01 [2018-06-07T21:16:28.094Z] MON: SYS Stack size: 2870 [2018-06-07T21:16:28.097Z] MON: heap usage: 152KB (237KB), free: 187KB [2018-06-07T21:16:29.061Z] LORA: UART TIMEOUT [2018-06-07T21:16:29.065Z] LORA: Configuration succeeded [2018-06-07T21:16:29.072Z] LORA: Starting operation [2018-06-07T21:16:29.075Z] LORA: Changing state from 6 to 8 [2018-06-07T21:16:35.062Z] LORA: Changing state from 8 to 5 [2018-06-07T21:16:35.065Z] LORA: GOING ASYNC [2018-06-07T21:16:35.068Z] LORA: Changing state from 5 to 11 [2018-06-07T21:16:35.071Z] [2018-06-07T21:16:35.073Z] CNFG: Load online user config state change to 9 [2018-06-07T21:16:35.076Z] [2018-06-07T21:16:35.077Z] MAIN: Leaving state 3 [2018-06-07T21:16:35.081Z] MAIN: Entering state 4 [2018-06-07T21:16:35.083Z] SDCARD: Mounted disk [2018-06-07T21:16:35.085Z] FLASH: Loading FOTA Data [2018-06-07T21:16:35.088Z] FIRM: Requesting key ... [2018-06-07T21:16:35.090Z] HTTP: Starting connection [2018-06-07T21:16:35.094Z] HTTPS: Connection Opened: Starting TLS Negotiation [2018-06-07T21:16:35.097Z] HTTP: Wait for TLS Connect [2018-06-07T21:16:35.638Z] HTTP: TLS Connection Opened: Starting Clear Text Communication [2018-06-07T21:16:35.683Z] HTTP: Got 515 bytes [2018-06-07T21:16:37.685Z] HTTP: Connection Closed [2018-06-07T21:16:37.688Z] HTTP: Close active socket 1 [2018-06-07T21:16:37.691Z] FIRM: Starting download [2018-06-07T21:16:37.695Z] FIRM: available bytes: 79 [2018-06-07T21:16:37.702Z] 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-06-07T21:16:37.713Z] 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-06-07T21:16:37.717Z] FIRM: Firmware is already downloaded [2018-06-07T21:16:37.720Z] MAIN: No new firmware available [2018-06-07T21:16:37.723Z] [2018-06-07T21:16:37.726Z] MAIN: Leaving state 4 [2018-06-07T21:16:37.728Z] MAIN: Entering state 5 [2018-06-07T21:16:37.731Z] MQTT: GOT IP: 52.169.76.203 [2018-06-07T21:16:37.733Z] Connecting to: 52.169.76.203 [2018-06-07T21:16:38.088Z] MON: SYS Stack size: 2870 [2018-06-07T21:16:38.091Z] MON: heap usage: 174KB (256KB), free: 165KB [2018-06-07T21:16:38.704Z] MQTT: Opening socket timed out, restarting [2018-06-07T21:16:38.708Z] MQTT: GOT IP: 52.169.76.203 [2018-06-07T21:16:38.711Z] Connecting to: 52.169.76.203 [2018-06-07T21:16:38.735Z] MQTT: Connection Opened: Starting TLS Negotiation [2018-06-07T21:16:38.738Z] MQTT: Wait for SSL Connect [2018-06-07T21:16:39.275Z] MQTT: TLS ready: Connect MQTT [2018-06-07T21:16:39.395Z] RQMQTT: Connected [2018-06-07T21:16:39.401Z] [2018-06-07T21:16:39.405Z] ************************* [2018-06-07T21:16:39.407Z] MAIN: Gateway bridging [2018-06-07T21:16:39.412Z] ************************* [2018-06-07T21:16:39.414Z] [2018-06-07T21:16:39.424Z] MQTT: Sending status packet [2018-06-07T21:16:39.426Z] MQTT: Report reboot error: 0140 [2018-06-07T21:16:39.433Z] MQTT: Sending status succeeded: 0 [2018-06-07T21:16:43.815Z] LORA: Packet dropped! Bad CRC [2018-06-07T21:16:43.883Z] LORA: Accepted packet [2018-06-07T21:16:43.912Z] MQTT: Sending UPLINK OK [2018-06-07T21:16:48.082Z] MON: SYS Stack size: 2870 [2018-06-07T21:16:48.086Z] MON: heap usage: 263KB (266KB), free: 76KB [2018-06-07T21:16:50.543Z] LORA: Accepted packet [2018-06-07T21:16:50.571Z] MQTT: Sending UPLINK OK ```

Any Screenshots or Photos?

Not applicable.

Do you think you can try to fix this yourself and submit a pull request?

No.

KrishnaIyer commented 5 years ago

This issue was the focal point of our 1.0.5 fix. I'm closing this since we have enough positive feedback. Please feel free to re-open it if you experience it in the latest stable build.

avbentem commented 5 years ago

This might still be happening in 1.0.5.

But as now the LoRa module is actually working, maybe it's related to #8, and reported there instead: https://github.com/TheThingsProducts/gateway/issues/8#issuecomment-410536382

danielkucera commented 1 year ago

I think this is more related to #71