[gelöst] Logfile zeigt falsches Logfile an.

[betateilchen]

Titel klingt komisch, ist aber so 

Im Webfrontend wird in der Navigation unter "Logfile" das falsche Log (fhem-31.log) angezeigt.
FHEM loggt aber in das korrekte Logfile (fhem-11.log)

Code Auswählen Erweitern


http://192.168.123.45:8083/fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-31.log


in global steht:

Code Auswählen Erweitern


attr global logdir ./log
attr global logfile %L/fhem-%d.log
attr global nrarchive 3

Internals:
   currentlogfile ./log/fhem-11.log
   logfile    %L/fhem-%d.log


in Logfile steht:

Code Auswählen Erweitern


define Logfile FileLog %L/fhem-%d.log fakelog
attr Logfile nrarchive 3


Wenn ich mir die Logik in FHEMWEB.pm zur Ermittlung des korrekten Filenamens anschaue,

Code Auswählen Erweitern


  my $lfn = "Logfile";
  if($defs{$lfn}) { # Add the current Logfile to the list if defined
    my @l = FW_fileList($defs{$lfn}{logfile});
    my $fn = pop @l;
    splice @list, 4,0, ("Logfile",
                      "$FW_ME/FileLog_logWrapper?dev=$lfn&type=text&file=$fn");
  }


ergbit sich der Fehler:

Code Auswählen Erweitern


{ my @l = FW_fileList($defs{Logfile}{logfile});; return pop(@l);; }


liefert als Ergebnis "fhem-31.log".

Vermutung:
Es besteht ein Problem mit nrarchive im Zusammenhang mit Tageslogs, wenn ein Monatswechsel erfolgt,
denn die Logs vom Monatsende Januar sind alle noch vorhanden:

fhem-11.log
fhem-29.log
fhem-30.log
fhem-31.log

was bedeutet, dass die Logfiles von gestern und vorgestern bereits gelöscht wurden, weil die Gesamtzahl der Files (nrarchive=3) überschritten wird.
Die Erkennung, was "ältere" Files sind sowie deren Löschung, scheint nicht korrekt zu funktionieren.

[betateilchen]

Noch ein bisschen weitergeforscht. Es gibt mindestens zwei Baustellen, um das Problem zu lösen.

1. HandleArchiving($;$) in fhem.pl

Dort wird einfach nur alphanumeirsch nach Dateinamen sortiert, wobei stillschweigend vorausgesetzt wird, dass die Dateinamen dafür immer geeignet sind. Das ist aber mitnichten immer der Fall. Besser wäre m.E. die Sortierung nach dem letzten Modifikationszeitpunkt eines vorhandenen Logfiles.

Hierzu habe ich testweise die unten markierte Zeile eingefügt:

Code Auswählen Erweitern


  $file =~ s/%./.+/g;
  my @t = localtime;
  $dir = ResolveDateWildcards($dir, @t);
  return if(!opendir(DH, $dir));
  my @files = sort grep {/^$file$/} readdir(DH);
+++  @files = sort { (stat("$dir/$a"))[9] cmp (stat("$dir/$b"))[9] } @files;
  closedir(DH);


Damit funktioniert HandleArchiving($;$) bei mir korrekt (getestet mit minütlich erstellten Logs über einen Stundenwechsel)



2. FW_fileList($) in 01_FHEMWEB.pm

Da passiert im Prinzip genau das Gleiche: Am Ende der Funktion wird das Rückgabearray ebenfalls einfach alphanumerisch sortiert:

Code Auswählen Erweitern


FW_fileList($)
{
  ...
  return sort @ret;
}


Diese Sortierung macht an vielen Stellen in FHEM Sinn, aber nicht, wenn es um Logfiles geht. Damit erklärt sich der eingangs beschriebene Fehler.

Zur Lösung an dieser Stelle schlage ich vor, die Funktion FW_fileList() mit einem zweiten, optionalen Parameter als Schalter auszustatten,
mit dessen Hilfe das Rückgabearray nach der letzten Änderungszeit sortiert wird anstatt nach dem Dateinamen.

Code Auswählen Erweitern


Index: 01_FHEMWEB.pm
===================================================================
--- 01_FHEMWEB.pm (Revision 13383)
+++ 01_FHEMWEB.pm (Arbeitskopie)
@@ -20,7 +20,7 @@
sub FW_directNotify($@);
sub FW_doDetail($);
sub FW_fatal($);
-sub FW_fileList($);
+sub FW_fileList($;$);
sub FW_htmlEscape($);
sub FW_iconName($);
sub FW_iconPath($);
@@ -1523,7 +1523,7 @@

   my $lfn = "Logfile";
   if($defs{$lfn}) { # Add the current Logfile to the list if defined
-    my @l = FW_fileList($defs{$lfn}{logfile});
+    my @l = FW_fileList($defs{$lfn}{logfile},1);
     my $fn = pop @l;
     splice @list, 4,0, ("Logfile",
                       "$FW_ME/FileLog_logWrapper?dev=$lfn&type=text&file=$fn");
@@ -1837,9 +1837,10 @@
#################
# return a sorted list of actual files for a given regexp
sub
-FW_fileList($)
+FW_fileList($;$)
{
-  my ($fname) = @_;
+  my ($fname,$mtime) = @_;
+  $mtime //= 0;
   $fname =~ m,^(.*)/([^/]*)$,; # Split into dir and file
   my ($dir,$re) = ($1, $2);
   return $fname if(!$re);
@@ -1853,6 +1854,7 @@
     push(@ret, $f);
   }
   closedir(DH);
+  return sort { (stat("$dir/$a"))[9] cmp (stat("$dir/$b"))[9] } @ret if ($mtime == 1);
   @ret = cfgDB_FW_fileList($dir,$re,@ret) if (configDBUsed());
   return sort @ret;
}


