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

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.