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.
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;
}
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
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 :)
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.
Dito, hat mich auch erwischt.
Ws genau? betateilchens Problem? Meine Befuerchtungen? Wenn ja, welche der drei? Eine Erkaeltung?
Ja Erkältung zwar auch, aber das wollte ich hier nicht so breittreten... :-)
Es handelt sich um das erste von betateilchen gemeldete Problem.
Ist hierfür eine Lösung in Aussicht?
VG
Das Problem ist gelöst
(seit 12.02.2017, also per update am 13.02.)
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
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.
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.
geh mal bitte auf die Betriebssystemebene, mache ein
ls -al /opt/fhem/log/fhem-2017-01.log
und poste die Ausgabe hier.
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]$
huhuu....gleiches Problem bei mir:
Wenn ich auf den Menüpunkt Logfile klicke wird folgendes Logfile geöffnet:
fhem-1970-01.log
gibt es dazu schon eine Lösung?
Geloggt wird in das korrekte fhem-2017-02.log...
Viele Grüße
Michael
der patch hat noch ein kleines problem.
wenn man reload 01_FHEMWEB.pm verwendet ist stat durch File::stat ersetzt wenn ein anderes modul dieses importiert hat. und das erzeugt dann beim seitenaufbau pro log file ein mal diese meldung:2017.02.19 21:27:41 1: PERL WARNING: Use of uninitialized value in string comparison (cmp) at ./FHEM/01_FHEMWEB.pm line 1867.
2017.02.19 21:27:41 1: stacktrace:
2017.02.19 21:27:41 1: main::__ANON__ called by ./FHEM/01_FHEMWEB.pm (1867)
2017.02.19 21:27:41 1: main::FW_fileList called by ./FHEM/01_FHEMWEB.pm (1537)
2017.02.19 21:27:41 1: main::FW_roomOverview called by ./FHEM/01_FHEMWEB.pm (1002)
2017.02.19 21:27:41 1: main::FW_answerCall called by ./FHEM/01_FHEMWEB.pm (528)
2017.02.19 21:27:41 1: main::FW_Read called by ./fhem.pl (3302)
2017.02.19 21:27:41 1: main::CallFn called by ./fhem.pl (674)
dagegen hilft wenn man in fhemweb zeile 1867 jeweils CORE::stat verwendet.
Genau die Meldung habe ich auch im Logfile...
PERL WARNING: Use of uninitialized value in string comparison (cmp) at ./FHEM/01_FHEMWEB.pm line 1861.
@justme1968: Danke fuer die Analyze und den Vorschlag, habs eingebaut, getestet, eingecheckt.
Ich finde unveschaemt vom Autor des FILE::stat, die eingebaute Funktionalitaet inkompatibel zu ueberschreiben. Welches FHEM-Modul braucht eigentlich FILE::stat?
ZitatIch finde unveschaemt vom Autor des FILE::stat, die eingebaute Funktionalitaet inkompatibel zu ueberschreiben.
immerhin hat er es dokumentiert :):
ZitatThis module's default exports override the core stat() and lstat() functions, replacing them with versions that return "File::stat" objects...
ZitatWelches FHEM-Modul braucht eigentlich FILE::stat?
aktuell wird es von 00_SONOS.pm, 70_ONKYO_AVR.pm und 98_BOSEST.pm eingebunden.
Daher auch die Fehlermeldung vom SONOS Modul beim FHEM-Start?
PERL WARNING: Redundant argument in sprintf at ./FHEM/00_SONOS.pm line 572.
Zitat von: rudolfkoenig am 20 Februar 2017, 08:55:32
Welches FHEM-Modul braucht eigentlich FILE::stat?
Die Frage ist, ob die drei Module das wirklich
brauchen oder ob das nur irgendwo per copy&paste übernommen wurde.
zumindest sonos und bose verwenden es tatsächlich.
Hallo,
mich hat es nach einem fhem update heute erwischt. Beim Klick auf Log-File auf der Web-Oberfläche bekomme ich immer das älteste von 01/2000 (fhem-2000-01.log) angezeigt. Hab verschiedene Ansätze hier aus dem Thread probiert, jedoch ohne Verbesserung.
Edit: Da das Logfile vom 01-2000 nicht wichtig ist (wurde mal angelegt, als der PC die falsche Zeit hatte) habe ich es jetzt mal kurzerhand gelöscht, um zu sehen, ob ich dann das nächst älteste von 2014 angezeigt bekomme, wenn ich auf Log-File klicke. Statt dessen bekomme ich jetzt wieder das neueste von 02-2017 angezeigt. Muss man nicht verstehen, oder?
Also bei mir ist bezüglich der LogFile Problematik nach dem heutigen Update alles wieder Ok.
gerade alle Updates unter Raspbian und FHEM gezogen.
das älteste LOG wird angezeigt. (2000-01)
2000-01 file gelöscht --> 2016-11 wird angezeigt. hat unter ls -l Änderungsdatum von 1970 --> file gelöscht
jetzt ist alles "OK", dennoch ein komisches Fehlverhalten welches mit dem Update kam.
Grüße
Zitat von: Frank_Huber am 22 Februar 2017, 17:14:00
jetzt ist alles "OK", dennoch ein komisches Fehlverhalten welches mit dem Update kam.
Das ist nicht komisch, das hängt vermutlich damit zusammen, dass Dein FHEM startet, bevor Dein Raspberry eine aktuelle Uhrzeit kennt.
Zitat von: betateilchen am 22 Februar 2017, 18:32:53
Das ist nicht komisch, das hängt vermutlich damit zusammen, dass Dein FHEM startet, bevor Dein Raspberry eine aktuelle Uhrzeit kennt.
negativ, mein RasPi hat einen RTC chip auf dem I2C bus stecken. Uhrzeit ist immer (auch beim offline starten) korrekt.
Das kam auch erst mit dem Update. Das letzte Update zuvor war im November 2016. da war noch alles OK.
Hallo zusammen,
leider ist das Problem mit dem Update von heute zurückgekehrt.
Grüße
Olli
Kommando zurück: Nach shutdown restart war der Fehler da. Nach einem service fhem stop / start ist das Phänomen wieder weg. Komisch...
na dann warte mal bis morgen früh :P