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

QuesT

Hallo,

weis nicht genau wohin damit.
Hab seit ein Tagen folgende Meldungen im log:

Was kann ich da tun?


2014.10.30 19:22:53 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:22:53 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:22:53 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:22:53 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:22:54 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:22:54 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:22:54 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:22:54 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:22:55 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:22:55 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:22:55 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:22:55 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:22:57 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:22:57 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:22:57 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:22:57 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:22:57 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:22:59 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:22:59 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:22:59 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:22:59 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:23:02 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:04 1: 127.0.0.1:1234 disconnected, waiting to reappear (hmusb)
2014.10.30 19:23:04 1: HMLAN_Parse: hmusb new condition disconnected
2014.10.30 19:23:04 1: 127.0.0.1:1234 reappeared (hmusb)
2014.10.30 19:23:04 1: HMLAN_Parse: hmusb new condition init
2014.10.30 19:23:05 1: HMLAN_Parse: hmusb new condition ok
2014.10.30 19:23:07 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:12 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:17 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:22 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:27 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:32 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:37 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:42 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:47 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:52 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:23:57 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:02 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:07 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:12 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:17 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:22 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:27 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:32 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:37 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:42 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:47 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:52 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:24:57 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:25:02 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 19:25:07 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.

hyper2910

habe ich auch, es hängt wohl mit einem Update nach dem 10.10. zusammen.

bei mir sieht es so aus:
14.10.30 22:14:41 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 22:14:46 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 22:14:51 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.10.30 22:14:56 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds


und dann läuft es irgendwann wieder.
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

QuesT

Hallo,

stimmt dürfte hinkommen.
Hmm hoffe es hat wer ein Fix dafür.

hyper2910

Hi,


so ich hatte jetzt ein Update der MAX Module angeboten bekommen:
habe immer noch folgendes:

2014.11.03 08:30:03 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 574.
2014.11.03 08:30:03 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 587.


desweiteren bekomme ich immer nach ca. 2Tagen dieses:

2014.11.03 07:40:16 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 574.
2014.11.03 07:40:16 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 587.
2014.11.03 07:40:16 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:21 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:26 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:31 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:36 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:41 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:46 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:51 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:40:56 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:01 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:06 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:12 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:17 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:22 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:27 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:32 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:37 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:42 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:47 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:52 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:41:57 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:02 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:07 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:12 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:17 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:22 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:27 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:32 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.03 07:42:37 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,

deune

Hallo Zusammen,

den beschriebenen Fehler habe ich auch - MAX ist bei mir nicht mehr prozesssicher.

WAF = -1000.

Auf dem CUL habe ich die aktuellste Firmware, aber dennoch wird nach einem fhem Neustart
das Max System immer träger, bis es dann nach ca. 18h ausfällt und mir das Log mit tausenden
Zeilen voll müllt.

Mach ich da was falsch?

Liebe Grüße aus der Eifel

Holger

hyper2910

Hi,

ich glaube das der Verantwortliche Matthias vom Modul nichts mehr macht.

Bei mir lief es jetzt auch ca. 18Std. durch und der Fehler war wieder da. Neustart und alles gut.

Vielleicht kann sich mal ein Programmierer das ansehen.!
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

Palm_Maniac

Hallo,

