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

Begonnen von Jojo11, 07 April 2017, 19:31:42

Vorheriges Thema - Nächstes Thema

Jojo11

Hallo,

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

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.

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

#4
Bitteschön:


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


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

#5
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

#6
*gulp*  :o
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

Zitat von: rudolfkoenig am 07 April 2017, 19:40:40
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

ZitatKann ich bei Zeile 998 irgendeinen log einbauen,
Ich empfehle, vor der Zeile 998 folgendes einzubauen
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:

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):

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

Keine Ahnung, wie ich damals darauf gekommen bin  :-[ ;D

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

Das hier ist die neue, funktionierende Definition:

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

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

#14
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

attr global stacktrace 1

gesetzt. Falls das einen Unterschied macht.

schöne Grüße
Jo