[00_CUL.pm] patch für verbesserte homematic kommunikation

[frank]

hallo rudi,

vielleicht hast du es ja nur übersehen.
hier https://forum.fhem.de/index.php/topic,120603.msg1160891.html#msg1160891 hat noansi "nebenbei" auf einen patch für 00_CUL.pm hingewiesen:

Hier https://forum.fhem.de/index.php/topic,120268.msg1160889.html#msg1160889 übrigens noch Verbesserungen an 00_CUL.pm auch als diff, wie in dem Thread entstanden.
Es verbessert das Timing für Folgesendemessages, die zuvor beim User zu früh gesendet wurden, außerdem das Message Logging für den HM Support.

ich wäre sehr erfreut, wenn du noansis änderung übernehmen würdest.

[rudolfkoenig]

vielleicht hast du es ja nur übersehen.

Ich verfolge HomeMatic spezifische Diskussionen nicht.
PM blockiere ich nicht bewusst.
 
Der Diff ist mir so leider zu gross und zu unspezifisch, da wird von Timing-Aenderungen ueber Parsen bis generische Logausgaben viel umgebaut. Ich habe nichts gegen ein HM-Only patch, insb. wenn die Aenderungen klar abgegrenzt sind, und der Grund fuer mich verstaendlich ist.

[noansi]

Hallo Rudolf,

die Änderungen sind HM spezifisch.

Das Logging hier:

Code: [Auswählen]

-  Log3 $name, 5, "CUL/RAW: $culdata/$buf";
+#  Log3 $name, 5, "CUL/RAW: $culdata/$buf"; #noansi: still really of interest, how a fillup from serial IO is in progress? Loglevel 6?

Code: [Auswählen]

+    Log3 $name, 5, "CUL: $rmsg"; #noansi: this is more of interest in most cases and better readable kannst Du natürlich auf altem Stand lassen. Kostet mAn aber nur unnötig Rechenzeit (Timingauswirkungen) und macht das Log insbesondere bei seriellen devices unleserlich, weil man quasi zuschaut, wie Zeichen reintröpfeln und darüber die eigentliche message kaum findet.
Für spezielle Probleme möglicherweise nochmal mit Loglevel 6 interessant, aber eigentlich inzwischen eher historisch aus der CUL und devio Entwicklung begründet, denke ich.

Das HM Logging wieder formatiert auszugeben war Userwunsch, Frank kann Dir den Link sicherlich raus suchen.
Damit verbunden ist eine kleine Optimierung bei der rssi Extraktion und $len Ausnutzung.

Der Rest betrifft HM Timing von Antworten und Folgemessages.
Die positiven Effekte kann Dir Frank sicherlich auch am zugehörigen Thread darlegen. Sicherlich auch mit mehr von seinem super Logging, wenn es zur Erklärung nötig ist.

Gruß, Ansgar,

[rudolfkoenig]

Ich verstehe den Wunsch, hat aber alles seine Probleme (s.u.), und wenn alles in einer Tuete kommt, weiss nicht, welche ich einzeln weglassen kann.

Logging: loglevel 6 ist nur bei verbose 5 ein Performance-Gewinn, und zieht eine Tuete weiterer Probleme hinter sich. Das Troepfchenweise ist dann interessant, wenn kein NL kommt, und verbose 5 ist kein Normalfall. Formatieren speziell fuer HM muss das HM Modull uebernehmen, sonst kann man ja das HM-Modul gleich ins CUL.pm integrieren. Wenn es Timingprobleme gibt, dann sollte die Aufgabe im Firmware geloest werden.

Bei der kleinen RSSI Optimierung kann ich auf Anhieb nicht sehen, ob es fuer die anderen Protokolle auch funktioniert.

Ich hoffe, dass man dem Frank auch ohne diese Aenderungen helfen kann.

[frank]

Ich hoffe, dass man dem Frank auch ohne diese Aenderungen helfen kann.

der ansgar hat dem frank mit diesem patch bereits optimal geholfen. 

allerdings dachte dieser frank ganz unbedarft, dass den vielen anderen cul usern, die es da draussen im dschungel der homematic-io-fw/modul-welt in grosser zahl gibt, ebenfalls geholfen werden könnte.
vor allem "neuen" usern, die an jeder ecke lesen, dass ein cul für homematic das beste wäre und erschrocken reagieren, wenn sie deshalb beim ersten problem sofort "gemobbt" werden.


zum logging:
beim logging wünsche ich mir eigentlich nur, dass das logging mit verbose=4 mindestens wieder so wird, wie es schon mal gewesen ist.

verbose 5 ist kein Normalfall

eine analyse der homematic kommunikation mit einem cul ist aktuell aber leider nur mit verbose=5 machbar, da die messages, die der cul sendet, irgendwann aus verbose=4 "verbannt" wurden. also der normalfall.