das gleiche Problem mit den selben Meldungen stellt sich auch b ei mir dar. Ich denke seit einer knappen Woche kommt es erst zu diesen Meldungen bei mir. Mal abgesehen davon, dass sich das Log File extrem schnell füllt, werden in dieser Phase auch keine Logfiles der Komponenten mehr geführt. Ich sehe das daran, dass die Grafen der Temp-Verläufe dann leer sind. Hoffentlich gibt es dafür bald eine Lösung, denn sonst muß ich erst mal wieder Back tu the Roots, also zum Cube. :(

Palm_Maniac

Hallo,

ich hab vorgestern mal meinen Raspi eine Rundumpflege verpasst, in dem ich das Linux aktualisiert habe. Alte Log-Files und Backups gelöscht usw. Dann bin ich in FHEM mal einem rumzickenden HT auf den Grund gegangen und habe ihn wieder zum "Mitspielen" bewegen können. Zuletzt habe ich die Firmware im CUL uf V1.61 aktualisiert. Alles in der Hoffnung, dass sich diese Meldungen verabschieden.

Heute dann die ernüchterung. Es hat nichts gebracht. Das Log ist wieder voll, das Interface reagiert extrem träge und es werden keine neuen Daten die grafischen Logfiles geschrieben.

Das ganze Elend wird mit folgendem Eintrag eingeleitet:

2014.11.08 12:04:18 2: CULMAX: unknown message 21  900
Z0F0104600363C10000000098482C00CA25

2014.11.08 12:04:21 1: /dev/ttyACM0 disconnected, waiting to reappear (CULMAX)


Und danach dann wieder nur noch diese hier:

2014.11.08 12:04:21 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:23 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:28 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:33 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:38 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:43 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:48 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:53 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:04:58 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:03 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:08 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:13 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:18 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:23 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:28 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:33 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:38 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:43 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:48 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:53 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:05:58 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:06:03 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.
2014.11.08 12:06:08 1: Error in CUL_MAX_SendQueueHandler: CUL CULMAX did not answer request for current credits. Waiting 5 seconds.


Das bläht die Logfiles gigantisch auf. In diesen Momenten geht hier Steuertechnisch alles nur noch im Zeitlupentempo oder garnicht. Ein Shutdown Restart Befehl löst das Problem bis zum nächsten Mal.

Gibt es denn dafür keine Lösung, keinen Lösungsansatz? Was kann ich tun, was können wir tun um das Problem los zu werden?

gero

Ich habe das Problem seit ca. 4 Wochen, dass mein CUL sich ca. einmal am Tag aufhängt. Vorher lief er mit derselben Firmware 1 Jahr ohne Probleme. Zuerst dachte ich an einen Hardware-Defekt, aber da sich die Meldungen häufen, liegt es vielleicht doch an einer Änderung in FHEM. Zur Info: Der CUL wird bei mir zur Ansteuerung von MAX Komponenten verwendet. Nachdem fhem ein  disconnect von ttyACM0 meldet hilft bei mir meist nur ein stromlosschalten vom Raspberry. Im syslog bzw. dmesg Output wird nichts verdächtiges vom USB-Treiber gemeldet. Führe ich nur ein reboot durch, schlägt das Enumerieren von CUL auf USB-Ebene fehl. Der Raspberry ist nicht Schuld. Den habe ich schon ausgetauscht. Strom Versorgungsprobleme kann ich auch ausschließen.

Gruß,
Gero

P.S. Zur Zeit läuft der CUL seit 3 Tagen ohne disconnect!
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

Heute war nach ca. 6Stunden Schluss,  gestern lief es bald 20 Stunden.   So sieht es immer im log aus.

2014.11.09 02:26:55 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 574.
2014.11.09 02:26:55 1: CUL_MAX_Parse: len mismatch
2014.11.09 02:26:55 1: CUL_MAX_Parse: len mismatch
2014.11.09 02:26:58 1: /dev/ttyACM0 disconnected, waiting to reappear (CUL868)
2014.11.09 02:26:59 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.09 02:26:59 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/14_CUL_MAX.pm line 587.
2014.11.09 02:27:00 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.09 02:27:06 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5



14.11.08 20:17:01 1: sendEmail Text: Arbeitszimmer battery: low
2014.11.08 20:17:05 1: sendEmail returned: Nov 08 20:17:05 raspberrypi sendEmail[17165]: Email was sent successfully! 2014.11.08 20:17:05 3: Arbeitszimmer: Batteriewarnung battery: low
2014.11.08 20:17:10 1: CUL_MAX_Parse: len mismatch
2014.11.08 20:17:13 1: /dev/ttyACM0 disconnected, waiting to reappear (CUL868)
2014.11.08 20:17:14 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.08 20:17:15 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.08 20:17:20 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.08 20:17:25 1: Error in CUL_MAX_SendQueueHandler: CUL CUL868 did not answer request for current credits. Waiting 5 seconds.
2014.11.08 20:17:30 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

Vielleicht kann Matthias mal was dazu sagen, ist das Modul noch am Leben?  Oder muss man zurück auf den Cube?
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

Rince

Ich schließe mich mal dem Problem an,
ZitatError in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
Wer zu meinen Posts eine Frage schreibt und auf eine Antwort wartet, ist hiermit herzlich eingeladen mich per PN darauf aufmerksam zu machen. (Bitte mit Link zum betreffenden Thread)

John

Das Ausgabe kommt wohl von diesem Code-Fragment in 14_CUL_MAX


    my ($credit10ms) = (CommandGet("","$hash->{IODev}{NAME} credit10ms") =~ /[^ ]* [^ ]* => (.*)/);
    if($credit10ms eq "No answer") {
      Log 1, "Error in CUL_MAX_SendQueueHandler: CUL $hash->{IODev}{NAME} did not answer request for current credits. Waiting 5 seconds.";
      $timeout += 5;


Das Modul versucht die credits vom CUL zu ermitteln, dies entspricht:
get CUL credit10ms
und erhält als Antwort "No answer". Also versucht es das 5 Sekunden später nochmals.
Es gibt auch einen Grund dafür, das Modul will eine Sendung absetzen und vergewissert sich,
ob ausreichend Credits vorhanden sind.

Wenn ihr also den Fehler bemerkt könnt ihr das über eure CUL-Seite selbst ausprobieren, mit dem erwähnten GET-Befehl.

Das Modul 14_CUL_MAX nutzt hierbei die Funktionen von 00_CUL.pm.
14_CUL_MAX ist also nur Symptom-Träger aber nicht die Ursache.
Die Frage ist, warum CUL permanent diese Meldung zurückliefert.
Und diese Frage müsst ihr Rudolf König stellen. Er ist der Betreuer von 00_CUL.pm.

John

CubieTruck Docker Node-Red Tasmota Shelly Homematic-IP

hyper2910

Hi John,

Ich glaube das ist ein Schritt zu weit. 

Der Fehler wird meiner Meinung nach verursacht durch den disconnect des cul,  und hier ist die frage warum

2014.11.08 12:04:21 1: /dev/ttyACM0 disconnected, waiting to reappear (CULMAX)
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

John

CubieTruck Docker Node-Red Tasmota Shelly Homematic-IP

Rince

Culfirmware 1.61 und fhem Update von gestern...
Bis jetzt ist Ruhe im Logfile...
Wer zu meinen Posts eine Frage schreibt und auf eine Antwort wartet, ist hiermit herzlich eingeladen mich per PN darauf aufmerksam zu machen. (Bitte mit Link zum betreffenden Thread)

hyper2910

1.61 ist bei mir drauf und auch das neueste update,  nach ca. 18 stunden wieder ausgestiegen
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

stgeran

Da schliess ich mich an. Version 1.61, neustes Update (auch update force) und völlig unmotiviert steigt die Kiste aus. Das kann Stunden gut gehen oder schon nach wenigen Minuten! Ich sags mal ganz brutal: So kommen wir nicht über den Winter! Wenn ich mit diesem Problem nicht alleine bin, muß doch was anderes im Busch sein. Ich nehme an, keiner der Betroffenen hat im System rumgebastelt. Also, wo kommt es her????? Mit der Hoffnung (die bekanntlicher Weise zuletzt stibt) auf baldige Genesung des Systems verbleibe ich.....
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

Seit dem 5.11. läuft mein CUL wieder ohne Probleme. Daher kann ich leider den Fehler nicht weiter analysieren.
Vielleicht kann jemand, der den Fehler häufiger beobachtet, mehr Input liefern. Man bräuchte einen genauen Trace der CUL Kommunikation und vielleicht noch interne Debug-Meldungen vom CUL.

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

Wenn es weiterhin bei mir auftritt, brauche ich Anweisungen, was ich für euch tun kann.
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

deune

Hallo Zusammen,

bei mir selbiges Bild cuno auf aktuellem Stand 1.61, fhem auf 5.6 und ich habe gar den Eindruck,
das es sich sogar schneller verabschiedet - die letzten beiden Male war nach 4 bzw 6 Stunden Schluß.

Das ist ganz besonders, wenn zwei einjährige Kinder und eine untertemperierte Frau tagsüber in einer
ungeheizten Wohnung leben: Sprüche wie "Dein Mist läuft schon wieder nicht!" wollte ich eigentlich vermeiden.

Liebe Grüße aus der Eifel (6Grad Außentemperatur)

Holger

Rince

Hm,
auch wenn es keine Dauerlösung ist, benutzt doch derweil einfach die Automatik in den Stellantrieben.
Die ist von fhem unabhängig...
Wer zu meinen Posts eine Frage schreibt und auf eine Antwort wartet, ist hiermit herzlich eingeladen mich per PN darauf aufmerksam zu machen. (Bitte mit Link zum betreffenden Thread)

rudolfkoenig

Ich fuerchte ich kann euch nur als Aussenstehender "mit Verstand" helfen das Problem zu lokalisieren, da ich keine MAX-Geraete habe, und mit dem Protokoll mich nur theoretisch auskenne. Auch der MAX-Anteil der culfw stammt nicht von mir.

Die "Disconnected" Meldung bedeutet, dass das CUL vom USB abgemeldet ist, entweder wg. CUL-reboot, oder Abstecken, oder, wie in diesem Fall vermutlich ein culfw Bug/Absturz. Evtl. wird der Absturz durch FHEM ausgeloest, aber das Problem liegt im culfw, da ein Abmelden vom USB nicht zulaessig ist.

Nachdem das CUL sich abgemeldet hat, kann ja nicht Antworten. Da das CUL_MAX Modul noch nicht auf Log3 umgestellt ist (boese, boese, Log3 gibts seit 15 Monaten!), kann man die Meldung auch nicht spezifisch abstellen, nur zusammen mit allen anderen in FHEM.

Es waere gut zu wissen (== Hausaufgaben an euch), ob:
- das CUL-Laempchen nach dem Absturz noch blinkt
- ein Abstecken/Anstecken was bewirkt
- das Problem auch existiert, wenn man das MAX-Cul _nur_ fuer MAX verwendet (keine F20/IT/etc Umschaltung)
- das Problem auch existiert, wenn man die MAX-Geraete nicht regelmaessig pollt (Temperaturmeldung?).
- mit einem alten FHEM (5.5?) das Problem auftritt
- mit einem alten culfw-firmware das Problem auftritt, wenn nein, ab welchen tritt es auf

Das wuerde vermutlich auch Matthias helfen, er hat vor zwei Wochen noch Patches eingecheckt, ist also nicht von der Bildflaeche verschwunden.

dubelkiste

Anbei meine Hausaufgaben ich habe das gleiche Problem....
- das CUL-Laempchen nach dem Absturz noch blinkt
*Ja die LED blinkt noch
---------------------------------------------------------------
- ein Abstecken/Anstecken was bewirkt
*nein ein Abstecken vom CUL bringt keine Besserung
---------------------------------------------------------------
- das Problem auch existiert, wenn man das MAX-Cul _nur_ fuer MAX verwendet (keine F20/IT/etc Umschaltung)
*das CUL wird nur fuer Max verwendet
---------------------------------------------------------------
-das Problem auch existiert, wenn man die MAX-Geraete nicht regelmaessig pollt (Temperaturmeldung?).
*da ich regelmaessig polle kann ich die Frage nicht beantworten
----------------------------------------------------------------
- mit einem alten FHEM (5.5?) das Problem auftritt
*ja da ich fast täglich einen Update mache leider keine Antwort....
--------------------------------------------------------------------
- mit einem alten culfw-firmware das Problem auftritt, wenn nein, ab welchen tritt es auf
* mit 1.57 hatte ich das Problem auch schon  seit einigen Tages schon jetzt bin ich auf 1.61keine Besserung ....

Das wuerde vermutlich auch Matthias helfen, er hat vor zwei Wochen noch Patches eingecheckt, ist also nicht von der Bildflaeche verschwunden.

hyper2910

Zitat von: dubelkiste am 13 November 2014, 18:57:19
Anbei meine Hausaufgaben ich habe das gleiche Problem....
- das CUL-Laempchen nach dem Absturz noch blinkt
*Ja die LED blinkt noch
---------------------------------------------------------------
- ein Abstecken/Anstecken was bewirkt
*nein ein Abstecken vom CUL bringt keine Besserung
---------------------------------------------------------------
- das Problem auch existiert, wenn man das MAX-Cul _nur_ fuer MAX verwendet (keine F20/IT/etc Umschaltung)
*das CUL wird nur fuer Max verwendet
---------------------------------------------------------------
-das Problem auch existiert, wenn man die MAX-Geraete nicht regelmaessig pollt (Temperaturmeldung?).
*da ich regelmaessig polle kann ich die Frage nicht beantworten
----------------------------------------------------------------
- mit einem alten FHEM (5.5?) das Problem auftritt
*ja da ich fast täglich einen Update mache leider keine Antwort....
--------------------------------------------------------------------
- mit einem alten culfw-firmware das Problem auftritt, wenn nein, ab welchen tritt es auf
* mit 1.57 hatte ich das Problem auch schon  seit einigen Tages schon jetzt bin ich auf 1.61keine Besserung ....

Das wuerde vermutlich auch Matthias helfen, er hat vor zwei Wochen noch Patches eingecheckt, ist also nicht von der Bildflaeche verschwunden.

Bis auf die fw kann ich das bestätigen,  war die ganze zeit auf 1.61  die Led habe ich jetzt wieder eingeschaltet,  war ausprogrammiert!
Ich habe jetzt die Logs durch, der cul schmiert nach ca 18std ab.


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

rudolfkoenig

Zitat*nein ein Abstecken vom CUL bringt keine Besserung
Naja, ich haette es gerne auch wieder eingesteckt. Meldet sich das CUL nach dem Einstecken am USB-Bus?

Zitat*da ich regelmaessig polle kann ich die Frage nicht beantworten
Sowas kann man aber bestimmt temporaer Abschalten, um das Problem zu lokalisieren.

Und bei den Antworten bitte extra ewrwaehnen, falls keine disconnected Meldung im log ist.

SirUli

Gleiches Problem hier, allerdings steigt er immer direkt nach dem Start aus:
Zitat2014.11.13 17:44:33 3: Opening SCC1 device /dev/ttyAMA0
2014.11.13 17:44:34 3: Setting SCC1 baudrate to 38400
2014.11.13 17:44:34 3: SCC1 device opened
2014.11.13 17:44:34 3: SCC1: Possible commands: mBCFiAZGMRTVWXef*ltux
2014.11.13 17:44:34 2: Switched SCC1 rfmode to MAX
2014.11.13 17:45:34 1: Including ./log/fhem.save
2014.11.13 17:45:35 0: Server started with 108 defined entities (version $Id: fhem.pl 6913 2014-11-08 10:32:44Z rudolfkoenig $, os linux, user fhem, pid 2133)
2014.11.13 17:45:35 1: CUL_MAX_Parse: len mismatch
2014.11.13 17:45:35 1: CUL_MAX_Parse: len mismatch
2014.11.13 17:45:38 1: /dev/ttyAMA0 disconnected, waiting to reappear (SCC1)
2014.11.13 17:45:38 1: Error in CUL_MAX_SendQueueHandler: CUL SCC1 did not answer request for current credits. Waiting 5 seconds.

Ich beantworte mal ein paar Fragen:

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- das CUL-Laempchen nach dem Absturz noch blinkt
Leuchtet durchgehend am ersten SCC, an den beiden weiteren (welche oben drauf gestapelt sind) jedoch dunkel (was bei mir aber auch Voreinstellung wäre - ich habe das leuchten abgestellt).

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- ein Abstecken/Anstecken was bewirkt
Habe leider den SCC - da ist das nicht so einfach ;) Aber es sind immerhin alle drei SCCs dann tot, da der erste ganz unten leider der vom MAX ist...

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- das Problem auch existiert, wenn man das MAX-Cul _nur_ fuer MAX verwendet (keine F20/IT/etc Umschaltung)
Habe einen extra SCC nur für MAX!

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- das Problem auch existiert, wenn man die MAX-Geraete nicht regelmaessig pollt (Temperaturmeldung?).
Ich habe keinen Temperaturscanner am laufen - nur ganz normale Sender/Empfänger Tätigkeit

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- mit einem alten FHEM (5.5?) das Problem auftritt
Müsste ich testen, habe ich momentan noch nicht auf dem Schirm

Zitat von: rudolfkoenig am 13 November 2014, 18:32:42
- mit einem alten culfw-firmware das Problem auftritt, wenn nein, ab welchen tritt es auf
Habe noch die 1.59 - ich habe culfw seit ewigkeiten nicht geupdated

Was ich noch sagen kann:
- Tritt sofort nach Start auf
- Tritt direkt nach dem Reboot des RPI auf
- Habe einmal ganz runtergefahren, alles vom Strom genommen und wieder dran - scheint nichts statisches zu sein - Problem war das gleiche.
- Trat bei mir erst seit dem Letzten Update von 2014.11.12 19:28:55 auf.  Mein letztes Update zuvor war am 2014.09.28 12:11:16 und da war noch alles ok.

Ich schau mal ob die alte Version (sollte ja gebackupped sein) noch funktioniert.

Vielen Dank schon mal fürs debuggen!

hyper2910

Das Problem tritt laut log seit dem 09 oder 10. Oktober auf, leider habe ich die Logs nicht mehr.
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

deune

Anbei meine Hausaufgaben ich habe das gleiche Problem....
- das CUL-Laempchen nach dem Absturz noch blinkt
*Kann ich leider nicht sagen, mein CUNO ist in einem geschl. Gehäuse, pingt aber noch
---------------------------------------------------------------
- ein Abstecken/Anstecken was bewirkt
*ein reboot des CUNO bringt nichts
---------------------------------------------------------------
- das Problem auch existiert, wenn man das MAX-Cul _nur_ fuer MAX verwendet (keine F20/IT/etc Umschaltung)
*das CUL wird nur fuer Max verwendet
---------------------------------------------------------------
-das Problem auch existiert, wenn man die MAX-Geraete nicht regelmaessig pollt (Temperaturmeldung?).
*ich Pille nichts, nur die ganz normalen Telegramme der Geräte und Temperaturänderungen am Tab über Web-Frontend
----------------------------------------------------------------
- mit einem alten FHEM (5.5?) das Problem auftritt
*mit 5.5 fing Anfang Oktober alles an, 5.6 ist seit Sonntag drauf und immer noch alles gleich
--------------------------------------------------------------------
- mit einem alten culfw-firmware das Problem auftritt, wenn nein, ab welchen tritt es auf
* hatte auch erst gedacht es hätte mit der alten Firmware zutun, aber alles bleibt gleich....

Vielleicht helfen meine Info's

Holger

hyper2910

Hat jemand die alten Logs um zu sehen mit welchem update das ganze begonnen hat. Dann könnte man ggf. Dieselben Dateien fuer alle Posten und das Problem ist erstmal erledigt.
Cubietruck mit FHEM, CUL V3 443MHz, 2 x CULV3 868MHz, Milights, Max Heizungssteuerung, Homematic, IT,

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

gero

Zitat von: stgeran am 14 November 2014, 19:04:17
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.
Ich kenne den MaxScanner nicht wirklich. Aber wegen des "No answer" in einer credit10ms Variable sieht es mir ganz stark nach einem Folgefehler vom Parsingproblem aus.
Ich habe großen Respekt vor allen Entwicklern von fhem. Aber ein großes Problem ist das fehlende einheitliche Konzept Fehlerwerte und Meldungen aus Funktionen und Modulen zurückzugeben.

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: pklaus am 14 November 2014, 13:23:11
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!)

