Select error

[jw9]

Hallo allerseits,

heute ist mir aufgefallen, dass beim shutdown von fhem des Öfteren folgende Fehlermeldung

Code Auswählen Erweitern


2022.04.24 12:06:15 2: DbLog LogDB - Last database write cycle due to shutdown ...
2022.04.24 12:06:15 2: DbLog LogDB - Last database write cycle done
2022.04.24 12:06:15 1: Server shutdown delayed due to LogDB for max 10 sec
2022.04.24 12:06:15 1: ERROR: Select error -1 (11), error count= 0
Select error -1 (11)

im logfile erscheint.

ein kurzer grep hat ergeben, dass diese Fehlermeldung nicht erst seit Kurzem auftritt, sondern schon seit ich fhem zu ersten mal installiert habe.

Hat das schon mal jemand anderes gesehen?

Hat jemand Tipps, wie ich die Ursache ausfindig machen könnte?

[ch.eick]

Hallo,
bitte ändere im ersten Post noch den Titel und ergänze DbLog, dann findet Heiko es besser
VG
  Christian

[DS_Starter]

Schon gefunden. 

Die Meldung

2022.04.24 12:06:15 1: ERROR: Select error -1 (11), error count= 0

Erzeuge ich nicht im DbLog.
Ich gehe davon aus, dass diese Meldung aus einem anderen Modul kommt.
Doch es gibt eine Schnittstelle die andere Module verwenden können. Aus dieser Schnittstelle kommt diese Meldung wahrscheinlich.
Mehr sieht man sicherlich wenn man das globale Attr stacktrace=1 setzt.

[jw9]

Die Stelle im Code scheint ja der main-loop in fhem.pl zu sein. Das ist die einzige Stelle, in der "Select error" vorkommt.

Was auch auffällt ist, dass der shutdown (mittels systemctl) eeewig (teilweise mehrere Minuten) dauert wenn der Select error auftritt. Wenn der Select-Error nicht auftritt, geht der shutdown relativ zügig.


Stacktrace hilft leider nicht wirklich weiter. Keinerlei zusätzliche Ausgabe.

[DS_Starter]

Die Stelle im Code scheint ja der main-loop in fhem.pl zu sein. Das ist die einzige Stelle, in der "Select error" vorkommt.

Nachdem ich auch mal in die fhem.pl geschaut habe, wirst du recht haben.
In fhem.pl die Zeile 739 findet man die Logausgabe.

Ich vermutete zuerst die Zeile 3446 in DbLog:

Code Auswählen Erweitern


Log3($name, 2, "DbLog $name - ERROR: $@");


Aber wenn man genau hinschaut, ist es erstens verbose 2 und außerdem schreibe ich wie bei meinen Modulen allgemein üblich das meldende Modul (DbLog) und das entsprechende Device vor die Meldung.

Deine Logausgabe hat etwas mit Filedeskriptoren zu tun.
DbLog hat m.M. nach damit nichts zu tun. Es erscheint nur so weil die Logausgaben halt davor zu sehen sind und suggerieren einen Zusammenhang.

[jw9]

Ich habe jetzt mal einige Debug-Outputs eingestreut:

Code Auswählen Erweitern


jw@vdr2:/opt/fhem# diff -u fhem.pl-orig fhem.pl|less
--- fhem.pl-orig        2022-04-24 14:20:56.095300692 +0200
+++ fhem.pl     2022-04-24 14:49:23.076154055 +0200
@@ -722,8 +722,21 @@
   $timeout = $readytimeout if(keys(%readyfnlist) &&
                               (!defined($timeout) || $timeout > $readytimeout));
   $timeout = 5 if $winService->{AsAService} && $timeout > 5;
+
+  Log 1, "select"
+      . "  rin:" . unpack ("b*", $rin)
+      . "  win:" . unpack ("b*", $win)
+      . "  ein:" . unpack ("b*", $ein)
+      . " tout:$timeout";
+
   $nfound = select($rout=$rin, $wout=$win, $eout=$ein, $timeout) if(!$nfound);

