FHEM Forum

FHEM - Hausautomations-Systeme => Home Connect => Thema gestartet von: RockFan am 01 April 2018, 22:39:16

Titel: Home Connect: Tausende Logeinträge
Beitrag von: RockFan am 01 April 2018, 22:39:16
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
     
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 02 April 2018, 10:28:01
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.

Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: moskito am 02 April 2018, 10:38:49
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
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: swhome am 04 April 2018, 20:08:11
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 04 April 2018, 20:23:32
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: moskito am 04 April 2018, 21:05:48
Nee, "verbose" war entweder gar nicht, oder auf 2 gesetzt.

Gruß
Danny
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: RockFan am 04 April 2018, 21:50:25
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  :-\
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: moskito am 05 April 2018, 06:50:34
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: gloob am 02 Mai 2018, 11:06:32
Arbeitet jemand an dem Problem, mir hat es jetzt auch das FHEM lahm gelegt und ich habe das Modul erstmal wieder entfernt?
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 08 Mai 2018, 05:43:48
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
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: gloob am 08 Mai 2018, 07:17:11
Ich habe deine Files jetzt mal übernommen und werde es testen.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Todie am 11 Mai 2018, 12:12:04
Mit den neuen Dateien läuft FHEM seit gestern wieder ohne Ausfälle!
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 11 Mai 2018, 12:59:08
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: gloob am 11 Mai 2018, 13:22:56

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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Todie am 11 Mai 2018, 13:42:23
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 ...
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: moskito am 11 Mai 2018, 13:44:49
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:""
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Pf@nne am 12 Mai 2018, 14:25:06
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)
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 12 Mai 2018, 19:36:43
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?

Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Pf@nne am 12 Mai 2018, 20:39:48
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
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 12 Mai 2018, 20:48:05
Hast du mit der Version noch immer Verzögerungen bei den Events? Ich hatte mit Stefan's letzten Version damit keine Probleme mehr.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Pf@nne am 12 Mai 2018, 23:15:32
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   
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 13 Mai 2018, 12:43:07
@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.



Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Pf@nne am 13 Mai 2018, 16:57:16
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
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: swhome am 13 Mai 2018, 17:44:51
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
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 13 Mai 2018, 18:30:13
super, Danke!
Freut mich, dass ich helfen konnte  :)
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: swhome am 13 Mai 2018, 18:38:53
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: Schlimbo am 13 Mai 2018, 18:55:03
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.
Titel: Antw:Home Connect: Tausende Logeinträge
Beitrag von: swhome am 13 Mai 2018, 20:17:32
Stimmt. Hab ich nun auch behoben. Merci!