ip_connection.py: struct.error: unpack requires a buffer of 1 Bytes

[Justus]

Ich lasse testweise ein condition monitoring (Python 3.7) laufen.
Sporadisch, aber immerhin fast täglich gibt es folgende Fehlermeldung:

Zitat

Exception in thread Brickd-Receiver:
Traceback (most recent call last):
  File "C:\Users\f_opscon\AppData\Local\Programs\Python\Python37-32\lib\threading.py", line 926, in _bootstrap_inner
    self.run()
  File "C:\Users\f_opscon\AppData\Local\Programs\Python\Python37-32\lib\threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "C:\Users\f_opscon\AppData\Local\Programs\Python\Python37-32\lib\site-packages\tinkerforge\ip_connection.py", line 978, in receive_loop
    self.handle_response(packet)
  File "C:\Users\f_opscon\AppData\Local\Programs\Python\Python37-32\lib\site-packages\tinkerforge\ip_connection.py", line 1253, in handle_response
    function_id = get_function_id_from_data(packet)
  File "C:\Users\f_opscon\AppData\Local\Programs\Python\Python37-32\lib\site-packages\tinkerforge\ip_connection.py", line 32, in get_function_id_from_data
    return struct.unpack('<B', data[5:6])[0]
struct.error: unpack requires a buffer of 1 Bytes

Ohne hier selbst tiefer einsteigen zu wollen: was kann ich tun, um den Fehler zu vermeiden bzw. zu beheben?
Danke für Input jeder Art.

[photron]

Was für Bricks und Bricklets verwendest du?

[Justus]

Accelerometer Bricklet 2.0, Air Quality Bricklet an Master Brick 2.1,
Kommunikation und PoE via Ethernet Master Extension (mit PoE)

[photron]

Der Fehler kommt von einem kaputten Paket. Die IP Connection versucht da ein Paket zu dekodieren, das einen falschen Wert im Längenfeld stehen hat. Das sollte eigentlich nicht passieren können.

Ich habe dir eine modifizierte IP Connection angehängt. Diese speichert die letzten 1000 byte empfangene Daten zwischen und gibt diese auf die Standardausgabe aus, wenn der Fehler auftritt.

Nutze bitte diese IP Connection in deinem Programm, erzeuge das Problem nochmal und poste die Ausgabe hier. Das wird dann etwa so aussehen, nur länger:

EXCEPTION 1574431120.7630146 b'1p\xb6\xc0"\xfd\x08\x005VGUhR\x00\x000\x00\x00\x00\x00\x00\x00\x000\x02\x01\x00\x02\x04\n\r\x00\x00'

Daraus sollte ich dann genauer ableiten könne was das Problem erzeugt.

ip_connection.py

[Justus]

Ich erhalte folgende Ausgabe:

EXCEPTION 1574731237.858008 b'\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\xc9\x04\x00\x00\x13)\x00\x00\xbe\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00g\x04\x00\x005)\x00\x00i\xfe\xff\xff
\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00V\x04\x00\x00\x1c)\x00\x00f\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\xdd\x04\x00\x0
02)\x00\x00|\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00-\x04\x00\x00F)\x00\x00a\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x
08\x00\x9b\x04\x00\x00\x04)\x00\x00\x90\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00t\x04\x00\x00\x1f)\x00\x00Z\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x
87\x01\x00(+\x02\x00\x14\x08\x08\x00\xe4\x04\x00\x00))\x00\x00P\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00[\x04\x00\x00!)\x00\x00\xb7\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x
00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\x9d\x04\x00\x00\x1f)\x00\x00$\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\x96\x04\x00\x00\x13)\x00\x00\x8d\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\
xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00@\x04\x00\x00\xff(\x00\x00\xb2\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\xfa\x04\x00\x00\xfa(\x00\x00\xa3\xfe\xff\
xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\x96\x04\x00\x00\x1c)\x00\x00w\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00g\x04\x00
\x00\x13)\x00\x00D\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00O\x04\x00\x00\xfa(\x00\x00z\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\
x14\x08\x08\x00j\x04\x00\x00\xf3(\x00\x00\x9a\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00[\x04\x00\x00\x06)\x00\x00_\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00
\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\x80\x04\x00\x00\x06)\x00\x00\x89\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00\xa4\x04\x00\x00$)\x00\x00\xa3\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x0
3\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00&\x04\x00\x00!)\x00\x00k\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00(+\x02\x00\x14\x08\x08\x00v\x04\x00\x00+)\x00\x00]\xfe\xff\xff\xd4,\x02\x00\x19\x06\x08\x00\
xb4\x00\x00\x00\x03\xd4\x04\x00\x00\xc6\x17\x00\x00\xad\x87\x01\x00'

 

