Stabilität und längere Testzeiträume des Terkin-Datenloggers

MKO · July 22, 2019, 9:23pm

Habe am Sonntag nacht um 1:20 Uhr das erste mal einen Totalcrash das erstaunliche ist, das absolut zeitgleich beide FiPy abgeschmiert sind. Kann also nur am WLan oder an der Spannungsversorgung gelegen haben. Die Spannungsversorgung ist zusammen über einen 12V mppt Laderegler mit USB Anschluß und 12V Akkus geregelt, da der Akku heute Mittag zu 100% gefüllt war und der eine FiPY durch ab und anstecken des USB neu gestartet werden konnte, schließe ich sie fast aus (der zweite bleibt stumm also auch kein IP Crash und der USB liefert Spannung) .
Den 2. habe ich extra noch nicht neu gestartet, da ich morgen Vormittag mal versuchen will bei ihn ins REPL. zu kommen. Bezweifel zwar das das klappt, aber einen versuch ist es Wert.

Wenn ja, wie sollte ich vorgehen, um möglichst viel Infos über den Ausfall zu bekommen?
Wollte erstmal mit Atom ran, da er beim Anschließend einfach ins Logging verbindet, ohne einen Reset auszuführen.

Andreas · July 22, 2019, 10:10pm

Interessant. Um das für die nächsten Iterationen zu verbessern, müsste die Aufmöbelung des Watchdogs dank @pinguin nun aus dem aktuellen Master heraus einsetzbar sein. Lass den Datenlogger doch gerne ab sofort mal (testweise) damit eine Weile losrennen.

Ich wüsste nicht, wie man da irgendetwas herausfinden könnte. Die Ausgaben auf der UART sind ja schon geschehen und wurden auf keinerlei Terminal geschrieben, wo man sie rauslesen könnte.

Andere benutzen für solche Feldforschungen einfache aber effektive AVR-basierte Datenlogger.

– ~~Turtles~~Dataloggers all the way down.

Beispielimplementierung

MKO · July 22, 2019, 10:36pm

Gut werde also einfach nur schauen ob über UART überhaupt noch was raus kommt.
und ob er sich Aufgehängt hat, oder das Programm abgebrochen wurde…

Wenn ich die UPtime meines Routers vergleiche, könnte das ganze mit einer Zwangstrennung oder Netzstörung zusammen hängen.

@Andreas zur Info. die Version ist immer noch die Ursprüngliche 0.5.1 vom Anfang Juli.
Glaube sogar noch ohne Wachdog.

caro · August 7, 2019, 11:10am

Könntest du da bitte noch die Software-Version dazu schreiben?

caro · August 7, 2019, 11:45am

Danke an alle Tester*innen! Ich habe zwei Bitten für zukünftige Tests und deren Dokumentation:
Könntet ihr bitte

die Softwareversion (hiveeyes / hiverize) mit Versionsnummer oder (falls nicht vorhanden) Pull-Datum sowie das verwendete Dateisystem (FatFS / littleFS) mit angeben
Elektronik nicht im Regen liegen lassen. Die Steckverbindungen mit den Pfostenbuchsen sind nicht wasserfest! Sehr gern stelle ich für Tests weitere Gehäuse zur Verfügung.
Danke!

Andreas · August 10, 2019, 12:05am

Im Rahmen der Untersuchungen zu elektromagnetischen Störungen des Wägezellen-Subsystems konnten wir noch die folgenden Beobachtungen zur Laufzeit feststellen.