+  Log 1, "select"
+      . " rout:" . unpack ("b*", $rout)
+      . " wout:" . unpack ("b*", $wout)
+      . " eout:" . unpack ("b*", $eout)
+      . " $nfound $!";
+
   $winService->{serviceCheck}->() if($winService->{serviceCheck});
   if($gotSig) {
     CommandShutdown(undef, undef) if($gotSig eq "TERM");


und bekomme damit folgende Ausgabe:

Code Auswählen Erweitern


2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:  ein: tout:0.94339394569397
2022.04.24 14:39:34 1: select rout:000000000000000000000100 wout: eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:  ein: tout:0.943104028701782
2022.04.24 14:39:34 1: select rout:000000000000000000000100 wout: eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:  ein: tout:0.942698001861572
2022.04.24 14:39:34 1: select rout:000000000000000000000100 wout: eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:  ein: tout:0.942102909088135
2022.04.24 14:39:34 1: select rout:000000000000000000000100 wout: eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:  ein: tout:0.941812992095947
2022.04.24 14:39:34 1: select rout:000000000000000000000100 wout: eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111100  win:000000000000000010000000  ein: tout:0.501828908920288
2022.04.24 14:39:34 1: select rout:000001000000000000000100 wout:000000000000000010000000 eout: 3 Resource temporarily unavaila
2022.04.24 14:39:34 1: select  rin:000001111101000111111000  win:000000000000000010000000  ein: tout:0.500715970993042
2022.04.24 14:39:34 1: select rout:000000000000000000000000 wout:000000000000000010000000 eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111000  win:000000000000000010000000  ein: tout:0.500171899795532
2022.04.24 14:39:34 1: select rout:000000000000000000000000 wout:000000000000000010000000 eout: 1
2022.04.24 14:39:34 1: select  rin:000001111101000111111000  win:  ein: tout:0.499826908111572
2022.04.24 14:39:35 1: select rout:000000000000000000000000 wout: eout: 0
2022.04.24 14:39:35 1: select  rin:000001111101000111111000  win:  ein: tout:0.998795032501221
2022.04.24 14:39:35 1: select rout:000001000000000000000000 wout: eout: 1
2022.04.24 14:39:35 1: select  rin:000001111101000111111000  win:  ein: tout:0.89614200592041
2022.04.24 14:39:36 1: select rout:000000000000000000000000 wout: eout: 0
2022.04.24 14:39:36 1: select  rin:000001111101000111111000  win:  ein: tout:0.998442888259888
2022.04.24 14:39:36 1: select rout:000001000000000000000000 wout: eout: 1
2022.04.24 14:39:36 1: select  rin:000001111101000111111000  win:  ein: tout:0.901750087738037
2022.04.24 14:39:36 1: select rout:000001111101000111111000 wout: eout: -1 Interrupted system call
2022.04.24 14:39:36 2: DbLog LogDB - Last database write cycle due to shutdown ...
2022.04.24 14:39:36 2: DbLog LogDB - Last database write cycle done
2022.04.24 14:39:36 1: Server shutdown delayed due to LogDB for max 10 sec
2022.04.24 14:39:36 1: ERROR: Select error -1 (11), error count= 0


Was mir hierbei auffällt:

• der EBITS-Parameter von select() wird gar nicht genutzt. Somit bekommt fhem gar nicht mit, wenn ein filehandle auf Systemebene wegen eines Fehlers geschlossen wird. Somit verwendet fhem fröhlich diesen geschlossenen Filehandle weiter. Das wird dann erst deutlich später aufgrund der Prüfung auf BADF abgefangen, das geliefert wird wenn Operationen auf ein geschlossenes Handle erfolgen.. Den Kommentar an dieser Stelle "This is a programming error" halte ich schlicht für falsch. Der "programming error" ist, EBITS nicht zu verwenden.
  
• In der Fehlerbehandlung wird zwar versucht EINTR abzufangen, es drängelt sich aber DbLog davor. Wenn DbLog an dieser Stelle irgendwelche Calls in die C-Library macht (und das macht es: last database write), dann kann $! bereits verändert worden sein bevor die Prüfung auf EINTR erfolgt. Das geht natürlich gründlich in die Hose... Die Fehlerbehandlung sollte unmittelbar nach dem Aufruf von select() erfolgen.
  

[rudolfkoenig]

2022.04.24 12:06:15 1: ERROR: Select error -1 (11), error count= 0

11 ist EAGAIN, was bei read/write mit nicht blockierenden FDs bedeutet, dass der Aufruf blockieren wuerde.
Die Bedeutung dieses Fehlers bei select ist mAn fragwuerdig.
Aus https://stackoverflow.com/questions/4193043/select-on-a-pipe-in-blocking-mode-returns-eagain :
"If you are thinking that returning a silly non-error error code like that is kinda bad client interface design, you aren't the first."

Ich habe fhem.pl jetzt so angepasst, dass EAGAIN genauso wie EBADF behandelt wird, das heisst FHEM wird erst nach 3, direkt hintereinander auftretenden select-Fehler beendet, und nicht sofort. Wenn das nicht hilft, bitte melden.

der EBITS-Parameter von select() wird gar nicht genutzt. Somit bekommt fhem gar nicht mit, wenn ein filehandle auf Systemebene wegen eines Fehlers geschlossen wird.

Das ist eine steile These, und ich haette gerne Nachweise dafuer.
Das Schliessen eines FD wird sowohl ueber read_fds wie auch ueber write_fds gemeldet.
Interessanterweise hat die select Doku except_fds inzwischen nach error_fds umbenannt.
Mir ist immer noch die hier beschriebene except_fds Beschreibung bekannt:
https://stackoverflow.com/questions/1342712/nix-select-and-exceptfds-errorfds-semantics

Im FHEM Umfeld wird EXCEPT_FDS nur von RPI_GPIO fuer die Interrupt-Benachrichtigung eingesetzt.

[jw9]

11 ist EAGAIN, was bei read/write mit nicht blockierenden FDs bedeutet, dass der Aufruf blockieren wuerde.
Die Bedeutung dieses Fehlers bei select ist mAn fragwuerdig.

select() liefert aber NICHT EAGAIN! Das habe ich ja versucht im letzten Absatz meines vorigen Posts zu erläutern.

Wie Du an dem Log in meinem vorigen Post erkennen kannst:

Code Auswählen Erweitern


2022.04.24 14:39:36 1: select rout:000001111101000111111000 wout: eout: -1 Interrupted system call

liefert select() NICHT EAGAIN sondern EINTR. Fhem versucht zwar EINTR zu behandeln, aber erst NACHDEM DbLog den wahren Fehlercode von select() überschrieben hat.

Bitte lies nochmal aufmerksam den letzten Absatz meines obigen Posts: Bevor die Fehlerbehandlung von select() ausgeführt wird, drängelt sich DbLog vor. EAGAIN ist also nicht der Fehlercode von select() sondern der Fehlercode der DbLog-Operationen ("last database write", sowie auch in die Log-Datei schreiben, möglicherweise passiert da sogar noch mehr...). Der Fehlercode von select() kann(!) dabei verloren gehen!

$! spiegelt errno aus der C-Library wieder, und ist somit eine globale Variable. Prinzipiell kann jeder Aufruf in die C-Library $! überschreiben. Wenn nach dem select() und vor dem Abfragen von $! irgendwelcher Code ausgeführt wird, der potentiell Calls in die C-Library machen kann, dann ist das ein Fehler, weil der Fehlercode von select() dabei überschrieben wird und somit verloren geht.

Meiner Meinung nach sollte der Code-Block, der anfängt mit "if($nfound < 0) {" unmittelbar nach dem select() kommen.

Ich habe fhem.pl jetzt so angepasst, dass EAGAIN genauso wie EBADF behandelt wird, das heisst FHEM wird erst nach 3, direkt hintereinander auftretenden select-Fehler beendet, und nicht sofort. Wenn das nicht hilft, bitte melden.

Nur leider ist EAGAIN nicht das Problem hier, weil EAGAIN nicht von select() kommt sondern von den DbLog-Aktivitäten.

Make sure you fix the real bug... (SCNR)

[rudolfkoenig]

Bitte lies nochmal aufmerksam den letzten Absatz meines obigen Posts:

Habe ich gemacht, und ich sehe Deine Argumente.

Meiner Meinung nach sollte der Code-Block, der anfängt mit "if($nfound < 0) {" unmittelbar nach dem select() kommen.

Damit wird SIGTERM erst nach dem naechsten select ausgewertet, und das kann u.U. laenger dauern.
Ich habe stattdessen "my $err = int($!);" direkt nach dem select aufgerufen.

[jw9]

Damit wird SIGTERM erst nach dem naechsten select ausgewertet, und das kann u.U. laenger dauern.

Ist das ein Problem? Von welchen Zeiten reden wir hier?

Ich habe stattdessen "my $err = int($!);" direkt nach dem select aufgerufen.

Das geht natürlich auch. Eleganter fände ich, erkannte Fehler unmittelbar zu behandeln: das minimiert das Risiko über Folgefehler zu stolpern.

Danke!

[rudolfkoenig]

Ist das ein Problem? Von welchen Zeiten reden wir hier?

Haengt von den definierten Instanzen ab.
Ich kann was sinnvolles konfigurieren, wo es mehrere Stunden dauert

[jw9]

Haengt von den definierten Instanzen ab.
Ich kann was sinnvolles konfigurieren, wo es mehrere Stunden dauert

Echt?

Du machst mich neugierig...

Wir reden doch von dem Block (Zeilen 735..760), der die Fehlerbehandlung vornimmt? Das war ja der Block der meinem Vorschlag nach vorgezogen werden sollte. Eine Fehlerbehandlung die mehrere Stunden dauern kann macht mich ein wenig stutzig.

Im aktuellen Code (Zeilen 735..760) werden im Wesentlichen zwei Fälle behandelt:

• EBADF: wenn das Rauswerfen der entsprechenden FDs aus %selectlist mehrere Stunden dauert, dann ist doch was faul... Oh, und "etwas sinnvolles", was gezielt mit kaputten FDs arbeitet übersteigt auch ein wenig mein Vorstellungsvermögen. Dein Beispiel würde mich echt mal interessieren...
• EINTR: hier könnte das "next" in Zeile 737 tatsächlich dazu führen, dass über längere Zeit nicht nach den signals geschaut werden würde. Dazu müssten die signals aber so schnell kommen, dass jeder select-Aufruf abgebrochen wird, und das über Stunden: also allenfalls eine akademische Diskussion... Und wenn man es genau nimmt, dann könnte man EINTR als Aufforderung verstehen mal explizit nach den signals zu schauen anstatt einfach nur stupide die nächste Iteration anzuschubsen... Schliesslich ist EINTR genau das Ergebnis eines eintreffenden Signal...

Sorry, ich sehe hier nichts was die Behandlung der signals um mehr als einige dutzend Millisekunden verzögern würde...

So richtig überzeugend finde ich Deine Argumentationskette nicht. Kannst Du mal erläutern wie es zu so einer Situation kommen könnte?

Wenn wir gerade dabei sind: gibt es eine Erklärung für "$err==0" in Zeile 737? So richtig einleuchten tut mir das nicht: Soweit ich mich entsinne, spiegelt $! errno und die C-Library darf nur gültige Werte an errno zuweisen. Welcher Fehler hat den Wert 0? Wie kommt 0 in $! ? Sollte das tatsächlich auf perl-Ebene geschehen? Ich habe einen Verdacht: jemand ist beim Debuggen den Fall "$nfound<0 && $err==0" gestolpert und nicht erkannt, dass die Ursache darin liegt, dass DbLog (oder irgend ein anderes Modul) sich vorgedrängelt hat. Also kurzerhand $err==0 rein in die Abfrage und gut...

Mein Vorschlag wäre, das wie folgt abzuändern:

Code Auswählen Erweitern


--- fhem.pl-orig        2022-04-24 14:20:56.095300692 +0200
+++ fhem.pl     2022-04-26 01:12:36.255752061 +0200
@@ -723,19 +723,9 @@
                               (!defined($timeout) || $timeout > $readytimeout));
   $timeout = 5 if $winService->{AsAService} && $timeout > 5;
   $nfound = select($rout=$rin, $wout=$win, $eout=$ein, $timeout) if(!$nfound);
