Masterbrick hängt sich nach Timeout auf.

[nbkr]

Hallo,

ich baue mir mittels Raspberry Pi und Tinkerforge eine Haussteuerung. Die Steuerung kontrolliert aktuell einige Flurlichter, die Rollläden und die Türklingel. Die Motoren der Rollläden hängen mittels Zwischenrelais per 24 Volt an Industrial Digital Out Ausgängen.

Die Industrial Out Bricklets sind in Schaltschrankgehäusen eingebaut. Mit einem der Kästen habe ich Probleme. In dem Kasten sind 8 Industrial Digital Out Bricklets (Version 1.0) verbaut. Dazu kommt, in der Reihenfolge von unten nach oben: Step-Down-Power Supply, Master Brick (2.1), Ethernet Extension, Master Brick (2.1)

Ich bekomme in der Steuerung immer wieder einen Timeout:

File “/opt/nexaphor4/tinkerforge/nexaphor-tf.py”, line 222, in on_mqtt_idout
brickletid = bricklet.get_identity()
File “/usr/local/lib/python3.9/dist-packages/tinkerforge/bricklet_industrial_digital_out_4.py”, line 223, in get_identity
return GetIdentity(*self.ipcon.send_request(self, BrickletIndustrialDigitalOut4.FUNCTION_GET_IDENTITY, (), ‘’, 33, ‘8s 8s c 3B 3B H’))
File “/usr/local/lib/python3.9/dist-packages/tinkerforge/ip_connection.py”, line 1314, in send_request
raise Error(Error.TIMEOUT, msg, suppress_context=True)
tinkerforge.ip_connection.Error: Did not receive response for function 255 in time (-1)

 

Die Stelle an der das aufgerufen wird im Code sieht so aus.

def on_mqtt_idout(bricklet, userdata, msg):                                   
                                   
    logging.debug("bugfix-id-identifier - msg.topic: '{}'".format(msg.topic))                                   
                                   
    # TODO: This is where things fail. So I could just add an exception around this                                   
    brickletid = bricklet.get_identity()                                   
    uid = brickletid[0]                  

 

Die Codestelle wird aufgerufen sobald die Steuerung eine MQTT Nachricht erhält dass es den Ausgang einen bestimmten Ausgang eines bestimmten Bricklets ein bzw. ausschalten soll.

Ich konnte einen Workaround bauen, der die Steuerung neustartet sobald es zu einem Timeout kommt. Das funktioniert meistens. Allerdings kann es auch passieren, dass sich der gesamte Kasten aufhängt. Sprich an den beiden verbauten Masterbricks leuchtet keine Lampe mehr, die Steuerung bekommt keine Ethernetconnection mehr und nur noch ein Reset bringt Abhilfe.

Nun bin ich am Rätseln woran das liegen könnte. In einem anderen Beitrag zum Thema Timeout hieß es, dass sowas passieren kann wenn das Bricklet benutzt wird bevor die Authentifizierung und Enummeriung abgeschlossen sind. Das kann ich, glaube ich ausschließen. Da das alles via Callbacks läuft ist die Reihenfolge zwar nicht 100% vorhersehbar, allerdings registrieren sich die Bricklets selbst am MQTT Brocker. Das passiert erst am Ende des Enummerate Callback. Insbesondere das sich der Masterbrick komplett aufhängt spricht wohl gegen ein Softwareproblem.

Im Health Monitor des BrickV sehe ich kein Problem - da stehen die Zähler immer auf Null:

Jetzt ist die Frage:

• Stimmt die Vermutung dass sich der Masterbrick bei einem reinen Softwareproblem nicht aufhängen würde?
• Wie bekomme ich raus welches Bricklet das Problem verursacht, oder ob es evtl. am Masterbrick selbst liegt.

 

[nbkr]

Ich habe den get_identity() Aufruf jetzt mal mit einem try/except Block umgeben. Auf diese Art und Weise finde ich vielleicht heraus welches Bricklet betroffen ist. Außerdem stürzt so die Software nicht mehr ab und die restlichen Funktionen können weiter genutzt werden.

    try:                               
        brickletid = bricklet.get_identity()        
    except:                                                                          
        logging.debug("bugfix-id-identifier - workaround-failed - msg.topic: '{}'".format(msg.topic))                            
        return 

 