Nachdem ich die alte Version von 00_CUL.pm wiederhergestellt habe funktioniert die Heizungssteuerung jetzt wieder zuverlässig. Ich habe aber dennoch erneut einen Fehler im Log gefunden, von dem sich FHEM aber wohl von selbst wieder erholt hat:

2014.11.14 21:54:30 3: MAX MAX_0dcce1: MaxScanRun.753 <<set MAX_0dcce1 desiredTemperature auto 18.5>>
2014.11.14 21:56:13 1: CUL_MAX_Parse: len mismatch
2014.11.14 21:56:16 1: /dev/cul868 disconnected, waiting to reappear (cul868)
2014.11.14 21:56:16 1: Error in CUL_MAX_SendQueueHandler: CUL cul868 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 21:56:16 3: MAX MAX_0d284b: MaxScanRun.753 <<set MAX_0d284b desiredTemperature auto 18.0>>
2014.11.14 21:56:16 3: Setting cul868 baudrate to 9600
2014.11.14 21:56:16 1: /dev/cul868 reappeared (cul868)
2014.11.14 21:56:16 3: cul868: Possible commands: BbCFiAZEGMKUYRTVWXefmltux
2014.11.14 21:57:39 3: MAX MAX_0daaae: MaxScanRun.753 <<set MAX_0daaae desiredTemperature auto 19.0>>

