falscher Name des SIGNALduino in den Logs

elektron-bbs commented 2 years ago

Expected Behavior

NAME des verwendeten SIGNALduino sollte im Log stehen.

Actual Behavior

Es wird scheinbar der NAME des beim FHEM-Start zuletzt definierten SIGNALduinos verwendet. Passiert nur bei Log-Ausgaben, die in der SD_Protocols.pm z.B. mittels $self->_logging(qq[lib/postDemo_WS7035, ERROR - wrong checksum],3 ); oder anderen postDemodulation erzeugt werden.

Steps to Reproduce the Problem

dispatch

MU;P0=-384;P1=837;P2=-194;P3=352;P4=-870;D=10341010101034101010103410341010341010101034341010343410341010343410341034101010;CP=3;

show Log

2022.02.08 14:19:41.363 4: sduino_dummy: get rawmsg: MU;P0=-384;P1=837;P2=-194;P3=352;P4=-870;D=10341010101034101010103410341010341010101034341010343410341010343410341034101010;CP=3;
2022.02.08 14:19:41.365 4: sduino_dummy: Parse_MU, Fingerprint for MU protocol id 60 -> WS2000 matches, trying to demodulate
2022.02.08 14:19:41.369 1: PERL WARNING: Use of uninitialized value in join or string at FHEM/lib/SD_Protocols.pm line 1439.
2022.02.08 14:19:41.369 3: sduinoEasy868: lib/postDemo_WS2000, Sensortyp 0 Adr 0 - ERROR check XOR

Specifications

Microcontroller: egal
Version (Firmware): egal
Versionmodul (FHEM Module): 3.5.4+20220201

elektron-bbs commented 2 years ago

Gleich noch ein paar Erläuterungen dazu. Mir sind schon mehrmals Log-Einträge dieser Art aufgefallen:

2022.02.08 00:39:56 3: sduinoEasyESP32_868: lib/postDemo_WS7035, ERROR - wrong checksum
2022.02.08 02:48:32 3: sduinoEasyESP32_868: lib/postDemo_WS7035, ERROR - wrong checksum
2022.02.08 03:03:31 3: sduinoEasyESP32_868: lib/postDemo_WS7035, ERROR - wrong checksum

Allerdings war dieser SIGNALduino zu der Zeit gar nicht in Betrieb, kann also unmöglich irgend etwas empfangen haben.

Bei Tests heute wegen einer Perl-Warnung taucht dieser Fehler wieder auf:

2022.02.08 14:19:41.363 4: sduino_dummy: get rawmsg: MU;P0=-384;P1=837;P2=-194;P3=352;P4=-870;D=10341010101034101010103410341010341010101034341010343410341010343410341034101010;CP=3;
2022.02.08 14:19:41.365 4: sduino_dummy: Parse_MU, Fingerprint for MU protocol id 60 -> WS2000 matches, trying to demodulate
2022.02.08 14:19:41.369 1: PERL WARNING: Use of uninitialized value in join or string at FHEM/lib/SD_Protocols.pm line 1439.
2022.02.08 14:19:41.369 3: sduinoEasy868: lib/postDemo_WS2000, Sensortyp 0 Adr 0 - ERROR check XOR

2022.02.08 20:46:01 4: sduino_dummy: get rawmsg: MU;P0=-384;P1=837;P2=-194;P3=352;P4=-870;D=10341010101034101010103410341010341010101034341010343410341010343410341034101010;CP=3;
2022.02.08 20:46:01 4: sduino_dummy: Parse_MU, Fingerprint for MU protocol id 60 -> WS2000 matches, trying to demodulate
2022.02.08 20:46:01 3: sduinoEasyESP32_868: lib/postDemo_WS2000, Sensortyp 0 - ERROR rest of message < 4 (3)

sidey79 commented 2 years ago

Ich denke, das liegt daran, dass das Objekt nur einmal initialisiert wird und somit nur eine log callback bekommt.

Entweder jeder Signalduino initialisiert sein eigenes Modul oder wir finden eine Möglichkeit den Namen mit zu geben.

elektron-bbs commented 2 years ago

Ich habe keine Ahnung, wo ich da ansetzen soll, um den Fehler zu beseitigen. Ich habe heute mal den sduinoEasyESP32_868 auf verbose 4 gesetzt und bekam anschließend z.B. folgende Ausgaben ins Log:

2022.03.07 17:58:34 3: sduinoEasyESP32_868: Attr, setting Verbose to: 4
2022.03.07 17:58:39 4: sduinoEasyESP32_868: lib/postDemo_WS2000, Sensortyp 1 Adr 6 - Thermo/Hygro
2022.03.07 17:58:44 4: sduinoEasyESP32_868: lib/mcBit2Hideki, receive data is inverted
2022.03.07 17:59:08 4: sduinoEasyESP32_868: lib/postDemo_WS7035, 10100000011000101001000101110111100100010100
2022.03.07 18:00:56 3: sduinoEasyESP32_868: Attr, setting Verbose to: 3

Der sduinoEasyESP32_868 ist eingestellt auf rfmode Lacrosse_mode2 - kann also unmöglich diese Protokolle empfangen.

HomeAutoUser commented 2 years ago

Ein paar Ideen vielleicht.

1) Wenn du den Receiver umbenennst, wechselt da auch der Name?

2) Was ist, wenn du den Empfänger mal auf closed setzt, was passiert da mit der Verarbeitung wo der falsche Name angezeigt wird?

