{"id":571,"date":"2021-07-05T11:41:25","date_gmt":"2021-07-05T09:41:25","guid":{"rendered":"https:\/\/www.iot-embedded.de\/iot-2021\/?p=571"},"modified":"2021-07-05T11:41:27","modified_gmt":"2021-07-05T09:41:27","slug":"datenverlust-beim-feldversuch-suche-nach-dem-problem","status":"publish","type":"post","link":"https:\/\/www.iot-embedded.de\/iot-2021\/smart-drive\/datenverlust-beim-feldversuch-suche-nach-dem-problem\/","title":{"rendered":"Datenverlust beim Feldversuch – Suche nach dem Problem"},"content":{"rendered":"

Wie Marius vor wenigen Tagen beschrieben hat<\/a>, sind bei seinen ersten Fahrten mit Smart Drive keine bzw. nicht alle Messdaten in der Datenbank und somit im Frontend der Kunden angekommen. Nach der Auswertung des Log des Device in der Balena Cloud k\u00f6nnen wir davon ausgehen, dass die Messwerte durch den Pi auch w\u00e4hrend der Fahrt \u00fcber den mobilen Internetzugang als MQTT-Messages verschickt worden sind. Daher muss der Fehler im Backend gesucht werden.<\/p>\n

Das Ansehen der Konsolenausgabe eines als Daemon laufenden Docker Containers geschieht mit dem Befehl<\/p>\n

docker logs iot-receiver -f\n<\/pre>\n
“
\nDabei ist iot-receiver<\/i> der Name eines Docker Containers und f<\/i> steht f\u00fcr follow, es werden also nicht nur vergangene Ausgaben angezeigt, sondern auch alle neu ausgegebenen Zeilen bis man mit Strg+C beendet.<\/p>\n
Problem 1<\/h2>\n
Bei Durchsicht der Ausgabe unseres MQTT-Receivers wird deutlich, dass zwar alle Nachrichten durch den Receiver empfangen worden sind, jedoch nicht in die Datenbank geschrieben werden konnten. Eine entsprechende Warnung wurde ab dem Zeitpunkt des Fahrtbeginns f\u00fcr jede Nachricht ausgegeben. Bei den bisherigen Tests wurde alle 2 Sekunden eine Messung durchgef\u00fchrt und diese \u00fcber eine stabile Internetverbindung versendet. F\u00fcr den Einsatz im Auto wurde die Anzahl der Messungen auf 4 Messungen pro Sekunde erh\u00f6ht. Au\u00dferdem wurde die weniger stabile Internetverbindung eines Smartphones benutzt.<\/p>\n
Zun\u00e4chst wurden die Auswirkungen des h\u00f6heren Messintervalls gepr\u00fcft. Da das Intervall einige Minuten vor Fahrtbegin umgestellt wurde und zun\u00e4chst alles weiterhin funktioniert hat, k\u00f6nnen wir dies als Problemursache eher ausschlie\u00dfen. Zum weiteren Test wurde das Intervall jedoch noch einmal deutlich verk\u00fcrzt, n\u00e4mlich auf 0,01 Sekunden, also 100 Messvorg\u00e4nge pro Sekunde. Dabei ist zu beobachten, dass der Pi nicht ann\u00e4hernd soviele Messungen pro Sekunde schafft, jedoch ca 30 MQTT-Messages pro Sekunde \u00fcbertragen werden und die Werte ohne Probleme in die Datenbank geschrieben werden k\u00f6nnen.<\/p>\n
Als zweite m\u00f6gliche Ursache des Problems kommt die instabile Internetverbindung in Betracht. Zwar werden auf dem Pi die Messwerte zwischengespeichert und dann bei Neuaufbau der Verbindung versandt, jedoch passiert an dieser Stelle ein entscheidender Fehler. Bisher wurde angenommen, dass das Attribut _id<\/i> den Zeitpunkt der Messung als Zeitstempel beinhaltet. Diese Annahme ist leider falsch und f\u00fchrt zu einem fatalen Fehler. Der Zeitstempel gibt den Zeitpunkt des Versands der Nachricht an. Konnten nun einige Nachrichten nicht versandt werden und m\u00fcssen in einem Block als Liste versandt werden, berechnet der MQTT-Receiver f\u00fcr alle Nachrichten einer Liste den identischen Zeitstempel und verwendet diesen als Teil des Prim\u00e4rschl\u00fcssels einer Zeile in der Datenbank. Da der Prim\u00e4rschl\u00fcssel aus dem Zeitstempel und der Device ID besteht, wird dann versucht mehrere Zeilen mit identischem Prim\u00e4rschl\u00fcssel in die Datenbank zu schreiben.<\/p>\n
L\u00f6sung<\/h2>\n
Zur L\u00f6sung des Problems wurde im Service sensor<\/i> auf dem Device ein Zeitstempel zu jedem Messwert hinzugef\u00fcgt. Dazu wird die Methode time()<\/i> des gleichnamigen Python-Moduls verwendet. Diese gibt die aktuelle Zeit als UNIX-Timestamp mit sechs Stellen nach dem Komma als float-Wert zur\u00fcck. Danach wird der Messwert in das zu versendende Dictionary aufgenommen und bekommt den Schl\u00fcssel Timestamp<\/i>. Nun kann dieses Attribut im MQTT-Receiver statt _id<\/i> verwendet werden. Da der Wert bereits mit Nachkommastellen \u00fcbermittelt wird, ist keine Division mehr notwendig.<\/p>\n
Mit gro\u00dfer Hoffnung wurde nun eine weitere Testfahrt durchgef\u00fchrt, die leider ein weiteres Problem aufzeigte.<\/p>\n
Problem 2<\/h2>\n
Bei der zweiten Fahrt sind nicht alle Messwerte verloren gegangen. Ab Fahrtbeginn konnten die Messwerte jedoch zun\u00e4chst wieder nicht in die Datenbank geschrieben werden. Nach einem Neustart des MQTT-Receivers trat der Fehler jedoch nicht mehr auf. Die Fehlerursache war diesmal nicht so leicht zu finden, da es nicht gelungen ist, das Problem nachzustellen. Daher die folgenden Gedanken zur m\u00f6glichen Ursache des Problems:<\/p>\n
    \n
  • Im MQTT-Receiver wird die Methode loop_forever()<\/i> verwendet, der Empfang von Nachrichten also im Main-Thread durchgef\u00fchrt.<\/li>\n
  • Die Callback-Methode, die f\u00fcr jede empfangene Nachricht aufgerufen wird l\u00e4uft somit im selben Thread<\/li>\n
  • Die Callback-Methode ist teuer, da zun\u00e4chst die empfangene Zeichenkette als JSON geparst wird, anschlie\u00dfend \u00fcber die empfangene Liste iteriert wird, f\u00fcr jeden Messwert 7 Typecasts der numerischen Werte durchgef\u00fchrt werden und jeder Messwert einzeln in die Datenbank geschrieben wird.<\/li>\n
  • Bei instabiler Internetanbindung des Device und 4 Messwerten pro Sekunde sammeln sich in einer MQTT-Nachricht bereits bei kurzem Verbindungsausfall viele Messwerte.<\/li>\n
  • Bei erneutem Verbindungsaufbau wird dann eine Liste mit vielen Messwerten versandt und sehr schnell danach weitere Messwerte.<\/li>\n<\/ul>\n
    Ich vermute, dass es durch die Ausf\u00fchrung in einem einzigen Thread zu einer \u00dcberschneidung zwischen der noch laufenden Verarbeitung einer MQTT-Message mit mehreren Messwerten und dem Empfang der darauffolgen MQTT-Message kommt. Dadurch k\u00f6nnte ein SQL-Statement nicht korrekt ausgef\u00fchrt werden und somit der Cursor der Datenbankverbindung unbrauchbar werden, sodass keine folgenden Werte mehr in die Datenbank geschrieben werden k\u00f6nnen. Hierzu ist zu beachten, dass PostgreSQL nach jedem SQL-Statement ein Semikolon erwartet. Wird dieses nicht gesetzt, wird das Statement als unvollst\u00e4ndig interpretiert und das nachfolgende Statement angeh\u00e4ngt.<\/p>\n
    L\u00f6sung<\/h2>\n
    Zur L\u00f6sung des Problems bei der vermuteten Ursache, wird der Empfang von MQTT-Messages in einen eigenen Thread ausgelagert. Wichtig dabei ist, dass die Callback-Methode so umgeschrieben wird, dass die Verarbeitung der Nachrichten im Main-Thread verbleibt und der neue Thread somit nicht blockiert.<\/p>\n
    Dazu wird die Methode loop_start()<\/i> des MQTT-Clients verwendet, da diese automatisch einen eigenen Thread verwendet und den Main-Thread nicht blockiert. Somit ist es m\u00f6glich den Main-Thread zur Kommunikation mit der Datenbank einzusetzen. Dazu ist jedoch eine \u00dcbermittlung der empfangenenen MQTT-Messages zwischen beiden Threads notwendig. Als Datenstruktur bietet sich daf\u00fcr eine Warteschlange, di nach dem FIFO-Prinzip funktioniert, an. Eine solche Queue ist im Python Modul Queue<\/i> enthalten. F\u00fcr die Verwendung wichtig ist das Anstellen eines Objekts an hinterer Position sowie das Herausnehmen eines Objekts von der vorderen Position. Dazu stehen die Methoden put()<\/i> und get()<\/i> zur Verf\u00fcgung. Dabei ist zu beachten, dass beide Methoden solange blockieren, bis die Aktion tats\u00e4chlich ausgef\u00fchrt werden konnte. Dieser Effekt ist beim Herausnehmen eines Objekts erw\u00fcnscht, damit das Programm immer solange wartet bis tats\u00e4chlich ein Objekt in der Warteschlange vorhanden ist. Beim Anstellen eines Objekts sollte der Effekt theoretisch nicht auftreten, da die L\u00e4nge der Warteschlange nicht begrenzt wird, damit dies auch in der Praxis nicht vorkommen kann, wird statt der Methode put()<\/i> die Methode put_nowait<\/i> verwendet. Diese blockiert den Thread nicht, sondern wirft sofort einen Fehler, wenn kein Element an die Warteschlange angeh\u00e4ngt werden kann.<\/p>\n
    Die vom MQTT-Client aufgerufene Callback-Methode beim Empfang einer Nachricht stellt diese nur noch an die Warteschlange an und \u00fcbernimmt keine weitere Verarbeitung mehr. Damit wird der Thread zum Empfang der Nachrichten nicht blockiert, auch wenn die Verarbeitung l\u00e4nger dauert. In diesem Fall sammeln sich dann Elemente in der Queue und werden geordnet nacheinander verarbeitet. Im Main-Thread wird in einer Endlosschleife auf Elemente in der Queue gewartet. Ist kein Element in der Queue angestellt, wird der Thread durch die Methode get()<\/i> der Queue blockiert. Ist ein Element vorhanden, wird dieses verarbeitet und erst nach Abschluss der Verarbeitung ein neues aus der Queue genommen. Dieses Verhalten verdeutlicht der folgende Code-Ausschnitt<\/p>\n
    while True:\n    self._log.info(f\"Queued Messages: {self._message_queue.qsize()}\")\n    messages_json = self._message_queue.get()\n    message_list = json.loads(messages_json)\n    for m in message_list:\n        self._write_message_to_db(\n            float(m['Timestamp']),\n            m['_device_uuid'],\n            float(m['X_acceleration']),\n            float(m['Y_acceleration']),\n            float(m['Z_acceleration']),\n            int(m['X_rotation']),\n            int(m['Y_rotation']),\n            int(m['Z_rotation'])\n<\/pre>\n
    Um die weitere Analyse zu vereinfachen, sollte der Fehler erneut auftreten, wurden au\u00dferdem die Ausgaben der except<\/i>-Bl\u00f6cke aussagekr\u00e4ftiger gestaltet. Statt einer selbst definierten Ausgabe k\u00f6nnen wie im folgenden Beispiel dargestellt zus\u00e4tzlich Informationen zur aufgetretenen Exception als Log ausgegeben werden, sodass die Fehlerursache besser eingrenzbar ist.<\/p>\n
    try:\n    pass # Hier Code, der Exception wirft\nexcept Exception as e:\n    print(\"Fehler aufgetreten\"\n    print(e))\n<\/pre>\n
    Mit print(e)<\/i> werden die Informationen ausgegeben, die bei nicht abgefangenen Fehlern in der Konsole erscheinen. Hier kann aber trotzdem auf das Problem reagiert und die Ausf\u00fchrung des Programms fortgesetzt werden.<\/p>\n
    Als weitere Sicherheit wurde im except<\/i>-Block der Datenbankkommunikation eingef\u00fchrt, dass der Cursor geschlossen wird und anschli\u00dfend ein neues Cursor-Objekt instanziiert wird. Dadurch wird ein Cursor, der einmal einen Fehler produziert hat, nicht weiter verwendet und kann somit als Fehlerursache f\u00fcr folgende Datenbankkommunikation ausgeschlossen werden.<\/p>\n","protected":false},"excerpt":{"rendered":"
    Wie Marius vor wenigen Tagen beschrieben hat, sind bei seinen ersten Fahrten mit Smart Drive keine bzw. nicht alle Messdaten in der Datenbank und somit im Frontend der Kunden angekommen. Nach der Auswertung des Log des Device in der Balena<\/p>\n","protected":false},"author":3,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[8],"tags":[],"_links":{"self":[{"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/posts\/571"}],"collection":[{"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/users\/3"}],"replies":[{"embeddable":true,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/comments?post=571"}],"version-history":[{"count":1,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/posts\/571\/revisions"}],"predecessor-version":[{"id":572,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/posts\/571\/revisions\/572"}],"wp:attachment":[{"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/media?parent=571"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/categories?post=571"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.iot-embedded.de\/iot-2021\/wp-json\/wp\/v2\/tags?post=571"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}