00_CUL vom 27.5. defekt

[Elektrolurch]

Hallo,

seit der o.g. Version steigt mir beim Neustart von fhem der angeschlossen CUL 868 aus. Die Meldung im log sagt, das ein Problem mit /dev/tiaco besteht und der CUL wird per attr auf "dummy = 1" gesetzt.
Die INTERNAL - Values sehen auch recht merkwürdig aus, bspw. fehlt VERSION.
Herumprobieren mit
a) set CUL_0 reopben
zeigten kein Erfolg.
Bei der Gelegenheit habe ich dann den CUL auf die CULF 1.65 upgedated, aber der Effekt ist der gleiche.
Löscht man das Attribut dummy beim CUL klappt es ein über das andere Mal beim Neustart (halbe zu halbe).
Ich habe jetzt die Vorgängerversion von der 00_CUL
wieder eingespielt, da tritt der Fehler nicht auf.


Elektrolurch

[rudolfkoenig]

Wenn ich was reparieren soll, dann brauche ich einen aussagekraeftigen FHEM-Log, z.Bsp. mit verbose 5.

[fhainz]

Hallo!

Gestern hab ich ein Update gemacht und hatte anschließend auch dieses Problem. Bei mir war zwar das dummy attr nicht gesetzt, aber das Internal VERSION war nicht vorhanden und funktelegramme kamen weder an noch gingen sie raus. Heute mittag fiel mir das zum ersten mal auf. Hab dann FHEM-Neugestartet und folgendes mit verbose 3 im Log.

2015.06.01 12:24:42.714 3: Opening CUL1 device /dev/tty.usbmodem1a1221
2015.06.01 12:24:42.715 3: Setting CUL1 baudrate to 9600
2015.06.01 12:24:42.715 3: CUL1 device opened
2015.06.01 12:24:42.851 1: Not an CUL device, got for V:  T4C3D00BA0013

2015.06.01 12:24:42.853 1: Cannot init /dev/tty.usbmodem1a1221, ignoring it (CUL1)

Jetzt zuhause hab ich wieder die alte Version eingespielt und es klappte alles problemlos.
Hab anschließend diesen Thread im Forum entdeckt und wollte einen Log spendieren und hab wieder ein Update gemacht. Jetzt funktioniert der CUL aber auch mit der neuen Version
Ich werde das beobachten und bei Problemen melde ich mich nochmals.

Grüße

[Elektrolurch]

Hallo,

das hatte ich auch im log:
Zitat
2015.06.01 12:24:42.714 3: Opening CUL1 device /dev/tty.usbmodem1a1221
2015.06.01 12:24:42.715 3: Setting CUL1 baudrate to 9600
2015.06.01 12:24:42.715 3: CUL1 device opened
2015.06.01 12:24:42.851 1: Not an CUL device, got for V:  T4C3D00BA0013

2015.06.01 12:24:42.853 1: Cannot init /dev/tty.usbmodem1a1221, ignoring it (CUL1)


Die Zeile: Not an CUL device, got for V: 
zeigt, das der Autor ein gewisses Maß an Humor hat.
Leider wurde mir mitgeteilt, dass ich verbose 5 einschalten solte. Ob da wirklich mehr kommt?

Ich hatte:

get CUL_0 ccconf
eingetippt und bekam die Meldung, dass dies für einen dummy nicht ginge.

Daraufhin habe ich unter den Attributen nachgesehen und festgestellt, dass attr dummy 1 gesetzt war.
Gelöscht, save gemacht und neu gestartet und wieder
war attr dummy 1 gesetzt.

So, mehr sinnvolle Hinweise kann ich wirklich nicht geben, denn das Attribut muss ja in der 10_cul.pm irgendwo auf Grund einer Condition gesetzt werden.

Außerdem gibt es ja auch noch einen diff zur funktionierenden Vorgängerversion...

Elektrolurch

[rudolfkoenig]

@Elektrolurch: Ich brauche einen Log mit "attr global verbose 5".

[gero]

Ich habe bei mir in den Logs auch zweimal den Fehler entdeckt:

Code Auswählen Erweitern

2015.05.29 15:02:55 1: Not an CUL device, got for V:  Z0C6B044205D62900000000V 1.65 CUL868

Code Auswählen Erweitern

2015.05.29 15:07:36 1: Not an CUL device, got for V:  Z0B1C0630073448123456001011

Der Fehler ist ziemlich sicher durch das jetzt korrekte Handling von $hash->{PARTIAL} in CUL_ReadAnswer reingekommen ist.
Vermutlich funktioniert das CUL_Clear nicht korrekt . Im ersten Fehlerfall (s.o.) sieht man, dass moch eine unfertige Nachricht in $hash->{PARTIAL} gestanden haben muß.
Zusätzlich muß wahrscheinlich in der CUL_DoInit das CUL_ReadAnswer($hash, "Version", 0, undef) mit einer vernünfigen regexp versehen werden. Wie im zweiten Fehlerfall zu sehen ist, wird die erstbeste Nachricht vom CUL als Versionsinformation geparst.