Während der letzten Testreihe mit einem Vorseriengerät über ca. 170 Stunden ^[1] musste das Gerät zweimal per Reset oder Power-Cycle neu angekurbelt werden. Wir kennen die Ursache dafür noch nicht, der einzige Indikator war, dass das Blaulicht zu blinken aufhörte ^[2].
Da der Eumel ausschließlich an einem USB-Netzteil angeschlossen war, konnte die UART-Ausgabe leider nicht zur Laufzeit beobachtet werden, in der sich entsprechende Spuren hätten finden können.
Um diesen STOP-THE-WORLD-FOREVERs nachzugehen, hängt die Appliance nun an einem RaspberryPi3 SBC, um Stromversorgung plus dauerhaftes Debugging zu realisieren, ohne damit implizit meine Workstation über Tage an das Gerät fesseln zu müssen. Dieses Setup haben wir unter Monitoring and recording the serial interface output of a microcontroller attached to an UART interface näher beschrieben, um einen entsprechenden Nachbau einfacher zu machen.

Mit dem commit Revert "Adjust waiting time after resetting 1-Wire bus" · hiveeyes/hiveeyes-micropython-firmware@11e8eaf · GitHub vor ein paar Tagen waren hoffentlich endlich alle Sensor-Reading-Adjustments ordentlich im Kasten, so dass sich aus meiner Sicht diese Art von Testreihe überhaupt erstmalig lohnt. ↩︎
Ganz schön flashy übrigens, wenn das Teil in der Nacht in einem dunklen Zimmer ohne Lichtabschirmung steht und ungehindert seine Signalisierungen über die weißen Zimmerwände in den Innenhof reflektieren kann. ↩︎

Andreas · August 10, 2019, 4:21am

Direkt beim Starten des Geräts am SBC ist der Datenlogger zweimal sporadisch ausgerutscht.

   15.7152 [terkin.device            ] INFO   : Starting networking
   15.7978 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c3:42:bd', 'sta_mac': '80:7d:3a:c3:42:bc'}
   15.8128 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('0.0.0.0', '0.0.0.0', '0.0.0.0', '0.0.0.0')
Traceback (most recent call last):
  File "main.py", line 72, in <module>
  File "main.py", line 67, in main
  File "datalogger.py", line 138, in start
  File "device.py", line 70, in start_networking
  File "device.py", line 61, in start_networking
  File "network/core.py", line 35, in start_wifi
  File "network/wifi.py", line 52, in start
TimeoutError: Connection to AP Timeout!

   26.5656 [terkin.api.http          ] INFO   : Setting up HTTP API
Unhandled exception in thread started by <bound_method>
Traceback (most recent call last):
  File "network/ip.py", line 24, in start_real
OSError: Network card not available
   26.9306 [terkin.api.http          ] INFO   : Starting HTTP server
Traceback (most recent call last):
  File "main.py", line 72, in <module>
  File "main.py", line 67, in main
  File "datalogger.py", line 143, in start
  File "device.py", line 211, in start_network_services
  File "network/core.py", line 71, in start_httpserver
  File "api/http.py", line 70, in start
  File "microWebSrv.py", line 221, in Start
OSError: Network card not available

Andreas · August 14, 2019, 7:19pm

Zwischenbericht

Nach 420.330,4291 Sekunden, also gut 4 Tagen und 20 Stunden, hat der Datenlogger von sich aus neugestartet und ist wohl nach dem Neustart auf dem gleichen Fehler OSError: Network card not available ausgerutscht, der oben schon erwähnt wurde. Hier muss dringend nachgebessert werden.

Als Ursache für das Ausrutschen konnte diesmal dank Monitoring and recording the serial interface output of a microcontroller attached to an UART interface ein CORE DUMP beobachtet werden. Anbei finden sich entsprechende Logs dazu.

01-post-mortem-01-narrow.log (4.3 KB)
01-post-mortem-02-medium.log (42.5 KB)

STGTFO

   24.4832 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 1 retries left
   25.3060 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 0 retries left
   26.1432 [terkin.network.wifi      ] ERROR  : WiFi STA: Connecting to "GartenNetzwerk" failed
Traceback (most recent call last):
  File "network/wifi.py", line 117, in connect_stations
  File "network/wifi.py", line 192, in connect_station
WiFiException: WiFi STA: Unable to connect to "GartenNetzwerk"

   26.5553 [terkin.api.http          ] INFO   : Setting up HTTP API