sidey79 commented 2 years ago

Rename und Close helfen da nicht.

Das Objekt existiert nur einmal und nicht je Definition:

https://github.com/RFD-FHEM/RFFHEM/blob/8e29da6356ae92e1b722f56aef815990375b4d07/FHEM/00_SIGNALduino.pm#L286

Wenn etwas in das Log geschrieben werden soll, dann werden zwei Parameter übergeben:

https://github.com/RFD-FHEM/RFFHEM/blob/8e29da6356ae92e1b722f56aef815990375b4d07/FHEM/lib/SD_Protocols.pm#L465

Die logCallback nimmt den Namen der Definition von dem es zuletzt initialisiert würde.

https://github.com/RFD-FHEM/RFFHEM/blob/8e29da6356ae92e1b722f56aef815990375b4d07/FHEM/00_SIGNALduino.pm#L3777-L3787

elektron-bbs commented 2 years ago

Ich denke, das liegt daran, dass das Objekt nur einmal initialisiert wird und somit nur eine log callback bekommt. Entweder jeder Signalduino initialisiert sein eigenes Modul oder wir finden eine Möglichkeit den Namen mit zu geben.

Ich hätte jetzt Variante 2 (der Name des SIGNALduino wird mit übergeben) am Laufen. Ist halt etwas aufwändig das einzuarbeiten. Es müssen ca. 90 Logausgaben in der SD_Protocols.pm angepasst werden.

Für Variante 1 habe ich keine Lösung gefunden. Dazu fehlt mir der Überblick, was wo zu ändern ist.

Welche Variante würdest du bevorzugen? Macht es Sinn, das ich mit Variante 2 weiter mache?

sidey79 commented 2 years ago

Die Mega Lösung habe ich auf Anhieb nicht.

Jede Instanz generiert eine eigene Log Callback. In der Log Callback stehen der Name. Wir merken uns aber nur die zuletzt initialisierte LogCallback. Wenn wir eine Möglichkeit finden, die richtige Callback aufzurufen, dann wäre alles gelöst.

sidey79 commented 2 years ago

Also wir initalisieren {protocolObject} einmal im Modul und dann speichern wir dieses Objekt in jeden Gerätehash. Ich bin gerade nicht so sicher ob das ggf. als Referenz hinterlegt wird oder dupliziert.

Im Modulkontext brauchen wir es nur um die Attributliste zu laden. Im Gerätehash brauchen wir es für die Verarbeitung der Daten. Hier kommt dann auch das Logging vor. Wir könnten hier einfach jedem Gerätehash eine eigene Instanz der Klasse geben. Die Protokolldaten sind referenziert, werden also nicht doppelt geladen. Ich würde auch fast annehmen, dass die subs nur einmal im speicher liegen und ebenfalls referenziert sind.

elektron-bbs commented 2 years ago

Also wir initalisieren {protocolObject} einmal im Modul und dann speichern wir dieses Objekt in jeden Gerätehash. Ich bin gerade nicht so sicher ob das ggf. als Referenz hinterlegt wird oder dupliziert.

Mhmm, es wird aber offensichtlich alles immer wieder in ein und demselben Hash abgelegt:

2022.03.08 17:51:38 1: Including fhem.cfg
2022.03.08 17:51:38 3: WEB: port 8083 opened
2022.03.08 17:51:39 2: eventTypes: loaded 15324 lines from ./log/eventTypes.txt
2022.03.08 17:51:39 1: SIGNALduino: SIGNALduino_Initialize, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:39 1: sduinoIP: SIGNALduino_Define, name = sduinoIP
2022.03.08 17:51:39 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:39 1: sduinoACM: SIGNALduino_Define, name = sduinoACM
2022.03.08 17:51:39 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:39 1: sduinoUSB0: SIGNALduino_Define, name = sduinoUSB0
2022.03.08 17:51:39 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:39 1: sduino_dummy: SIGNALduino_Define, name = sduino_dummy
2022.03.08 17:51:39 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:45 1: sduinoD1: SIGNALduino_Define, name = sduinoD1
2022.03.08 17:51:45 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)
2022.03.08 17:51:45 1: sduinoEasyESP32_868: SIGNALduino_Define, name = sduinoEasyESP32_868
2022.03.08 17:51:45 1: SIGNALduino: SIGNALduino_Define, Protocols = lib::SD_Protocols=HASH(0x16f9850)

sidey79 commented 2 years ago

Was genau hast Du da ausgegeben?

elektron-bbs commented 2 years ago

Zum einen:

sub SIGNALduino_Initialize {
  my ($hash) = @_;

  my $dev = '';
  $dev = ',1' if (index(SDUINO_VERSION, 'dev') >= 0);

  $Protocols->registerLogCallback(SIGNALduino_createLogCallback($hash));
  $hash->{protocolObject} = $Protocols;
  Log3 'SIGNALduino', 1, "SIGNALduino: SIGNALduino_Initialize, Protocols = $Protocols";

und in der sub SIGNALduino_Define:

  my $ret=undef;
  Log3 $name, 1, "$name: SIGNALduino_Define, name = $name";
  # $Protocols->registerLogCallback(SIGNALduino_createLogCallback($name));
  $Protocols->registerLogCallback(SIGNALduino_createLogCallback($hash));
  $hash->{protocolObject} = $Protocols;
  Log3 'SIGNALduino', 1, "SIGNALduino: SIGNALduino_Define, Protocols = $Protocols";

RFD-FHEM / RFFHEM