[photron]

Die ersten 10 Byte sind kein vollständiges Paket, das ist erwartet, da ich einfach die letzten 1000 Bytes ausgeben, ohne auf Paketgrenzen zu achten.

Wenn ich die ersten 10 Byte weglasse, dann dekodieren die restlichen Daten sauber zu 44 Callbacks, jeweils abwechselnd der Accelerometer Bricklet 2.0 Acceleration Callback und der Air Quality Bricklet All Values Callback. Die ersten weggelassenen 10 Byte sehen aus wie die letzten 10 Bytes eines der All Values Callbacks. Sprich, ich sehen aus den Daten nicht warum der Fehler auftritt.

Wenn ich die ersten 11 Byte weglasse, dann tritt der Fehler im dritten Paket auf. Das ergibt aber wenig Sinn, denn damit das wirklich so aufgetreten sein könnte, müssen die restlichen Daten, die 42 Pakete ergeben, bei der IP Connection in einem Socket Receive Aufruf angekommen sein. Das ist nicht unmöglich, aber doch sehr unwahrscheinlich.

Ich kann aus den Daten leider so nicht sehen was da wirklich los ist, sorry.

Hier eine IP Connection die beim Auftreten des Problems alles ausgibt was an Daten da ist. Damit bitte nochmal das Problem erzeugen. Die Ausgabe ist deutlich umfangreicher und sieht in etwa so aus:

--------- BEGIN ---------
timestamp: 106665.961430398
exception:
  Traceback (most recent call last):
    File "/home/matthias/tf/dev/brickv/src/brickv/bindings/ip_connection.py", line 992, in receive_loop
      raise Exception('a')
  Exception: a