gero

Zitat von: pklaus am 14 November 2014, 23:49:16
Nachdem ich die alte Version von 00_CUL.pm wiederhergestellt habe funktioniert die Heizungssteuerung jetzt wieder zuverlässig. Ich habe aber dennoch erneut einen Fehler im Log gefunden, von dem sich FHEM aber wohl von selbst wieder erholt hat:

2014.11.14 21:54:30 3: MAX MAX_0dcce1: MaxScanRun.753 <<set MAX_0dcce1 desiredTemperature auto 18.5>>
2014.11.14 21:56:13 1: CUL_MAX_Parse: len mismatch
2014.11.14 21:56:16 1: /dev/cul868 disconnected, waiting to reappear (cul868)
2014.11.14 21:56:16 1: Error in CUL_MAX_SendQueueHandler: CUL cul868 did not answer request for current credits. Waiting 5 seconds.
2014.11.14 21:56:16 3: MAX MAX_0d284b: MaxScanRun.753 <<set MAX_0d284b desiredTemperature auto 18.0>>
2014.11.14 21:56:16 3: Setting cul868 baudrate to 9600
2014.11.14 21:56:16 1: /dev/cul868 reappeared (cul868)
2014.11.14 21:56:16 3: cul868: Possible commands: BbCFiAZEGMKUYRTVWXefmltux
2014.11.14 21:57:39 3: MAX MAX_0daaae: MaxScanRun.753 <<set MAX_0daaae desiredTemperature auto 19.0>>