-
-  $winService->{serviceCheck}->() if($winService->{serviceCheck});
-  if($gotSig) {
-    CommandShutdown(undef, undef) if($gotSig eq "TERM");
-    CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
-    $attr{global}{verbose} = 5    if($gotSig eq "USR1");
-    $gotSig = undef;
-  }
+  my $err = int($!);

   if($nfound < 0) {
-    my $err = int($!);
-    next if($err==0 || $err==4); # 4==EINTR
-
     Log 1, "ERROR: Select error $nfound ($err), error count= $errcount";
     $errcount++;

@@ -759,6 +749,16 @@
     $errcount= 0;
   }

+  $winService->{serviceCheck}->() if($winService->{serviceCheck});
+  if($gotSig) {
+    CommandShutdown(undef, undef) if($gotSig eq "TERM");
+    CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
+    $attr{global}{verbose} = 5    if($gotSig eq "USR1");
+    $gotSig = undef;
+  }
+
+  next if($err==4); # 4==EINTR
+
   ###############################
   # Message from the hardware (FHZ1000/WS3000/etc) via select or the Ready
   # Function. The latter ist needed for Windows, where USB devices are not


BTW: Bei der Behandlung von EBADF sehe ich auch nicht die Notwendigkeit, die komplette %selectlist durchzuarbeiten: der kaputte FD, über den der select in Zeile 725 gestolpert ist, muss in der Veroderung von $rin mit $win enthalten sein. Es würde also reichen genau diese auch zu prüfen. Das aber nur nebenbei, der Fall sollte ja  nicht so häufig vorkommen, dass es richtig weh tun würde..