Unhandled exception in thread started by <bound_method>
Traceback (most recent call last):
  File "network/ip.py", line 24, in start_real
OSError: Network card not available
   26.9223 [terkin.api.http          ] INFO   : Starting HTTP server
Traceback (most recent call last):
  File "main.py", line 72, in <module>
  File "main.py", line 67, in main
  File "datalogger.py", line 143, in start
  File "device.py", line 211, in start_network_services
  File "network/core.py", line 71, in start_httpserver
  File "api/http.py", line 70, in start
  File "microWebSrv.py", line 221, in Start
OSError: Network card not available

Überlegung

Für die Ursache des sporadischen CORE DUMPs könnten “weiche” Fehler sein, die über Single-Event Upsets (SEUs) zustande kommen können ^[1].

Zwischenfazit

Die exakte Ursache solcher sporadischer Abstürze muss uns an dieser Stelle jedoch gar nicht primär interessieren, wir müssen nur durch optimale Vorbereitung das Chaos gut im Griff haben.

Dankenswerterweise übernimmt der Watchdog-Timer (WDT) an dieser Stelle eine wichtige Aufgabe und führt das Gerät automatisch wieder aus dem Fehlerzustand heraus.

Ein Single Event Upset (SEU) ist ein Soft Error (deutsch „weicher“ Fehler), der beispielsweise beim Durchgang hochenergetischer ionisierender Teilchen durch Halbleiterbauelemente hervorgerufen werden kann. Der Fehler äußert sich beispielsweise als bitflip, also der Änderung des Zustandes eines einzelnen oder mehrerer Bits in Speicherbausteinen oder CPU-Registern, was wiederum zu einer Fehlfunktion des betroffenen Bauteils führen kann. Wissenschaftliches und gleichermaßen Kurioses dazu haben wir auch unter Soft errors caused by single-event upsets (SEUs) zusammengetragen. ↩︎

Andreas · August 15, 2019, 12:41pm

8 posts were merged into an existing topic: Lagerkoller wegen kosmischer Strahlung

Andreas · August 15, 2019, 1:46am

Verhalten bei der WiFi-Verbindung

Nach dem Wechsel von einer AVM FRITZ!Box 7320 auf eine AVM FRITZ!Box 7520 als DSL-Modem und WiFi Access Point konnte ich ein paar Verhaltensänderungen bei der Verbindungsaufname des FiPy zum WiFi Access Point feststellen.

Im Gegensatz dazu, dass vorher bei jedem Neustart die IP-Adresse wechselte, bleibt sie nun stabil. Möglicherweise ist also der DHCP-Server auf der Box irgendwie besser geworden.
Bisher dauerte die Verbindungsaufname ca. fünf Sekunden, nun klappt es oft schon nach drei Sekunden.
Allerdings klappt die Verbindung zum AP deterministisch nur jedes zweite Mal, also in der Hälfte aller Fälle nicht. Im Anhang kann man die Verläufe im Erfolgsfall und im Fehlerfall nachlesen.

Anhang

STA connection succeeded

   18.0049 [terkin.device            ] INFO   : Starting networking
   18.1074 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c2:de:45', 'sta_mac': '80:7d:3a:c2:de:44'}
   18.1239 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('0.0.0.0', '0.0.0.0', '0.0.0.0', '0.0.0.0')
   18.1572 [terkin.network.wifi      ] INFO   : WiFi STA+AP: Starting interface
   18.1763 [terkin.network.wifi      ] INFO   : WiFi STA: Directly connecting to configured networks: ['GartenNetzwerk']
   18.1966 [terkin.network.wifi      ] INFO   : WiFi STA: Prepare connecting to network "GartenNetzwerk"
   18.2700 [terkin.network.wifi      ] INFO   : WiFi STA: Auth mode from NVRAM with key=wa.0a10c7c77510, value=3
   18.2906 [terkin.network.wifi      ] INFO   : WiFi STA: Attempt connecting to network "GartenNetzwerk" with auth mode "3"
   18.3113 [terkin.network.wifi      ] INFO   : WiFi STA: Starting connection to "GartenNetzwerk" with timeout of 15.0 seconds
   18.3346 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 17 retries left
   19.1591 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 16 retries left
   19.9851 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 15 retries left
   20.8110 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 14 retries left
   21.6484 [terkin.network.wifi      ] INFO   : WiFi STA: Connected to "('GartenNetzwerk', 'fipy-wlan-de44')" with IP address "192.168.178.30"
   21.7385 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c2:de:45', 'sta_mac': '80:7d:3a:c2:de:44'}
   21.7543 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('192.168.178.30', '255.255.255.0', '192.168.178.1', '192.168.178.1')
   21.7756 [terkin.network.core      ] INFO   : Network interface ready

