Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current

Begonnen von QuesT, 30 Oktober 2014, 21:34:58

Vorheriges Thema - Nächstes Thema

gero

Ich kann morgen mal nachsehen, ob ich noch alte Logfiles habe. In den mir vorliegenden  Files besteht das Problem seit Anfang Oktober. Allerdings gab es anfänglich immer noch nach jedem disconnect ein reappear, später nicht mehr.

In der Datei 14_CUL_MAX.pm scheinen laut svn die letzten Änderungenam 22.3.2014 gemacht worden zu sein. Matthias hat damals zwei Patches von mir eingepflegt.

Heute ist der Fehler nach über einer Woche Ruhe wieder aufgetreten:


2014.11.13 19:23:15 1: CUL_MAX_Parse: len mismatch
2014.11.13 19:23:18 1: /dev/ttyACM0 disconnected, waiting to reappear (CUL_0)
2014.11.13 19:23:22 1: Error in CUL_MAX_SendQueueHandler: CUL CUL_0 did not answer request for current credits. Waiting 5 seconds.


Im dmesg Output sieht man kein USB disconnect.
Ein Neustart von fhem hat diesmal gereicht, den Fehler zu beheben.


Gruß,
Gero

P.S.: Meine weiter oben beschriebenen Fehlerbilder sind hinfällig. Es haben sich bei mir zwei verschiedene Fehler vermischt.

Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

gero

Um den Fehler zu lokalisieren, wäre es hilfreich wenn jemand, bei dem der Fehler häufiger auftritt in der Datei 14_CUL_MAX.pm in Zeile 248
Log 1, "CUL_MAX_Parse: len mismatch";
durch
Log 1, "CUL_MAX_Parse: len mismatch ($rmsg)";
ersetzen kann.

Das Problem scheint übrigens schon älter zu sein:
http://forum.fhem.de/index.php/topic,19453.msg130724.html#msg130724

Ich vermute den Fehler im MAX-Teil der culfw. Der CUL scheint irgendetwas zu empfangen, was ihn durcheinanderbringt. Warum der Fehler zur Zeit verstärkt auftritt, ist mir allerdings noch ein Rätsel. Mal sehen...

Gruß,
Gero
Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

hyper2910

ist geändert und fhem neugestartet.

also bis zum 09.10. gab es diese Meldung bei mir nicht.

erst danach, jedoch habe ich diese Logs nicht mehr.




Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

SirUli

2014.11.13 23:04:20 1: CUL_MAX_Parse: len mismatch (Z0CBF044202A5A0021DD90022D215
Z0EBF0202021DD902A5A000011800221F
**T0C4000A619F0
Z0CEF044201D2F50000000022C900
21 524 )
2014.11.13 23:04:23 1: /dev/ttyAMA0 disconnected, waiting to reappear (SCC1)


Kam ja direkt  ;)

hyper2910

in der Nacht war der Disconnect da:

014.11.14 04:26:38 1: CUL_MAX_Parse: len mismatch (Z0C5004420789030000000025E7F4
21  900
)
2014.11.14 04:26:42 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 04:26:43 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 04:26:48 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

hyper2910

und nach einem Batteriewechsel direkt wieder:

014.11.14 06:54:17 3: CUL_MAX_Parse: Re-Pairing device 078903 of type WallMountedThermostat with serial KEQ0065278
2014.11.14 06:54:18 1: CUL_MAX_Parse: len mismatch (Z0A000A0307890312345600F8
21  900
)
2014.11.14 06:54:22 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 06:54:23 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

gero

Danke für den Input!

Leider habe ich heute und wahrscheinlich auch am Wochenende sehr wenig Zeit. Daher teile ich mal meine bisherige Analyse, die nicht unbedingt richtig sein muß. Aber vielleicht hat jemand etwas mehr Zeit oder kommt auf den richtigen Gedanken:

Fehlerbild: Nach einem "len mismatch" wird ein "disconnect" gemeldet.

Ich habe den Fehler in allen meinen Logfiles gefunden (seit Februar 2014, ältere Logfiles habe ich nicht mehr). ALLERDINGS gab es bis Anfang Oktober immer ein "reappear" nach dem disconnect. Daher ist der Fehler nicht aufgefallen. Vielleicht ist das auch der Grund dafür, dass zur Zeit vermehrt Probleme gemeldet werden.

Die Ursache für den "len mismatch" scheint darin zu liegen, dass mehr als eine Nachricht vom CUL ausgelesen wird.
Wer ist für das Zerlegen der empfangenen Daten in einzelne Nachrichten zuständig? (00_CUL.pm oder 14_CUL_MAX.pm)

In den Beispielen oben, z.B.
2014.11.14 06:54:18 1: CUL_MAX_Parse: len mismatch (Z0A000A0307890312345600F8
21  900
)