[rudolfkoenig]

Sorry, ich sehe hier nichts was die Behandlung der signals um mehr als einige dutzend Millisekunden verzögern würde...

Mit folgendem fhem.cfg

Code Auswählen Erweitern

define t telnet 7072

ist $timeout nicht definiert, und select wartet unbestimmt lange.
Mit einer zusaetzlichen FHEMWEB Instanz ist $timeout = 60 (Sekunden).

Falls man die Behandlung des Select-Rueckgabewertes vor der Signal-Auswertung durchfuehrt (wie Du es urspruenglich vorgeschlagen hast) landet man nach einem SIGTERM wieder im select, und wartet entsprechend lange. Ich will nicht sagen, dass das in jeder FHEM Installation der Normalfall ist, aber wenn man nur gut geschriebene Module verwendet, kann die Verzoegerung merkbar sein.
Und in diesem Fall hilft auch ein beliebig oft wiederholtes SIGTERM nicht => gerade getestet mit einer "telnet+FHEMWEB" fhem.cfg

Die aktuell eingecheckte fhem.pl Version (wie auch dein letzter Patch) sollte dieses Problem nicht haben.

Wenn wir gerade dabei sind: gibt es eine Erklärung für "$err==0" in Zeile 737?

Vermutlich, ich kann sie aber leider nicht liefern.
Diese Pruefung habe ich gerade bis fhz1000-2.0 zurueckverfolgt (2006-04-02, erste Version mit "richtigen" Modulen), und damals habe ich solche nicht intuitiven Codestuecke noch nicht mit dem Forums-Hinweis dokumentiert.
DbLog hat Ende 2012 angefangen.