Der Parse-Fehler ist schon ewig vorhanden und wird durch den Rückschritt auf die letzte 00_CUL.pm Version nicht behoben.
Lediglich das Reappear vom CUL funktioniert jetzt wieder.

Es sind zwei Fehler zu beheben:
1. Mit der aktuellen Version von 00_CUL.pm funktioniert das Reappier nicht mehr.
2. Die Funktion CUL_ReadAnswer segmentiert empfangene Nachrichten nicht richtig und erzeugt dadurch unnötigerweise das Disconnect.

Laßt uns darauf warten, dass Rudolf König hier nochmal reinschaut und seinen Kommentar dazu abgibt.

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

Ich habe auch die "alte" Verion. Jetzt kommt öfter
CUL_MAX_Parse: Got unhandled message type 4E
2014.11.14 23:50:12 2: CUL_MAX_Parse: Got unhandled message type F7
2014.11.14 23:50:12 2: CUL_MAX_Parse: Got unhandled message type F7
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

rudolfkoenig

Es ist eine lange Verkettung von Bugs & Zufaellen.

- CUL_ReadAnswer1: falls bei der Antwort auf die "credit10ms" Frage im Puffer noch andere Daten waren (in diesem Fall eine MAX-Nachricht, vermutlich weil FHEM wg. irgendwelche Verzoegerungen diese Daten noch nicht abgeholt hat), dann wurden diese _zusammen_ mit der credit10ms Antwort zum Analysieren freigegeben (deswegen die "len mismatch" Fehlermeldung).
Das habe ich jetzt gefixt und eingecheckt.

- CUL_ReadAnswer2: da die eigentliche Antwort an falsche Stelle geschickt ist, wartet diese Routine vergeblich die weiteren 3 Sekunden auf die Antwort, und schliesst danach die USB-Verbindung via DevIo_Disconnected (XXX disconnected, waiting to reappear). Welche Probleme das Schliessen loesen soll, weiss ich nicht, allerdings traue ich das nicht zu aendern. CUL_Get schliesst die Verbindung auch noch zusaetzlich im Fehlerfall.

- 00_CUL.pm: die Umstellung am 2014-10-12 auf readingsSingleUpdate sorgt dafuer, das die zwischenzeitlich auf "disconnected" gesetzte Status des CULs auf "Initialized" zurueckgesetzt wird, was wiederum das automatische "reappeared" verhindert.
Das habe ich jetzt gefixt und eingecheckt.

- Die credit10ms Abfrage vor jedem Senden halte ich fuer problematisch, weil das von CUL_MAX_Parse aufgerufene CUL_Get die CUL_MAX_Parse nochmal aufgeruft, falls vor dem Antwort auf die Daten MAX-Nachrichten sind. Weiterhin ist diese Abfrage inkompatibel mit FHEM2FHEM:RAW. Ich wuerde stattdessen diese Zaehlung im Modul selbst realisieren. Das Modul sollte von Log auf Log3 (bzw. von loglevel auf verbose) umgestellt werden.

-> Nach einem update (ab morgen) sollte das Problem verschwunden sein.

SirUli


Palm_Maniac

Auch von mir ein Herzliches Dankeschön an rudolfkoenig. :) Du machst uns MAX User damit sehr Glücklich. :)

gero

Zitat von: rudolfkoenig am 15 November 2014, 14:12:24
Es ist eine lange Verkettung von Bugs & Zufaellen.

- CUL_ReadAnswer1: falls bei der Antwort auf die "credit10ms" Frage im Puffer noch andere Daten waren (in diesem Fall eine MAX-Nachricht, vermutlich weil FHEM wg. irgendwelche Verzoegerungen diese Daten noch nicht abgeholt hat), dann wurden diese _zusammen_ mit der credit10ms Antwort zum Analysieren freigegeben (deswegen die "len mismatch" Fehlermeldung).
Das habe ich jetzt gefixt und eingecheckt.

- CUL_ReadAnswer2: da die eigentliche Antwort an falsche Stelle geschickt ist, wartet diese Routine vergeblich die weiteren 3 Sekunden auf die Antwort, und schliesst danach die USB-Verbindung via DevIo_Disconnected (XXX disconnected, waiting to reappear). Welche Probleme das Schliessen loesen soll, weiss ich nicht, allerdings traue ich das nicht zu aendern. CUL_Get schliesst die Verbindung auch noch zusaetzlich im Fehlerfall.

- 00_CUL.pm: die Umstellung am 2014-10-12 auf readingsSingleUpdate sorgt dafuer, das die zwischenzeitlich auf "disconnected" gesetzte Status des CULs auf "Initialized" zurueckgesetzt wird, was wiederum das automatische "reappeared" verhindert.
Das habe ich jetzt gefixt und eingecheckt.

