Jump to content

Masterbrick hängt sich nach Timeout auf.


nbkr

Recommended Posts

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:

image.thumb.png.4ddec5913611bbe9168d373a3a88d7fe.png

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.

 

Link to comment
Share on other sites

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 

 

Link to comment
Share on other sites

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.

Link to comment
Share on other sites

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.

Edited by nbkr
Link to comment
Share on other sites

  • 2 weeks later...
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.

Link to comment
Share on other sites

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).

Link to comment
Share on other sites

  • 1 month later...
  • 2 weeks later...

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.

Link to comment
Share on other sites

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.

Link to comment
Share on other sites

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.

Link to comment
Share on other sites

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.

Link to comment
Share on other sites

  • 2 months later...

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.

×
×
  • Create New...