[jw9]

Mit folgendem fhem.cfg

Code Auswählen Erweitern

define t telnet 7072

ist $timeout nicht definiert, und select wartet unbestimmt lange.
Mit einer zusaetzlichen FHEMWEB Instanz ist $timeout = 60 (Sekunden).

Wieso kann fhem nicht ein maximales timeout vorgeben? Wie wäre es mit:

Code Auswählen Erweitern


  $timeout = $readytimeout if(keys(%readyfnlist) &&
                               (!defined($timeout) || $timeout > $readytimeout));
-  $timeout = 5 if $winService->{AsAService} && $timeout > 5;
+  $timeout = 5 if $timeout > 5;
   $nfound = select($rout=$rin, $wout=$win, $eout=$ein, $timeout) if(!$nfound);


Falls man die Behandlung des Select-Rueckgabewertes vor der Signal-Auswertung durchfuehrt (wie Du es urspruenglich vorgeschlagen hast) landet man nach einem SIGTERM wieder im select, und wartet entsprechend lange.

Ich denke das muss man etwas differenzierter betrachten. Das signal kann kommen:

• Während des select: In diesem Fall ist $nfound<0 und $!==EINTR. Hier landet man in der Fehlerbehandlung, kein Grund erneut in den Select zu gehen.
• Vor "if($gotSig)": hier wird das Signal verarbeitet, und zwar unabhängig davon ob die Fehlerbehandlung davor oder danach stattgefunden hat
• Nach"if($gotSig)": hier landet man wieder im select, und zwar auch wieder unabhängig davon ob die Fehlermeldung vor oder nach den Signals behandelt wird.

