Driver timed out trying to send

[misa]

Hallo

Leider bekomme ich immer mal Zwischendurch einen "Driver timed out trying to send" Fehler mit folgenden Logeinträgen:

Sep 27 09:53:46 raspberrypi knxd[30591]: E00000055: [16:B.tpuarts] Driver timed out trying to send (B.tpuarts)
Sep 27 09:53:46 raspberrypi knxd[30591]: E00000000: [18:B.tpuarts] send timeout: too many retries
Sep 27 09:53:53 raspberrypi knxd[30591]: F00000000: [16:B.tpuarts] Link down, terminating
Sep 27 09:53:53 raspberrypi systemd[1]: [B]knxd.service: main process exited, code=exited, status=1/FAILURE[/B]
Sep 27 09:53:53 raspberrypi systemd[1]: [B]Unit knxd.service entered failed state.[/B]
Sep 27 09:54:03 raspberrypi systemd[1]: knxd.service holdoff time over, scheduling restart.
Sep 27 09:54:03 raspberrypi systemd[1]: Stopping KNX Daemon...
Sep 27 09:54:03 raspberrypi systemd[1]: Starting KNX Daemon...
Sep 27 09:54:03 raspberrypi systemd[1]: Started KNX Daemon.

Der Service startet dann neu. Ich kann den Fehler leider nicht reproduzieren. Ich dachte erst, es sei ein Timing Problem, wenn ggf. viele Nachrichten am Stück gesendet werden. Habe dann --send-delay=100 gesetzt. Ohne Besserung. Ich habe dann ein paar Lasttests gemacht, aber da lief alles stabil.

Mein Konfig ist (nach wie vor) wie folgt:
Raspberry Pi3, mit TULE von Busware im und Transparent TUPART FW.

Der PI dient auch als KNX Router und parallel läuft darauf OpenHAB.

dazu folgende knxd Konfiguration / Status:

[B][19:43:27] [/B][B]pi@raspberrypi[/B]:[B]~[/B]$ sudo systemctl status knxd.service
[B]●[/B] knxd.service - KNX Daemon
   Loaded: loaded (/lib/systemd/system/knxd.service; enabled)
   Active: [B]active (running)[/B] since Wed 2017-09-27 09:54:03 CEST; 10h ago
 Main PID: 18141 (knxd)
   CGroup: /system.slice/knxd.service
           └─18141 /usr/bin/knxd -e 15.15.1 -E 15.15.2:8 --send-delay=100 -T -R -A multi-port=true -S -A retry-delay=1 -A max-retry=2 -b tpuar...

Sep 27 09:54:03 raspberrypi systemd[1]: Starting KNX Daemon...
Sep 27 09:54:03 raspberrypi systemd[1]: Started KNX Daemon.

und

KNXD_OPTS="-e 15.15.1 -E 15.15.2:8 --send-delay=100 -T -R -A multi-port=true -S -A retry-delay=1 -A max-retry=2 -b tpuarts:/dev/ttyKNX1"

Soweit mal alles geschmeidig.

das Problem tritt ca. 2-3mal am Tag auf. Irgendwelche Ideen?

Anmerkung:

[B][20:02:23] [/B][B]pi@raspberrypi[/B]:[B]~[/B]$ knxd --version
knxd 0.14.18:ef3c496

[Smurf]

Hmm. Nachdem du bereits einen Retry drin hast, ist das ziemlich seltsam.
Bitte Debugging aktivieren: "-f9 -t1023 -B log" vor dem "-b tpuarts:…".

[SwenS]

Hallo zusammen,

ist das das gleiche Problem wie hier? "umstieg-von-eibd-nach-knxd"

Vielen Dank

Swen

[misa]

Hmm. Nachdem du bereits einen Retry drin hast, ist das ziemlich seltsam.
Bitte Debugging aktivieren: "-f9 -t1023 -B log" vor dem "-b tpuarts:…".

Melde mich nach den Herbstferien wieder....

[misa]

So, habe den Debug mal angeworfen. Mal sehen, was dabei herauskommt.

