"send_more is not set" im Log / openHAB als Quelle/Senke

[FoxWhiskey]

Hallo zusammen,

Ich betreibe den knxd als Router für openHAB2 und mir fallen seit geraumer Zeit regelmäßige Logbucheinträge im system-log auf, die mir keine Hinweise auf das Problem geben und somit auch nicht auf die Lösung! :-/

F00000051: [15:B.tpuarts] internal error: send_more is not set

Setup

• knxd 0.14.8
• RPI B, Debian 8
• Busware RPi-ROT Modul
• openHAB 2.3

Wie emfohlen habe ich den knxd mal im Debug-Mode laufen lassen:

knxd.conf:
KNXD_OPTS="-f9 -t1023 -e 0.0.1 -E 0.0.3:2 -c -n howard -T -S -B log -b tpuarts:/dev/ttyKNX1"

Damit erhalte ich folgendes Log (mehr im Pastebin)

Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [16:B.tpuarts/BusDriver 209.131] Read(008): BC 01 01 14 26 D2 00 80
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 20>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.131] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [16:B.tpuarts/BusDriver 209.135] Read(002): 00 23
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.135] ser state 21>21
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.135] state: wait_more > wait_more
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.135] ser state 21>20
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [16:B.tpuarts/BusDriver 209.135] state: wait_more > wait
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [12:server/Server      209.138] Recv(021): 06 10 04 20 00 15 04 01 18 00 11 00 BC E0 01 01 14 33 01 00 00
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [22:tunnel/0.0.3       209.138] TUNNEL_REQ
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [21:tunnel/ConnC       209.138] found addr 0.1.1
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 1 [12:server/Server      209.138] Send(004): 04 01 18 00
[COLOR=#FF0000]Jan 22 17:52:18 howard knxd[5860]: howard: F00000051: [15:B.tpuarts] internal error: send_more is not set[/COLOR]
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 6 [ 1:main               209.138] sending set
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 6 [ 1:main               209.138] OK
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 6 [ 2:main/L             209.138] OK L
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 1 [12:server/Server      209.138] Send(015): 04 01 22 00 2E 00 BC E0 01 01 14 33 01 00 00
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [12:server/Server      209.138] Send(010): 06 10 04 21 00 0A 04 01 18 00
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [16:B.tpuarts/BusDriver 209.138] Read(001): 8B
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 6 [17:log/B.tpuarts      209.139] send next
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 6 [ 1:main               209.139] send_more set
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [12:server/Server      209.139] Send(021): 06 10 04 20 00 15 04 01 22 00 2E 00 BC E0 01 01 14 33 01 00 00
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 0 [12:server/Server      209.139] Recv(010): 06 10 04 21 00 0A 04 01 22 00
Jan 22 17:52:18 howard knxd[5860]: howard: Layer 8 [22:tunnel/0.0.3       209.139] TUNNEL_ACK

Kann jemand aus dem Log lesen, was hier genau Sache ist?
Danke für's Durchschauen
-bernie

[Smurf]

"send_more is not set" ist ein nerviger interner Synchronisationsfehler, den ich bisher noch nicht gefunden habe. (Was hauptsächlich daran liegt, dass die Schnittmenge der Leute, die sich einigermaßen mit KNX und C++ auskennen, ausreichend übersichtlich ist. :-/ )

[ChrisPHL]

Hey Smurf,

ich bin gerade dabei neue Heizungsaktoren in Betrieb zu nehmen und scheiter am Programmieren der Geräte... ein wenig das Log vom knxd gewälzt und siehe da, er spuckt mir den selben blöden Fehler aus: "send_more is not set".
Nun bin ich im echten Leben Softwareentwickler, habe zwar mit C++ wenig Berührung aber das sollte angesichts der von dir zitierten Schnittmenge kein Grund sein, dem Fehler nicht einmal auf den Zahn zu fühlen.
Hast du Lust und Zeit, die Sache mal mit mir anzugehen?
Im Moment kann ich leider noch nix konkretes über die Reproduzierbarkeit des Fehlers sagen, allerdings geht er derweil auch nicht weg... :-/
Ich kann mit Hilfe von OpenHAB (RasPi3b mit TPUART) das Licht vom Handy aus ein- und ausschalten, bekomme sofort Feedback, wenn das Licht über den Taster geschaltet wird aber eine Programmierung der Geräte ist aktuell nicht möglich. :-(
Ergo: Der Leidensdruck ist hoch, wann können wir loslegen? ^^

Gruß
Christian

[Smurf]

Du kannst gerne loslegen …

Ich habe eben im master-Zweig ein paar Patches eingecheckt, die u.A. dokumentieren (sollen), was der Router da so tut. Was passiert: ein Paket kommt an via Router::recv_L_Data > RouterHigh::recv_L_Data > RouterLow::recv_L_Data, wird dort gepuffert, und dann in die umgekehrte Richung via ::send_L_Data wieder rausgeschickt. Router::send_L_Data prüft ob alle(!) Schnittstellen ein Paket abschicken können.

Die Invariante von ::send_L_Data() ist (im gesamten knxd-Code), dass es genau einmal aufgerufen werden darf; danach muss auf genau einen Aufruf von ::send_Next() gewartet werden, bevor das nächste Paket gesendet werden darf. Die Variablen Router::high_sending und Router::high_send_more sind ausschließlich dazu da, im Router diese Invariante zu überprüfen, und der obige fatale Fehler dokumentiert dass sie verletzt wurde. Das Paket, das die Meldung ausgelöst hat, wird dann nicht gesendet, sondern weggeschmissen.

Frag mich am besten via Email, wenn du noch weitere Info zum Code brauchst.