Im Gegensatz zu Deiner Argumentation verhindert die vorrangige Behandlung der Signals NICHT diese langen Hänger. Diese Hänger sind ja schon im ursprünglichen Code aufgetreten, wie ich schon im Eröffnungspost geschrieben hatte. Und das obwohl die  signals zuallererst behandelt wurden.

Wenn man das in allen Varianten durchdenkt, dann ist bei der Variante "erst fehler dann signals" die Wahrscheinlichkeit, wiederholt im select zu landen GERINGER (wenn auch kaum nennenswert), weil zwischen "if($gotSig)" und erneutem select weniger code ausgeführt wird!

Oh, und ich sehe gerade, bei EAGAIN werden neuerdings auch filedescriptoren rausgeworfen? Ernsthaft?!? Welcher Gedankengang steckt hier dahinter?

Wie wäre es mit folgender Variante:

Code Auswählen Erweitern


--- fhem.pl     2022-04-27 03:01:00.490427634 +0200
+++ fhem.pl.1   2022-05-08 23:50:26.779325997 +0200
@@ -721,27 +721,16 @@
   }
   $timeout = $readytimeout if(keys(%readyfnlist) &&
                               (!defined($timeout) || $timeout > $readytimeout));
-  $timeout = 5 if $winService->{AsAService} && $timeout > 5;
+  $timeout = 5 if $timeout > 5;
   $nfound = select($rout=$rin, $wout=$win, $eout=$ein, $timeout) if(!$nfound);
   my $err = int($!);