[misa]

Hi Smurf, hier das Ergebnis vom Debug Lauf:

Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22786.582] Recv(001): 00
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22786.582] Recv(001): 2B
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 1 [19:B.tpuarts/LowF      22786.582] RecvLP(011): BC FF FA 09 07 E3 00 80 00 00 2B
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22786.582] Recv L_Data low from 15.15.250 to 1/1/7 hops: 06 T_DATA_XXX_REQ A_GroupValue_Write 00 00
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 0 [18:log/B.tpuarts       22786.582] Recv L_Data low from 15.15.250 to 1/1/7 hops: 06 T_DATA_XXX_REQ A_GroupValue_Write 00 00
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 8 [16:B.tpuarts/Conn      22786.582] found addr 15.15.250
Oct 19 21:52:08 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22786.582] state: wait_more > wait
Oct 19 21:52:09 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22787.634] send timeout: retry
Oct 19 21:52:09 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22787.634] Send(022): 80 9C 81 00 82 01 83 09 84 07 85 D3 86 00 87 80 88 00 89 00 4A 1F
Oct 19 21:52:09 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22787.649] Recv(001): 47
Oct 19 21:52:09 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22787.649] State: 47
Oct 19 21:52:09 raspberrypi knxd[10223]: W00000063: [19:B.tpuarts] TPUART error state x47
Oct 19 21:52:09 raspberrypi knxd[10223]: W00000063: [19:B.tpuarts] TPUART state wait should not happen
Oct 19 21:52:11 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22789.636] send timeout: retry
Oct 19 21:52:11 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22789.636] Send(022): 80 9C 81 00 82 01 83 09 84 07 85 D3 86 00 87 80 88 00 89 00 4A 1F
Oct 19 21:52:11 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22789.650] Recv(001): 47
Oct 19 21:52:11 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22789.650] State: 47
Oct 19 21:52:11 raspberrypi knxd[10223]: W00000063: [19:B.tpuarts] TPUART error state x47
Oct 19 21:52:11 raspberrypi knxd[10223]: W00000063: [19:B.tpuarts] TPUART state wait should not happen
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.567] Recv(001): BC
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.569] Recv(001): FF
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22791.569] state: wait > wait_more
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.570] Recv(001): FA
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.571] Recv(001): 09
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.573] Recv(001): 07
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.573] Recv(001): E3
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22791.573] Known Addr 1/1/7: yes
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [19:B.tpuarts/LowF      22791.573] SendAck 11
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.573] Send(001): 11
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.575] Recv(001): 00
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.576] Recv(001): 80
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.578] Recv(001): 00
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.579] Recv(001): 00
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.581] Recv(001): 2B
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 1 [19:B.tpuarts/LowF      22791.581] RecvLP(011): BC FF FA 09 07 E3 00 80 00 00 2B
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22791.581] Recv L_Data low from 15.15.250 to 1/1/7 hops: 06 T_DATA_XXX_REQ A_GroupValue_Write 00 00
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [18:log/B.tpuarts       22791.581] Recv L_Data low from 15.15.250 to 1/1/7 hops: 06 T_DATA_XXX_REQ A_GroupValue_Write 00 00
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 8 [16:B.tpuarts/Conn      22791.581] found addr 15.15.250
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22791.581] state: wait_more > wait
Oct 19 21:52:13 raspberrypi knxd[10223]: E00000055: [16:B.tpuarts] Driver timed out trying to send (B.tpuarts)
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22791.629] up => down/error
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 4 [16:B.tpuarts/Conn      22791.629] up/error
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22791.629] Stopping
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [18:log/B.tpuarts       22791.629] State stop
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22791.629] Stop
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.629] Stop
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22791.629] Stopped
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22791.629] state: wait > new
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22791.629] Stopped
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 0 [18:log/B.tpuarts       22791.629] State stopped
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22791.629] up/error => down
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22791.629] retry in 1 sec
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 4 [16:B.tpuarts/Conn      22791.629] is error/retry
Oct 19 21:52:13 raspberrypi knxd[10223]: E00000000: [19:B.tpuarts] send timeout: too many retries
Oct 19 21:52:13 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22791.636] state: new > error
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22792.630] error/retry => >up
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 5 [16:B.tpuarts/Conn      22792.630] Starting
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [18:log/B.tpuarts       22792.630] State start
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [20:B.tpuarts/log       22792.630] Start
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22792.630] Start
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [21:B.tpuarts/TPU_ser   22792.631] Opened /dev/ttyKNX1 with baud 19200
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 2 [21:B.tpuarts/TPU_ser   22792.631] Opened
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 2 [21:B.tpuarts/TPU_ser   22792.631] Buffer Setup on fd 6
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22792.631] Started
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22792.631] state: error > new
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 8 [19:B.tpuarts/LowF      22792.632] state: new > start
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [19:B.tpuarts/LowF      22792.632] SendReset 01
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [22:B.tpuarts/log       22792.632] Send(001): 01
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 4 [16:B.tpuarts/Conn      22792.632] >up
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 4 [16:B.tpuarts/Conn      22792.632] is >up
Oct 19 21:52:14 raspberrypi knxd[10223]: Layer 0 [19:B.tpuarts/LowF      22793.131] SendReset 01