[nbkr]

Ich denke ich habe den Fehler gefunden. Netzwerküberlast.

An der Steuerung hängt auch ein NFC Kartenleser. Die Implementierung die ich aus dem Beispielcode übernommen habe, sorgt dafür dass der Kartenleser ständig prüft ob eine Karte vorhanden ist. Falls nicht wird die Chipart gewechselt und es nochmal versucht. Das sorgt dafür dass ständig Datenpackete übermittelt wurden. Dadurch war die Netzwerkkarte des Raspberry Pis zu beschäftigt, so dass die Verbindung zu den anderen Bricklets in ein Timeout gelaufen ist.

Ich habs mit einem 'time.sleep(1)' gelöst. Außerdem zeigte sich dass die Bewegungsmelder im Flur ebenfalls zu oft Infos weitergeleitet haben. Auch das habe ich durch einen Anpassung in der Software gelöst. Der Code welcher auf die Bewegungsmelder reagiert, merkt sich nun den letzten Stand und leitet nur Daten weiter, wenn es wirklich etwas zu tun gibt. Ich hoffe das reicht erstmal.

[nbkr]

Tja, so schnell kann es gehen. Pustekuchen, heute früh ist wieder der ganze Kasten abgestürzt. Ich flash jetzt mal alle Bricklets durch und ggf. auch nochmal die beiden Masterbricks. Wenn das nicht hilft wird der ganze Kasten ausgetauscht.

[nbkr]

Also, ein flashen hat nichts gebracht. Ich habe jetzt mal den Stapel der Masterbricks umgebaut. Ich habe den obersten Master entfernt in der Hoffnung dass ich so den Fehler finde. Aber es scheint keiner der Master zu sein. Egal welchen ich verwende als 'Hauptmaster' es gibt immer das gleiche Problem. Evtl. liegt es also an einem der Bricklets oder an der Ethernet Extension - oder an etwas ganz anderem.

bearbeitet April 1, 2023 at 07:32 von nbkr

[nbkr]

Ich habe den brickv mal - versehentlich - mitlaufen lassen, als der Fehler aufgetreten ist. Da zeigt sich jetzt das hier:

Leider finde ich nirgends was mir 'Timeouts' sagen soll, bzw. wie ich die Fehlerursache damit finden kann.

[borg]

Mh, die Ethernet Extension hat nur eine feste Anzahl von Sockets die genutzt werden können. Kann es sein dass du irgendwie neue Verbindungen zur Ethernet Extension aufbaust und auf Dauer alle Sockets verwendet sind? Wenn dann der Neustart klappt sind wieder alle Sockets verfügbar.

[nbkr]

On 4/14/2023 at 12:15 PM, borg said:

Mh, die Ethernet Extension hat nur eine feste Anzahl von Sockets die genutzt werden können. Kann es sein dass du irgendwie neue Verbindungen zur Ethernet Extension aufbaust und auf Dauer alle Sockets verwendet sind? Wenn dann der Neustart klappt sind wieder alle Sockets verfügbar.

Danke für die Antwort.

Nein, ich baue (wissentlich) keine neuen Verbindungen auf. Ich nutze die Callback für Verbindungsaufbau-, Abbau und und Enumeration. In allen Methoden sind Logaufrufe eingebaut und die Logfiles zeigen keine zusätzlichen Einträge. Was auch noch dagegen spricht, ist dass es nur einen der beiden Schaltschrankgehäuse betrifft. Ich habe zwei davon und der zweite, welche ebenfalls zwei Master, 1x Ethernet und 8 Bricks (mehrere Industrial Digitial out und in, sowie ein Remote Switch), wird über den gleichen Code angesteuert und läuft ohne Probleme durch.

Auch hat es den Kasten in Frage zerrissen, als wir über das Osterwochenende verreist waren. Der Raspberry Pi auf dem die Steuerung läuft war abgeschaltet. Der einzig andere Rechner auf dem die Software prinzipiell installiert ist, war mein Notebook und das war mit auf Reisen. Trotzdem waren an dem Kasten alle Lichter aus als wir wieder heim kamen.