data_counter: 19
data_history: [
  (0, 106663.574052653, 68, b' %\xf6\xc8"\xfd\x08\x0068WcDS\x00\x000\x00\x00\x00\x00\x00\x00\x000\x02\x01\x00\x02\x04\x04\r\x00\x00\x90>J\xbd"\xfd\x08\x005QCAEd\x00\x0068WcDS\x00\x00a\x01\x01\x00\x02\x00\x02\x1b\x00\x00'),
  (1, 106663.574205742, 68, b'\xd6z\x00\x00"\xfd\x08\x00amb\x00\x00\x00\x00\x0068WcDS\x00\x00b\x01\x01\x00\x02\x00\x03\x15\x00\x00\xe2\x90\x01\x00"\xfd\x08\x00wvq\x00\x00\x00\x00\x0068WcDS\x00\x00c\x01\x00\x00\x02\x00\x02\xdd\x00\x00'),
  (2, 106663.574246151, 34, b'i\xe1&""\xfd\x08\x00SCD32\x00\x00\x0068WcDS\x00\x00d\x01\x02\x00\x02\x00\x06\xd4\x00\x00'),
  (3, 106663.579172704, 9, b' %\xf6\xc8\t\x058\x00\x00'),
  (4, 106663.580263621, 9, b' %\xf6\xc8\t\x12H\x00\x00'),
  (5, 106663.580755935, 9, b' %\xf6\xc8\t\x1aX\x00\x00'),
  (6, 106663.581016582, 9, b' %\xf6\xc8\tAh\x00\x00'),
  (7, 106663.581347659, 9, b' %\xf6\xc8\tNx\x00\x00'),
  (8, 106663.581620615, 9, b' %\xf6\xc8\tM\x88\x00\x01'),
  (9, 106663.604665966, 16, b'i\xe1&"\x10\x0c\x98\x00\xaa\xaa\xaa\xaa\xaa\xaa\xaa\xaa'),
  (10, 106665.059943865, 10, b'\x90>J\xbd\n\x01\xa8\x00e\x01'),
  (11, 106665.160133984, 10, b'\x90>J\xbd\n\x01\xb8\x00d\x01'),
  (12, 106665.260356932, 10, b'\x90>J\xbd\n\x01\xc8\x00d\x01'),
  (13, 106665.360479232, 10, b'\x90>J\xbd\n\x01\xd8\x00e\x01'),
  (14, 106665.460632221, 10, b'\x90>J\xbd\n\x01\xe8\x00e\x01'),
  (15, 106665.56087381, 10, b'\x90>J\xbd\n\x01\xf8\x00e\x01'),
  (16, 106665.661021859, 10, b'\x90>J\xbd\n\x01\x18\x00d\x01'),
  (17, 106665.76111894, 10, b'\x90>J\xbd\n\x01(\x00e\x01'),
  (18, 106665.861319748, 10, b'\x90>J\xbd\n\x018\x00e\x01'),
  (19, 106665.961430398, 10, b'\x90>J\xbd\n\x01H\x00e\x01'),
]
packet_history: [
  (0, 0, 106663.574052653, 34, 34, b' %\xf6\xc8"\xfd\x08\x0068WcDS\x00\x000\x00\x00\x00\x00\x00\x00\x000\x02\x01\x00\x02\x04\x04\r\x00\x00', b'\x90>J\xbd"\xfd\x08\x005QCAEd\x00\x0068WcDS\x00\x00a\x01\x01\x00\x02\x00\x02\x1b\x00\x00'),
  (0, 1, 106663.574052653, 34, 34, b'\x90>J\xbd"\xfd\x08\x005QCAEd\x00\x0068WcDS\x00\x00a\x01\x01\x00\x02\x00\x02\x1b\x00\x00', b''),
  (1, 2, 106663.574205742, 34, 34, b'\xd6z\x00\x00"\xfd\x08\x00amb\x00\x00\x00\x00\x0068WcDS\x00\x00b\x01\x01\x00\x02\x00\x03\x15\x00\x00', b'\xe2\x90\x01\x00"\xfd\x08\x00wvq\x00\x00\x00\x00\x0068WcDS\x00\x00c\x01\x00\x00\x02\x00\x02\xdd\x00\x00'),
  (1, 3, 106663.574205742, 34, 34, b'\xe2\x90\x01\x00"\xfd\x08\x00wvq\x00\x00\x00\x00\x0068WcDS\x00\x00c\x01\x00\x00\x02\x00\x02\xdd\x00\x00', b''),
  (2, 4, 106663.574246151, 34, 34, b'i\xe1&""\xfd\x08\x00SCD32\x00\x00\x0068WcDS\x00\x00d\x01\x02\x00\x02\x00\x06\xd4\x00\x00', b''),
  (3, 5, 106663.579172704, 9, 9, b' %\xf6\xc8\t\x058\x00\x00', b''),
  (4, 6, 106663.580263621, 9, 9, b' %\xf6\xc8\t\x12H\x00\x00', b''),
  (5, 7, 106663.580755935, 9, 9, b' %\xf6\xc8\t\x1aX\x00\x00', b''),
  (6, 8, 106663.581016582, 9, 9, b' %\xf6\xc8\tAh\x00\x00', b''),
  (7, 9, 106663.581347659, 9, 9, b' %\xf6\xc8\tNx\x00\x00', b''),
  (8, 10, 106663.581620615, 9, 9, b' %\xf6\xc8\tM\x88\x00\x01', b''),
  (9, 11, 106663.604665966, 16, 16, b'i\xe1&"\x10\x0c\x98\x00\xaa\xaa\xaa\xaa\xaa\xaa\xaa\xaa', b''),
  (10, 12, 106665.059943865, 10, 10, b'\x90>J\xbd\n\x01\xa8\x00e\x01', b''),
  (11, 13, 106665.160133984, 10, 10, b'\x90>J\xbd\n\x01\xb8\x00d\x01', b''),
  (12, 14, 106665.260356932, 10, 10, b'\x90>J\xbd\n\x01\xc8\x00d\x01', b''),
  (13, 15, 106665.360479232, 10, 10, b'\x90>J\xbd\n\x01\xd8\x00e\x01', b''),
  (14, 16, 106665.460632221, 10, 10, b'\x90>J\xbd\n\x01\xe8\x00e\x01', b''),
  (15, 17, 106665.56087381, 10, 10, b'\x90>J\xbd\n\x01\xf8\x00e\x01', b''),
  (16, 18, 106665.661021859, 10, 10, b'\x90>J\xbd\n\x01\x18\x00d\x01', b''),
  (17, 19, 106665.76111894, 10, 10, b'\x90>J\xbd\n\x01(\x00e\x01', b''),
  (18, 20, 106665.861319748, 10, 10, b'\x90>J\xbd\n\x018\x00e\x01', b''),
]
packet_counter: 21
packet: 10 10 b'\x90>J\xbd\n\x01H\x00e\x01'
pending_data: 0 b''
---------- END ----------

 