ist ein korrektes MAX-Telegram UND die Antwort auf die credit-Abfrage enthalten.
Da die Funktion CUL_Get daher keine Antwort auf die credit-Abfrage bekommt, wird DevIo_Disconnected aufgerufen, das zu einem Löschen des Filedescriptors führt. Dadurch laufen auch alle folgenden Anfragen an den CUL ins Leere.

Was ich noch nicht klären konnte, ist warum der CUL nicht mehr wie früher wieder auftaucht ("reappear").

Mittlerweile bin ich mir ziemlich sicher, dass der Fehler doch in fhem liegt und nicht in der CUL-Firmware.
Um den Fehler zu beheben sollte zuerst das Parsing der vom CUL empfangenen Daten korrigiert werden.
Zusätzlich muß geklärt werden, warum der "reappear"-Mechanismus nicht mehr arbeitet.

Vielleicht hat Rudolf ein paar Ideen oder Antworten.

Gruß,
Gero
Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

stgeran

Schade, ich wollte versuchen, ob der CSM die MAX! Sache übernehmen kann und der CUL das slowrf um festzustellen ob es am CUL liegt. Leider unterstützt CSM den MAX! Mode nicht. Also weiterhin auf Besserung hoffen.
FHEM auf Raspberry
CSM 866MHz für EM1010 mit Strom und Gaszähler
CUL 866MHz für MAX! Radiator Thermostat 
CUL 433MHz für Innen und Aussen Temp
HMLAN für HM-LC-Sw1-PI-2

gero

Zitat von: gero am 14 November 2014, 08:03:23
Die Ursache für den "len mismatch" scheint darin zu liegen, dass mehr als eine Nachricht vom CUL ausgelesen wird.
Wer ist für das Zerlegen der empfangenen Daten in einzelne Nachrichten zuständig? (00_CUL.pm oder 14_CUL_MAX.pm)

Okay, ich habe die Stelle gefunden. in CUL_Read (00_CUL.pm) werden die empfangenen Nachrichten segmentiert:
  while($culdata =~ m/\n/) {
    my $rmsg;
    ($rmsg,$culdata) = split("\n", $culdata, 2);
    $rmsg =~ s/\r//;
    CUL_Parse($hash, $hash, $name, $rmsg) if($rmsg);
  }

Demnach dürfte niemals eine Nachricht mit Zeilenumbrüchen bei CUL_MAX_Parse landen.
Aber diese Ausgabe sieht doch stark danach aus:
2014.11.14 06:54:18 1: CUL_MAX_Parse: len mismatch (Z0A000A0307890312345600F8
21  900
)

Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

gero

Entschuldigt, wenn ich hier meine Gedanken ungefiltert teile, aber ich weiß nicht, wieviel Zeit ich heute noch investieren kann.

Das Problem wird nicht durch CUL_Read verursacht, denn dort werden die Nachrichten sauber segmentiert. Das Problem ist die Abfrage der credits mittels CUL_Get, das wiederum CUL_ReadAnswer aufruft.
In CUL_ReadAnswer werden alle empfangenen Daten sobald sie nicht der regexp entspechen an CUL_Parse weitergegeben, ohne evtl. mehrere Nachrichten vorher zu trennen:

    if($mculdata =~ m/\r\n/ || $anydata || $mculdata =~ m/\n\n/ ) {
      (undef, $mculdata) = CUL_prefix(0, $ohash, $mculdata); # Delete prefix
      if($regexp && $mculdata !~ m/$regexp/) {
        CUL_Parse($ohash, $hash, $ohash->{NAME}, $mculdata);
      } else {
        return (undef, $mculdata)
      }
    }


