Hallo,
am 29.3. hatte ich im FHEM nach 11 Tagen mal wieder ein Update gemacht - natürlich inkl. Home Connect 8)
Seither läuft der FHEM-Prozess unregelmäßig, aber mindestens einmal täglich in eine 100% CPU-Auslastung (leider meist spät nachts). Logeinträge gibt es dann bis zu einem gewaltsamen Neustart keine mehr. Um dem Problem auf die Schliche zu kommen, habe ich gestern Abend global verbose=5 gesetzt.
Heute am frühen Morgen musste ich dann mit Schrecken feststellen, dass FHEM nicht nur wieder die CPU zu 100% auslastete, sondern das Log auch schon auf 6 GB (!) angewachsen war und immer noch rasant wuchs.
Nachdem ich die Logdatei auf meinen PC kopiert hatte und in 50MB Dateien zerstückelt hatte, um überhaupt einen Blick hineienwerfen zu können, stellte ich schnell fest, dass bereits in der erste Datei eine endlose Folge von zwei Einträgen von meinem einzigen Home Connect Gerät - einem Siemens Trockner - das Log vollschrieb:
2018.04.01 01:16:23 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:23 5: Trockner_WT7YH701 event channel received no more data
2018.04.01 01:16:24 4: BlockingCall (MilightBridge_DoPing): created child (10756), uses telnetPort to connect back
2018.04.01 01:16:24 4: Connection accepted from telnetPort_127.0.0.1_52312
2018.04.01 01:16:24 5: Cmd: >{BlockingRegisterTelnet($cl,3331)}<
2018.04.01 01:16:24 5: MilightBridge_DoPing: Executing ping
2018.04.01 01:16:24 5: Cmd: >{BlockingStart('3331')}<
2018.04.01 01:16:24 5: Cmd: >{MilightBridge_DoPingDone('MilightBridge|1')}<
2018.04.01 01:16:28 5: [myTwilight] Original weather readings
2018.04.01 01:16:28 5: Starting notify loop for myTwilight, 2 event(s), first is azimuth: 359.08
2018.04.01 01:16:28 5: Luftfeuchte_kritisch: not on any display, ignoring notify
2018.04.01 01:16:28 5: TALKTOUSER TALKTOUSER_Familie: called function TALKTOUSER_Notify()
2018.04.01 01:16:28 5: rg_battery: not on any display, ignoring notify
2018.04.01 01:16:28 5: myHome: Events from monitored device myTwilight: azimuth: 359.08 --- elevation: -35.67
2018.04.01 01:16:28 5: End notify loop for myTwilight
2018.04.01 01:16:28 5: [myTwilight] removing Timer: myTwilight_sunpos
2018.04.01 01:16:28 5: [myTwilight] setting Timer: myTwilight_sunpos 2018-04-01 01:21:28
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel searching for data
2018.04.01 01:16:28 5: Trockner_WT7YH701 event channel read failed
Soweit ich das beurteilen kann, war um 01:16:23 Uhr noch alles in Ordnung. Ab 01:16:28 Uhr werden dann sekündlich tausende (!) der beiden Zeilen "searching for data" und "read failed" geschrieben. Sichprobenartig habe ich in ein paar weitere der über Hundert von mir zerstückelten Logdateien reingeschaut und finde nur noch diese beiden Zeilen.
Hier noch ein list des Devices:
Internals:
DEF myHomeConnectConnection SIEMENS-WT7YH701-68A40E11A618
NAME Trockner_WT7YH701
NR 992
STATE Idle
TYPE HomeConnect
aliasname Trockner
brand SIEMENS
commandPrefix
eventChannelTimeout 1522614497
haId SIEMENS-WT7YH701-68A40E11A618
hcconn myHomeConnectConnection
programs
retrycounter 0
type Dryer
vib WT7YH701
READINGS:
2018-03-30 21:37:33 BSH.Common.Event.ProgramFinished BSH.Common.EnumType.EventPresentState.Present
2018-03-04 14:10:23 BSH.Common.Option.EstimatedTotalProgramTime 8880 seconds
2018-03-04 14:10:23 BSH.Common.Option.FinishInRelative 8880 seconds
2018-03-30 21:37:33 BSH.Common.Option.ProgramProgress 0 %
2018-03-30 21:37:33 BSH.Common.Option.RemainingProgramTime 0 seconds
2018-02-27 19:46:37 BSH.Common.Option.RemainingProgramTimeIsEstimated true
2018-03-30 21:37:33 BSH.Common.Root.ActiveProgram -
2018-03-30 18:18:17 BSH.Common.Root.SelectedProgram LaundryCare.Dryer.Program.Synthetic
2018-03-30 21:37:43 BSH.Common.Status.DoorState BSH.Common.EnumType.DoorState.Open
2018-03-30 21:37:43 BSH.Common.Status.LocalControlActive true
2018-03-30 21:37:33 BSH.Common.Status.OperationState BSH.Common.EnumType.OperationState.Finished
2018-03-30 21:37:43 BSH.Common.Status.RemoteControlActive false
2018-03-18 19:24:34 BSH.Common.Status.RemoteControlStartAllowed false
2018-03-03 17:54:59 LaundryCare.Common.Event.DoorOpen BSH.Common.EnumType.EventPresentState.Off
2018-03-30 21:33:11 LaundryCare.Dryer.Event.DryingProcessFinished BSH.Common.EnumType.EventPresentState.Off
2018-03-30 18:16:17 LaundryCare.Dryer.Option.DryingTarget LaundryCare.Dryer.EnumType.DryingTarget.CupboardDry
2018-01-20 19:49:13 LaundryCare.Dryer.Option.Gentle false
2018-03-04 14:09:22 LaundryCare.Dryer.Option.ProcessPhase LaundryCare.Dryer.EnumType.ProcessPhase.FinishedAntiCrease
2018-01-20 19:49:13 LaundryCare.Dryer.Option.WrinkleGuard LaundryCare.Dryer.EnumType.WrinkleGuard.Min60
2018-04-01 22:28:17 RemainingTime 0
2018-04-01 22:28:17 Status Idle
2018-04-01 17:21:02 state Idle
Attributes:
alias Trockner
group Wäsche
icon scene_clothes_dryer
room Endgeräte,Keller
userReadings RemainingTime { ReadingsNum("Trockner_WT7YH701","BSH.Common.Option.RemainingProgramTime","0")/60 },
Status { ((ReadingsNum("Trockner_WT7YH701","BSH.Common.Option.ProgramProgress","100") == 100 or
ReadingsAge("Trockner_WT7YH701","BSH.Common.Option.ProgramProgress",10801) > 10800) and
(ReadingsVal("Trockner_WT7YH701","BSH.Common.Status.DoorState","BSH.Common.EnumType.DoorState.Open") eq "BSH.Common.EnumType.DoorState.Open" or ReadingsAge("Trockner_WT7YH701","BSH.Common.Status.DoorState",10801) > 10800))?"Idle":"Closed" }
webCmd startProgram:stopProgram
Da ich weder das Trockner-Device noch das Connection-Device deaktivieren kann, habe ich zunächst mal ein Logoff der Connection gemacht.
Irgend eine Idee?
Viele Grüße
Dieter
Hallo RockFan,
habe das gleiche Problem:
Zitat von: Schlimbo am 23 März 2018, 05:05:24
Hallo Stefan,
hatte es jetzt schon drei mal, dass sich mein FHEM aufgehängt hat, das Log ist voll mit der Meldung:
2018.03.23 04:52:06.185 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.185 5: TI123xxx event channel read failed
2018.03.23 04:52:06.186 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.187 5: TI123xxx event channel read failed
2018.03.23 04:52:06.187 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.188 5: TI123xxx event channel read failed
2018.03.23 04:52:06.188 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.189 5: TI123xxx event channel read failed
2018.03.23 04:52:06.190 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.190 5: TI123xxx event channel read failed
2018.03.23 04:52:06.191 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.192 5: TI123xxx event channel read failed
2018.03.23 04:52:06.192 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.193 5: TI123xxx event channel read failed
2018.03.23 04:52:06.193 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.194 5: TI123xxx event channel read failed
2018.03.23 04:52:06.194 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.195 5: TI123xxx event channel read failed
2018.03.23 04:52:06.195 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.196 5: TI123xxx event channel read failed
2018.03.23 04:52:06.196 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.197 5: TI123xxx event channel read failed
2018.03.23 04:52:06.197 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.198 5: TI123xxx event channel read failed
2018.03.23 04:52:06.198 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.199 5: TI123xxx event channel read failed
2018.03.23 04:52:06.200 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.200 5: TI123xxx event channel read failed
2018.03.23 04:52:06.201 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.202 5: TI123xxx event channel read failed
2018.03.23 04:52:06.202 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.203 5: TI123xxx event channel read failed
2018.03.23 04:52:06.203 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.204 5: TI123xxx event channel read failed
2018.03.23 04:52:06.205 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.205 5: TI123xxx event channel read failed
2018.03.23 04:52:06.206 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.207 5: TI123xxx event channel read failed
2018.03.23 04:52:06.207 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.208 5: TI123xxx event channel read failed
2018.03.23 04:52:06.209 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.209 5: TI123xxx event channel read failed
2018.03.23 04:52:06.209 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.210 5: TI123xxx event channel read failed
2018.03.23 04:52:06.211 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.211 5: TI123xxx event channel read failed
2018.03.23 04:52:06.212 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.212 5: TI123xxx event channel read failed
2018.03.23 04:52:06.213 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.213 5: TI123xxx event channel read failed
2018.03.23 04:52:06.214 5: TI123xxx event channel searching for data
2018.03.23 04:52:06.214 5: TI123xxx event channel read failed
Das passiert mit der neuen Version ungefähr zwei mal täglich.
Leider gibt es noch keinen fix.
Da das Modul das disable Attribut nicht unterstützt, habe ich es bei mir erst mal komplett gelöscht.
Moin Dieter,
plage mich seit Tagen mit dem selben Problem herum, und hatte zuerst das (inoffizielle) 37_echodevice Modul in Verdacht, bei dem es in der Vergangenheit auch mal zu ähnlichen Problemen kam. Urlaubsbedingt und aus der Ferne konnte ich aber nicht tiefer in die Fehlersuche einsteigen.
Über Home Connect frage ich eine Waschmaschine ab, die auch nach gebrauch komplett ausgeschaltet wird, d. h. es gibt auch keine "Standby-Verbindung" zu Home Connect.
Gruß
Danny
Hi, haben die Devices vielleicht ein Attribut verbose=5 ? Diese Einträge werden eigentlich nur für die Diagnose gebraucht und sollten normalerweise nicht sichtbar sein. Wenn man gerade nicht auf Fehlersuche ist, sollte dieses Attribut einfach gelöscht werden.
Das Probleme ist ja das FHEM nach einiger Zeit durch das Modul komplett unbedienbar wird.
Das Loglevel habe ich erst später auf fünf gestellt um den Fehler auf die Spur zu kommen.
Ohne verbose 5 sind zwar keine Log Einträge vorhanden, aber FHEM ist trotzdem nicht mehr erreichbar.
Für mich sieht es so aus, als würde das Modul eine Endlosschleife verursachen.
Sytemlast steigt dann auf 99% und es hilft nur noch den FHEM Prozess zu killen.
Nee, "verbose" war entweder gar nicht, oder auf 2 gesetzt.
Gruß
Danny
Meine Ausgangssituation war die Suche nach der Ursache für die hohe CPU-Last. Deshalb hatte ich verbose=5 global gesetzt und dann kamen nach einigen Stunden die Endlosen Logeinträge.
Ob das die 100% CPU verursacht ist natürlich nur spekulativ :-\
Der verbose Level kann eigentlich nicht die Ursache sein, denn da ich zu erst ein anderes Modul in Verdacht hatte, war dieser bei mir im Home Connect Device, als auch global nicht verändert worden.
Ansonsten hat Schlimbo das Problem exakt wie bei mir beschrieben.
Arbeitet jemand an dem Problem, mir hat es jetzt auch das FHEM lahm gelegt und ich habe das Modul erstmal wieder entfernt?
Hallo Zusammen,
habe mir das Problem jetzt mal etwas genauer angesehen.
Das Problem ist diese while-Schleife in "48_HomeConnect.pm":
# read data
while($hash->{conn}->fileno()) {
# check channel data availability
Log3 $hash->{NAME}, 5, "$hash->{NAME} event channel searching for data";
my $nfound = select($rout=$rin, undef, undef, 0);
if($nfound < 0) {
Log3 $hash->{NAME}, 2, "$hash->{NAME} event channel timeout/error: $!";
HomeConnect_CloseEventChannel($hash);
return undef;
}
if($nfound == 0) {
last;
}
my $len = sysread($hash->{conn},$inputbuf,32768);
# check if something was actually read
if (defined($len) && $len > 0 && defined($inputbuf) && length($inputbuf) > 0) {
# process data
Log3 $hash->{NAME}, 5, "$hash->{NAME} event channel received $inputbuf";
# reset timeout
$hash->{eventChannelTimeout} = time();
readingsBeginUpdate($hash);
# split data into lines,
for (split /^/, $inputbuf) {
# check for http result line
if (index($_,"HTTP/1.1") == 0) {
if (substr($_,9,3) ne "200") {
Log3 $hash->{NAME}, 2, "$hash->{NAME} event channel received an http error: $_";
HomeConnect_CloseEventChannel($hash);
return undef;
} else {
# successful connection, reset counter
$hash->{retrycounter} = 0;
}
}
# extract data json elements
if (index($_,"data:") == 0) {
if (length ($_) < 10) { next };
my $json = substr($_,5);
Log3 $hash->{NAME}, 5, "$hash->{NAME} event channel data: $json";
my $parsed = eval {$JSON->decode ($json)};
if($@){
Log3 $hash->{NAME}, 2, "$hash->{NAME} - JSON error reading from event channel";
} else {
# update readings from json elements
my %readings = ();
for (my $i = 0; 1; $i++) {
my $item = $parsed->{items}[$i];
if (!defined $item) { last };
my $key = $item->{key};
$readings{$key}=(defined $item->{value})?$item->{value}:"-";
$readings{$key}.=" ".$item->{unit} if defined $item->{unit};
if ($key eq "BSH.Common.Root.SelectedProgram" &&
defined($hash->{commandPrefix}) && length($readings{$key}) > length($hash->{commandPrefix}) ) {
my $prefixLen = length $hash->{commandPrefix};
$readings{$key} = substr($readings{$key}, $prefixLen);
}
readingsBulkUpdate($hash, $key, $readings{$key});
Log3 $hash->{NAME}, 4, "$key = $readings{$key}";
}
}
# define new device state
my $state;
my $operationState = ReadingsVal($hash->{NAME},"BSH.Common.Status.OperationState","");
my $program = ReadingsVal($hash->{NAME},"BSH.Common.Root.ActiveProgram","");
if (defined($program) && defined($hash->{commandPrefix}) && length($program) > length($hash->{commandPrefix}) ) {
my $prefixLen = length $hash->{commandPrefix};
$program = substr($program, $prefixLen);
}
if ($operationState eq "BSH.Common.EnumType.OperationState.Active" ||
$operationState eq "BSH.Common.EnumType.OperationState.Run") {
$state = "Program $program active";
my $pct = ReadingsVal($hash->{NAME},"BSH.Common.Option.ProgramProgress",undef);
$state .= " ($pct)" if (defined $pct);
} elsif ($operationState eq "BSH.Common.EnumType.OperationState.DelayedStart") {
$state = "Delayed start of program $program";
} else {
$state = "Idle";
}
readingsBulkUpdate($hash, "state", $state) if ($hash->{STATE} ne $state);
}
}
readingsEndUpdate($hash, 1);
} else {
Log3 $hash->{NAME}, 5, "$hash->{NAME} event channel read failed";
}
}
Problem ist, dass wenn die IF Bedingung:
# check if something was actually read
if (defined($len) && $len > 0 && defined($inputbuf) && length($inputbuf) > 0) {
nicht erfüllt ist, die while-Schleife nie beendet wird.
Hier mein erweitertes Log dazu (Ich habe in die Log Ausgabe noch ein paar Variablen aufgenommen und einen LoopCounter eingebaut, der bei 100 Loop Durchgängen die Schleife beendet):
2018.05.07 01:16:30.559 5: TI123xxx event channel searching for data, fileno:"12", nfound:"1", loopCounter:"1"
2018.05.07 01:16:30.562 5: TI123xxx event channel len:"0", received:""
2018.05.07 01:16:30.563 5: TI123xxx event channel read failed
2018.05.07 01:16:30.563 5: TI123xxx event channel searching for data, fileno:"12", nfound:"1", loopCounter:"2"
2018.05.07 01:16:30.563 5: TI123xxx event channel len:"0", received:""
2018.05.07 01:16:30.563 5: TI123xxx event channel read failed
.
.
.
2018.05.07 01:16:30.631 5: TI123xxx event channel searching for data, fileno:"12", nfound:"1", loopCounter:"99"
2018.05.07 01:16:30.632 5: TI123xxx event channel len:"0", received:""
2018.05.07 01:16:30.632 5: TI123xxx event channel read failed
2018.05.07 01:16:30.632 5: TI123xxx event channel searching for data, fileno:"12", nfound:"1", loopCounter:"100"
2018.05.07 01:16:30.632 5: TI123xxx event channel len:"0", received:""
2018.05.07 01:16:30.633 5: TI123xxx event channel read failed
2018.05.07 01:16:30.633 2: TI123xxx event channel fatal error: infinite loop
2018.05.07 01:16:30.633 5: TI123xxx event channel received no more data
Es kommt also gelegentlich vor, dass Daten mit einer Länge von "0" ankommen, was dann die Endlosschleife verursacht.
Habe den Code jetzt so erweitert, dass bei einem "read fail" der Event Channel geschlossen und die Schleife beendet wird:
} else {
Log3 $hash->{NAME}, 5, "$hash->{NAME} event channel read failed";
HomeConnect_CloseEventChannel($hash);
return undef;
Im Anhang mein komplettes Logfile (hier noch ohne die Anpassung bei "read fail") und das angepasste Modul.
Edit 13.05.2018: swhome hat die Anpassungen in seinen master branch übernommen.
Wäre schön, wenn das mal jemand Testen könnte, bei mir gab es seitdem keinen Absturz mehr.
Habe auch noch das "disable" Attribut (https://forum.fhem.de/index.php/topic,87506.0.html) ergänzt und den Fehler beim Einschalten der Kaffeemaschine (https://forum.fhem.de/index.php/topic,85090.0.html) behoben.
Gruß
Schlimbo
Ich habe deine Files jetzt mal übernommen und werde es testen.
Mit den neuen Dateien läuft FHEM seit gestern wieder ohne Ausfälle!
An alle die meine angepasste Version verwenden.
Könnt ihr bitte mal euer Log nach folgenden Einträgen durchsuchen:
2018.05.09 01:16:29.083 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.09 08:10:34.382 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.10 01:16:26.304 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.10 23:56:56.431 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.11 01:16:28.669 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.11 17:57:02.342 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.12 00:16:22.166 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.12 01:16:30.975 2: TI909701HC event channel read failed, len:"0", received:""
2018.05.12 11:57:01.814 2: TI909701HC event channel read failed, len:"0", received:""
Dies wären mit der alten Version alles Abstürze.
Mir ist aufgefallen, dass es jede Nacht um die gleiche Uhrzeit (01:16 Uhr) passiert. Wäre interessant ob bei euch die Zeiten gleich sind.
2018.05.09 00:16:33 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.09 01:16:30 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.09 07:16:52 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.09 08:10:36 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.09 08:10:36 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.10 00:16:35 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.10 01:16:21 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.10 01:16:26 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.10 19:16:54 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.11 00:16:32 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.11 01:16:28 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.11 13:16:53 2: SX558Sxxxx event channel read failed, len:"0", received:""
2018.05.11 13:16:53 2: SX558Sxxxx event channel read failed, len:"0", received:""
Hier sind meine letzten Einträge.
2018.05.10 23:47:39 2: WAYHXXXX event channel read failed, len:"0", received:""
2018.05.10 23:52:46 2: WTYHXXXX event channel read failed, len:"0", received:""
2018.05.11 00:16:25 2: WAYHXXXX event channel read failed, len:"0", received:""
2018.05.11 00:16:26 2: WTYHXXXX event channel read failed, len:"0", received:""
2018.05.11 01:16:21 2: WAYHXXXX event channel read failed, len:"0", received:""
2018.05.11 11:46:47 2: WAYHXXXX event channel read failed, len:"0", received:""
2018.05.11 11:46:47 2: WTYHXXXX event channel read failed, len:"0", received:""
Mein Log seit gestern ...
Hab´s erst seit gestern wieder aktiviert, aber um 01:16 bin ich auch dabei:
2018.05.11 01:16:30 2: WAYHxxxx event channel read failed, len:"0", received:""
Moin, hier mein LOG von heute:
2018.05.11 18:28:52 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.11 18:28:57 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.11 21:04:38 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.11 21:04:48 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.11 23:34:38 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.11 23:34:48 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 00:16:26 2: SN878D26PE event channel read failed, len:"0", received:""
2018.05.12 00:16:26 2: HN878G4B6 event channel read failed, len:"0", received:""
2018.05.12 01:16:30 2: SN878D26PE event channel read failed, len:"0", received:""
2018.05.12 01:16:30 2: CS858GRB6 event channel read failed, len:"0", received:""
2018.05.12 01:16:30 2: EX907KXX1E event channel read failed, len:"0", received:""
2018.05.12 01:16:30 2: HN878G4B6 event channel read failed, len:"0", received:""
2018.05.12 04:10:26 2: SN878D26PE event channel timeout, two keep alive messages missing
2018.05.12 04:10:26 2: CS858GRB6 event channel timeout, two keep alive messages missing
2018.05.12 04:10:26 2: EX907KXX1E event channel timeout, two keep alive messages missing
2018.05.12 04:10:26 2: HN878G4B6 event channel timeout, two keep alive messages missing
2018.05.12 08:05:09 3: hcconn refreshing token
2018.05.12 08:59:09 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.12 09:07:34 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 10:25:59 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.12 10:26:09 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 10:54:21 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.12 10:54:46 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 12:44:08 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.12 12:44:18 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 13:04:45 3: ENIGMA2 set VU_WZ msg info 2 GS%5fAUF
2018.05.12 13:04:55 3: ENIGMA2 set VU_WZ msg info 2 GS%5fZU
2018.05.12 14:06:19 2: SN878D26PE event channel read failed, len:"0", received:""
2018.05.12 14:06:19 2: CS858GRB6 event channel read failed, len:"0", received:""
2018.05.12 14:06:19 2: EX907KXX1E event channel read failed, len:"0", received:""
2018.05.12 14:06:19 2: HN878G4B6 event channel read failed, len:"0", received:""
Bisher keine Abstürze!! 8)
Also, was alle gemeinsam haben ist der Eintrag um 01:16Uhr die anderen Einträge decken sich nur vereinzelt.
Sieht für mich irgendwie so aus, als würde der HomeConnect Server die Event Channels ab und an selbst beenden, richtig erklären kann ich mir das aber auch nicht.
Da die Version ja bei allen ohne Abstürze läuft, würde ich vorschlagen diese offiziell einzuchecken.
Das Loglevel für "event channel read failed" sollte vorher wieder auf 5 gesetzt werden, damit das Logfile "sauber" bleibt.
@swhome: könntest du das bitte einchecken?
Ich habe Stefan angeschrieben, weiß aber nicht wie zeitnah er dazu kommt.
Wie schaut es denn mit den Verzögerungen der Events aus, kann man diese Verzögerung noch wegbekommen oder muss man damit leben?
Gruß und vielen Dank für deine Unterstützung!
Pf@nne
Hast du mit der Version noch immer Verzögerungen bei den Events? Ich hatte mit Stefan's letzten Version damit keine Probleme mehr.
Wie schnell reagiert das Modul den bei dir?
Hast du etwas mit Tür?
Bei mir liegen immer noch gut 3-6 Sekunden zwischen dem Öffnen/Schließen der Ofentür und dem Eventuell im Modul.
Zum Ableiten einer direkten Reaktion z.B. anschalten der Küchenbeleuchtung ist das eher ungeeignet.
Was bei laufendem Programm passiert habe ich noch nicht getestet.
Das ging bisher garniert, das Event ist Teilweise 10 Minuten später gekommen.
Leider kommen wir nicht lokal auf die Geräte.....
Die HomeConnect App greift auch lokal zu, das ist dann auch ohne merkliche Verzögerung.
Gruß
Pf@nne
@all:
Habe die Version in meinem Beitrag noch mal aktualisiert. Habe noch einen Fehler gefunden, der zum Absturz bei "set SelectedProgram" führen konnte.
@Pf@nne:
Habe leider kein Gerät mit Tür, bei meiner Kaffeemaschine kommen die Events ohne spürbare Verzögerung an, allerdings kann es sein, dass mir hier die 3-6 Sekunden auch bloß nicht auffallen.
Vielleicht kann Stefan hierzu noch was sagen, habe mir die Event Geschichte noch nicht im Detail angesehen.
Kannst du bitte für die geänderte Version einen PullRequest erstellen.
Stefan Check das dann ein.
Vielen Dank für deinen Einsatz!
Gruß
Pf@nne
Ich teste es noch kurz und checke es dann ein. Pull Request machen wir nächstes Mal ;)
...Update: Die Änderungen von Schlimbo sind in der master Version eingecheckt. VIELEN DANK!
Das mit der Tür probiere ich aus sobald die Sonne untergegangen ist. Erst dann ist meine Küchenbeleuchtung mit der Spülertür synchronisiert :D
super, Danke!
Freut mich, dass ich helfen konnte :)
Hab gerade noch eine Mini-Änderung nachgeschossen, damit das Attribut "updateTimer" wieder setzbar ist.
Für das Thema mit der Tür noch folgende Anmerkung:
Die letzten Änderungen von Schlimbo und mir hatten zum Ziel, bei Geräten mit sehr vielen Updates zeitnah und schnell genug verarbeiten zu können. Beispiele waren der Backofen oder die Kaffeemaschine mit laufendem Programm. Eine geringere Verzögerung bei einzelnen Updates hingegen kann durch das Setzen des Attributs updateTimer bei der betreffenden Maschine erzielt werden. Hier steht der Standardwert auf 5 Sekunden um in FHEM Ressourcen für wichtigere Dinge freizuhalten. Wenn schneller reagiert werden soll, ist auch der Wert 1 ok.
Zitat von: swhome am 13 Mai 2018, 18:38:53
Hab gerade noch eine Mini-Änderung nachgeschossen, damit das Attribut "updateTimer" wieder setzbar ist.
Der gleiche Fehler hat sich auch bei "accessScope" in der 48_HomeConnectConnection.pm eingeschlichen.
Stimmt. Hab ich nun auch behoben. Merci!