STA connection failed

   18.0040 [terkin.device            ] INFO   : Starting networking
   18.1067 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c2:de:45', 'sta_mac': '80:7d:3a:c2:de:44'}
   18.1233 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('0.0.0.0', '0.0.0.0', '0.0.0.0', '0.0.0.0')
   18.1566 [terkin.network.wifi      ] INFO   : WiFi STA+AP: Starting interface
   18.1758 [terkin.network.wifi      ] INFO   : WiFi STA: Directly connecting to configured networks: ['GartenNetzwerk']
   18.1959 [terkin.network.wifi      ] INFO   : WiFi STA: Prepare connecting to network "GartenNetzwerk"
   18.2694 [terkin.network.wifi      ] INFO   : WiFi STA: Auth mode from NVRAM with key=wa.0a10c7c77510, value=3
   18.2900 [terkin.network.wifi      ] INFO   : WiFi STA: Attempt connecting to network "GartenNetzwerk" with auth mode "3"
   18.3106 [terkin.network.wifi      ] INFO   : WiFi STA: Starting connection to "GartenNetzwerk" with timeout of 15.0 seconds
   18.3339 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 17 retries left
   19.1575 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 16 retries left
   19.9845 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 15 retries left
   20.8077 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 14 retries left
   21.6305 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 13 retries left
   22.4536 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 12 retries left
   23.2766 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 11 retries left
   24.0996 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 10 retries left
   24.9215 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 9 retries left
   25.7436 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 8 retries left
   26.5656 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 7 retries left
   27.3875 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 6 retries left
   28.2095 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 5 retries left
   29.0316 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 4 retries left
   29.8535 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 3 retries left
   30.6756 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 2 retries left
   31.4969 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 1 retries left
   32.3185 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 0 retries left
   33.1520 [terkin.network.wifi      ] ERROR  : WiFi STA: Connecting to "GartenNetzwerk" failed
Traceback (most recent call last):
  File "/flash/lib/terkin/network/wifi.py", line 126, in connect_stations
  File "/flash/lib/terkin/network/wifi.py", line 201, in connect_station
WiFiException: WiFi STA: Unable to connect to "GartenNetzwerk"

   33.1909 [terkin.network.wifi      ] INFO   : WiFi STA: Forgetting NVRAM data for network "GartenNetzwerk"
   33.2824 [terkin.network.wifi      ] ERROR  : WiFi STA: Connecting to any network candidate failed. Please check your WiFi configuration for one of the station candidates 1.
   33.3003 [terkin.network.wifi      ] WARNING: Todo: We might want to switch to AP mode here or alternatively buffer telemetry data to flash to be scheduled for transmission later.
   33.3226 [terkin.network.core      ] INFO   : Network interface ready

wtf · August 15, 2019, 7:15am

Du schreibst weiter unten, dass Dein (neues) WLAN ohnehin jeden zweiten Verbindungsversuch zum Scheitern verurteilt. Wie unterscheidet sich der Umgang mit dem Fehler “unable to connect” dort wie hier?

Andreas · August 15, 2019, 12:49pm

Scheinbar, leider, ja.

