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

MKO · July 15, 2019, 11:12am

So mal ein Aktueller Bericht der Langzeittests bei mir.
Immer noch mit Datalogger 0.5.1 auf 1.20.0.rc11
FiPy 0

12 Tage
5 DS Fehler
1 HX Fehler
0 Abstürze

FiPy 1

10 Tage
7 DS Fehler
0 HX Fehler
0 Abstürze

WiPy 1

8 Tage
2 DS Fehler
0 HX Fehler
0 Abstürze

FiPy 2 habe ich selbst vom Test ausgeschlossen, da ich derzeit mit im für das Webinterface arbeiten will. Er hat aber nach 5 Tagen 0 Störungen gehabt.
Abstürze hatte ich bei ihn aktuell aufgrund des abgeschalteten Deep Sleep aber schon ein paar mal.

Die Diskussion rund um die Glitches beim Auslesen der DS18B20 haben wir nun bei Untersuchung und Verbesserung des Timings bei der Ansteuerung der DS18B20 untergebracht.

Andreas · July 15, 2019, 11:13am

Herzlichen Dank für die Testberichte! Das hört sich ja vielversprechend an.

Du meinst, das Gerät stürzt manchmal ab, wenn es nicht im Deep Sleep Modus ist? Kannst Du ungefähr eingrenzen, an welcher Stelle oder unter welchen Umständen?

MKO · July 15, 2019, 11:14am

Muß ich noch genauer untersuchen. Habe leider immer den PC nicht an gehabt, um das Logging zu sehen auch ist die Telemetrie aktuell ausgeschaltet, wodurch ich keinen Zeitpunkt ausmachen kann.
Kann aber auch an dem Branch liegen ist aktuell das merge Branch von Diren mit Webserver drauf.
Wie gesagt, muß ich daher nochmal untersuchen.

Andreas · July 15, 2019, 11:15am

Vielen Dank für diese Details zu Deinen Beobachtungen. Wir haben die notwendigen Schritte zur Analyse und Lösung bei [Backlog] Terkin-Datenlogger für BOB aufgenommen.

Unmotivierte Abstürze

Vielleicht ist das genau das Ding, das @pinguin beobachtet hatte und ich neulich ebenfalls. Ich glaube, dass das Gerät bei mir ebenfalls nicht im Deep Sleep Modus war. Wir sollten hierzu dringend den Watchdog ins Spiel bringen.

clemens · July 15, 2019, 9:29am

Bisher schaut das – was die Stabilität angeht – alles recht gut aus:

Wir haben fast immer die 9-10 Übertragungen pro Stunde, der längere Ausfall am 2019-07-10 geht auf mein Konto, da habe ich den Node in die Sonne gestellt und damit zu weit vom WLAN weg, es konnten also keine Daten übertragen werden, dass der node aber weiterlief und läuft zeigt die system.time, die auch in der Zeit ohne Datenübertragung zunahm, es gab also keinen Ausfall der Hardware oder reset in der Zeit:

Das Gerät läuft also stabil seit ca. 7 Tagen!

clemens · July 22, 2019, 9:42am

Testsystem-Ausfall 2019-07-20

Leider stieg mein Testsystem am 2019-07-20, 23:16 (GMT) komplett aus und wollte auch bis jetzt keine Daten mehr senden:

Batterie ok, die letzte gemessene Spannung war 4 V, passt also.
WLAN ok, das WLAN an das der node die Daten sendet wurde in den letzten Tagen normal genutzt, offensichtliche Ausfälle sind nicht aufgefallen.
Server ok einen Serverausfall gab es nicht, andere Systeme lieferten kontinuierlich Daten.

Beim Blick auf andere Daten ist mir aufgefallen, dass zur gleichen Zeit Stockgewichte um 1 kg – mitten in der Nacht – zugenommen haben und ich erinnerte mich an die Wetterwarnung des DWD! Auch wir hatten hier Wind und Regen.

Bei einer weiteren Inspektion habe ich die Spannung des LiPos gemessen: 3,1 V! Wie passt das zum letzten Datensatz mit 4 V? Ein Blick unter den Blumentopf:

Hmm, der BME lag da “schön” flach ganz unten! Könnte ein ordinärer Kurzschluss über den BME durch viel Regenwasser das Problem gewesen sein?

Nach einem Tausch der Batterie sendet der node wieder und er scheint keine bleibenden Schäden gegeben zu haben.

Fazit

Durch die Koinzidenz von Regen und Nodeausfall gehe ich mal davon aus, das beides miteinander zu tun hat (obwohl ich das Wort Scheinkorrelation auch kenne und weiß, dass Schuhgröße und Intelligenz hoch korrelieren),
Der sehr ungeschützte, flach auf der Steinplatte liegende BME könnte in Verbindung mit starkem Regen zu einem Kurzschluss geführt haben.
Alle Systemteile laufen mit vollem LiPo nun wieder.

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. ↩︎