[gelöst] Nach Update "...fhem.pl line 4362"

[Jojo11]

Hallo,

nach heutigem Update wird mein log file mit folgender Meldung geflutet:

Code Auswählen Erweitern


Use of uninitialized value $cmd in pattern match (m//) at fhem.pl line 998.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.


Bin ich der Einzige oder gibt sich das wieder? 

schöne Grüße
Jo

[rudolfkoenig]

998: AnalyzeCommandChain wurde mit einem undefinierten Befehl aufgerufen.
4362: irgendein event-min-interval ist madig.

Evtl. sieht man bei "attr global verbose 5" mehr.

[Jojo11]

Puuh, daraus kann ich auch nichts erkennen (verbose 5). Die Zeile hängt überall mal dazwischen.

Code Auswählen Erweitern


2017.04.07 19:24:56.113 0: Server started with 1248 defined entities (fhem.pl:13911/2017-04-06 perl:5.022001 os:linux user:fhem pid:11460)
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
2017.04.07 19:24:58.576 3: FHEM2FHEM device opened (RPiMODBUS)
[...]
2017.04.07 19:47:15.512 4: HMW_IO12_7_03: HM485_ChannelDoUpdate
2017.04.07 19:47:15.513 5: HMW_IO12_7_03: HM485_ChannelDoUpdate: valueKey = press_long value = 40 Alter Wert = 40
2017.04.07 19:47:15.513 4: HMW_IO12_7_03: press_long -> 40
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
2017.04.07 19:47:15.805 5: HM485: HM485:Device:dataConversion: retVal = 40
2017.04.07 19:47:15.806 5: HM485: Device:valueToControl: valName = press_long = 40
2017.04.07 19:47:15.809 5: Starting notify loop for HMW_IO12_7, 1 event(s), first is ACK
[...]
017.04.07 19:47:55.201 5: End notify loop for AV_Receiver
2017.04.07 19:47:55.251 5: HMLAN_Send:  HMUSB1 I:K
^* matches null string many times in regex; marked by <-- HERE in m/^* <-- HERE $/ at fhem.pl line 4362.
2017.04.07 19:47:55.301 5: HMLAN/RAW: /HHM-USB-IF,03C7,KEQ1111252,2639FC,123ABC,F962EE1E,0009,02
2017.04.07 19:47:55.301 5: HMLAN_Parse: HMUSB1 V:03C7 sNo:KEQ1111252 d:2639FC O:123ABC t:F962EE1E IDcnt:0009 L:2 %
2017.04.07 19:47:55.301 5: Starting notify loop for HMUSB1, 1 event(s), first is loadLvl: low


schöne Grüße
Jo

[rudolfkoenig]

Bitte die Ausgabe von "list HMW_IO12_7_03" und "list .* event-min-interval" hier anhaengen.

[Jojo11]

Bitteschön:

Code Auswählen Erweitern


Internals:
   CFGFN      ./FHEM/fhem.cfg
   CHANGED
   DEF        0000F6F6_03
   FW_VERSION 3.06
   IODev
   MODEL      HMW_IO_12_Sw7_DR
   NAME       HMW_IO12_7_03
   NR         534
   STATE      press_long_47
   TYPE       HM485
   chanNo     03
   device     HMW_IO12_7
....


und

Code Auswählen Erweitern


AV_Receiver              10
AV_Receiver_Zone2        10
BM_Garage                brightness:180
BM_Garten                brightness:180
BM_Hof                   brightness:180
BM_Z                     brightness:180
LaCrosse_sensor1         *:300
LaCrosse_sensor2         *:300
LaCrosse_sensor5         *:300
LaCrosse_sensor6         *:300
LaCrosse_sensor7         *:300
SDM630M_1c               300


schöne Grüße
Jo

[rudolfkoenig]

Alle event-min-interval Werte fuer LaCrosse.* sind kaputt, da * kein Regexp ist.
* alleine ist im Shell ueblich (siehe https://en.wikipedia.org/wiki/Glob_(programming) ), das entsprechende regexp ist .*
FHEM verwendet ausschliesslich regexp, regexp ist deutlich maechtiger als glob, bitte irgendwo eine Einfuehrung dazu lesen (z.Bsp. perldoc perlretut)

P.S.: das Problem hat nichts mit irgendeinem update zu tun

[Jojo11]

*gulp* 
Hab ich vor Jahren mal so (falsch) definiert und lief seitdem.

Ist korrigiert und die Meldung ist weg. Vielen Dank!

schöne Grüße
Jo

[Jojo11]

998: AnalyzeCommandChain wurde mit einem undefinierten Befehl aufgerufen.
[...]

Kann ich bei Zeile 998 irgendeinen log einbauen, welches mir mehr Infos geben könnte? Stacktrace gibt nichts und verbose 5 ja irgendwie auch nicht. Die andere Meldung ist weg, aber die 998er kommt doch noch alle 2 Minuten 

Schöne Grüße
Jo

[rudolfkoenig]

Kann ich bei Zeile 998 irgendeinen log einbauen,

Ich empfehle, vor der Zeile 998 folgendes einzubauen

Code Auswählen Erweitern


if(!defined($cmd)) {
  Log 1, "ERROR: undefined cmd";
  stacktrace();
  return;
}
(ungetestet).

[Jojo11]

Vielen Dank!
Werde ich testen und dann berichten.

Schöne Grüße
Jo

[Jojo11]

Hallo,

mit dem code konnte ich folgenden log-Eintrag produzieren:

Code Auswählen Erweitern


2017.04.10 19:27:57.524 1: ERROR: undefined cmd
2017.04.10 19:27:57.524 1: stacktrace:
2017.04.10 19:27:57.524 1:     main::AnalyzeCommandChain           called by fhem.pl (3425)
2017.04.10 19:27:57.524 1:     main::fhem                          called by (eval 2771) (2)
2017.04.10 19:27:57.524 1:     (eval)                              called by fhem.pl (1076)
2017.04.10 19:27:57.524 1:     main::AnalyzePerlCommand            called by fhem.pl (1096)
2017.04.10 19:27:57.524 1:     main::AnalyzeCommand                called by fhem.pl (1024)
2017.04.10 19:27:57.524 1:     main::AnalyzeCommandChain           called by ./FHEM/90_at.pm (179)
2017.04.10 19:27:57.524 1:     main::at_Exec                       called by fhem.pl (2978)
2017.04.10 19:27:57.524 1:     main::HandleTimeout                 called by fhem.pl (617)


Dieser kam exakt alle 2 Minuten (was vorher nicht ersichtlich war). Bei der Durchsicht aller ATs, die alle 2 Minuten aufgerufen wurden bin ich fündig geworden. Es war ein (ziemlich alter) "addlog"-trigger. Nach dem Löschen war Ruhe.

Danke nochmal 

schöne Grüße
Jo

[rudolfkoenig]

Kannst du bitte noch die entfernte at Definition zeigen? Fuer at fuehle ich mich verantwortlich, und so'n Muell sollte er nicht produzieren.

[Jojo11]

Hallo,

gerne, das hier war die alte Definition (direkt aus der cfg kopiert):

Code Auswählen Erweitern


define at_addlogPwr at +*00:02:00 {fhem (addLogPwr("FS01_Pwr_aktuell","state"))}

Keine Ahnung, wie ich damals darauf gekommen bin 

Wobei addLogPwr eine sub in der 99_myUtils.pm ist.

Das hier ist die neue, funktionierende Definition:

Code Auswählen Erweitern


define at_addlogPwr at +*00:02:00 {addLogPwr("FS01_Pwr_aktuell","state")}


Wie gesagt, die Definition habe ich seit bestimmt 3 Jahren nicht geändert und bisher lief die eigentlich trotz des falschen codes.

schöne Grüße
Jo

[rudolfkoenig]

Code Auswählen Erweitern

define at_addlogPwr at +*00:02:00 {fhem (addLogPwr("FS01_Pwr_aktuell","state"))}

Ok, das erklaert es: addLogPwr liefert undef zurueck, und das verursacht die Meldung aus AnalyzeCommandChain.
at ist unschuldig, und die Ursache haette man einfacher (sprich ohne Code-Aenderung) auch mit "attr global stacktrace" finden koennen.

[Jojo11]

Aber genau das hatte ich ja schon gemacht. Mit dem Ergebnis, dass weder vor noch hinter der Meldung zusätzliche Informationen kamen.
Allerdings hatte ich

Code Auswählen Erweitern


attr global stacktrace 1

gesetzt. Falls das einen Unterschied macht.

schöne Grüße
Jo