Ich konnte das Problem etwas reduzieren in dem ich schlichtweg die 'get_identity()' Funktion nicht mehr benutze. Ich hatte darüber die UID des Bricklets abgefragt, aber ich kann die Information auch anhand des MQTT Topics bestimmen welcher die Nachricht zum Schalten des Industrial Out Bricklets liefert.

Danach trat das Problem deutlich seltener auf, war aber nicht vollständig weg. Auch hat sich die Art des Problems etwas geändert. Mit get_identity wurde die Steuerung nach und nach träger. Knöpfe reagierten langsamer. Die Lichtsteuerung war verzögert und somit unbenutzbar, aber ging prinzipiell noch. Ohne get_identity läuft es lange Zeit (ca. einen Tag) einwandfrei nur um dann auf einmal gar nicht mehr zu funktionieren. Dass ist dann der Zeitpunkt an dem ich an den Kasten muss um die Reset Taste zu drücken.

Inzwischen vermute ich dass es an einem der Industrial Out Bricklets liegt. Durch das umbauen und testen der Masterbricks konnte ich es auf 4 Bricklets eingrenzen. Der Preis von 4 Bricklets liegt inzwischen unterhalb der Schmerzgrenze den mir das Projekt bisher verursacht hat. Also habe ich beschlossen 4 neue Bricklets zu bestellen und die fraglichen aus zu tauschen, als das Problem durch weiteres Hardware-Gefummel weiter einzugrenzen.

[borg]

Sehr mysteriös irgendwie. Ich weiß nicht welche Art von Hardwaredefekt dazu führen könnte das es zu diesem "langsamen Absturz" kommt wenn man get_identity aufruft. Sag auf jeden Fall Bescheid ob der Tausch der Hardware etwas bringt. Wir können dir das dann natürlich auch rückerstatten wenn ein Hardwaredefekt vorliegt (und es wäre schön wenn du die defekte Hardware dann zurückschicken könntest, damit wir uns das anschauen können).

[nbkr]

So, ich habe die 4 Bricklets gegen IndustrialDigitalOutV2 getauscht. Mal sehen ob das den Fehler behoben hat.

[nbkr]

Fehler trat wieder auf. Ich habe jetzt die Ethernet Extension ausgetauscht. Mal schauen.

[nbkr]

Der Fehler noch da, aber immerhin anders. Nachdem ich die Ethernet Extension getauscht habe lief bis vor wenigen Minuten ohne Probleme durch. Dann ging wieder nichts mehr. Ich bin zum Schaltschrank und zu meiner Überraschung war noch Licht im Kasten. Die Master Bricks leuchteten noch - aber per Netzwerk war nichts mehr zu erreichen. Nach einen Reset ging es wieder. Ich habe mal das Log durchsucht. Ich hatte bei einer IPConError Exception einen automatischen Restart des Scriptes eingebaut. Die entsprechende Exception ist jetzt mehrmals geflogen. Hier error.value und error.description.

[22:46:30] root haus-blau:/var/log/supervisor # grep -i IPConError nexaphor-tf-stderr---supervisor-40jdmbvp.log 
2023-05-27 10:46:53,465|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 10:50:07,971|DEBUG|IPConError - value: '-1' - description: 'Did not receive response for function 2 in time'
2023-05-27 21:27:03,433|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 21:35:19,897|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 21:37:37,740|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 21:41:25,193|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 22:22:28,709|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-27 22:39:40,030|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-28 21:26:12,385|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-29 02:19:46,595|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-29 11:29:50,244|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-29 22:42:11,411|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-30 21:26:33,278|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-30 23:00:50,742|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-30 23:23:30,247|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'
2023-05-31 19:14:25,974|DEBUG|IPConError - value: '-8' - description: 'Not connected'
2023-05-31 22:37:07,337|DEBUG|IPConError - value: '-16' - description: 'Device has been replaced'

