Verständnisproblem FileLog mit addLog oder Bug?

[Nobbynews]

Guten Morgen am Ostersonntag,

ich habe mal eine Frage zu FileLog in Verbindung mit dem Attribut addlog.
Im httpmod-Device ist gesetzt:

Code Auswählen Erweitern

attr Star_Buettgen event-on-change-reading .*Im FileLog-Device ist gesetzt:

Code Auswählen Erweitern

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:285
Im Log-File erscheinen (gekürzt, da die anderen httpMod devices kein eoc gesetzt haben) folgende Einträge:

Code Auswählen Erweitern

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 SuperE5
Nach 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:

addLog
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

[Nobbynews]

Hat keiner eine Idee oder Tipp für mich?

[RalfRog]

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.

[Nobbynews]

Guten Morgen,

ich habe jetzt mal losgelöst von meiner eigentlichen Definition ein Testdevice zusammen mit einem gesonderten FileLog definiert:

Code Auswählen Erweitern

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



Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

attr LogSpritStar addLog Star2:Diesel:120,Star2:SuperE10:125Ergebnis in der Logdatei:

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

attr LogSpritStar addLog Star2:Diesel:125,Star2:SuperE10:120Und dazu das Logfile:

Code Auswählen Erweitern

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

[RalfRog]

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.

[RalfRog]

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.