Ich versuche das Problem heute nachzustellen. Aber das wird nicht ganz so einfach...
Falls jemand anderes ein Log mit attr global verbose 5 beisteuern kann, würde es die Sache vereinfachen.

Der Fehler sollte auftreten, wenn fhem längere Zeit nicht läuft und während dieser Zeit Nachrichten vom CUL empfangen werden.

Gruß,
Gero

[Elektrolurch]

Hallo,

Zitat:
Der Fehler sollte auftreten, wenn fhem längere Zeit nicht läuft und während dieser Zeit Nachrichten vom CUL empfangen werden.

dagegen spricht aber, dass bei mir der Fehler im neustart, auftritt und dass zum Zeitpunkt des shutdowns noch Nachrichten im CUL standen, ist tagsüber eher unwahrscheinlich, da habe ich kaum traffic auf dem System.

[gero]

Nochmal vorsichtiger ausgedrückt:
Die hier im Thread vorhandenen Fehlermeldungen zeigen, dass bei der Abfrage der Version des CULs eine falsche Nachricht geparst wird. Und das führt zu dem attr dummy 1.
Der Fehler sollte vermehrt auftreten, wenn fhem längere Zeit nicht läuft und während dieser Zeit Nachrichten vom CUL empfangen werden.
Es kann natürlich noch eine Besonderheit bei FHT geben. Ich verwende MAX.

Ich bin zuversichtlich, dass ich einen Patch liefern kann, der das Problem behebt. Allerdings hätte ich doch erstmal gerne einen Nachweis dafür.

[rudolfkoenig]

Ganz andere Baustelle: auf der Leitung ist echo eingeschaltet.
Eigentlich sollte das mit einer CUL-Definition mit @ abgeschaltet sein.

[duke-f]

Ok, hab meinen Beitrag gelöscht, um niemand in die Irre zu führen.

[drdownload]

Mehr kommt leider auch bei verbose5 am CUL nicht:

2015.06.02 11:38:24 3: Opening CUL_0 device /dev/serial/by-id/usb-busware.de_CUL868-if00
2015.06.02 11:38:24 3: Setting CUL_0 baudrate to 9600
2015.06.02 11:38:24 3: CUL_0 device opened
2015.06.02 11:38:27 1: Not an CUL device, got for V:  K113532550D

2015.06.02 11:38:27 1: Cannot init /dev/serial/by-id/usb-busware.de_CUL868-if00, ignoring it (CUL_0)

[Elektrolurch]

Sag ich doch, verbose 5 wird auch nicht mehr bringen. Ich hatte mir vor einiger Zeit  genau das auch schon mal angesehen und da stand beim Init des CULs nicht mehr drin., als bei verbose 3.

[gero]

Ihr müsst das verbose 5 in global setzen. Zum Zeitpunkt des Startups greift das Attribut verbose vom CUL noch nicht.

Ich habe den Fehler inzwischen nachstellen können. Und werde meine Mittagspause nutzen einen Patch zu schreiben.

Hier das Log:

Code Auswählen Erweitern

2015.06.02 08:54:57 3: Opening CUL_0 device /dev/ttyACM_CUL
2015.06.02 08:54:57 3: Setting CUL_0 baudrate to 9600
2015.06.02 08:54:57 3: CUL_0 device opened
2015.06.02 08:54:57 1: CUL_Clear
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Clear regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): Z0CC3044205D6290000000022D82F

2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Clear regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): Z0CD204420881AB0000000022CD11
Z0CC4044205D6290000000022D82F
Z0
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Clear regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}: Z0CC4044205D6290000000022D82F
Z0
2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): CD304420881AB0000000022CF11
Z0CC5044205D6290000000022D82E
Z0CD
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Clear regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}: Z0CD304420881AB0000000022CF11
Z0CC5044205D6290000000022D82E
Z0CD
2015.06.02 08:54:57 1: CUL_Clear: hash->{PARTIAL}: Z0CD304420881AB0000000022CF11
Z0CC5044205D6290000000022D82E
Z0CD
2015.06.02 08:54:57 1: SW: V
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Version regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}: Z0CD304420881AB0000000022CF11
Z0CC5044205D6290000000022D82E
Z0CD
2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): V 1.65 CUL868

2015.06.02 08:54:57 1: SW: V
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Version regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}: Z0CC5044205D6290000000022D82E
Z0CDV 1.65 CUL868

2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): V 1.65 CUL868

2015.06.02 08:54:57 1: SW: V
2015.06.02 08:54:57 1: CUL_ReadAnswer arg:Version regexp:
2015.06.02 08:54:57 1: CUL_ReadAnswer hash->{PARTIAL}: Z0CDV 1.65 CUL868
V 1.65 CUL868

2015.06.02 08:54:57 1: CUL/RAW (ReadAnswer): V 1.65 CUL868