- Die credit10ms Abfrage vor jedem Senden halte ich fuer problematisch, weil das von CUL_MAX_Parse aufgerufene CUL_Get die CUL_MAX_Parse nochmal aufgeruft, falls vor dem Antwort auf die Daten MAX-Nachrichten sind. Weiterhin ist diese Abfrage inkompatibel mit FHEM2FHEM:RAW. Ich wuerde stattdessen diese Zaehlung im Modul selbst realisieren. Das Modul sollte von Log auf Log3 (bzw. von loglevel auf verbose) umgestellt werden.

-> Nach einem update (ab morgen) sollte das Problem verschwunden sein.

Danke! Ich bin gespannt, wie deine Änderungen genau aussehen.

Wenn du Zeit hast, kannst du auch nochmal in diesen Thread sehen:
http://forum.fhem.de/index.php/topic,25745.0.html
Es gibt auch in der CUL-Firmware bzgl. MAX noch einen kleinen BUG.

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

rudolfkoenig

ZitatDanke! Ich bin gespannt, wie deine Änderungen genau aussehen.
Dann schau ins SVN. Ich meine Minimalinvasiv.

Wenn du Zeit hast, kannst du auch nochmal in diesen Thread sehen:
Habs gesehen, fuehl mich aber nicht zustaendig, da es nicht von mir ist, ausserdem kann ich es nicht testen.
Wenn Matthias keine Zeit hat, dann muesste jemand anderes (Du?) die Pflege uebernehmen.

gero

Zitat von: rudolfkoenig am 15 November 2014, 21:02:42
Dann schau ins SVN. Ich meine Minimalinvasiv.
Habe ich gerade gemacht. Die Änderung sollte das aktuelle Problem beheben.
Aber sauberer wäre es doch, wenn man in CUL_ReadAnswer auch noch $hash->{PARTIAL} mit berücksichtigen würde, oder sehe ich das falsch? Ebenso kann man nur hoffen, dass in CUL_ReadAnswer die Antwort auf das letzte Kommando komplett vom CUL gelesen wird. Falls das letzte Telegram im Buffer unvollständig ist, müßte evtl. nochmal gelesen werden. Ob und wie hoch die Wahrscheinlichkeit, für ein nicht komplettes Lesen ist, wage ich gerade nicht zu beurteilen. Schöner wäre es natürlich, wenn man auf CUL_ReadAnswer komplett verzichten könnte. Aber es ist manchmal von der Softwarearchitektur einfacher, wenn man einen blocking call an Stellen realisieren kann, an denen man eigentlich asynchron arbeiten müßte.
Bitte sieh meine Äußerungen nicht als böse Kritik. Ich will nur konstruktiv weiterhelfen, soweit es mir möglich ist.

Zitat von: rudolfkoenig am 15 November 2014, 21:02:42
Wenn du Zeit hast, kannst du auch nochmal in diesen Thread sehen:
Habs gesehen, fuehl mich aber nicht zustaendig, da es nicht von mir ist, ausserdem kann ich es nicht testen.
Wenn Matthias keine Zeit hat, dann muesste jemand anderes (Du?) die Pflege uebernehmen.
Soweit es in meinen Möglichkeiten liegt (vor allem zeitlich), möchte ich die fhem Entwicklung natürlich unterstützen.
Sprichst du von 14_CUL_MAX.pm oder vom rf_moritz in der CUL Firmware?

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

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

rudolfkoenig

@gero: ich meinte beides.
Aber wir sollten noch eine Woche auf Matthias warten, drei Wochen Urlaub waeren nichts ungewoehnliches.

Matthias Gehre

So, bin wieder da :-)

Die Log3 Umstellung kann ich in der nächsten Woche machen.

Zu:
ZitatDie credit10ms Abfrage vor jedem Senden halte ich fuer problematisch, weil das von CUL_MAX_Parse aufgerufene CUL_Get die CUL_MAX_Parse nochmal aufgeruft, falls vor dem Antwort auf die Daten MAX-Nachrichten sind. Weiterhin ist diese Abfrage inkompatibel mit FHEM2FHEM:RAW. Ich wuerde stattdessen diese Zaehlung im Modul selbst realisieren. Das Modul sollte von Log auf Log3 (bzw. von loglevel auf verbose) umgestellt werden.
Das muss ich mir noch einmal anschauen, Ich glaube das ursprüngliche Problem war, dass das MAX Modul keine Rückmeldung hatte, falls der CUL die Pakete wg fehlenden Credits nicht sendet.
Ich schau mir das nochmal an.

deune

Hallo Zusammen,

Heute Morgen ein update gemacht und ich bin guter Dinge das es nun stabiler läuft und die Rückmeldung von Matthias vertreibt jeglichen Kummer - Vielen lieben Dank allen Zusammen!

Holger

hyper2910

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

stgeran

Diese Fehler sind immer noch da:
2014.11.06 04:45:52 3: MAX Hzg_WZ_RE: MaxScanRun.753 <<set Hzg_WZ_RE desiredTemperature auto 21.0>>
2014.11.06 04:45:52 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:45:52 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:46:26 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:46:26 1: PERL WARNING: Use of uninitialized value $credit10ms in string eq at ./FHEM/14_CUL_MAX.pm line 478.
2014.11.06 04:46:26 1: PERL WARNING: Use of uninitialized value $credit10ms in concatenation (.) or string at ./FHEM/14_CUL_MAX.pm line 485.
2014.11.06 04:46:26 3: MAX Hzg_Buero: MaxScanRun.753 <<set Hzg_Buero desiredTemperature  21.0>>
2014.11.06 04:46:26 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:46:26 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:49:29 1: 192.168.100.110:1000 disconnected, waiting to reappear (HMLAN1)
2014.11.06 04:49:29 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.11.06 04:49:30 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:49:30 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:49:30 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:50:29 1: 192.168.100.110:1000 reappeared (HMLAN1)
2014.11.06 04:50:29 1: HMLAN_Parse: HMLAN1 new condition init
2014.11.06 04:50:30 1: HMLAN_Parse: HMLAN1 new condition ok
2014.11.06 04:50:41 1: PERL WARNING: Argument "No answer" isn't numeric in addition (+) at ./FHEM/99_UtilsMaxScan.pm line 528.
2014.11.06 04:50:41 1: [color=red]PERL WARNING: Use of uninitialized value $credit10ms in string eq at ./FHEM/14_CUL_MAX.pm line 478.[/color]
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