im forum habe ich logs von ende 2016 gefunden, in denen die sende messages (CUL_send) noch mit verbose=4 zu sehen sind:

Code: [Auswählen]

2016.09.05 21:09:01.505 4: CUL_Parse: CUL0 A 0C B9 A641 278291 1DA462 01EF0031 -49.5
2016.09.05 21:09:01.608 4: CUL_send:  CUL0As 0D B9 8002 1DA462 278291 0101C800
aktuell ist erst bei verbose=5 eine ausgabe durch DevIO.pm zu sehen (SW), die mit CUL_send vergleichbar ist.

Code: [Auswählen]

2021.05.15 10:05:27.687 5: CUL/RAW: /A14
2021.05.15 10:05:27.689 5: CUL/RAW: A14/22A45F
2021.05.15 10:05:27.690 5: CUL/RAW: A1422A45F/653B
2021.05.15 10:05:27.691 5: CUL/RAW: A1422A45F653B/E0F1
2021.05.15 10:05:27.692 5: CUL/RAW: A1422A45F653BE0F1/1234
2021.05.15 10:05:27.693 5: CUL/RAW: A1422A45F653BE0F11234/8110
2021.05.15 10:05:27.694 5: CUL/RAW: A1422A45F653BE0F112348110/4C00
2021.05.15 10:05:27.695 5: CUL/RAW: A1422A45F653BE0F1123481104C00/1723
2021.05.15 10:05:27.696 5: CUL/RAW: A1422A45F653BE0F1123481104C001723/0223
2021.05.15 10:05:27.697 5: CUL/RAW: A1422A45F653BE0F1123481104C0017230223/0947F
2021.05.15 10:05:27.698 5: CUL/RAW: A1422A45F653BE0F1123481104C00172302230947F/A29
2021.05.15 10:05:27.699 5: CUL/RAW: A1422A45F653BE0F1123481104C00172302230947FA29
/

2021.05.15 10:05:27.700 4: CUL_Parse: SCC A 14 22 A45F 653BE0 F11234 81104C00172302230947FA29 -53.5
2021.05.15 10:05:27.701 5: SCC: dispatch A1422A45F653BE0F1123481104C00172302230947FA::-53.5:SCC
2021.05.15 10:05:27.706 5: SCC sending As0A228002F11234653BE000
2021.05.15 10:05:27.707 5: CUL 653BE0 dly:93ms
2021.05.15 10:05:27.801 5: SW: As0A228002F11234653BE000
das macht nicht nur keinen spass mehr sich durch diese logs zu wühlen. es wird nahezu unmöglich probleme zu entdecken, besonders wenn man homematic mit mehreren io betreibt.

Formatieren speziell fuer HM muss das HM Modull uebernehmen, sonst kann man ja das HM-Modul gleich ins CUL.pm integrieren.

das ist doch sicherlich ein wenig übertrieben.
ohne es genau zu wissen, behaupte ich mal, 00_CUL war das erste modul, das das logging für homematic vorgegeben hat. daran haben sich später 00_HMLAN, 00_HMUARTLGW und 00_TSCUL orientiert, um einigermassen kompatibel zu sein.
warum auch immer ist 00_CUL dann scheinbar (mit version 13833 vom 27.3.2017) aus dieser "allianz" ausgestiegen.



zum timing:

Wenn es Timingprobleme gibt, dann sollte die Aufgabe im Firmware geloest werden.

antworten vom cul an das device werden ja bereits in 00_CUL (schon immer?) verzögert gesendet, damit hier das "timing" passt. an dieser stelle wird also das timing bestimmt.

probleme mit der aktuellen 00_CUL gibt es in der regel nur, wenn der cul 2 messages nacheinander an das device senden muss, da dann nur die erste message verzögert gesendet wird, aber die 2. message bereits unmittelbar nach der ersten. diese fehlende 2. verzögerung, soll der patch "bereinigen".
die aktuelle implementierung hat diesen umstand scheinbar "übersehen".

dazu hat ansgar zusätzlich ein attribut vorgesehen, womit diese 2. verzögerung einstellbar wird. default 60ms.
ich erziele mit der default verzögerung von 60ms beste ergebnisse.

würde der patch eventuell mehr zustimmung erhalten, wenn das attribut gestrichen wird?
dann müsste man sich vielleicht noch mal über diesen dann festen wert gedanken machen.

[rudolfkoenig]

aktuell ist erst bei verbose=5 eine ausgabe durch DevIO.pm zu sehen (SW), die mit CUL_send vergleichbar ist.

Ich meine CUL_HM sollte auf verbose 4 die passend formatierten Daten anzeigen.