ip_connection.py

[Justus]

Die Standardausgabe (CMD Fenster) hat die ersten Zeilen abgeschnitten.
Angehängt, was ich dennoch als Ausgabe erhalte. Vielleicht ist daraus etwas ersichtlich.

Ich leite ab heute die Ausgabe in ein txt um. Kann ich erst später posten.

Vielleicht hilft noch zu wissen: Master Brick und Bricklet Sensoren sind physisch via langem Patchkabel, Switch, Kupfer auf LWL, LWL auf Kupfer, Switch und wieder langem Patchkabel angebunden. Ich könnte mir vorstellen, dass Pakete durch irgendein regelmäßiges, tägliches Ereignis in dieser Kette abgeschnitten werden?

Justus.txt

[photron]

Ich muss mir die Ausgabe noch genauer ansehen, was aber schon auf den ersten Blick auffällt ist, dass die pending_data 6645 Byte lang sind. Es scheint doch zu passieren, was ich für unwahrscheinlich hielt.

The Receive Thread ließt eingehende Daten vom Socket und sammelt die in pending_data auf. Nach jedem Empfangen wird dann geprüft , ob genug Daten da sind um daraus ein Paket zu dekodieren. Die absolute maximale Paketlänge ist 80 Byte.

Damit sich 6645 Byte in pending_data aufstauen können, müssen die mehr oder weniger in einem Receive Aufruf ankommen. Das sollte erstmal kein Problem sein, die IP Connection kommt damit zurecht.

Das Problem hier ist, dass die IP Connection hier versucht ein Paket der Länge 0 zu dekodieren. Die minimale Länge ist aber 8 Byte. Das hat jetzt zwei mögliche Ursachen. Entweder schickt eines der Bricklets ein Paket mit falschen Wert im Längenfeld, das führt zu einem Offset in der Dekodieren der IP Connection die dann ultimativ die Daten falsch versteht. Oder beim Ethernet Transport gehen Daten verloren oder werden verfälscht, was zum gleichen Ergebnis führt.

Hilfreich wäre es einen vollständigen Dump zu haben.

[Justus]

Ich muss die Fehlerausgabe im Laufe des heutigen Tages abwarten.
Poste das Ergebnis dann.
Ich vermute nach deinen Ausführungen aber eben genau das: Datenpakete werden abgeschnitten oder gehen verloren.

bearbeitet November 28, 2019 at 10:23 von Justus