Da wir noch keinen Hintergrund-Dienst zur Überwachung der Verbindung im WiFi-Manager haben, habe ich versucht, die Dinge erst einmal pragmatisch zu verbessern. Ein paar neue commits ^[1] tragen dazu bei, dass a) der Datenlogger an den genannten Stellen nun nicht mehr unmotiviert abstürzt und b) dass zwei Verbindungsversuche unternommen werden weil ja immer einer von beiden deterministisch fehlschlägt.

Die nächsten Ausbaustufen ^[2] kommen dann hoffentlich bald in einer späteren Iteration.

Comparing 495890c085fe459fb1fcc6112875d5fc77abc58a...6eddea24b3b4ee8ba9154d38de0de0c7aad905a2 · hiveeyes/terkin-datalogger · GitHub ↩︎
Pragmatischer Service-Thread zur Verbindungsüberwachung oder ggf. ein Ruf zu ensure_connection() kurz vor dem Telemetrie-Akt. Generell wollen wir die bereits separat getrennten Domänen (Sensor vs. Telemetrie) gerne auch beizeiten parallelisieren, um Effizienzgewinne zu erzielen. Momentan wird noch so ziemlich alles sequentiell abgearbeitet. ↩︎

Andreas · August 15, 2019, 12:59pm

2 posts were merged into an existing topic: Lagerkoller wegen kosmischer Strahlung

Andreas · August 15, 2019, 8:37pm

Beobachtungen

In der Praxis sieht das dann so aus wie unten im Log bei Connect to WiFi twice zu sehen. Erst einmal schlägt die Verbindung fehl aber nachdem noch einmal nachgehakt wurde, klappt es erfolgreich. Alles andere als optimal, ist halt aber scheinbar so.

Connect to WiFi twice shmoo

=============================
Bee Observer Datalogger 0.5.1
=============================
CPU freq     160.0 MHz
Device id    807d3ac342bc

Python  : 3.4.0
lorawan : 1.0.2
machine : FiPy with ESP32
nodename: FiPy
release : 1.20.0.rc12.1
sigfox  : 1.0.1
sysname : FiPy
version : 6c0000f on 2019-08-01

   23.7123 [terkin.device            ] INFO   : Starting networking
   23.8151 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c3:42:bd', 'sta_mac': '80:7d:3a:c3:42:bc'}
   23.8323 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('0.0.0.0', '0.0.0.0', '0.0.0.0', '0.0.0.0')
   23.8654 [terkin.network.wifi      ] INFO   : WiFi STA+AP: Starting interface
   23.8867 [terkin.network.wifi      ] INFO   : WiFi STA: Connecting to configured networks: ['GartenNetzwerk']. Attempt: #1
   23.9091 [terkin.network.wifi      ] INFO   : WiFi STA: Prepare connecting to network "GartenNetzwerk"
   23.9923 [terkin.network.wifi      ] INFO   : WiFi STA: Auth mode from NVRAM with key=wa.0a10c7c77510, value=3
   24.0140 [terkin.network.wifi      ] INFO   : WiFi STA: Attempt connecting to network "GartenNetzwerk" with auth mode "3"
   24.0376 [terkin.network.wifi      ] INFO   : WiFi STA: Starting connection to "GartenNetzwerk" with timeout of 15.0 seconds
   24.0640 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 17 retries left
   24.8910 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 16 retries left
   25.7192 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 15 retries left
   26.5462 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 14 retries left
   27.3736 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 13 retries left
   28.2000 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 12 retries left
   29.0255 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 11 retries left
   29.8515 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 10 retries left
   30.6755 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 9 retries left
   31.4993 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 8 retries left
   32.3224 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 7 retries left
   33.1464 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 6 retries left
   33.9704 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 5 retries left
   34.7944 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 4 retries left
   35.6183 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 3 retries left
   36.4423 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 2 retries left
   37.2665 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 1 retries left
   38.0903 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 0 retries left
   38.9280 [terkin.network.wifi      ] ERROR  : WiFi STA: Connecting to "GartenNetzwerk" failed