In der ip_connection.py habe ich den 'Device has been replaced' Fehlertext gefunden. Allerdings bin ich noch nicht dahinter gekommen was das bedeutet. Die Exception wird geworfen wenn 'self.replaced == True'. Gesetzt wird replaced auf True in der add_device Methode der IPConnection Klasse. Das hat wohl was mit parallelen Threads zu tun, allerdings komme ich heute Abend da nicht mehr dahinter. Ich schau's mir morgen wieder an.

[nbkr]

Ok, ich bin ein wenig weiter. Die Fehlermeldung 'Device has been replaced' wird in der 'check_validity' Methode der Device Klasse aufgerufen.

Die ip_connection Klasse hat ein Dict an devices. Diese Map wird benutzt um eingehende Packages an das Device Objet weiter zu leiten.

Jedes Bricklet ist ein Device und registriert sich bei der ip_connection und wird dort unter seiner UID in die Liste eingetragen. Wenn sich ein zweites Device mit der gleichen UID registiert, wird das vorhandene Device ersetzt und fliegt aus der Liste. Es kann dann keine Nachrichten mehr bekommen. Wenn ein solches Device dann irgendwas tun soll prüft es ob es ersetzt wurde. Wenn das der Fall ist, wird eine Exception geworfen. Diese Exception wird dann von meinem Code abgefangen und mit einem Restart des Scripts behandelt.

Aus irgendeinem Grund werden jetzt also meine Devices ersetzt. Warum weiß ich noch nicht genau, ich vermute das ist eine Race Condition.

[nbkr]

Wieder einen kleinen Schritt weiter - und zum ersten Mal habe ich einen wirklichen Ansatzpunkt. Ich habe den try/except block um die set_value und get_value Funktionen gesetzt und konnte damit sehen dass beide Funktionen immer mal wieder nicht greifen. Die zugehörigen Lampen und Rollläden schalteten aber. Das hat mich darauf gebracht mir die MQTT Anbindung nochmal anzusehen und dabei ist mir aufgefallen, dass ich die gleiche Nachricht stellenweise bis zu 5 Mal bekomme. Mit nur wenigen Millisekunden Abstand. Mein Code reicht dass dann an die Bricklets weiter, was die wohl schlicht überfordert hat bzw. sich das in den verschiedenen Threads verheddert hat.

Ich habe entsprechend im MQTT das 'clean_session' nochmal explizit auf True gesetzt, und den Clients permanente IDs vergeben, sowie einen ordentlichen 'disconnect' der MQTT Verbindung eingebaut. Jetzt heißt es wieder warten ob das Problem nochmal kommt.

[nbkr]

Seit dem letzten Post habe ich raus gefunden warum die Nachrichten doppelt kommen. Das liegt nicht am MQTT, sondern am neu verbinden. Mein Code hat den Auto Reconnect auf True, d.h. jedesmal wenn die Verbindung zum Masterbrick verloren geht, wird sie neu aufgebaut und neu 'enumeriert'. Die Objekte der Bricklets waren in einer Liste gespeichert. Bei jedem neu verbinden wurde die Liste eins länger. Wenn eine MQTT Message ankam wurde das über die Liste an die passenden Brickletobjekte weitergegeben. Die vorherigen haben natürlich keine Verbindung mehr zur IPConnection und somit kommt es zu dem 'replaced' Fehler. Das konnte ich beheben in dem ich die alten Objekte in der Liste ersetzt habe anstatt die neuen anzufügen.

Jetzt bleibt die Frage warum es immer wieder zu Neuverbindungen kommt. Ich hatte bisher nur einen Logeintrag wenn bei DISCONNECT_REASON_ERROR. Das habe ich erweitert und es zeigt sich das vor jeder Enumerierung ein 'DISCONNECT_REASON_SHUTDOWN' geliefert wird. Im ip_connection.py Code wird das ausgelöst wenn im receive_loop leere Daten geliefert werden. Warum das passiert konnte ich noch nicht erkennen.

[nbkr]

Ich habe jetzt die Masterbricks und die noch verbleibenden Digitial Out Bricks getauscht. Die Steuerung läuft seit 5 Tagen ohne das de Fehler nochmal aufgetreten ist. Ich gehe mal davon aus dass es das jetzt war - auch wenn ich nicht rausbekommen habe, was das genaue Problem war.