[Justus]

Folgendes ist vielleicht off topic, aber könnte auch mit fehlerhaften Paketen zu tun haben:
Das acceleration bricklet wird per callback abgefragt und liefert z. B. heute zwischendurch immer wieder Werte, die unplausibel, i. e. außerhalb des Wertebereichs sind.
Bsp.:
 

2019-11-28 05:59:31:      ! : ... - condition monitoring : state of ... changed to False : current values: 0.158 g, 1.08 g, 72410.692 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
2019-11-28 05:59:36:      ! : ... - condition monitoring : state of ... changed to True : current values: 0.134 g, 1.07 g, -0.025 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
...
2019-11-28 06:45:31:      ! : ... - condition monitoring : state of ... changed to False : current values: 14.212 g, 52.636 g, 0.112 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
2019-11-28 06:45:36:      ! : ... - condition monitoring : state of ... changed to True : current values: 0.144 g, 1.068 g, -0.022 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
...
2019-11-28 09:45:13:      ! : ... - condition monitoring : state of ... changed to False : current values: 14.212 g, 52.636 g, 0.118 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
2019-11-28 09:45:18:      ! : ... - condition monitoring : state of ... changed to True : current values: 0.14 g, 1.07 g, -0.025 g : benches from ini: [0.1, 1.45], [1.0, 2.95], [-0.05, 0.9]
...

 

[Justus]

Vollständiger dump anbei.

Justus2.txt

[photron]

In den Daten sehen ich Folgendes: Es kommen sehr häufig mehrere Pakete in einem Socket Read an (data_history, 3. Spalte ist die Paketlänge), bis dann dauerhaft 8192 Byte pro Socket Read ankommen mit längeren Pausen dazwischen. Die Kommunikation ist also sehr Burst-artig. Das ist unerwartet.

Die Exception kommt dann, weil da zwischen zwei Paketen 3 Byte extra stehen, die da nicht hingehören.

Zur Veranschaulichung: Es kommen abwechselnd zwei Callbacks an, A und B. In der ersten Zeile die normale Abfolge ABAB, alles vollständig, alles okay. In der zweiten Zeile der kaputte Fall. Erst kommt ein normales A an, gefolgt von den ersten 3 Byte eines B, das sind die 3 Byte die da nicht hingehören. Dann ein normales B, gefolgt von einem A bei dem die ersten 3 Byte fehlen, dann wieder ein normales B.

[           A           ][           B           ][           A           ][           B           ]
[           A           ][ B.. ][           B           ][      ..A       ][           B           ]

Die Frage ist jetzt wo diese Veränderung der Daten wegkommt. Ist es möglich den Master Brick über USB statt Ethernet anzuschließen, um zu testen ob das Problem durch die Ethernet Verbindung bzw die Ethernet Extension entsteht? Läuft auf allen Brick und Bricklets die aktuelle Firmware (Brick Viewer kann dir das sagen)?

[Justus]

USB am Brick in Benutzung ist physisch nicht möglich.

USB an Testbrick aufm Tisch wäre möglich.

Das und Firmware checke ich Mo. Vielen Dank bis hierher, melde mich dann wieder. Bis dann.

[Justus]

USB Tests sind unauffällig.
FW ist auch up to date.
Ich sehe das Problem in der netzwerktechnischen Anbindung. Da passiert irgendetwas mit den Paketen, was ich mit meiner Anwendung dann handlen muss.
Danke bis hierher. Ich denke, wir können hier schließen.

[Justus]

Update:
Ich nutze (blöderweise) mehrere IPConnection Objekte für die Sensoren mit den selben IPs, Ports, also z. B.
Sensor 1 an EthernetExt1 (IP1:Port1) -> extra IPConnection in Thread
Sensor 2 an EthernetExt2 (IP1:Port1) -> extra IPConnection in Thread
Sensor 2 an EthernetExt2 (IP2:Port1) -> extra IPConnection in Thread

Könnte das zu dem beschriebenen Problem führen?