rudolfkoenig

Die Meldungen koennen nicht von einem aktuellen fhem.pl stammen.
Auch wenn es unwahrscheinlich ist, dass es in diesem Fall daran liegt, ist mir wichtig, dass alles aktuell ist.

locutus

Die Meldungen treten seit dem gestrigen Update wieder auf.
Ausgangskonfiguration: Hauptserver RPi verbunden via FHEM2FHEM mit Remoteserver TuxRadio. Keine Auffälligkeiten im Logfile des TuxRadios. RPi Log-Einträge im 5 Sekundentakt:
2014.12.01 23:00:04 1: Error in CUL_MAX_SendQueueHandler: CUL TuxRadio_RC did not answer request for current credits. Waiting 5 seconds.
2014.12.01 23:00:09 1: Error in CUL_MAX_SendQueueHandler: CUL TuxRadio_RC did not answer request for current credits. Waiting 5 seconds.
2014.12.01 23:00:14 1: Error in CUL_MAX_SendQueueHandler: CUL TuxRadio_RC did not answer request for current credits. Waiting 5 seconds.
2014.12.01 23:00:19 1: Error in CUL_MAX_SendQueueHandler: CUL TuxRadio_RC did not answer request for current credits. Waiting 5 seconds.
2014.12.01 23:00:24 1: Error in CUL_MAX_SendQueueHandler: CUL TuxRadio_RC did not answer request for current credits. Waiting 5 seconds.


# $Id: fhem.pl 7097 2014-11-30 07:41:36Z rudolfkoenig $
# $Id: 00_CUL.pm 6980 2014-11-15 13:06:08Z rudolfkoenig $
# $Id: 14_CUL_MAX.pm 7067 2014-11-26 19:49:23Z mgehre $
# $Id: 93_FHEM2FHEM.pm 6203 2014-07-06 12:31:20Z rudolfkoenig $
# $Id: 10_MAX.pm 7068 2014-11-26 19:50:04Z mgehre $

stgeran

Ich weis nicht, ob es dazu gehört, bei mir ist fhem gestern gegen 23:00 komplett ausgestiegen und war erst über einen reboot des raspi über die Konsole wieder ins rollen zu bringen. Wenn nötig schaue ich heute Abend ins log zu diesem Zeitpunkt nach den letzten Meldungen.
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

haufsolutions

Schließe mich hier Mal an. Habe in den letzten Wochen immer Mal wieder beobachtet das er nachm CUL_MAX_Parse: len mismatch nicht mehr weiter macht, disconnected und das wars:

2015.02.22 02:01:18 3: set cm fakeWT MAX_0ad5a9 17.0 17.1
2015.02.22 02:01:18 1: CUL_MAX_Parse: len mismatch
2015.02.22 02:01:21 1: /dev/ttyACM0 disconnected, waiting to reappear (CUL0)
2015.02.22 02:01:21 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:23 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:28 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:33 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:38 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:43 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:48 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.22 02:01:53 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.


2015.02.24 18:05:47 3: CUL_MAX_Parse: Re-Pairing device 0ad573 of type HeatingThermostat with serial KEQ0406120
2015.02.24 18:05:47 1: CUL_MAX_Parse: len mismatch
2015.02.24 18:05:50 1: /dev/ttyACM0 disconnected, waiting to reappear (CUL0)
2015.02.24 18:05:50 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.24 18:05:52 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.24 18:05:57 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.24 18:06:02 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.24 18:06:07 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.
2015.02.24 18:06:12 1: Error in CUL_MAX_SendQueueHandler: CUL CUL0 did not answer request for current credits. Waiting 5 seconds.


Wie oben zu sehen ist nicht ganz ersichtlich wann das ganze passiert. Mehr oder weniger Zufall. Fazit shutdown restart hilft danach immer.
Bis man das allerdings immer detektiert ist man schon eingefroren  ;D daher habe ich mir einen kleinen Lösungsansatz programmiert für die 14_CUL_MAX.pm

 
if(2*$len+3 != length($rmsg)) { #+3 = +1 for 'Z' and +2 for len field in hex
    Log 1, "CUL_MAX_Parse: len mismatch";
    Log 1, "CUL_MAX_Parse: Something went wrong... going to restart.";
    fhem("shutdown restart");
    return $shash->{NAME};
  }


Der ideale Weg währe natürlich, wenn sich der CUL reconnected... aber ich hoffe mein fast and dirty Weg funktioniert auch  :D

haufsolutions

Scheint zu klappen. Grade beim Batteriewechsel erneut passiert:


2015.02.24 20:50:02 3: set  fakeWT MAX_0ad599 17.5 17.6 : Please define fakeWT first
2015.02.24 20:50:02 3: SendExtTemp_GWZ return value: Please define fakeWT first
2015.02.24 20:50:31 3: CUL_MAX_Parse: Re-Pairing device 0ad5a9 of type HeatingThermostat with serial KEQ0406174
2015.02.24 20:50:31 1: CUL_MAX_Parse: len mismatch
2015.02.24 20:50:31 1: CUL_MAX_Parse: Something went wrong... going to restart.
2015.02.24 20:50:31 0: Server shutdown
2015.02.24 20:50:35 1: Including fhem.cfg
2015.02.24 20:50:35 3: telnetPort: port 7072 opened
2015.02.24 20:50:36 3: WEB: port 8083 opened
....

SirUli

Ich habe das gleiche Problem - dankbarerweise läuft der Kram autark, sonst hätte es heute direkt wieder eins auf den Deckel gegeben... ;) Habe seit dem Update (ich habe 2015.02.23 23:10:20 das update mit der 10_MAX.pm gemacht) nur die folgende Zeile tausend mal drin:
2015.02.24 00:23:13 1: CUL_MAX_Parse: len mismatch

Das ging dann so den ganzen Tag...bis ich eben hier die Mailbenachrichtigung gesehen habe und mir böses schwante... ;)

haufsolutions

