Hallo,
ich bekomme seit geraumer Zeit immer folgende Fehlermeldung im Log.
[Thu May 31 09:43:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 09:44:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 09:44:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 09:45:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 09:45:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
Immer zwei Meldungen und auch immer zur vollen Minute.
Verbose 5 und stacktrace 1 haben hier nicht geholfen, dem Verursacher auszumachen.
Hat jemand eine Idee, wie ich diesen finden kann? Google und die Forumsuche konnten mir auch nicht wirklich helfen.
Danke und Gruß
Kai
Zitat von: kaizo am 31 Mai 2018, 09:49:18
Verbose 5 und stacktrace 1 haben hier nicht geholfen, dem Verursacher auszumachen.
wer sagt das - ausser Dir?
Es wäre schon schön, wenn man den stacktrace mal sehen könnte.
Ok. Es hat mir nicht geholfen, den Verursacher auszumachen.
Hier drei Auszüge aus dem Log
1.
2018.05.31 11:15:59 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:15:55, Device: Warmwasser_unten, Type: OWTHERM, Event: state: T: 45.62 °C, Reading: data, Value: state: T: 45.62 °C, Unit: 45.62 °C
2018.05.31 11:15:59 5: Starting notify loop for Heizung, 1 event(s), first is ch_Tmixer: 22.3
2018.05.31 11:15:59 4: dewpoint_notify: cmd_type=dewpoint devname=Heizung dewname=dew_state, dev=Heizung, dev_regex=.* temp_name=T hum_name=H
2018.05.31 11:15:59 5: dewpoint_notify: s='ch_Tmixer: 22.3'
2018.05.31 11:15:59 5: dewpoint_notify: evName='ch_Tmixer:' val=22.3'
2018.05.31 11:15:59 5: dewpoint max_timediff=120
2018.05.31 11:15:59 5: rg_battery: not on any display, ignoring notify
2018.05.31 11:15:59 5: End notify loop for Heizung
[Thu May 31 11:16:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 11:16:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
2018.05.31 11:16:00 5: FRM FRM:>f0730102f7
2018.05.31 11:16:00 5: SW: f0730102f7
2018.05.31 11:16:00 1: OWX_FRM::Write Sending out 0x55 0x28 0x42 0x87 0x2c 0x04 0x00 0x00 0x63 0xbe 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff
2018.05.31 11:16:00 5: FRM FRM:>f0732c0228041d6442000000633a003802402ff7
2018.05.31 11:16:00 5: SW: f0732c0228041d6442000000633a003802402ff7
2018.05.31 11:16:00 5: FRM FRM:<f07343022700
2018.05.31 11:16:00 5: FRM FRM:<400d6008453f
2 (hier ist der Zeitpunkt nicht genau der Minutenstart, sondern 2sek. später)
2018.05.31 11:17:02 5: DbLog logdb -> MemCache contains: 2018-05-31 11:16:58|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 112.08|state|Lux|112.08
2018.05.31 11:17:02 5: DbLog logdb -> MemCache contains: 2018-05-31 11:16:59|Kueche|LACROSSE|temperature: 23.8|temperature|23.8|°C
2018.05.31 11:17:02 4: BlockingCall (DbLog_PushAsync): created child (26193), uses telnetForBlockingFn_1527757846 to connect back
2018.05.31 11:17:02 5: DbLog logdb -> DbLog_PushAsync called with timeout: 86400
[Thu May 31 11:17:02 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 11:17:02 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
2018.05.31 11:17:02 4: Connection accepted from telnetForBlockingFn_1527757846_127.0.0.1_42429
2018.05.31 11:17:02 5: Starting notify loop for Heizung, 2 event(s), first is ch_Tmixer: 22.5
2018.05.31 11:17:02 4: dewpoint_notify: cmd_type=dewpoint devname=Heizung dewname=dew_state, dev=Heizung, dev_regex=.* temp_name=T hum_name=H
2018.05.31 11:17:02 5: dewpoint_notify: s='ch_Tmixer: 22.5'
2018.05.31 11:17:02 5: dewpoint_notify: evName='ch_Tmixer:' val=22.5'
2018.05.31 11:17:02 5: dewpoint_notify: s='ch_burner_power: 0'
2018.05.31 11:17:02 5: dewpoint_notify: evName='ch_burner_power:' val=0'
2018.05.31 11:17:02 5: dewpoint max_timediff=120
und einmal etwas länger
2018.05.31 11:17:50 4: DbLog logdb -> added event - Timestamp: 2018-05-31 11:17:50, Device: ESPEasy_esp8266_1_Keller, Type: ESPEASY, Event: state: Hum: 62 Tem: 23, Reading: state, Value: Hum: 62 Tem: 23, Unit:
2018.05.31 11:17:50 5: rg_battery: not on any display, ignoring notify
2018.05.31 11:17:50 5: End notify loop for ESPEasy_esp8266_1_Keller
2018.05.31 11:17:58 4: ESPEasy espBridge_192.168.3.82_56260: Received content length ok
2018.05.31 11:17:58 5: ESPEasy ESPEasy_esp8266_1_Helligkeit: Received: esp8266_1_Helligkeit::192.168.3.82::1::0::1::i||unit||1||0|||i||sleep||0||0|||i||build||20102||0|||i||build_git||mega-20180501||0|||i||build_notes|| - Mega||0|||i||version||2||0|||i||node_type_id||17||0|||r||Lux||114.17||1
2018.05.31 11:17:58 4: ESPEasy ESPEasy_esp8266_1_Helligkeit: Lux: 114.17
2018.05.31 11:17:58 5: ESPEasy ESPEasy_esp8266_1_Helligkeit: Internals: unit:1 sleep:0 build:20102 build_git:mega-20180501 build_notes: - Mega version:2 node_type_id:17: ESP Easy Mega
2018.05.31 11:17:58 5: Starting notify loop for ESPEasy_esp8266_1_Helligkeit, 2 event(s), first is Lux: 114.17
2018.05.31 11:17:58 4: dewpoint_notify: cmd_type=dewpoint devname=ESPEasy_esp8266_1_Helligkeit dewname=dew_state, dev=ESPEasy_esp8266_1_Helligkeit, dev_regex=.* temp_name=T hum_name=H
2018.05.31 11:17:58 5: dewpoint_notify: s='Lux: 114.17'
2018.05.31 11:17:58 5: dewpoint_notify: evName='Lux:' val=114.17'
2018.05.31 11:17:58 5: dewpoint_notify: s='Lux: 114.17'
2018.05.31 11:17:58 5: dewpoint_notify: evName='Lux:' val=114.17'
2018.05.31 11:17:58 5: dewpoint max_timediff=120
2018.05.31 11:17:58 4: DbLog logdb -> ################################################################
2018.05.31 11:17:58 4: DbLog logdb -> ### start of new Logcycle ###
2018.05.31 11:17:58 4: DbLog logdb -> ################################################################
2018.05.31 11:17:58 4: DbLog logdb -> number of events received: 2 for device: ESPEasy_esp8266_1_Helligkeit
2018.05.31 11:17:58 4: DbLog logdb -> check Device: ESPEasy_esp8266_1_Helligkeit , Event: state: Lux: 114.17
2018.05.31 11:17:58 5: DbLog logdb -> parsed Event: ESPEasy_esp8266_1_Helligkeit , Event: state: Lux: 114.17
2018.05.31 11:17:58 4: DbLog logdb -> added event - Timestamp: 2018-05-31 11:17:58, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:17:58 4: DbLog logdb -> check Device: ESPEasy_esp8266_1_Helligkeit , Event: state: Lux: 114.17
2018.05.31 11:17:58 5: DbLog logdb -> parsed Event: ESPEasy_esp8266_1_Helligkeit , Event: state: Lux: 114.17
2018.05.31 11:17:58 4: DbLog logdb -> added event - Timestamp: 2018-05-31 11:17:58, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:17:58 5: rg_battery: not on any display, ignoring notify
2018.05.31 11:17:58 5: End notify loop for ESPEasy_esp8266_1_Helligkeit
[Thu May 31 11:18:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
[Thu May 31 11:18:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3319.
2018.05.31 11:18:05 4: DbLog logdb -> ################################################################
2018.05.31 11:18:05 4: DbLog logdb -> ### New database processing cycle - asynchronous ###
2018.05.31 11:18:05 4: DbLog logdb -> ################################################################
2018.05.31 11:18:05 4: DbLog logdb -> MemCache contains 15 entries to process
2018.05.31 11:18:05 4: DbLog logdb -> DbLogType is: History
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:38|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 113.75|state|Lux|113.75
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:38|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 113.75|state|Lux|113.75
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:40|Junkers_gr|READINGSGROUP|Heizung.dhw_Tmeasured: <html><div valueStyle {(52.4 ne "on")?'style="color:gray"':'style="color:orange"'}>52.4 °C</div></html>|Heizung.dhw_Tmeasured|<html><div valueStyle {(52.4 ne "on")?'style="color:gray"':'style="color:orange"'}>52.4 °C</div></html>|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:40|Heizung|HEATRONIC|dhw_Tmeasured: 52.4|dhw_Tmeasured|52.4|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:41|MyBroker|MQTT|connection: active|connection|active|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:42|ESPEasy_esp8266_1_rssi|ESPEASY|rssi: -65.00|rssi|-65.00|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:42|ESPEasy_esp8266_1_rssi|ESPEASY|state: rss: -65.00|state|rss|-65.00
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:48|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 114.17|state|Lux|114.17
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:48|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 114.17|state|Lux|114.17
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:50|Heizung|HEATRONIC|ch_Tmixer: 22.3|ch_Tmixer|22.3|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:50|ESPEasy_esp8266_1_Keller|ESPEASY|Humidity: 62|Humidity|62|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:50|ESPEasy_esp8266_1_Keller|ESPEASY|Temperature: 23|Temperature|23|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:50|ESPEasy_esp8266_1_Keller|ESPEASY|state: Hum: 62 Tem: 23|state|Hum: 62 Tem: 23|
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:58|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 114.17|state|Lux|114.17
2018.05.31 11:18:05 5: DbLog logdb -> MemCache contains: 2018-05-31 11:17:58|ESPEasy_esp8266_1_Helligkeit|ESPEASY|state: Lux: 114.17|state|Lux|114.17
2018.05.31 11:18:05 4: BlockingCall (DbLog_PushAsync): created child (26200), uses telnetForBlockingFn_1527757846 to connect back
2018.05.31 11:18:05 5: DbLog logdb -> DbLog_PushAsync called with timeout: 86400
2018.05.31 11:18:05 4: Connection accepted from telnetForBlockingFn_1527757846_127.0.0.1_42434
2018.05.31 11:18:05 5: Cmd: >{BlockingRegisterTelnet($cl,311)}<
2018.05.31 11:18:05 5: DbLog logdb -> Start DbLog_PushAsync
2018.05.31 11:18:05 5: DbLog logdb -> DbLogType is: History
2018.05.31 11:18:05 4: DbLog logdb -> AutoCommit mode: ON, Transaction mode: ON
2018.05.31 11:18:05 5: DbLog logdb -> Primary Key used in fhem.history: id
2018.05.31 11:18:05 5: DbLog logdb -> Primary Key used in fhem.current: none
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:38, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 113.75, Reading: state, Value: Lux, Unit: 113.75
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:38, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 113.75, Reading: state, Value: Lux, Unit: 113.75
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:40, Device: Junkers_gr, Type: READINGSGROUP, Event: Heizung.dhw_Tmeasured: <html><div valueStyle {(52.4 ne "on")?'style="color:gray"':'style="color:orange"'}>52.4 °C</div></html>, Reading: Heizung.dhw_Tmeasured, Value: <html><div valueStyle {(52.4 ne "on")?'style="color:gray"':'style="color:orange"'}>52.4 °C</div></html>, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:40, Device: Heizung, Type: HEATRONIC, Event: dhw_Tmeasured: 52.4, Reading: dhw_Tmeasured, Value: 52.4, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:41, Device: MyBroker, Type: MQTT, Event: connection: active, Reading: connection, Value: active, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:42, Device: ESPEasy_esp8266_1_rssi, Type: ESPEASY, Event: rssi: -65.00, Reading: rssi, Value: -65.00, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:42, Device: ESPEasy_esp8266_1_rssi, Type: ESPEASY, Event: state: rss: -65.00, Reading: state, Value: rss, Unit: -65.00
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:48, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:48, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:50, Device: Heizung, Type: HEATRONIC, Event: ch_Tmixer: 22.3, Reading: ch_Tmixer, Value: 22.3, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:50, Device: ESPEasy_esp8266_1_Keller, Type: ESPEASY, Event: Humidity: 62, Reading: Humidity, Value: 62, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:50, Device: ESPEasy_esp8266_1_Keller, Type: ESPEASY, Event: Temperature: 23, Reading: Temperature, Value: 23, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:50, Device: ESPEasy_esp8266_1_Keller, Type: ESPEASY, Event: state: Hum: 62 Tem: 23, Reading: state, Value: Hum: 62 Tem: 23, Unit:
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:58, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:18:05 5: DbLog logdb -> processing event Timestamp: 2018-05-31 11:17:58, Device: ESPEasy_esp8266_1_Helligkeit, Type: ESPEASY, Event: state: Lux: 114.17, Reading: state, Value: Lux, Unit: 114.17
2018.05.31 11:18:07 4: DbLog logdb -> 15 of 15 events inserted into table history using PK on columns id
2018.05.31 11:18:07 4: DbLog logdb -> insert table history committed by autocommit
2018.05.31 11:18:07 5: DbLog logdb -> DbLog_PushAsync finished
2018.05.31 11:18:07 5: Cmd: >{BlockingStart('311')}<
2018.05.31 11:18:07 5: Cmd: >{DbLog_PushAsyncDone('logdb|0|1.769765,1.983395|0')}<
2018.05.31 11:18:07 5: DbLog logdb -> Start DbLog_PushAsyncDone
2018.05.31 11:18:07 5: DbLog logdb -> DbLog_PushAsyncDone finished
2018.05.31 11:18:08 4: ESPEasy espBridge_192.168.3.82_56261: Received content length ok
Weisst Du nun, wer oder was es sein kann?
DBlog ist auf asynchron, wie man sehen kann.
Kann ich in die fhem.pl einen Eintrag an entsprechender Stelle einfügen, so dass der Aufruf dokumentiert wird und ich mehr erfahren kann?
da ist kein stacktrace aktiv
Laut global aber doch, siehe Bild
@Kaizo: Kannst du bitte in der Zeile 3319 (direkt unter my $cmd...) Folgende einfuegen, und nochmal testen:
stacktrace() if(!defined($cmd));
@betateilchen: ich vermute, wir kriegen hier sonst kein stacktrace selbst mit gesetzten "attr global stacktrace", da die Meldung selbst nicht mit PERL WARNING kommt, und die Datumsangabe nicht von FHEM stammt.
Ok. Habe ich gemacht.
Stimmt auch, ist ja gar keine Warning.
2018.05.31 11:34:37 3: CUL_HM set Ventil_Wohnzimmer_Garten getConfig
2018.05.31 11:35:00 1: stacktrace:
2018.05.31 11:35:00 1: main::SemicolonEscape called by fhem.pl (3338)
2018.05.31 11:35:00 1: main::EvalSpecials called by ./FHEM/02_RSS.pm (613)
2018.05.31 11:35:00 1: main::RSS_evalLayout called by ./FHEM/02_FRAMEBUFFER.pm (342)
2018.05.31 11:35:00 1: (eval) called by ./FHEM/02_FRAMEBUFFER.pm (342)
2018.05.31 11:35:00 1: main::FRAMEBUFFER_returnPNG called by ./FHEM/02_FRAMEBUFFER.pm (168)
2018.05.31 11:35:00 1: main::FRAMEBUFFER_updateDisplay called by ./FHEM/02_FRAMEBUFFER.pm (74)
2018.05.31 11:35:00 1: main::FRAMEBUFFER_rewindCounter called by fhem.pl (3121)
2018.05.31 11:35:00 1: main::HandleTimeout called by fhem.pl (645)
[Thu May 31 11:35:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3320.
[Thu May 31 11:35:00 2018] fhem.pl: Use of uninitialized value $cmd in substitution (s///) at fhem.pl line 3320.
Schon besser!
Also die 02_FRAMEBUFFER.pm und die 02_RSS.pm sind die Übeltäter, wenn ich das richtig sehe!
Soweit ich sehe, ruft RSS seit der letzten Aenderung vor ca einem Monat EvalSpecials in fhem.pl mit undef als erstes Argument auf, das ist aber (seit mind. 15 Monaten) Pflicht. Bitte eine passende Meldung fuer RSS erstellen.
Zitat von: rudolfkoenig am 31 Mai 2018, 11:49:58
Soweit ich sehe, ruft RSS ...
das siehst Du genau richtig - und Du warst schneller beim Tippen :)
Erstmal Danke für die Unterstützung. Super!!
Aber was sagt mir
ZitatBitte eine passende Meldung fuer RSS erstellen.
Lt. RSS-Modul habe ich alles richtig eingetragen, auch wird das "RSS" richtig angezeigt.
Ist das ein Fall für den Maintainer vom RSS-Modul?
Zitat von: kaizo am 31 Mai 2018, 11:56:38
Ist das ein Fall für den Maintainer vom RSS-Modul?
Das hat Rudi doch schon geschrieben :)
Im richtigen Forumbereich für RSS (https://forum.fhem.de/index.php/board,77.0.html) einen Thread anlegen und das Problem dort beschreiben.
Oder diesen Thread dorthin verschieben und den Thread-Titel im ersten Beitrag so ändern, dass daraus ersichtlich wird, dass es sich um ein RSS Problem handelt.
Einfach ins passende Forum für RSS einen Eintrag erstellen und auf diesen Thread verweisen.
Verschieben ist doof weil die Abonenten des Forums für RSS beim verschieben nicht informiert werden.
Ich habe einen entsprechenden Hinweis auf diesen Thread in die Diskussion zu RSS und die Erweiterung um labels geschrieben, die letztendlich für das Auftreten des ungültigen Funktionsaufrufes verantwortlich ist.
gefixt und eingecheckt