2015.06.02 08:54:57 1: Not an CUL device, got for V:  Z0CDV 1.65 CUL868

2015.06.02 08:54:57 1: Cannot init /dev/ttyACM_CUL, ignoring it (CUL_0)
2015.06.02 08:54:57 1: SW: X21
2015.06.02 08:54:57 1: SW: Zr
2015.06.02 08:54:57 2: Switched CUL_0 rfmode to MAX
2015.06.02 08:54:57 1: CUL_MAX_Check: No IODev has no VERSION
2015.06.02 08:54:57 3: CUL_MAX_Check: Detected firmware version 0 of the CUL-compatible IODev


[drdownload]

Hallo Gero, danke für die schnelle Reaktion, ich habe jetzt auch erstmal eine alte pm vor dem 27.5. eingespielt aus dem backup.

[gero]

Anbei der Patch, der das Init-Problem hoffentlich behebt.

Was bleibt sind noch potentielle Unknow code Meldungen während der Initphase. Die gab es aber früher meiner Meiung nach auch schon. Treten jetzt aber etwas wahrscheinlicher auf.
@Rudi: Du kannst mit Sicherheit am besten überblicken, bis zu welchem Zeitpunkt man das CUL_Parse deaktivieren kann. Oder ob die Nachrichten überhaupt ein Problem darstellen.

Hier nochmal ein Log mit gepachter 00_CUL.pm:

Code Auswählen Erweitern

2015.06.02 12:50:01 3: Opening CUL_0 device /dev/ttyACM_CUL
2015.06.02 12:50:01 3: Setting CUL_0 baudrate to 9600
2015.06.02 12:50:01 3: CUL_0 device opened
2015.06.02 12:50:01 1: CUL_Clear
2015.06.02 12:50:01 1: CUL_ReadAnswer arg:Clear regexp:wontmatch
2015.06.02 12:50:01 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 12:50:01 1: CUL/RAW (ReadAnswer): Z0C18044205D6290000000022DA2F
Z0C2704420881AB0000000022D910
Z0C19044205D6290000000022DA2F
Z0C2804420881AB0000000022D910

2015.06.02 12:50:01 1: CUL_Parse: CUL_0 Z0C18044205D6290000000022DA2F -50.5
2015.06.02 12:50:02 3: CUL_0: Unknown code Z0C18044205D6290000000022DA, help me!
2015.06.02 12:50:02 1: CUL_Parse: CUL_0 Z0C2704420881AB0000000022D910 -66
2015.06.02 12:50:02 3: CUL_0: Unknown code Z0C2704420881AB0000000022D9, help me!
2015.06.02 12:50:02 1: CUL_Parse: CUL_0 Z0C19044205D6290000000022DA2F -50.5
2015.06.02 12:50:02 3: CUL_0: Unknown code Z0C19044205D6290000000022DA, help me!
2015.06.02 12:50:02 1: CUL_Parse: CUL_0 Z0C2804420881AB0000000022D910 -66
2015.06.02 12:50:02 3: CUL_0: Unknown code Z0C2804420881AB0000000022D9, help me!
2015.06.02 12:50:02 1: CUL_Clear: hash->{PARTIAL}:
2015.06.02 12:50:02 1: SW: V
2015.06.02 12:50:02 1: CUL_ReadAnswer arg:Version regexp:^V
2015.06.02 12:50:02 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 12:50:02 1: CUL/RAW (ReadAnswer): V 1.65 CUL868

2015.06.02 12:50:02 1: SW: ?
2015.06.02 12:50:02 1: CUL_ReadAnswer arg:cmds regexp:.*Use one of[ \*0-9A-Za-z]+[\r\n]*$
2015.06.02 12:50:02 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 12:50:02 1: CUL/RAW (ReadAnswer): ? (? is unknown) Use one of B b C F i A Z N k G M K U Y R T V W X e f m L l t u x

2015.06.02 12:50:02 3: CUL_0: Possible commands: BbCFiAZNkGMKUYRTVWXefmLltux
2015.06.02 12:50:02 1: SW: X21
2015.06.02 12:50:02 1: SW: T01
2015.06.02 12:50:02 1: CUL_ReadAnswer arg:FHTID regexp:
2015.06.02 12:50:02 1: CUL_ReadAnswer hash->{PARTIAL}:
2015.06.02 12:50:02 1: CUL/RAW (ReadAnswer): 1034

2015.06.02 12:50:02 1: SW: Ax
2015.06.02 12:50:02 1: SW: X21
2015.06.02 12:50:02 1: SW: Zr
2015.06.02 12:50:02 2: Switched CUL_0 rfmode to MAX
2015.06.02 12:50:02 3: CUL_MAX_Check: Detected firmware version 165 of the CUL-compatible IODev
2015.06.02 12:50:02 1: SW: Za123456
2015.06.02 12:50:02 1: SW: Zw111111


Gruß,
Gero