Und hier der Link auf den vollständigen Pastebin : https://pastebin.com/EUv5jq4Q.

Hier noch eine zweite Stelle: https://pastebin.com/yJsNPpii

[misa]

Frage: was genau macht der pace Filter?

[Smurf]

Er stellt sicher, dass nach einem gesendeten Datenpaket mindestens n Millisekunden verstreichen, bevor das nächste gesendet wird.
"n" kann man einstellen; die Verzögerung hängt außerdem von der Paketlänge und den ankommenden Daten ab – KNX ist ja ein shared medium.

[misa]

OK, danke. Ggf. kommt es nur beim schnellen Senden vor. Ich habe mal einen --arg=delay=50 -B pace mit in die Ops mit aufgenommen.

>>>>>> Hat allerdings keinen Impact.

[misa]

Habe mal den Upgrade auf knxd 0.14.19-2 gemacht. ggf. hilft es :-D

[misa]

Ich hab zudem etwas im Programm-Code geschaut: knxd/src/backend/tpuart.cpp

Dort findet sich ein auskommentierter Bereich ab Zeile 473:

// if (c == 0x47)
//   {
//     ERRORPRINTF (t, E_ERROR | 62, "TPUART detected. Hardware ACK not supported.");
//     my_addr = 0;
//   }

und später auch die Fehlermeldung:

default:
ERRORPRINTF (t, E_WARNING | 63, "TPUART state %s should not happen", SN(state));
break;

Das scheint wohl irgendetwas mit dem Aknowledgement zu tun zu haben. Habe da ich das State-Modell von TPUART nicht kenne, fällt es mir schwer hier zu helfen.

[misa]

Gibts nicht irgendeine Idee wegen dem 0x47 TPUART Status?
Zudem erhalte ich beim Re-Start dann folgende Fehlermeldung: F00000051: [20:router] internal error: send_more is not set
Sachdienliche Hinweise zum Beheben werden sehr geschätzt.

[hubidoo]

Habe dasselbe Problem. Habe dazu einen Bug eröffnet: https://github.com/knxd/knxd/issues/297
In meiner Konstellation stirbt der knxd sofort, sobald man versucht, auf den Bus zu schreiben.
Ich verwende das IBBCape von Robert auf einem BBB.
Der knxd in der Version 0.11.18 läuft darauf problemlos, die aktuelle Version 0.14.19-2 läuft nicht.

[misa]

<deleted>

[misa]

Habe jetzt einen Downgrade auf 0.11.18 gemacht. Interessant ist, dass alle meine Probleme verschwunden sind.

Mein Options haben sich reduziert auf -e 15.15.1 -D -T -R -S -b tpuarts:/dev/ttyKNX1

Ich werde das mal über die nächsten Tage beobachten.