Autor Thema: [gelöst] Logfile zeigt falsches Logfile an.  (Gelesen 1380 mal)

Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
[gelöst] Logfile zeigt falsches Logfile an.
« am: 11 Februar 2017, 17:45:42 »
Titel klingt komisch, ist aber so  8)

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)

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

in global steht:

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:

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,

  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:

{ 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.
« Letzte Änderung: 16 Februar 2017, 17:46:29 von betateilchen »
-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
Antw:Logfile zeigt falsches Logfile an.
« Antwort #1 am: 12 Februar 2017, 01:34:05 »
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:

  $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:

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.

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;
 }
« Letzte Änderung: 12 Februar 2017, 01:52:51 von betateilchen »
-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
Antw:Logfile zeigt falsches Logfile an.
« Antwort #2 am: 12 Februar 2017, 02:03:02 »
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.

http://192.168.123.159:8083/fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-00.log
-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
-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 17266
Antw:Logfile zeigt falsches Logfile an.
« Antwort #3 am: 12 Februar 2017, 16:55:21 »
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 :)

Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
Antw:Logfile zeigt falsches Logfile an.
« Antwort #4 am: 12 Februar 2017, 18:40:37 »
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.
-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:Logfile zeigt falsches Logfile an.
« Antwort #5 am: 13 Februar 2017, 09:25:59 »
Dito, hat mich auch erwischt.

Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 17266
Antw:Logfile zeigt falsches Logfile an.
« Antwort #6 am: 13 Februar 2017, 09:39:02 »
Ws genau? betateilchens Problem? Meine Befuerchtungen? Wenn ja, welche der drei? Eine Erkaeltung?

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:Logfile zeigt falsches Logfile an.
« Antwort #7 am: 13 Februar 2017, 09:43:12 »
Ja Erkältung zwar auch, aber das wollte ich hier nicht so breittreten... :-)
Es handelt sich um das erste von betateilchen gemeldete Problem.

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:Logfile zeigt falsches Logfile an.
« Antwort #8 am: 16 Februar 2017, 15:58:30 »
Ist hierfür eine Lösung in Aussicht?

VG


Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
Antw:Logfile zeigt falsches Logfile an.
« Antwort #9 am: 16 Februar 2017, 17:46:07 »
Das Problem ist gelöst

(seit 12.02.2017, also per update am 13.02.)

-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:[gelöst] Logfile zeigt falsches Logfile an.
« Antwort #10 am: 16 Februar 2017, 19:31:19 »
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):
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:
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




Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 17266
Antw:[gelöst] Logfile zeigt falsches Logfile an.
« Antwort #11 am: 16 Februar 2017, 20:01:00 »
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.

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:[gelöst] Logfile zeigt falsches Logfile an.
« Antwort #12 am: 16 Februar 2017, 20:11:50 »
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.

Offline betateilchen

  • Developer
  • Hero Member
  • ****
  • Beiträge: 13591
  • Das "S" in "IoT" steht für "Security"
Antw:[gelöst] Logfile zeigt falsches Logfile an.
« Antwort #13 am: 17 Februar 2017, 10:17:14 »
geh mal bitte auf die Betriebssystemebene, mache ein

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

und poste die Ausgabe hier.
-----------------------
Nächster Hamburg-Stammtisch: 15.12.2017

Offline octek0815

  • Full Member
  • ***
  • Beiträge: 276
Antw:[gelöst] Logfile zeigt falsches Logfile an.
« Antwort #14 am: 17 Februar 2017, 10:36:39 »
bitteschön...

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]$

 

decade-submarginal