würde der patch eventuell mehr zustimmung erhalten, wenn das attribut gestrichen wird?

Ich habe nichts gegen das Attribut, ich will nur nicht neben den HM-spezifischen Timing-Aenderungen auch noch generell Logging, Parsen, etc umbauen.

[noansi]

Hallo Rudolf,

Ich meine CUL_HM sollte auf verbose 4 die passend formatierten Daten anzeigen.

Ist zwar möglich, aber die Ankunftzeitinformation wird deutlich schlechter und insbesondere die Sendezeitinformation wird unbrauchbar.

Bei der kleinen RSSI Optimierung kann ich auf Anhieb nicht sehen, ob es fuer die anderen Protokolle auch funktioniert.

Wird auf die gleichen "Anfangsbuchstaben" angewendet mit gleicher "Erkennung", ob ein RSSI mitgeliefert wird.
Er wird weiterhin aus den letzten beiden Zeichen gewonnen. Die letzten beiden Zeichen werden daraufhin weiterhin von der dispatch message abgeschnitten. Die Stringlängeninformation wird durch -2 entsprechend korrigiert.
Außerdem wird die Zeit etwas früher genommen (nach Deiner üblichen Zeittoleranz irrelevant) und die Information "wiederverwendet", ebenso wie "Anfangsbuchstabe" und die Stringlänge.
$dmsgLog entfällt, da es nicht wirklich erforderlich ist.
Alles nicht dramatisch.
Auch bei HM messages ist der RSSI nicht Teil der message, sondern ebenfalls nur angehangen, gehört bei der Log message also hex abgeschnitten, wie bei anderen Protokollen auch. Der Patch behebt damit einen Bug beim HM Parse Logging.
Siehe auch Franks Beispiel, len=0x0c aber 13 Bytes in der Log message.
Das kannst Du natürlich auch anders mit weniger Eingriff lösen.

Was Frank aber vor allem neben der Timing Korrektur fehlt, ist das verbose 4 HM Sende Logging, weil er dann gar nicht auf verbose 5 einstellen müßte.

Code: [Auswählen]

+      Log3 $name, 4, "CUL sent: $name ".join(" ",(unpack'A2A2A2A4A6A6A*',$bstring)); #noansi: for support guys better readable https://forum.fhem.de/index.php/topic,120268.msg1156754.html#msg1156754
Und auch hier ist die möglichst genaue Zeit des Abschickens interessant, wie schon angeführt.

Dann wären ihm auch die beiden von mir schon genannten Zeilen bezüglich verbose 5 egal.

Wenn es Timingprobleme gibt, dann sollte die Aufgabe im Firmware geloest werden.

Ganz meine Meinung. Kannst Du gerne übernehmen, der Patch fetzt dann aber richtig durch den Code. 

Gruß, Ansgar.

[frank]

hallo rudi,

ich tue mich schwer damit, genau zu verstehen, an welcher stelle deine "bauchschmerzen" entstehen.

meine spekulation:
- du möchtest die loginfo der sendemsg weiterhin in devio behalten, nicht in 00_cul.
- in devio möchtest du aber keine hm-spezifischen fallunterscheidungen.

falls das in die richtige richtung geht, wäre es dann eventuell möglich, die aktuelle loginfo aus devio:

Code: [Auswählen]

2021.05.15 10:05:27.801 5: SW: As0A228002F11234653BE000
auf verbose=4 zu ändern?

der sende string braucht nicht "zerlegt" zu werden, also ohne formatierung. 
allerdings müsste der devicename vom entsprechenden cul noch eingebaut werden, um bei multi-io betrieb eine eindeutige zuordnung zu bekommen.
der devicename fehlt eigentlich auch in 2 weiteren log infos, wenn ich mir das obige log anschaue. die CUL/RAW-einträge und die info mit der dly-info zeigen ebenfalls nicht das sendende io. 

die logzeile würde dann zb so aussehen:

Code: [Auswählen]

2021.05.15 10:05:27.801 4: SW: SCC As0A228002F11234653BE000

[rudolfkoenig]

Ist zwar möglich, aber die Ankunftzeitinformation wird deutlich schlechter und insbesondere die Sendezeitinformation wird unbrauchbar.

Wenn Timing so wichtig ist, dann muesste das von Firmware mitgeschickt werden. FHEM ist nicht realtime faehig, und ich habe nicht vor, daran was zu aendern.

ich tue mich schwer damit, genau zu verstehen, an welcher stelle deine "bauchschmerzen" entstehen.