[betateilchen]

Mit den vorgeschlagenen Änderungen verhält sich FHEM so, wie ich es ursprünglich erwartet habe.
Im Link zu Logfile steht das korrekte File fhem-00.log, obwohl es Files gibt, deren Dateinamen "höher" sind.

Code Auswählen Erweitern

http://192.168.123.159:8083/fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-00.log

Code Auswählen Erweitern


-rw-r--r--  1 fhem dialout  437 Feb 12 02:00 fhem-00.log
-rw-r--r--  1 fhem dialout 1713 Feb 12 01:50 fhem-50.log
-rw-r--r--  1 fhem dialout  356 Feb 12 01:52 fhem-52.log
-rw-r--r--  1 fhem dialout 1445 Feb 12 01:53 fhem-53.log


[rudolfkoenig]

Habe die Patches ohne nennenswerte Aenderungen eingecheckt, auch wenn ich inzwischen unsicher geworden bin.

stat() in der sort-Funktion stoert mich zwar, aber nicht genug, dass ich was aendere. Bin gespannt, wann der Erste mit 1000 Logdateien sich meldet, dass FHEMWEB langsamer geworden ist. Wer soviele Logdateien hat, ist selbst schuld

Weiterhin werden solche, die in alten Logfiles rumeditieren, vermutlich ueberrascht sein, was geloescht wird. Muss daran denken bei der Fehlermeldung. Und ich hoffe sehr, dass restore an die Zeitstempel denkt

[betateilchen]

Wenn Du andere Ideen hast, wie man die Sortierung korrigieren kann, kannst Du sie ja gerne einbauen.

Meine Tests gestern dienten vor allem dazu, die Fehlerursachen einzugrenzen und einen möglichen Lösungansatz zu finden.

[octek0815]

Dito, hat mich auch erwischt.

[rudolfkoenig]

Ws genau? betateilchens Problem? Meine Befuerchtungen? Wenn ja, welche der drei? Eine Erkaeltung?

[octek0815]

Ja Erkältung zwar auch, aber das wollte ich hier nicht so breittreten...
Es handelt sich um das erste von betateilchen gemeldete Problem.

[octek0815]

Ist hierfür eine Lösung in Aussicht?

VG

[betateilchen]

Das Problem ist gelöst

(seit 12.02.2017, also per update am 13.02.)

[octek0815]

Ok, Updates habe ich jeden Tag gefahren, muss ich noch bei mir was verändern?

Ich bekomme noch immer beim Click bzw. Hover-Over das falsche Log-File aufgerufen bzw. angezeigt (siehe Bild).

Und hier die Config (Logfile):

Code Auswählen Erweitern

Internals:
   DEF        ./log/fhem-%Y-%m.log fakelog
   NAME       Logfile
   NR         15
   NTFY_ORDER 50-Logfile
   REGEXP     fakelog
   STATE      active
   TYPE       FileLog
   currentlogfile ./log/fhem-2017-02.log
   logfile    ./log/fhem-%Y-%m.log
   Readings:
     2017-02-01 00:00:03   linesInTheFile  0
Attributes:
   icon       logfile
   room       _systemLog,System

und Global:

Code Auswählen Erweitern

Internals:
   DEF        no definition
   NAME       global
   NR         1
   STATE      no definition
   TYPE       Global
   currentlogfile ./log/fhem-2017-02.log
   logfile    ./log/fhem-%Y-%m.log
Attributes:
   archiveCompress 1
   archivedir ./log-archive/
   autoload_undefined_devices 1
   backupdir  /mnt/BACKUPaufDISKSTATION/FHEM/fhem1/
   backupsymlink yes
   configfile fhem.cfg
   holiday2we holidayFeiertage
   logfile    ./log/fhem-%Y-%m.log
   modpath    .
   nofork     0
   nrarchive  1
   restoreDirs 10
   room       System
   sendStatistics onUpdate
   showInternalValues 0
   stacktrace 0
   statefile  ./log/fhem.save
   updateInBackground 1
   userattr   DbLogExclude alexaName alexaRoom cmdIcon devStateIcon devStateStyle fp_fpHeizung fp_fpIPcams fp_fpInfo fp_fpKalender fp_fpSmartphone fp_fpSystem fp_fpTablet1 fp_fpVerbraeuche fp_fpWetter genericDeviceType:security,ignore,switch,outlet,light,blind,thermometer,thermostat,contact,garage,window,lock homebridgeMapping:textField-long icon offset offsetA offsetB sortby webCmd widgetOverride
   verbose    3
   version    fhem.pl:13411/2017-02-14

[rudolfkoenig]

Ein Reload der Seite im Browser loest das Problem bei mir.
Falls ein manuelles Reload nicht zumutbar ist, dann muss ein kleines JavaScript Programm dafuer sorgen.

[octek0815]

Klappt nicht. 3 verschieden Browser getestet IE, Chrome, Firefox.
Es ändert sich nix. Es wird weiterhin üben den Direktlink vom Hauptmenü das älteste Logfile geladen.

[betateilchen]

geh mal bitte auf die Betriebssystemebene, mache ein

Code Auswählen Erweitern


ls -al /opt/fhem/log/fhem-2017-01.log


und poste die Ausgabe hier.

[octek0815]

bitteschön...

Code Auswählen Erweitern


os@fhem1 / [22]$ ls -al /opt/fhem/log/fhem-2017-01.log
-rw-r--r-- 1 fhem dialout 4252353 Jan 31 23:59 /opt/fhem/log/fhem-2017-01.log
os@fhem1 / [23]$