Guten Morgen am Ostersonntag,
ich habe mal eine Frage zu FileLog in Verbindung mit dem Attribut
addlog.
Im httpmod-Device ist gesetzt:
attr Star_Buettgen event-on-change-reading .*Im FileLog-Device ist gesetzt:
defmod LogSprit FileLog /Festplatte/FHEM/log/Sprit-%Y-%W.log (Star_Buettgen|ARAL_Kaarst|Total_Korschenbroich|Supermarkt|Jet_Juelicher):(Diesel|SuperE10|SuperE5):.*
attr LogSprit addLog Star_Buettgen:Diesel:295,Star_Buettgen:SuperE10:290,Star_Buettgen:SuperE5:285Im Log-File erscheinen (gekürzt, da die anderen httpMod devices kein eoc gesetzt haben) folgende Einträge:
2026-04-05_09:12:37 Star_Buettgen SuperE5: 2.249
2026-04-05_09:12:37 Star_Buettgen SuperE10: 2.189
2026-04-05_09:12:37 Star_Buettgen Diesel: 2.429
2026-04-05_09:17:22 Star_Buettgen SuperE5: 2.249
2026-04-05_09:22:07 Star_Buettgen SuperE5: 2.249
2026-04-05_09:22:07 Star_Buettgen SuperE10: 2.189
2026-04-05_09:22:07 Star_Buettgen Diesel: 2.429
2026-04-05_09:26:52 Star_Buettgen SuperE5: 2.249
2026-04-05_09:31:37 Star_Buettgen SuperE5: 2.249
2026-04-05_09:31:37 Star_Buettgen SuperE10: 2.189
2026-04-05_09:31:37 Star_Buettgen Diesel: 2.429Um 9:12:37 werden Log-Einträge für alle drei readings erzeugt.
285 Sekunden später dann um 9:17:22 nur für das reading
SuperE5Nach meinem Verständnis hätten doch dann im Abstand von jeweils 5 Sekunden die Einträge für die Readings
SuperE10 und
Diesel kommen sollen.
Dafür werden dann aber um 9:22:07, also wiederum 285 Sekunden später, Einträge für alle drei readings erzeugt.
Das Verhalten wiederholt sich dann um 9:26:52 bzw. 9:31:37.
Lt. commandref zu addLog:
ZitataddLog
Dieses Attribut enthält eine durch Kommata getrennte Liste von "devspec:readings:maxInterval" Tripel. readings wird als Regexp ausgewertet. Falls nach maxInterval Sekunden kein passendes Event eingetroffen ist, wird der letzte Wert zum Logfile hinzugefügt.
Wo ist denn jetzt mein Verständisfehler bzw. mein Konfigurationsfehler?
Schönen Sonntag noch.
Norbert
Hat keiner eine Idee oder Tipp für mich?
Ich wäre vor dem Hintergrund der CommandRef auch so verwundert wie du.
Nähere dich dem Problem doch erstmal indem du nur ein Argument im addLog verwendest und schrittweise die beiden anderen dazu packst.
Diesel und E10 kommen ja vermutlich nur halb so oft wie sie sollten.
Nachtrag:
Die Zeitstempel scheinen ja zu dem Tripel: "Star_Buettgen:SuperE5:285" zu gehören.
Guten Morgen,
ich habe jetzt mal losgelöst von meiner eigentlichen Definition ein Testdevice zusammen mit einem gesonderten FileLog definiert:
define Star2 HTTPMOD http://www.clever-tanken.de/tankstelle_details/4571 86400
attr Star2 userattr reading04Name reading04Regex
attr Star2 enableControlSet 1
attr Star2 group Sprit
attr Star2 model clever_tanken_single_station
attr Star2 reading01Name Diesel
attr Star2 reading01Regex <div class=\"price-type-name\">Diesel</div>[\S\s\r\n]*?<span id=\"current-price-\d+\">(\d.\d{2}</span>[\S\s\r\n]*?<sup id=\"suffix-price-\d\">[\d]+)</sup>
attr Star2 reading02Name SuperE10
attr Star2 reading02Regex <div class=\"price-type-name\">Super E10</div>[\S\s\r\n]*?<span id=\"current-price-\d+\">(\d.\d{2}</span>[\S\s\r\n]*?<sup id=\"suffix-price-\d\">[\d]+)</sup>
attr Star2 reading03Name SuperE5
attr Star2 reading03Regex <div class=\"price-type-name\">Super E5</div>[\S\s\r\n]*?<span id="current-price-\d+">(\d.\d{2}</span>[\S\s\r\n]*?<sup id=\"suffix-price-\d\">[\d]+)</sup>
attr Star2 readingOExpr $val =~ s/<[\d\D]+>//;;;;$val
attr Star2 room 00_A,HTTPMOD
attr Star2 stateFormat E5: SuperE5 €<br/>E10: SuperE10 €<br/>D: Diesel €
attr Star2 timeout 10
attr Star2 verbose 2
# BUSY 0
# CFGFN
# DEF http://www.clever-tanken.de/tankstelle_details/4571 86400
# FUUID 69d71ba8-f33f-8873-7c0f-9a755be27818a9d6
# Interval 86400
# MainURL http://www.clever-tanken.de/tankstelle_details/4571
# ModuleVersion 4.2.0 - 11.8.2023
# NAME Star2
# NOTIFYDEV global
# NR 1172987
# NTFY_ORDER 50-Star2
# STATE E5: 2.169 €<br/>E10: 2.109 €<br/>D: 2.359 €
# TYPE HTTPMOD
# eventCount 13
# value
# CompiledRegexes:
# HTTPCookieHash:
# csrftoken;:
# Name csrftoken
# Options expires=Thu, 08 Apr 2027 04:27:10 GMT; Max-Age=31449600; Path=/; SameSite=Lax
# Path
# Value LGc4EzdiyrXAxKUHbPnqO4zdfeLhro5V
# HttpUtils:
# NAME
# addr https://www.clever-tanken.de:443
# auth 0
# code 200
# compress 1
# conn
# data
# displayurl https://www.clever-tanken.de/tankstelle_details/4571
# header Cookie: csrftoken=LGc4EzdiyrXAxKUHbPnqO4zdfeLhro5V
# host www.clever-tanken.de
# httpheader HTTP/1.1 200 OK
#Date: Thu, 09 Apr 2026 04:27:10 GMT
#Server: Apache/2.4.52 (Ubuntu)
#Vary: Cookie,Accept-Encoding
#Content-Encoding: gzip
#Content-Type: text/html; charset=utf-8
#Set-Cookie: csrftoken=LGc4EzdiyrXAxKUHbPnqO4zdfeLhro5V; expires=Thu, 08 Apr 2027 04:27:10 GMT; Max-Age=31449600; Path=/; SameSite=Lax
#X-Correlation-Uid: adcqni-BUS95oX7k7IfGqgAAAqU
#Connection: close
# httpversion 1.0
# hu_blocking 0
# hu_filecount 1
# hu_port 443
# hu_portSfx
# ignoreredirects 1
# loglevel 4
# path /tankstelle_details/4571
# protocol https
# redirects 0
# timeout 10
# url https://www.clever-tanken.de/tankstelle_details/4571
# sslargs:
# QUEUE:
# READINGS:
# 2026-04-09 06:27:10 Diesel 2.359
# 2026-04-09 06:27:10 SuperE10 2.109
# 2026-04-09 06:27:10 SuperE5 2.169
# REQUEST:
# context reading
# data
# header
# ignoreredirects 0
# num unknown
# priority 1
# retryCount 0
# type update
# url https://www.clever-tanken.de/tankstelle_details/4571
# defptr:
# readingBase:
# Diesel reading
# SuperE10 reading
# SuperE5 reading
# readingNum:
# Diesel 01
# SuperE10 02
# SuperE5 03
# readingOutdated:
# requestReadings:
# update:
# Diesel reading 01
# SuperE10 reading 02
# SuperE5 reading 03
#
setstate Star2 E5: 2.169 €<br/>E10: 2.109 €<br/>D: 2.359 €
setstate Star2 2026-04-09 06:27:10 Diesel 2.359
setstate Star2 2026-04-09 06:27:10 SuperE10 2.109
setstate Star2 2026-04-09 06:27:10 SuperE5 2.169
define LogSpritStar FileLog /Festplatte/FHEM/log/Sprit_Star-%Y-%W.log Star2:(Diesel|SuperE10|SuperE5):.*
attr LogSpritStar addLog Star2:Diesel:120
attr LogSpritStar addStateEvent 1
attr LogSpritStar comment Star_Buettgen:Diesel:295,Star_Buettgen:SuperE10:290,Star_Buettgen:SuperE5:285
attr LogSpritStar createGluedFile 1
attr LogSpritStar logtype text
attr LogSpritStar nrarchive 5
attr LogSpritStar room HTTPMOD
# CFGFN
# DEF /Festplatte/FHEM/log/Sprit_Star-%Y-%W.log Star2:(Diesel|SuperE10|SuperE5):.*
# FD 302
# FUUID 69d7128c-f33f-8873-0fae-caf0773e167ae675
# NAME LogSpritStar
# NR 1170552
# NTFY_ORDER 50-LogSpritStar
# REGEXP Star2:(Diesel|SuperE10|SuperE5):.*
# STATE active
# TYPE FileLog
# addLogMinInterval 120
# currentlogfile /Festplatte/FHEM/log/Sprit_Star-2026-14.log
# logfile /Festplatte/FHEM/log/Sprit_Star-%Y-%W.log
# READINGS:
# 2026-04-09 06:37:28 linesInTheFile 48
#
setstate LogSpritStar active
setstate LogSpritStar 2026-04-09 06:37:28 linesInTheFile 48
Hier mal ein Log-Auszug:
2026-04-09_06:17:28 Star2 Diesel: 2.359
2026-04-09_06:17:43 Star2 Diesel: 2.359
2026-04-09_06:17:43 Star2 SuperE10: 2.109
2026-04-09_06:17:43 Star2 SuperE5: 2.169
2026-04-09_06:21:28 Star2 Diesel: 2.359
2026-04-09_06:23:28 Star2 Diesel: 2.359
2026-04-09_06:25:28 Star2 Diesel: 2.359
2026-04-09_06:27:10 Star2 Diesel: 2.359
2026-04-09_06:27:10 Star2 SuperE10: 2.109
2026-04-09_06:27:10 Star2 SuperE5: 2.169
2026-04-09_06:29:28 Star2 Diesel: 2.359
2026-04-09_06:31:28 Star2 Diesel: 2.359
2026-04-09_06:33:28 Star2 Diesel: 2.359
2026-04-09_06:35:28 Star2 Diesel: 2.359Um 6:21:28, 6:23:28 und 6:25:28 kamen die Einträge durch addlog.
Um 6:27:10 habe ich im httpmod ein reread ausgeführt und damit für aller 3 readings einen neuen Eintrag generiert.
Dann sieht man ein Verhalten, dass ich so nicht erwartet hätte.
Erst um 6:29:28 wurde wieder ein Eintrag für das reading Diesel erzeugt, also genau 4 Minuten nach dem letzten mit addlog erzeugten Eintrag. Danach dann wieder im 2 Minuten Takt.
Das heißt für mich, dass der Timer von addlog durch ein vorzeitiges reguläres Ereignis nicht neu gesetzt wird.
Richtig?
Als nächstes habe ich das Attribut geändert:
attr LogSpritStar addLog Star2:Diesel:120,Star2:SuperE10:125Ergebnis in der Logdatei:
2026-04-09_06:57:31 Star2 Diesel: 2.359
2026-04-09_06:59:31 Star2 Diesel: 2.359
2026-04-09_06:59:31 Star2 SuperE10: 2.109
2026-04-09_07:00:33 Star2 Diesel: 2.359
2026-04-09_07:00:33 Star2 SuperE10: 2.109
2026-04-09_07:00:33 Star2 SuperE5: 2.169
2026-04-09_07:03:31 Star2 Diesel: 2.359
2026-04-09_07:03:31 Star2 SuperE10: 2.109
2026-04-09_07:05:31 Star2 Diesel: 2.359
2026-04-09_07:07:31 Star2 Diesel: 2.359
2026-04-09_07:07:31 Star2 SuperE10: 2.109
2026-04-09_07:09:31 Star2 Diesel: 2.359Um 7:00:33 wieder ein reread ausgeklöst.
Um 7:03:31 kommen 4 Minuten nach dem letzten addlog die Einträge für Diesel und SuperE10.
Komisch ist, dass um 7:05:31 nur ein Eintrag für Diesel kommt, dafür aber um 7:07:31 wieder für Diesel und Super E10.
Weitere Änderung im Filelog:
attr LogSpritStar addLog Star2:Diesel:125,Star2:SuperE10:120Und dazu das Logfile:
2026-04-09_07:11:31 Star2 Diesel: 2.359
2026-04-09_07:11:31 Star2 SuperE10: 2.109
2026-04-09_07:13:31 Star2 Diesel: 2.359
2026-04-09_07:14:12 Star2 Diesel: 2.359
2026-04-09_07:14:12 Star2 SuperE10: 2.109
2026-04-09_07:14:31 Star2 Diesel: 2.359
2026-04-09_07:14:31 Star2 SuperE10: 2.109
2026-04-09_07:14:31 Star2 SuperE5: 2.169
2026-04-09_07:18:12 Star2 Diesel: 2.359
2026-04-09_07:18:12 Star2 SuperE10: 2.109
2026-04-09_07:20:12 Star2 SuperE10: 2.109
2026-04-09_07:22:12 Star2 Diesel: 2.359
2026-04-09_07:22:12 Star2 SuperE10: 2.109Nach einem reread um 7:14:31 dreht sich das Verhalten um und die readings werden im Intervall von SuperE10 erzeugt.
Sieht also ganz so aus, als wenn immer das kürzeste Intervall genommen würde und andere Angaben ignoriert werden.
Würde also mal sagen, dass es sich vermutlich um einen Bug handelt.
Norbert
Sieht schon ein wenig so aus.
Vor allem kommen die 3 letzten mit 120 Abstand (vom E10) im Wechsel E10 und E10/Diesel.
Sieht schon aus wie "nicht so gewollt" und das fällt vielleicht erst bei mehr als einer Bedingung auf.
Auch den Abstand nach dem Reread von 3:42 Min hätte ich nicht erwartet. Dem Filelog sollte es doch egal sein wie das Event erzeugt wird.
Hab mal die Suche bemüht aber nichts passendes gefunden.
Ausser einem Hinweis, dass "Beim Ausfuehren von "attr XX addLog" werden die Paremeter geprueft.... ..... dann wird ein Internal Wert addLogMinInterval gesetzt".
(https://forum.fhem.de/index.php?msg=1124963)
Das Internal sieht man bei dir ja auch. Es gibt halt nur dieses eine "addLogMinInterval" und nicht mehrere. Vielleicht kann der Code tatsächlich nicht mit den in der CommandRef beschriebenen Möglichkeiten mehrerer Add-Intervalle umgehen (weil es in der Form noch keiner probiert hat?).
Eventuell stolpert Rudi ja noch über den Beitrag und kann was dazu sagen.
Das mit dem Internal addLogMinInterval hatte ich auch gelesen, aber wohl nicht richtig weiterverfolgt.
Es wird tatsächlich immer der kleinste Werte dort abgelegt.
Das erklärt vielleicht auch, warum mal nur ein Wert geschrieben wird und dann beim nächsten mal beide Werte. Dann ist nämlich die größere Zeitspanne ohne Event wieder vergangen.
Ich möchte das Thema wieder hochholen.
Vielleicht kann jemand das beschriebene Verhalten bestätigen oder @rudolfkoenig wird darauf aufmerksam.
Norbert
Hat keiner mehr eine Idee oder einen weiteren Hinweis??
Ich habe das jetzt mal als Bug im Titel bezeichnet.
Bin da jetzt ziemlich aufgemischen.
Norbert
Ich brauche es nicht so.
Konnte aber immerhin nachvollziehen - verhält sich unerwartet.