Hallo,
hab seit Wochen i.d.R einmal in der Nacht diesen Eintrag im Log, heute mehrfach, kann mir bitte wer einen Tipp geben wie ich die Ursache finde ?
2021.09.12 00:00:00 3: alexa: using logfile: ./log/alexa-2021-09-12.log
2021.09.12 03:04:45 1: OWXTHERM_BinValues: EG_Innensensor_Buero: invalid CRC, -0.0625 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff
2021.09.12 03:35:08 0: Strange call for nonexistent : ReadFn
2021.09.12 03:35:08 1: stacktrace:
2021.09.12 03:35:08 1: main::CallFn called by fhem.pl (773)
2021.09.12 04:24:03 3: MQTT2_Server: MQTT2_Server_192.168.188.34_39492/ebusd_3.3_505 left us (keepalive check)
2021.09.12 04:27:28 3: MQTT2_Server: MQTT2_Server_192.168.188.128_50764/mysensors-1 left us (keepalive check)
2021.09.12 04:43:09 0: Strange call for nonexistent : ReadFn
2021.09.12 04:43:09 1: stacktrace:
2021.09.12 04:43:09 1: main::CallFn called by fhem.pl (773)
2021.09.12 04:43:49 0: Strange call for nonexistent : ReadFn
2021.09.12 04:43:49 1: stacktrace:
2021.09.12 04:43:49 1: main::CallFn called by fhem.pl (773)
2021.09.12 04:51:49 0: Strange call for nonexistent : ReadFn
2021.09.12 04:51:49 1: stacktrace:
2021.09.12 04:51:49 1: main::CallFn called by fhem.pl (773)
2021.09.12 04:53:09 0: Strange call for nonexistent : ReadFn
2021.09.12 04:53:09 1: stacktrace:
2021.09.12 04:53:09 1: main::CallFn called by fhem.pl (773)
2021.09.12 04:55:49 0: Strange call for nonexistent : ReadFn
2021.09.12 04:55:49 1: stacktrace:
2021.09.12 04:55:49 1: main::CallFn called by fhem.pl (773)
2021.09.12 05:05:49 0: Strange call for nonexistent : ReadFn
2021.09.12 05:05:49 1: stacktrace:
2021.09.12 05:05:49 1: main::CallFn called by fhem.pl (773)
2021.09.12 11:28:31 2: After sleep: done
Offensichtlich hat es ja was mit Homematic zu tun, hier mal vorsichtshalber vorab mal meine HMUARTLGW- und VCCU-Definitionen:
defmod HMUART1 HMUARTLGW /dev/ttyAMA0
attr HMUART1 hmId F12030
attr HMUART1 room Homematic
setstate HMUART1 opened
setstate HMUART1 2021-09-08 11:28:35 D-HMIdAssigned F12030
setstate HMUART1 2021-09-08 11:28:35 D-HMIdOriginal 6A5832
setstate HMUART1 2021-09-08 11:28:37 D-firmware 1.4.1
setstate HMUART1 2021-09-08 11:28:39 D-serialNr PEQ0533394
setstate HMUART1 2021-09-08 11:27:11 D-type HM-MOD-UART
setstate HMUART1 2021-09-08 11:28:41 cond ok
setstate HMUART1 2021-09-12 11:57:00 load 0
setstate HMUART1 2021-09-08 11:28:41 loadLvl low
setstate HMUART1 2021-09-08 11:27:26 state opened
defmod VCCU CUL_HM F12030
attr VCCU .mId FFF0
attr VCCU IOList HMUART1
attr VCCU IOgrp VCCU
attr VCCU expert defReg,rawReg
attr VCCU model CCU-FHEM
attr VCCU room Homematic
attr VCCU subType virtual
attr VCCU webCmd virtual
setstate VCCU HMUART1:ok
setstate VCCU 2021-03-04 11:07:18 .associatedWith VCCU,VCCU_Btn1,VCCU
setstate VCCU 2021-09-08 11:28:12 IODev HMUART1
setstate VCCU 2021-09-08 11:28:41 IOopen 1
setstate VCCU 2021-09-08 11:28:41 state HMUART1:ok
Gruß
Thomas
Welches Unterforum wäre denn das Richtige wenn es um fhem.pl geht ?
Hast du eine aktuelle CUL_HM im Einsatz? Wenn ja: welche? Das Problem ist jedenfalls nicht fhem.pl, das ist nur das "ausführende Organ", das nach dem Motto handelt "Melden macht frei".
Falls CUL_HM: Ich habe da was gesehen, was in die Richtung gehen könnte, und hatte das in meinen letzten Testversionen (nicht mehr der allerletzten!) gefixt. (Die Stellen sind noch markiert und hoffentlich gut zu finden, siehe kommentierter patch in https://forum.fhem.de/index.php/topic,122422.msg1174414.html#msg1174414)
Zitat10_CUL_HM.pm 24851 2021-08-15 05:57:45Z martinp876
Hatte nicht vor mich damit weiter/tiefer mit zu beschäftigen, die angehängte Datei hab ich mir (noch) nicht angeschaut, mach ich
vlt. noch.
...brauchst du nicht, ich war vermutlich auf dem Holzweg...
Das zu finden wird vermutlich schwierig, es sei denn, die Zeiten könnte man irgendwie zuordnen.
ReadFn klingt nach DevIo-Nutzung, vielleicht schaust du mal mit "fhemdebug timerList" (?), ob da irgendwo was komisches zu finden ist? Es müsste sich um ein Modul handeln, das von irgendwo her Daten liest.
Zitat von: TomLee am 12 September 2021, 19:09:34
Welches Unterforum wäre denn das Richtige wenn es um fhem.pl geht ?
Ein Blick in die MAINTAINER.txt könnte helfen, diese Frage zu beantworten.
Ich würde einfach in die fhem.pl direkt vor der Zeile 773 die Zeile
Debug $hash->{NAME};
einfügen und schauen, was dann im Log auftaucht.
fhemdebug timerList kannte ich noch nicht, Danke, das gefällt mir.
OT: Ist es korrekt das mir in der Liste alle ATs angezeigt werden die eigentlich inactive gesetzt sind ?
ZitatDebug $hash->{NAME};
Danke, mach ich, sieht/hört sich vielversprechend aus/an.
Zitat von: TomLee am 12 September 2021, 23:15:15
OT: Ist es korrekt das mir in der Liste alle ATs angezeigt werden die eigentlich inactive gesetzt sind ?
Logischerweise ja.
Die at werden trotzdem gestartet, sie tun nur nix. Das ist wichtig, um bei wiederkehrenden at den nächsten Ausführungszeitpunkt berechnen zu können.
Aus Interesse, hab eben die debug-Ausgabe erst ergänzt, geh davon aus das die Änderung doch erst nach einem restart greift oder würd auch einfach reload fhem.pl ausreichen ?
edit:
Ok, reload fhem.pl geht gar nicht.
Can't read ./FHEM/fhem.pl.pm: No such file or directory
Wenn ich die debug-Ausgabe kurze Zeit aktiviere sehe ich im Log in kurzer Zeit etliche Devices die nicht in Frage kommen, die Log-Datei würde ewig groß werden wenn ich das über Nacht aktiviert lasse, würde das gerne vermeiden, man kann das doch bestimmt irgendwie ? bspw. mit einem regulären Ausdruck der die Namen ausnimmt die nicht in Frage kommen (meinetwegen geb ich die Namen alle einzeln an), kompensieren ?
Hallo TomLee,
ich habe auch die Fehlermeldung, allerdings tritt das bei mir nur Nachts zwischen 2 und 3 Uhr bei der Zwangstrennung auf.
Ich habe folgendes in fhem.pl ergänzt, um den Log File nicht überlaufen zu lassen:
my ($sec,$min,$hour,$mday,$month,$year,$wday,$yday,$isdst) = localtime(gettimeofday());
my $hms = sprintf("%02d:%02d:%02d", $hour, $min, $sec);
if ($hms ge "02:00:00" && $hms le "03:00:00") {Debug $hash->{NAME};}
Äquivalent kannst Du Dir deine eigenen Bedingungen definieren.
Danke.
Ja, so um die Zwangstrennung war mir eigentlich auch in Erinnerung, bis zum ersten Post, da war mir halt aufgefallen das es später wie sonst und dann auch gleich mehrfach zu der Meldung kam, deshalb hatte ich dann auch mal nachgefragt.
Natürlich kam die Meldung bisher nicht mehr, zumindest ist sie mir nicht aufgefallen, hab die letzten Tage aber auch hier und da was ausprobiert wozu ich dann das Log immer löschte und auf die Meldung nicht achtete. Ich werds einfach mal einbauen.
Ich habe jetzt die Zwangstrennung in der FB einfach manuell herbeigeführt, und kann die Meldung reproduzieren.
Das passiert jedesmal nach dem Aufruf von den Presence collect devices. Hier die def vom den Presence devices (stellvertretend für alle), und die Log einträge.
In fhem.pl ist "Debug $hash->{NAME};" eingefügt, wie betateilchen vorgeschlagen hatte.
Wo kommt die Meldung jetzt her??
defmod Presence_GTag_RED_collect PRESENCE lan-bluetooth 7C:2F:80:98:C2:2A 127.0.0.1:5222 300 300
attr Presence_GTag_RED_collect absenceThreshold 3
attr Presence_GTag_RED_collect alias PresenceRED_LE
attr Presence_GTag_RED_collect event-on-change-reading batteryPercent,presence
attr Presence_GTag_RED_collect group PRESENCE,SERVER
attr Presence_GTag_RED_collect room Favourites,Presence
attr Presence_GTag_RED_collect sortby 041
attr Presence_GTag_RED_collect stateFormat {myPresenceGTagCollectStateFormat($name)}
attr Presence_GTag_RED_collect verbose 0
attr Presence_GTag_RED_collect webCmd statusRequest
2021.09.21 09:47:23 1: DEBUG>WEB_192.168.0.14_56513
2021.09.21 09:47:23 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 09:47:23 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 09:47:23 1: DEBUG>deCONZ
2021.09.21 09:47:24 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 09:47:24 1: DEBUG>Presence_GTag_White_collect
2021.09.21 09:47:24 1: DEBUG>Presence_Gast_Orange_collect
2021.09.21 09:47:24 1: DEBUG>
2021.09.21 09:47:24 0: Strange call for nonexistent : ReadFn
2021.09.21 09:47:24 1: stacktrace:
2021.09.21 09:47:24 1: main::CallFn called by /opt/fhem/fhem.pl (773)
2021.09.21 09:47:25 1: DEBUG>HMUART1
2021.09.21 09:47:25 1: DEBUG>HMUART1
2021.09.21 09:47:25 1: DEBUG>HMUART1
2021.09.21 09:47:25 1: DEBUG>HMUART2
2021.09.21 09:47:25 1: DEBUG>HMUART3
2021.09.21 09:47:25 1: DEBUG>HMUSB1
2021.09.21 09:47:25 1: DEBUG>d_rpc000001HmIP_RF
2021.09.21 09:47:26 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 09:47:26 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 09:47:26 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 10:01:18 1: DEBUG>telnetForBlockingFn_1632210020_127.0.0.1_45950
2021.09.21 10:01:19 1: DEBUG>Presence_GTag_Black_collect
2021.09.21 10:01:20 1: DEBUG>deCONZ
2021.09.21 10:01:21 1: DEBUG>deCONZ
2021.09.21 10:01:21 1: DEBUG>deCONZ
2021.09.21 10:01:21 1: DEBUG>deCONZ
2021.09.21 10:01:22 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 10:01:23 1: DEBUG>Presence_Jamo_Orange_collect
2021.09.21 10:01:23 1: DEBUG>Presence_GTag_Black_collect
2021.09.21 10:01:23 1: DEBUG>Presence_Jamo_Orange_collect
2021.09.21 10:01:23 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 10:01:24 1: DEBUG>
2021.09.21 10:01:24 0: Strange call for nonexistent : ReadFn
2021.09.21 10:01:24 1: stacktrace:
2021.09.21 10:01:24 1: main::CallFn called by /opt/fhem/fhem.pl (773)
2021.09.21 10:01:24 1: DEBUG>Presence_GTag_Black_collect
2021.09.21 10:01:24 1: DEBUG>Presence_GTag_White_collect
2021.09.21 10:01:24 1: DEBUG>Presence_Gast_Orange_collect
2021.09.21 10:01:24 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 10:01:26 1: DEBUG>HMUART1
2021.09.21 10:01:26 1: DEBUG>HMUART1
2021.09.21 10:01:26 1: DEBUG>HMUART1
2021.09.21 10:01:26 1: DEBUG>HMUART1
2021.09.21 10:01:26 1: DEBUG>HMUART3
2021.09.21 10:01:26 1: DEBUG>HMUSB1
2021.09.21 10:01:26 1: DEBUG>HMUART2
2021.09.21 10:01:26 1: DEBUG>deCONZ
2021.09.21 10:01:26 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 10:07:22.487 1: DEBUG>WEB_192.168.0.14_60567
2021.09.21 10:07:23.322 1: DEBUG>Presence_Jamo_Orange_collect
2021.09.21 10:07:23.327 1: DEBUG>Presence_Jamo_Orange_collect
2021.09.21 10:07:23.332 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 10:07:23.336 1: DEBUG>Presence_GTag_Black_collect
2021.09.21 10:07:24.327 1: DEBUG>Presence_GTag_White_collect
2021.09.21 10:07:24.328 1: DEBUG>Presence_GTag_White_collect
2021.09.21 10:07:24.330 1: DEBUG>Presence_Gast_Orange_collect
2021.09.21 10:07:24.332 1: DEBUG>Presence_GTag_RED_collect
2021.09.21 10:07:24.784 1: DEBUG>
2021.09.21 10:07:24.785 0: Strange call for nonexistent : ReadFn
2021.09.21 10:07:24.785 1: stacktrace:
2021.09.21 10:07:24.785 1: main::CallFn called by /opt/fhem/fhem.pl (773)
2021.09.21 10:07:25.287 1: DEBUG>HMUSB1
2021.09.21 10:07:26.751 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 10:07:26.752 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 10:07:26.752 1: DEBUG>DLNASocket-myRenderer-1900
2021.09.21 10:07:28.833 1: DEBUG>HMUART2
2021.09.21 10:07:28.895 1: DEBUG>HMUART3
2021.09.21 10:07:28.925 1: DEBUG>d_rpc000001HmIP_RF
2021.09.21 10:07:28.946 1: DEBUG>d_rpc000001HmIP_RF
2021.09.21 10:07:29.155 1: DEBUG>HMUART1
$hash->{NAME} ist leer oder nicht definiert, wenn der fehler kommt.
Da ist nicht nur $hash->{NAME} leer, sondern eben auch die ReadFn, was bei einem PRESENCE-Device eigentlich nicht sein dürfte, und auch der mcse-Log spricht nicht unbedingt dafür, dass das der direkte Verursacher ist.
Klingt das nicht eher danach, als wäre eine myUtils kaputt (wobei dann weiter unklar ist, warum da überhaupt eine ReadFn aufgerufen wird).
Zeigst du mal, wie die Datei aussieht in der myPresenceGTagCollectStateFormat() drin ist? (v.a. die Initialize-funktion wäre relevant).
Gerne, so siehts aus. Alles bis auf die myPresenceGTagCollectStateFormat entfernt
# $Id: 99_MyUtils.pm 1932 2021-09-21 20:15:33Z Jamo $
package main;
use strict;
use warnings;
#use Blocking;
#use Net::hostent;
#use Socket;
#use IO::Socket::INET; ## only for Telnet Access
#use Time::Local;
#use FritzBoxUtils; ## only for web access login
sub MyUtils_Initialize {
my ($hash) = @_;
return;
}
.
.
.
.
#attr Presence_GTag_White_collect stateFormat { myPresenceGTagCollectStateFormat($name) }
sub myPresenceGTagCollectStateFormat {
my $name = shift // return "Error, myPresenceGTagCollectStateFormat: we need name as parameter!";
my $Switch = shift // 'none';
my $Switchstate = ReadingsVal($Switch,'state','on');
my $state = ReadingsVal($name,'presence','nA');
my $room = ReadingsVal($name,'room','-');
my $rooms = ReadingsVal($name,'rooms','-');
#Log 3, "[$sub] StatusMac=$StatusMac, Switchstate=$Switchstate, $MAC";
#y $GTRred = $name eq 'Presence_GTag_RED_collect' && ReadingsVal($name,'room','nA') ne 'flurLE';
if ($state eq 'disabled') {return $state;}
elsif ($Switchstate eq 'on' && $state ne 'present') {return '<font color="red"><b>'. $room . " / " . $rooms . '</b></font>';}
elsif ($Switchstate eq 'off' && $state ne 'present') {return $state;} #just absent
else {return $room . ' / ' . $rooms;}
}
.
.
.
1;
Hmm, sieht unverdächtig aus...
Keine weitere Idee grade.
Schade. Vielleicht hat TomLee ja noch weitere Erkenntnisse. . .
Sry, hatte den Vorschlag gestern Abend nicht mehr eingebaut gehabt und wie es der Zufall will gabs die Meldung diesmal genau/etwa zum Zeitpunkt der Zwangstrennung, hilft zwar denk ich nicht weiter, erwähns nur.
2021.09.21 03:16:19 0: Strange call for nonexistent : ReadFn
2021.09.21 03:16:19 1: stacktrace:
2021.09.21 03:16:19 1: main::CallFn called by fhem.pl (774)
774 weil ich die debug-Ausgabe von oben noch drin und (sinnfrei 8) ) erweitert hatte, das es zu gar keiner debug-Ausgabe mehr kommt.
JA, genau so siehts bei mir auch aus, der Fehler kommt immer zur Zwangstrennung.
Evtl irgendein Modul, das immer Internet benötigt?