[gelöst]Möglicher fhem crash mit 10_MQTT2_DEVICE.pm PrioQueue_add

[noansi]

Hallo Rudolf,

hier https://forum.fhem.de/index.php/topic,24436.msg903300.html#msg903300 hat ein User einen fhem crash bei der Abarbeitung von %prioQueues festgestellt.
Da ich in 97_timerTS.pm dafür den gleichen Code verwendet habe, wie fhem.pl in HandleTimeout(), hab ich mal weiter geschaut.

Nur in 10_MQTT2_DEVICE.pm Zeile 167 finde ich die Verwendung von PrioQueue_add.
Und hier scheint nicht oder nicht immer das zu geschehen, was Du beabsichtigt hast.

Wenn ich diesen Aufruf mit

Code Auswählen Erweitern

  PrioQueue_add(sub{
      Log 0, "PrioQueue executed";
    }, undef);


versuche nachzustellen, dann crashed es auch bei mir mit

Code Auswählen Erweitern

Can't use string ("") as a subroutine ref while "strict refs" in use at /opt/fhem/FHEM/97_timerTS.pm line 75.
oder

Code Auswählen Erweitern

Undefined subroutine &main:: called at /opt/fhem/FHEM/97_timerTS.pm line 75.
wenn ich " no strict "refs"; " verwende.

Entweder kann meine ältere perl Version 5.14.2 mit dem sub{} keine Referenz erzeugen oder die sub{} Funktion wird ausgeführt, liefert undef und damit wird dann PrioQueue_add als erstes Argument aufgerufen.
Da ich aber den "PrioQueue executed" Log Eintrag nicht zu sehen bekomme, erzeugt vermutlich mein perl keine Referenz auf die sub{}.

Bitte schau da mal nach. Danke!

Gruß, Ansgar.

PS: perl update ist für mich aufwändig, weil mein RasPi leider keine updates mehr bekommt.

[noansi]

Hallo Rudolf,

ich habe noch etwas weiter geschaut und festgestellt, dass PrioQueues gar nicht richtig funktioniert haben.
Das fängt schon bei PrioQueue_add an.

In fhem.pl muss

Code Auswählen Erweitern

sub
PrioQueue_add($$;$)
{
  my ($fn, $arg, $nice) = @_;

  $nice =   0 if(!defined($nice) || !looks_like_number($nice));
  $nice = -20 if($nice <-20);
  $nice =  19 if($nice > 19);
  $nextat = 1;
  $prioQueues{$nice} = [] if(!defined $prioQueues{$nice});
  push(@{$prioQueues{$nice}},{fn=>$fn, arg=>$arg});
};

geändert werden in

Code Auswählen Erweitern

sub
PrioQueue_add($$;$)
{
  my ($fn, $arg, $nice) = @_;

  if(!defined($nice) || !looks_like_number($nice)) {
    $nice =   0;
  }
  else {
    $nice = -20 if($nice <-20);
    $nice =  19 if($nice > 19);
  }
  $nextat = 1;
#  Log 0, "PrioQueue_add: adding ".$nice." ".$fn.":".$arg;
  my %h = (fn=>$fn, arg=>$arg);
  return push(@{$prioQueues{$nice}}, \%h);
};

damit eine brauchbarer hash ans jeweilige array angefügt wird. (Und nicht unnötig Limits geprüft werden)

In fhem.pl muss in sub HandleTimeout()

Code Auswählen Erweitern

  if(%prioQueues) {
    my $nice = minNum(keys %prioQueues);
    my $entry = shift(@{$prioQueues{$nice}});
    delete $prioQueues{$nice} if(!@{$prioQueues{$nice}});
    &{$entry->{fn}}($entry->{arg});
    $nextat = 1 if(%prioQueues);
  }

geändert werden in

Code Auswählen Erweitern

  if (scalar keys %prioQueues) {
    my $nice = MinPrioNum(keys %prioQueues);
    if (defined($nice)) {
      my $entry = shift(@{$prioQueues{$nice}});
      delete $prioQueues{$nice} if (!@{$prioQueues{$nice}});
#      Log 0, "HandleTimeout: executing ".$nice." ".$entry->{fn}.":".$entry->{arg};
      no strict "refs";
      &{$entry->{fn}}($entry->{arg}) if ($entry->{fn}); # avoid bad/undefined calls to crash fhem
      use strict "refs";
      $nextat = 1 if (scalar keys %prioQueues);
    }
  }