-  $winService->{serviceCheck}->() if($winService->{serviceCheck});
-  if($gotSig) {
-    CommandShutdown(undef, undef) if($gotSig eq "TERM");
-    CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
-    $attr{global}{verbose} = 5    if($gotSig eq "USR1");
-    $gotSig = undef;
-  }
-
   if($nfound < 0) {
-    next if($err==0 || $err==4); # 4==EINTR
-
     Log 1, "ERROR: Select error $nfound ($err), error count= $errcount";
     $errcount++;

     # Handling "Bad file descriptor". This is a programming error.
-    # 9/10038 => BADF, 11=>EAGAIN. don't want to "use errno.ph"
-    if($err == 11 || $err == 9 || $err == 10038) {
+    if($err == 11 || $err == 9 || $err == 10038) {
       my $nbad = 0;
       foreach my $p (keys %selectlist) {
         my ($tin, $tout) = ('', '');
@@ -755,11 +744,21 @@
       next if($nbad > 0);
       next if($errcount <= 3);
     }
-    die("Select error $nfound ($err)\n");
+    die("Select error $nfound ($err)\n") unless $gotSig;
   } else {
     $errcount= 0;
   }

+  $winService->{serviceCheck}->() if($winService->{serviceCheck});
+  if($gotSig) {
+      CommandShutdown(undef, undef) if($gotSig eq "TERM");
+      CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
+      $attr{global}{verbose} = 5    if($gotSig eq "USR1");
+      $gotSig = undef;
+  }
+
+  next if($err==4); # 4==EINTR
+
   ###############################
   # Message from the hardware (FHZ1000/WS3000/etc) via select or the Ready
   # Function. The latter ist needed for Windows, where USB devices are not


Und in diesem Fall hilft auch ein beliebig oft wiederholtes SIGTERM nicht => gerade getestet mit einer "telnet+FHEMWEB" fhem.cfg

Was genau hast Du getestet? Den Original-Code, oder den mit dem patch?

DbLog hat Ende 2012 angefangen.

Wie ich weiter oben im Thread ausgeführt habe, ist DbLog nicht die Ursache, sondern lediglich der Auslöser, der zufällig zum blöden Zeitpunkt ausgeführt wird und demzufolge $! verändert... Ich sehe keinen Grund, in diesem Zusammenhang weiterhin auf DbLog einzuprügeln...

[jw9]

Sorry, da hatte ich das EAGAIN noch gesehen, aber dann vergessen den Patch noch anzupassen:

Code Auswählen Erweitern

--- fhem.pl-orig        2022-05-09 07:44:43.843679097 +0200
+++ fhem.pl     2022-05-09 07:49:15.831936023 +0200
@@ -721,27 +721,19 @@
   }
   $timeout = $readytimeout if(keys(%readyfnlist) &&
                               (!defined($timeout) || $timeout > $readytimeout));
-  $timeout = 5 if $winService->{AsAService} && $timeout > 5;
+  $timeout = 5 if $timeout > 5;
   $nfound = select($rout=$rin, $wout=$win, $eout=$ein, $timeout) if(!$nfound);
   my $err = int($!);

-  $winService->{serviceCheck}->() if($winService->{serviceCheck});
-  if($gotSig) {
-    CommandShutdown(undef, undef) if($gotSig eq "TERM");
-    CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
-    $attr{global}{verbose} = 5    if($gotSig eq "USR1");
-    $gotSig = undef;
-  }
-
   if($nfound < 0) {
-    next if($err==0 || $err==4); # 4==EINTR
+    next if($err==11 || $err==4); # 4==EINTR, 11==EAGAIN

     Log 1, "ERROR: Select error $nfound ($err), error count= $errcount";
     $errcount++;

     # Handling "Bad file descriptor". This is a programming error.
-    # 9/10038 => BADF, 11=>EAGAIN. don't want to "use errno.ph"
-    if($err == 11 || $err == 9 || $err == 10038) {
+    # 9/10038 => BADF, don't want to "use errno.ph"
+    if($err == 9 || $err == 10038) {
       my $nbad = 0;
       foreach my $p (keys %selectlist) {
         my ($tin, $tout) = ('', '');
@@ -755,11 +747,19 @@
       next if($nbad > 0);
       next if($errcount <= 3);
     }
-    die("Select error $nfound ($err)\n");
+    die("Select error $nfound ($err)\n") unless $gotSig;
   } else {
     $errcount= 0;
   }

+  $winService->{serviceCheck}->() if($winService->{serviceCheck});
+  if($gotSig) {
+    CommandShutdown(undef, undef) if($gotSig eq "TERM");
+    CommandRereadCfg(undef, "")   if($gotSig eq "HUP");
+    $attr{global}{verbose} = 5    if($gotSig eq "USR1");
+    $gotSig = undef;
+  }
+
   ###############################
   # Message from the hardware (FHZ1000/WS3000/etc) via select or the Ready
   # Function. The latter ist needed for Windows, where USB devices are not


[rudolfkoenig]

Wieso kann fhem nicht ein maximales timeout vorgeben?

Klar ist das moeglich, aber welches Problem wird dadurch geloest?

Oh, und ich sehe gerade, bei EAGAIN werden neuerdings auch filedescriptoren rausgeworfen?

Um genau zu sein werden bei EAGAIN alle FDs sinnlos auf Gueltigkeit geprueft. Ich wollte damit zwei Zeilen Code sparen.
Ob jetzt 0.1s vergeudete Zeit in 0.0001% der Faelle schlimmer ist, oder zwei Zeilen mehr, ist mAn Geschmacksache.

Was genau hast Du getestet? Den Original-Code, oder den mit dem patch?

Deinen ersten Vorschlag:

Meiner Meinung nach sollte der Code-Block, der anfängt mit "if($nfound < 0) {" unmittelbar nach dem select() kommen.

Dein erster Patch loest das Problem vmtl. auch (wie ich das geschrieben habe), erfordert aber mehr Umbau, was ich vermeide, um Nebeneffekte zu minimieren.

Ich sehe keinen Grund, in diesem Zusammenhang weiterhin auf DbLog einzuprügeln...

Ich wollte damit nur deinen Verdacht entkraeften, dass DbLog die Ursache fuer die unerklaerliche Abfrage ist:

Ich habe einen Verdacht: jemand ist beim Debuggen den Fall "$nfound<0 && $err==0" gestolpert und nicht erkannt, dass die Ursache darin liegt, dass DbLog (oder irgend ein anderes Modul) sich vorgedrängelt hat.

Generell pruegele ich nicht auf Module ein, im Gegenteil, bin vmtl. zu tolerant.

Wie wäre es mit folgender Variante:

Ich sehe z.Zt. noch nicht das Problem, was dadurch geloest wird.
Wenn Du einen Testfall hast...

[jw9]

Klar ist das moeglich, aber welches Problem wird dadurch geloest?

Jenes, über welches Du Dich in https://forum.fhem.de/index.php/topic,127414.msg1219621.html#msg1219621 beschwert hattest: wenn das signal nach "if($gotSig) {" aber noch vor dem Aufruf von select eintrifft, dann wird select nicht mit EINTR abgebrochen, sondern wird sehr lange benötigen bis das (unter Umständen) lange timeout abläuft.

Um genau zu sein werden bei EAGAIN alle FDs sinnlos auf Gueltigkeit geprueft. Ich wollte damit zwei Zeilen Code sparen.

Du sparst damit aber keine einzige Zeile. Schau Dir mal meinen letzten Patch an: die unsinnige Behandlung von $err==0 wird durch die Behandlung von $err==11 ersetzt. Das ist exakt ein einziges Zeichen mehr gegenüber dem ursprünglichen Code. Verglichen mit dem aktuellen Code ist es sogar ein Stück kürzer 

Ob jetzt 0.1s vergeudete Zeit in 0.0001% der Faelle schlimmer ist, oder zwei Zeilen mehr, ist mAn Geschmacksache.

Die vergeudete Zeit ist Geschmackssache, da stimme ich Dir zu.

Eine saubere Fehlerbehandlung halte ich hingegen nicht für eine Geschmackssache. Der aktuelle Code läuft bei EAGAIN auf die() wenn die drei vorherigen select-Aufrufe einen Fehler geliefert haben, weil $nbad==0 && $errcount>3. Zugegeben, die Wahrscheinlichkeit dafür ist extrem gering. Ein Code der unabhängig von Wahrscheinlichkeiten immer korrekt funktioniert wäre aber vorzuziehen, IMHO...

Deinen ersten Vorschlag:Dein erster Patch loest das Problem vmtl. auch (wie ich das geschrieben habe),

Vergiss bitte meinen ersten patch, da hatte ich ebenfalls den die() übersehen...

erfordert aber mehr Umbau, was ich vermeide, um Nebeneffekte zu minimieren.

Nebeneffekte minimiert man indem man eine saubere Fehlerbehandlung macht. YMMV.

Ich sehe z.Zt. noch nicht das Problem, was dadurch geloest wird.
Wenn Du einen Testfall hast...

Einen Testfall für eine sehr unwahrscheinliche Racing-Condition einzufordern ist ein bisschen unfair, meinst Du nicht?

Wie und warum Fehler auftreten können habe ich ja schon mehrfach sehr ausführlich beschrieben. Wozu benötigst Du da noch Testfälle?