Traceback (most recent call last):
  File "/flash/lib/terkin/network/wifi.py", line 128, in connect_stations
  File "/flash/lib/terkin/network/wifi.py", line 203, in connect_station
WiFiException: WiFi STA: Unable to connect to "GartenNetzwerk"

   38.9691 [terkin.network.wifi      ] INFO   : WiFi STA: Forgetting NVRAM data for network "GartenNetzwerk"
   39.0721 [terkin.network.wifi      ] ERROR  : WiFi STA: Connecting to any network candidate failed. Please check your WiFi configuration for one of the station candidates 1.
   39.0921 [terkin.network.wifi      ] WARNING: Todo: We might want to buffer telemetry data to flash memory to be scheduled for transmission later.
   39.1095 [terkin.network.wifi      ] INFO   : WiFi STA: Connecting to configured networks: ['GartenNetzwerk']. Attempt: #2
   39.1325 [terkin.network.wifi      ] INFO   : WiFi STA: Prepare connecting to network "GartenNetzwerk"
   39.2188 [terkin.network.wifi      ] INFO   : WiFi STA: Unknown auth mode for network "GartenNetzwerk", invoking WiFi scan
   39.2358 [terkin.network.wifi      ] INFO   : WiFi STA: Scanning for networks
   42.2570 [terkin.network.wifi      ] INFO   : WiFi STA: Networks available: ['REDACTED', 'REDACTED', 'YADDA', 'GartenNetzwerk', 'REDACTED', 'REDACTED']
   42.3047 [terkin.network.wifi      ] INFO   : WiFi STA: Storing auth mode into NVRAM with key=wa.0a10c7c77510, value=3
   42.3286 [terkin.network.wifi      ] INFO   : WiFi STA: Attempt connecting to network "GartenNetzwerk" with auth mode "3"
   42.3546 [terkin.network.wifi      ] INFO   : WiFi STA: Starting connection to "GartenNetzwerk" with timeout of 15.0 seconds
   42.3840 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 17 retries left
   43.2122 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 16 retries left
   44.0407 [terkin.network.wifi      ] INFO   : WiFi STA: Waiting for network "GartenNetzwerk" to come up, 15 retries left
   44.8859 [terkin.network.wifi      ] INFO   : WiFi STA: Connected to "('GartenNetzwerk', 'fipy-wlan-42bc')" with IP address "192.168.178.21"
   44.9752 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (MAC): {'ap_mac': '80:7d:3a:c3:42:bd', 'sta_mac': '80:7d:3a:c3:42:bc'}
   44.9933 [terkin.network.wifi      ] INFO   : WiFi STA: Networking address (IP):  ('192.168.178.21', '255.255.255.0', '192.168.178.1', '192.168.178.1')
   45.0158 [terkin.network.core      ] INFO   : Network interface ready
   45.0446 [terkin.device            ] INFO   : [LoRa] Disabling LoRa interface as no antenna has been attached. ATTENTION: Running LoRa without antenna will wreck your device.
   45.0660 [terkin.device            ] INFO   : Starting telemetry

Weitere Nachforschungen

Für die Ursachenforschung könnte man noch ein paarmal den Mond umkreisen. Vermutlich ist es so, dass der halbgare Zustand durch den WiFi-Scan gerettet wird, der zwangsläufig beim zweiten Versuch folgt ^[1].

Einschätzung des Problems

Alles kein Drama. Dass die Verbindung mal nicht klappt, passierte innerhalb der letzten Testreihe nur zwei Mal innerhalb von 18 Stunden Laufzeit im Produktionsmodus (mit Deep Sleep, mit Watchdog, ohne LED-Heartbeat; dafür aber mit Logging und am Strom ohne Batterie) und wird ja nun durch den kleinen Workaround kompensiert.

root@kotori-one:~# cat /home/pi/sermon-workbench-fipy.log | grep Exception