und eine Funktion

Code Auswählen Erweitern

#####################################
sub
MinPrioNum(@)
{
  return undef if (!int(@_));
  my $min = shift(@_);
  for (@_) {
    $min = $_ if $_ < $min;
  }           
  return $min;
}

ergänzt werden.

if(%prioQueues) liefert auch was wahres, wenn %prioQueues einmal benutzt aber geleert wurde.

Dann liefert minNum 1, wenn mit dem scheinbar leeren %prioQueues aufgerufen. In der Folge geht die CPU Last dann auf 100%, selbst wenn HandleTimeout() ohne crash aufgerufen werden kann.

Gruß, Ansgar.

EDIT: Hier https://forum.fhem.de/index.php/topic,24436.msg903798.html#msg903798 war beim Crash-Problem MQTT2 im Einsatz und es gab zumindest Veränderungen. Außerdem Perl v5.24.1

[rudolfkoenig]

Ich habe eine perl 5.14 Installation aufgetrieben (fhem.pl:18497/2019-02-05 perl:5.014002 os:linux user:rudi pid:18029), und

Code Auswählen Erweitern

{ PrioQueue_add(sub{ Log 0, "PrioQueue executed" }, undef) }
via telnet eingegeben. FHEM lief munter weiter, und im FHEM-Log stand auch das, was man erwartet.

ich habe noch etwas weiter geschaut und festgestellt, dass PrioQueues gar nicht richtig funktioniert haben.

Das ist eine steile These, ich halte mit 500-600 MQTT2_SERVER Installationen dagegen, die ueber PrioQueues mehrere tausend MQTT2_DEVICE Instanzen angelegt haben.
Ich habe das selbst gefuehlt hundertmal getestet.

if(%prioQueues) liefert auch was wahres, wenn %prioQueues einmal benutzt aber geleert wurde.

Kann ich auch nicht nachvollziehen. Folgendes habe ich mit dem oben erwaehnten perl 5.14.2 getestet:

Code Auswählen Erweitern

fhem> { my %d;; $d{1}=1;; %d?1:0 }
1
fhem> { my %d;; $d{1}=1;; delete $d{1};; %d?1:0 }
0


[noansi]

Hallo Rudolf,

Das ist eine steile These, ich halte mit 500-600 MQTT2_SERVER Installationen dagegen, die ueber PrioQueues mehrere tausend MQTT2_DEVICE Instanzen angelegt haben.

Du hast recht, wenn ich es ohne timerTS teste, dann kommt Dein Ergebnis. 

Lade ich timerTS mit dem gleichen Code zur Abarbeitung der PrioQueues, dann knallt es mit

Code Auswählen Erweitern

2019.02.10 14:59:19.038 1: PERL WARNING: Use of uninitialized value $arg in concatenation (.) or string at fhem.pl line 3195.
2019.02.10 14:59:19.039 0: PrioQueue_add: adding 0 CODE(0x206c8b8):
2019.02.10 14:59:19.092 1: PERL WARNING: Use of uninitialized value in subroutine entry at /opt/fhem/FHEM/97_timerTS.pm line 75.
Can't use string ("") as a subroutine ref while "strict refs" in use at /opt/fhem/FHEM/97_timerTS.pm line 75.

Demnach verhält sich perl anders, wenn die HandleTimeout() Routine neu definiert wird. Oder "use vars qw(%prioQueues);" macht nicht das, was ich erwarte.

Danke für den Test!
Hast Du vielleicht eine Idee dazu, was der Unterschied sein könnte?

Erwarten würde ich gleiche Probleme mit apptime, da da ebenso neu definiert wird.

Gruß, Ansgar.

PS: ich hatte zum Testen die Log Zeilen aus obigem Änderungsvorschlag ergänzt, um den $nice Wert mit zu loggen. Daher die ersten beiden Log Zeilen.