Zitat von: SirUli am 24 Februar 2015, 20:57:20
Ich habe das gleiche Problem - dankbarerweise läuft der Kram autark, sonst hätte es heute direkt wieder eins auf den Deckel gegeben... ;) Habe seit dem Update (ich habe 2015.02.23 23:10:20 das update mit der 10_MAX.pm gemacht) nur die folgende Zeile tausend mal drin:
2015.02.24 00:23:13 1: CUL_MAX_Parse: len mismatch

Das ging dann so den ganzen Tag...bis ich eben hier die Mailbenachrichtigung gesehen habe und mir böses schwante... ;)

Gabs ein Update? Ich hab seit de letzten FHEM Update im Nov/ Dez? kein Update mehr gemacht  :D
Hört sich bei dir aber auch nicht sehr berauschend an.

gero

Die Meldung
CUL_MAX_Parse: len mismatch
habe ich ca. 3 - 4- mal pro Tag im Log. Allerdings läuft bei mir alles stabil.

Laßt euch doch mal die Nachricht ausgeben, die den Fehler verursacht:
In der Datei 14_CUL_MAX.pm Zeile 264 von
    Log3 $hash, 1, "CUL_MAX_Parse: len mismatch";
auf
    Log3 $hash, 1, "CUL_MAX_Parse: len mismatch ($rmsg)";
abändern.
Ich glaube es gibt immer noch einen kleinen Bug in der CUL_ReadAnswer Funktion (00_CUL.pm). Meiner Meinung nach werden im Dispatchteil der Routine die \r Zeichen nicht entfernt und das führt zu Problemen in der Routine CUL_Parse. Ich habe bei mir jetzt mal den Code geändert und werde ihn zum Testen einige Zeit laufen lassen.

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

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

netwalk

Hallo,

ich krame diesen Thread wieder hervor, da er meiner Meinung nach genau mein Problem beschreibt.

Ich habe vor einigen Tagen meinen CUBE deaktiviert, da ich durch ihn ständig Freezes hatte, die mein neues HMLGW disconnecten ließen.
Alle MAX Geräte habe ich mit einem CUL mit Firmware 1.66 gepairt. Dies funktionierte eigentlich ganz gut (mit entsprechender Credit-Wartezeit).
In der Regel laufen meine MAX HR im Auto-Modus, ich greife recht selten ein, nur zum Schlafen gehen durch setzen in den ECO-Modus mittels Taster.

Nun habe ich festgestellt, dass die WT bzw. HR nicht mehr reagierten, die Statusänderungen der FK jedoch einwandfrei angezeigt wurden.
Im Log fand ich folgende Einträge:

2016.12.30 06:49:02 1: Error in CUL_MAX_SendQueueHandler: CUL CUL1 did not answer request for current credits. Waiting 5 seconds.
2016.12.30 06:49:07 1: Error in CUL_MAX_SendQueueHandler: CUL CUL1 did not answer request for current credits. Waiting 5 seconds.
2016.12.30 06:49:12 1: Error in CUL_MAX_SendQueueHandler: CUL CUL1 did not answer request for current credits. Waiting 5 seconds.
2016.12.30 06:49:17 1: Error in CUL_MAX_SendQueueHandler: CUL CUL1 did not answer request for current credits. Waiting 5 seconds.
...


Ein "shutdown restart" brachte keine Änderung, nur ein "sudo reboot" des RasPi half.
Dieses Deaktivieren des CUL habe ich jetzt mehrfach erlebt, meistens nach ziemlich exakt 18 Stunden.

Sollte dieser Fehler nicht eigentlich behoben sein?
live long and prosper
netwalk
_______________________________________________
INTEL NUC7CJYH, Homematic mit 3x HMLGW, JEELINK mit 18x TX29-DTH-IT, DUOFERNSTICK, FB7590 mit FBDECT, NETATMO, Philips HUE, RFXtrx433, Ubiquiti G3 PRO/FLEX/DOME/MICRO

szoller

Ich muss das Thema auch wieder auskramen, das Problem tritt bei mir auch auf nun.

Ich bin von einem SCC2 mit rfmode MAX gewechselt zu einem als CUNO geflashten MAXCUBE (V 1.24.02 a-culfw Build: 208)

Sieht im Logfile dann so aus:
2017.06.15 19:12:39 1: 192.168.22.90:2323 disconnected, waiting to reappear (CUN_MAX)
2017.06.15 19:12:39 1: Error in CUL_MAX_SendQueueHandler: CUL CUN_MAX did not answer request for current credits. Waiting 5 seconds.
2017.06.15 19:12:44 3: CUN_MAX: Possible commands: BbCFiAZNEkGMKLUYRTVWXefhltxz
2017.06.15 19:12:44 1: 192.168.22.90:2323 reappeared (CUN_MAX)
2017.06.15 19:22:05 1: 192.168.22.90:2323 disconnected, waiting to reappear (CUN_MAX)
2017.06.15 19:22:05 3: CUN_MAX: Possible commands: BbCFiAZNEkGMKLUYRTVWXefhltxz
2017.06.15 19:22:05 1: 192.168.22.90:2323 reappeared (CUN_MAX)

Schafy

Hallo,

scheinbar ist das Problem auch 2023 noch aktiv. Ich habe zwar den ganzen Thread gelesen, aber keine wirkliche Lösung oder Workaround (ausser dem mit dem Reboot) gesehen. Kann mir jemand den Trick verraten?

Bei mir steigt FHEM komplett aus - die WebUI ist nicht mehr aufrufbar. Wären es nur die MAX Daten, die fehlen, wäre es halb so schlimm.
FHEM Docker auf QNAP NAS, DBLog, Max Cube als CUL, Max TH und FK, N4H-AJ3 & N4H-AR6

rudolfkoenig

Klassiche Ursachen solcher Probleme sind:
- ein zweites Programm, was von der gleichen Schnittstelle liest (z.Bsp. login oder zweites HA System)
- nicht ausreichende Stromversorgung
- defekt im CUL/etc: es haengt sich nach gewisser Zeit auf.

Ein FHEM-Log, am besten mit "attr global verbose 5" kann uns womoeglich bei der Fehlersuche helfen.

Es waere auch interessant zu sehen, ob das CUL/etc in "aufgehaengtem" Zustand auf direkte Anfragen antwortet.
Dazu FHEM stoppen, die USB Schnittstelle mit screen/etc oeffnen, und "V<RETURN>" absetzen.
Funktionierende Geraete antworten mit der Version.