Das ist leider sehr unschön :(
In unserem Fall liest CUL_ReadAnswer nicht nur die Antwort auf die credits-Abfrage sondern auch Nachrichten vom CUL, die bisher noch nicht abgeholt wurden. Da die regexp dann nicht passt, werden alle Daten an CUL_Parse weitergegen, die damit nichts anfangen kann (-> "len mismatch") und CUL_Get (Anfrage der credits) geht leer aus und erzeugt das "disconnect".

Ich hoffe, Rudolf König schaut hier nochmal rein und gibt seine Meinung dazu ab.

Ein zweites ungelöstes Problem bleibt, warum das automatische reopen nicht mehr funktioniert. Ich habe irgendwie das Gefühl, dass es mit den Änderungen an 00_CUL.pm vom 12.10.14 zu tun hat, kann es aber noch nicht nachvollziehen.

Als ersten Workaround, um den WAF wieder zu heben, könnte ein notify auf das DISCONNECTED event vom CUL sein, das dann ein reopen ausführt.

So etwas in der Art wie:


define CUL_0_not notify CUL_0:DISCONNECTED set CUL_0 reopen


Gruß,
Gero
Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

hyper2910

Andere Lösung die alte 00_CUL.pm nutzen.


anbei eine CuL vom 06.05.14


Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

SirUli

Erstmal tausend Dank an dich gero!

Zitat von: gero am 14 November 2014, 10:03:02
Demnach dürfte niemals eine Nachricht mit Zeilenumbrüchen bei CUL_MAX_Parse landen.
Ich kann dir gerne auch das originale Logfile geben - aber da sind definitiv Zeilenumbrücke drin. Ich habe mir das logfile grad mal im vi angeschaut und sehe dort noch die "\r" Zeilenumbrüche drin - siehe Anhang.

Wenn ich das Logfile einmal durch:
sed "s/\r//g" fhem-2014-11.log > fhem-debug.log
Jage, dann sind die zumindest mal weg.

Deine weiteren Gedanken habe ich mal kurz nachvollzogen - was wohl nicht mehr geht seit der Änderung ist der automatische reopen, denn wenn ich die 00_CUL.pm mit der Versionskennzeichnung "# $Id: 00_CUL.pm 6755 2014-10-12 13:12:10Z rudolfkoenig $" gegen die mit der "# $Id: 00_CUL.pm 6526 2014-09-09 15:12:39Z thomyd $" tausche, dann sieht das log so aus:

2014.11.14 12:22:22 3: SCC1 device opened
2014.11.14 12:22:22 3: SCC1: Possible commands: mBCFiAZGMRTVWXef*ltux
2014.11.14 12:22:22 2: Switched SCC1 rfmode to MAX
2014.11.14 12:22:22 3: SCC2: Possible commands: mBCFiAZGMRTVWXef*ltux
2014.11.14 12:22:22 2: Switched SCC2 rfmode to SlowRF
2014.11.14 12:22:22 3: SCC3: Possible commands: mBCFiAZGMRTVWXef*ltux
2014.11.14 12:23:28 1: Including ./log/fhem.save
2014.11.14 12:23:29 2: Hi
2014.11.14 12:23:29 0: Server started with 108 defined entities (version $Id: fhem.pl 6913 2014-11-08 10:32:44Z rudolfkoenig $, os linux, user root, pid 16535)
2014.11.14 12:23:30 1: CUL_MAX_Parse: len mismatch (Z0CD6044202A5A002474B0017C81C
Z0C06044201D2F50000000022C6E1
21  525
)
2014.11.14 12:23:33 1: /dev/ttyAMA0 disconnected, waiting to reappear (SCC1)
2014.11.14 12:23:33 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 12:23:33 3: telnetForBlockingFn: port 55664 opened
2014.11.14 12:23:34 3: Setting SCC1 baudrate to 38400
2014.11.14 12:23:34 1: /dev/ttyAMA0 reappeared (SCC1)
2014.11.14 12:23:34 3: SCC1: Possible commands: mBCFiAZGMRTVWXef*ltux


Das macht zwar das Parser-Problem nicht besser, aber er kommt wenigstens wieder hoch und spricht wieder mit meinen Heizkörpern und diese können auch wieder mit FHEM sprechen....

gero

Zitat von: SirUli am 14 November 2014, 12:28:45
Ich kann dir gerne auch das originale Logfile geben - aber da sind definitiv Zeilenumbrücke drin. Ich habe mir das logfile grad mal im vi angeschaut und sehe dort noch die "\r" Zeilenumbrüche drin - siehe Anhang.
Wie schon geschrieben, das Problem ist die Weiterleitung der Nachricht aus der Funktion CUL_ReadAnswer und nicht aus der Funktion CUL_Read, wie ich anfangs vermutet hatte.

Ich denke an dieser Stelle sollten wir auf ein Feedback von Rudolf warten. Ich kann zwar versuchen die Funktion CUL_ReadAnswer zu fixen, aber ob dann noch alles in anderen Modulen funktioniert, kann ich nicht abschätzen.

Gruß,
Gero
Odroid C1 - CULV3-868, JeeLink
16 x TX 29 DTH
MAX!: 15x Heizkörperthermostat+, 2x Wandthermostat, 14x Fenserkontakt, 1x Ecotaster
FS20 S4A, FS20IRF, BSB-Heizungssteuerung über Atmega2560
Z-Wave: ZME_UZB1, Fibaro Wall Plug + Motion Sensor

pklaus

Zitat von: hyper2910 am 14 November 2014, 12:26:53
Andere Lösung die alte 00_CUL.pm nutzen.

Danke! Mit der Version scheint es nun erst einmal wieder zu funktionieren. (Ob für mehr als 24 Stunden, wird sich zeigen – ich hoffe es!)

stgeran

Das Problem
PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
gibt es aber auch noch. Hoffentlich haben die beiden nichts miteinander zu tun.
FHEM auf Raspberry
CSM 866MHz für EM1010 mit Strom und Gaszähler
CUL 866MHz für MAX! Radiator Thermostat 
CUL 433MHz für Innen und Aussen Temp
HMLAN für HM-LC-Sw1-PI-2