Autor Thema: Home Connect: Tausende Logeinträge  (Gelesen 1862 mal)

Offline RockFan

  • New Member
  • *
  • Beiträge: 20
Home Connect: Tausende Logeinträge
« 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
     
Raspbian (Jessi) auf Raspberry Pi 3 / FHEM 5.8 / CUL + RFXTRX + TCM / FS20, FHT 80B, S300TH, Intertechno, DMX, Milight, EnOcean, Homematic, AMAD, Home Connect, MiSmartHome, Yeelight, ...

Offline Schlimbo

  • Sr. Member
  • ****
  • Beiträge: 561
Antw:Home Connect: Tausende Logeinträge
« Antwort #1 am: 02 April 2018, 10:28:01 »
Hallo RockFan,
habe das gleiche Problem:
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.


Offline moskito

  • Jr. Member
  • **
  • Beiträge: 58
  • No RISC - no fun
Antw:Home Connect: Tausende Logeinträge
« Antwort #2 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
FHEM auf Banana Pi (jessie) + HM-CFG-USB + CC1101 + Rademacher USB + Phillips HUE

Offline swhome

  • Moderator
  • Full Member
  • ***
  • Beiträge: 225
Antw:Home Connect: Tausende Logeinträge
« Antwort #3 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.
Im Einsatz: FHEM auf Raspberry Pi mit 350 devices, hauptsächlich Homematic Wired und HM-Heizungsregler, dazu diverse Eigenbauten für Fussbodenheizung und LED Beleuchtung. Und jetzt mit Alexa!

Offline Schlimbo

  • Sr. Member
  • ****
  • Beiträge: 561
Antw:Home Connect: Tausende Logeinträge
« Antwort #4 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.
« Letzte Änderung: 04 April 2018, 20:27:53 von Schlimbo »

Offline moskito

  • Jr. Member
  • **
  • Beiträge: 58
  • No RISC - no fun
Antw:Home Connect: Tausende Logeinträge
« Antwort #5 am: 04 April 2018, 21:05:48 »
Nee, "verbose" war entweder gar nicht, oder auf 2 gesetzt.

Gruß
Danny
FHEM auf Banana Pi (jessie) + HM-CFG-USB + CC1101 + Rademacher USB + Phillips HUE

Offline RockFan

  • New Member
  • *
  • Beiträge: 20
Antw:Home Connect: Tausende Logeinträge
« Antwort #6 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  :-\
Raspbian (Jessi) auf Raspberry Pi 3 / FHEM 5.8 / CUL + RFXTRX + TCM / FS20, FHT 80B, S300TH, Intertechno, DMX, Milight, EnOcean, Homematic, AMAD, Home Connect, MiSmartHome, Yeelight, ...

Offline moskito

  • Jr. Member
  • **
  • Beiträge: 58
  • No RISC - no fun
Antw:Home Connect: Tausende Logeinträge
« Antwort #7 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.
« Letzte Änderung: 05 April 2018, 06:52:10 von moskito »
FHEM auf Banana Pi (jessie) + HM-CFG-USB + CC1101 + Rademacher USB + Phillips HUE

Offline gloob

  • Hero Member
  • *****
  • Beiträge: 2274
Antw:Home Connect: Tausende Logeinträge
« Antwort #8 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?
Raspberry Pi 3 | miniCUL 433MHz | nanoCUL 868 MHz | nanoCUL 433 MHz | MySensors WLAN Gateway | LaCrosse WLAN Gateway | SignalESP 433 MHz | SignalESP 868 MHz | HM-MOD-UART WLAN Gateway | IR - 360 Grad WLAN Gateway

Offline Schlimbo

  • Sr. Member
  • ****
  • Beiträge: 561
Antw:Home Connect: Tausende Logeinträge
« Antwort #9 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 ergänzt und den Fehler beim Einschalten der Kaffeemaschine behoben.


Gruß
Schlimbo
« Letzte Änderung: 13 Mai 2018, 18:22:42 von Schlimbo »

Offline gloob

  • Hero Member
  • *****
  • Beiträge: 2274
Antw:Home Connect: Tausende Logeinträge
« Antwort #10 am: 08 Mai 2018, 07:17:11 »
Ich habe deine Files jetzt mal übernommen und werde es testen.
Raspberry Pi 3 | miniCUL 433MHz | nanoCUL 868 MHz | nanoCUL 433 MHz | MySensors WLAN Gateway | LaCrosse WLAN Gateway | SignalESP 433 MHz | SignalESP 868 MHz | HM-MOD-UART WLAN Gateway | IR - 360 Grad WLAN Gateway

Offline Todie

  • New Member
  • *
  • Beiträge: 4
Antw:Home Connect: Tausende Logeinträge
« Antwort #11 am: 11 Mai 2018, 12:12:04 »
Mit den neuen Dateien läuft FHEM seit gestern wieder ohne Ausfälle!

Offline Schlimbo

  • Sr. Member
  • ****
  • Beiträge: 561
Antw:Home Connect: Tausende Logeinträge
« Antwort #12 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.
« Letzte Änderung: 12 Mai 2018, 18:52:19 von Schlimbo »

Offline gloob

  • Hero Member
  • *****
  • Beiträge: 2274
Antw:Home Connect: Tausende Logeinträge
« Antwort #13 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.
Raspberry Pi 3 | miniCUL 433MHz | nanoCUL 868 MHz | nanoCUL 433 MHz | MySensors WLAN Gateway | LaCrosse WLAN Gateway | SignalESP 433 MHz | SignalESP 868 MHz | HM-MOD-UART WLAN Gateway | IR - 360 Grad WLAN Gateway

Offline Todie

  • New Member
  • *
  • Beiträge: 4
Antw:Home Connect: Tausende Logeinträge
« Antwort #14 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 ...