An vielen Stellen
Lowlevel read und write gehoert mAn auf level 5. Dass die Daten Tropfchenweise reinkommen, wundert mich, das ist bei mir (ueber USB anbundenes CUL, SlowRF Daten) nicht der Fall, ich kriege eine Zeile pro Nachricht. Ich tippe bei Dir auf ueber Netzwerk angebundenes CUL, fuer diesen Fall habe ich das CUL Attribut noRawReadLog eingebaut.

Dass man bei mehreren IO-Geraeten den Namen sehen will, versetehe ich, das habe ich fuer DevIO_SimpleWrite, CUL_Read und CUL_ReadAnswer eingebaut.

[noansi]

Hallo Rudolf,

Dass die Daten Tropfchenweise reinkommen, wundert mich, das ist bei mir (ueber USB anbundenes CUL, SlowRF Daten) nicht der Fall, ich kriege eine Zeile pro Nachricht.

Richtig, ein nativ USB fähiger CUL schickt seinen Buffer auch meißt in einem Rutsch raus (es sei denn, der USB Transferbuffer wird vor dem Compilieren sehr klein gewählt).
Alle nativ seriell angebundenen CULs schicken Ihren Buffer Zeichen für Zeichen. Und so schnell, wie FHEM die aus seinem Empfangsbuffer abholen kann, so tröpfchenweise kommen sie rein. Mal einzeln, mal mehrere auf einmal, wenn FHEM sehr beschäftigt ist, dann kann es auch mal eine Nachricht komplett sein.
Für interessierte Mitleser, die Nanos sind auch nativ seriell angebunden, nur via USB Interface Chip.

Wenn Timing so wichtig ist, dann muesste das von Firmware mitgeschickt werden. FHEM ist nicht realtime faehig, und ich habe nicht vor, daran was zu aendern.

Wenn User nun mal unbedingt die Standard oder a-culfw verwenden möchten, dann kommt vom CUL keine Timing Information und damit bleibt Frank als einem der Powersupporter dort nur noch das raw log, um Anhaltspunkte zu Problemursachen bezüglich Timing zu finden.

Gruß, Ansgar.

[noansi]

Hallo Rudolf,

ich habe den Patch nochmal etwas überarbeitet, siehe Anhang.

EDIT: Gehe ich richtig in der Annahme, das commandref_join.pl Zeile 82 nun eigentlich besser

Code: [Auswählen]

  $var = $1 if($l =~ m/<a (?:id|name)="(.*?)"(?:.*?)><\/a>/);
lauten sollte, damit auch id berücksichtigt wird?

Gruß, Ansgar.

[rudolfkoenig]

ich habe den Patch nochmal etwas überarbeitet, siehe Anhang.

Das geht eindeutig in die falsche Richtung: der neue Patch ist dreimal so gross wie der Alte.

Gehe ich richtig in der Annahme, das commandref_join.pl Zeile 82 nun eigentlich besser...lauten sollte, damit auch id berücksichtigt wird?

So oder aehnlich, aber ich fuerchte da ist noch mehr zu tun.
Ich nehme das auf meine TODO Liste. Danke fuer den Hinweis.

[noansi]

Hallo Rudolf,

Das geht eindeutig in die falsche Richtung: der neue Patch ist dreimal so gross wie der Alte.

Schade, ich dachte, es hilft Dir, wenn das CUL Commandref von <a name auf <a id umgearbeitet wäre.

EDIT: verbose 5 Logging in CUL_Read($) habe ich wieder zurück gebaut.

Gruß, Ansgar.

[rudolfkoenig]

Ich habe jetzt die noRawReadLog Aenderungen eingecheckt, das war irgendwie beim letzten Mal durchgerutscht.
Weiterhin die CUL.pm Doku auf die ID-Syntax umgestellt bzw. ergaenzt und das gemeldete commandref_join Problem gefixt.

[noansi]

Hallo Rudolf,

danke für die Änderungen.
@Frank: Timing ist unangetastet.

Im Anhang nochmal patches.

In commandref_join.pl.diff hat vermutlich der Suchen/Ersetzen Teufel zugeschlagen und ich habe mal nach naheliegender Annahme versucht zu korrigieren, bin mir aber nicht sicher und würde gerne den 50/50 Joker ziehen. 
In commandref_frame_DE.html steckt übrigens der gleiche englische Text, wie in commandref_frame.html, wäre damit genauso zu ändern, sofern Du nicht ohnehin planst, das zu übersetzen.

In 00_CUL.pm.diff habe ich nun nur die Timing Änderungen etwas schlechter drin + einem Fehler im commandref + dort zwei Zeilen mit überflüssigen Leerzeichen. Sollten die relevant sein, sorry.

@Frank: Bitte teste mal, ob das
a) noch genauso gut bezüglich HM Timing funktioniert
und
b) schau mal, ob Du mit dem Logging (+ aktueller devio.pm) so ausreichend gut leben kannst

Gruß, Ansgar.