WiFiException: WiFi STA: Unable to connect to "GartenNetzwerk"
WiFiException: WiFi STA: Unable to connect to "GartenNetzwerk"

P.S.: Wenn man das Log genau anschaut, entdeckt man so eine Versionsnummer:

Das kommt aus den ersten Versuchen zu Module freezing for Pycom MicroPython - #5 by Andreas.

… nachdem die auth-mode Informationen gelöscht wurden, die sich zwischenzeitlich im NVRAM gemerkt wurden, damit man im Normalfall keinen Scan benötigt, um das WiFi anzufahren. ↩︎

Andreas · August 15, 2019, 8:59pm

… ist natürlich viel zu unpräzise. Das Schlafintervall lag hier bei 60 Sekunden, zusammen mit den 30 Sekunden Laufzeit ergeben sich über die 18 Stunden Laufzeit also ungefähr 720 Zyklen, von denen wiederum zwei fehlschlugen.

wtf · August 17, 2019, 11:04am

Wie kommt das Terkin denn auf die AP-MAC-Adresse? Ist das ne Info, die nach nem Befehl “verbinde Dich mit $ESSID und $Passwort” generiert wird, oder ist diese “MAC-Adresse” (BSSID präzise zu sein) irgendwie hard-coded und damit Bestandteil des “verbinde Dich”-Befehls?

Also zunächst: Stimmt die denn überhaupt? Ich kann mir schwerlichst vorstellen, dass sowohl die MAC-Adresse des FiPy-Interfaces als auch die Deines WLAN-APs (mutmaßlich AVM Fritzbox) beide vom Vendor Expressif Inc. stammen und direkt nacheinander vergeben wurde (increase of one between ap_mac and sta_mac).

Andreas · August 17, 2019, 2:16pm

Hey,

danke fürs Lesen der Log-Meldungen ^[1].

Alles ist ganz einfach: Beide dort angegebenen MAC-Adressen sind im FiPy einprogrammiert. Die eine ist die designierte MAC-Adresse, die für die WiFi-Netzwerkkarte im STA-Modus benutzt wird (als WiFi-Client), die andere ist die, die im AP-Modus benutzt wird (als WiFi-AP).

Seit einiger Zeit schalten wir pauschal in der Terkin-Firmware beide Modi an, das kann sich zukünftig bestimmt noch einmal ändern, wenn wir den AP-Mode nur unter bestimmten Umständen (auf Zuruf per Knopfdruck oder Steuerbefehl) aktivieren.

Die MAC-Adresse des STA-Interfaces korreliert 1:1 mit der Geräte-ID.

Device id    807d3ac342bc

In der Tat wird für die Vergabe der MAC-Adresse des AP-Interfaces einfach eins auf die MAC-Adresse des STA-Interfaces draufaddiert, ja.

Hilft das weiter, um an dieser Stelle mehr Licht ins Dunkle zu bringen?

You know who you are. ↩︎

Andreas · August 19, 2019, 1:22am

Per Parallelize networking subsystem · hiveeyes/terkin-datalogger@22ed127 · GitHub konnten wir die Infrastruktur nun endlich auch in diesem Bereich verbessern.

clemens · August 19, 2019, 8:54am

Magst du mal erklären, was da nun parallel läuft, wir brauchen ja zuerst die Sensordaten um sie dann erst zu schicken. Was bringt das ca. in Sekunden für die runtime?

Andreas · August 19, 2019, 5:01pm

Auf die Gesamtlaufzeit wirkt sich das kaum aus. “Einmal hochfahren und messen” dauert derzeit immer noch um die 30 Sekunden lang.

Wichtig ist an dieser Stelle weiterhin die Stabilität bzw. Robustheit: Mit nun im Hintergrund dauerhaft wirksamen Servicing des WiFi-Moduls ist die Appliance gegenüber Verbindungsstörungen bei der Konnektivität zum Access Point nun auch im Live Mode resilienter.