Dummy über Notify aktualisiert schreibt kein Log in DBlog

[litronics]

Hallo zusammen,

ich hab ein kleines Problem, das ich auch mit lesen im Forum noch nicht lösen konnte. Einige Threats habe ich zwar gefunden aber irgendwie haben mir die alle noch nicht so wirklich weitergeholfen.

Konfiguriert habe ich einen Dummy, der meinen Öltank darstellt.
Dann gibt es ein Notify, das basierend auf Informationen von der Heitzung (HTTPMOD) den aktuellen Ölverbrauch berechnet und in den Dummy schreibt. Dazu gibt es dann auch einen Statistik, die die Verbräuch auf Tages, Wochen und Monatsbasis berechnet. All diese Werte würde ich nun gerne in mein DBlog schreiben, damit ich sie am Ende auch auswerten kann.

Insgesamt funktioniert das Zusammenspiel gut und ich bekomme alle Werte die ich haben möchte. Ich bekomme sie nur nicht in das DBlog geschrieben

Konfiguriert ist alles so, dass alle Werte Devices geloggt werden aber nur Readings, die in DBLogInclude stehen.
Jetzt habe ich auch bei dem Dummy einfach alle Readings, die ich im Log haben möchte, in DBLogInclude geschrieben aber das Log bleibt leer

Hat jemand eine Idee, was falsch ist?

Hier noch die Listings von den Devices:

Oeltank:

Code Auswählen Erweitern

Internals:
   NAME       Oeltank
   NR         152
   STATE      Ölstand: 4573.615 Liter
   TYPE       dummy
   Helper:
     DBLOG:
       Oelstand:
         LogDB:
           TIME       1517830281.344
           VALUE      4573.615
       last_consumption:
         LogDB:
           TIME       1517830281.36672
           VALUE      0.391
       statistik_OelstandDay1:
         LogDB:
           TIME       1517785195.04212
           VALUE      -13.495
       statistik_OelstandDay30:
         LogDB:
           TIME       1517785195.04212
           VALUE      -356.078
       statistik_OelstandDay5:
         LogDB:
           TIME       1517785195.04212
           VALUE      -71.434
   READINGS:
     2018-02-05 12:31:21   Oelstand        4573.615
     2017-12-30 12:11:07   Oeltank_aufgefuellt 29.12.2017
     2018-02-05 12:31:21   last_Runtime1   838259
     2018-02-05 12:31:21   last_Runtime2   310147
     2018-02-05 12:31:21   last_consumption 0.391
     2017-12-29 16:16:23   state           ""
     2018-02-05 12:59:55   statistik_Oelstand Hour: 0.000 Day: -8.193 Month: -58.861 Year: -403.015
     2018-02-04 23:59:55   statistik_OelstandDay1 -13.495
     2018-02-04 23:59:55   statistik_OelstandDay30 -356.078
     2018-02-04 23:59:55   statistik_OelstandDay5 -71.434
     2018-02-05 12:59:55   statistik_OelstandLast Hour: -0.391 Day: -13.495 Month: -344.154 Year: -4.861 (since: 2017-12-31_08:59:55 )
     2018-02-05 12:31:21   verbrauch_seit_auffuellen 422.423
   helper:
     _98_statistics myStatistics
Attributes:
   DbLogInclude Oelstand,last_consumption,statistik_OelstandDay1,statistik_OelstandDay30,statistik_OelstandDay5
   event-min-interval .*:300
   event-on-change-reading .*
   readingList Oeltank_aufgefuellt verbrauch_seit_auffuellen Oelstand last_Runtime1 last_Runtime2 last_consumption
   room       Heizung
   setList    Oelstand Oeltank_aufgefuellt
   stateFormat Ölstand: Oelstand Liter
   userReadings {

my $last_Runtime1_timestamp = ReadingsTimestamp('Oeltank','last_Runtime1','01.01.2001');
my $Oelstand_timestamp = ReadingsTimestamp('Oeltank','Oelstand','01.01.2001');

Log 3,"Time last_runtime1: $last_Runtime1_timestamp";
Log 3,"Time Oelstand: $Oelstand_timestamp";

if (ReadingsTimestamp('Oeltank','last_Runtime1','01.01.2001') ne ReadingsTimestamp('Oeltank','Oelstand','01.01.2001'))
{
my ($day, $month, $year) = (localtime)[3..5];
$year +=1900;
my $datestr = join '-', ++$month, $day, $year;
return  $datestr;
} else
{
my $Oelstand = ReadingsVal("Oeltank","Oeltank_aufgefuellt", "0");
return $Oelstand;
}
}

Oelverbrauch:

Code Auswählen Erweitern

Internals:
   DEF        Heizung_kessel:BrennerStufe1:.* {
if (ReadingsVal("Heizung_kessel","BrennerStufe1", "6") eq 0)
{
  my $oldRuntime1 = ReadingsVal("Oeltank","last_Runtime1", "0");
  my $oldRuntime2 = ReadingsVal("Oeltank","last_Runtime2", "0");
  my $currentRuntime1 = ReadingsVal("Heizung_kessel","LaufzeitStufe1", "0");
  my $currentRuntime2 = ReadingsVal("Heizung_kessel","LaufzeitStufe2", "0");

  my $diffRuntime1 = $currentRuntime1 - $oldRuntime1;
  my $diffRuntime2 = $currentRuntime2 - $oldRuntime2;

  Log 5,"diffRuntime1: $diffRuntime1";
  Log 5,"diffRuntime2: $diffRuntime2";
  Log 5,"oldRuntime1: $oldRuntime1";
  Log 5,"oldRuntime2: $oldRuntime2";

  if ($diffRuntime1 > 0 or $diffRuntime2 > 0)
  {
  my $verbrauch = sprintf("%.3f",(($diffRuntime1 * 1.5) + ($diffRuntime2 * 2))/3600);
  my $old_oelstand = ReadingsVal("Oeltank","Oelstand", "0");
  my $new_oelstand = $old_oelstand - $verbrauch;
  my $aktueller_verbrauch = ReadingsVal("Oeltank","verbrauch_seit_auffuellen","0");
  my $new_verbrauch = $aktueller_verbrauch + $verbrauch;

  Log 5,"verbrauch: $verbrauch";
  Log 5,"currentRuntime1: $currentRuntime1";
  Log 5,"currentRuntime2: $currentRuntime2";
  Log 5,"old_oelstand: $old_oelstand";
  Log 5,"new_oelstand: $new_oelstand";

  fhem "setreading Oeltank Oelstand $new_oelstand";
  fhem "setreading Oeltank last_Runtime1 $currentRuntime1";
  fhem "setreading Oeltank last_Runtime2 $currentRuntime2";
  fhem "setreading Oeltank last_consumption $verbrauch";
  fhem "setreading Oeltank verbrauch_seit_auffuellen $new_verbrauch";
  }
}
}
   NAME       Oelverbrauch
   NOTIFYDEV  Heizung_kessel
   NR         153
   NTFY_ORDER 50-Oelverbrauch
   REGEXP     Heizung_kessel:BrennerStufe1:.*
   STATE      2018-02-05 13:13:21
   TYPE       notify
   READINGS:
     2018-02-02 21:17:15   state           active
Attributes:
   room       Heizung

LogDB:

Code Auswählen Erweitern

Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./db.conf
   DEF        ./db.conf .*:.*
   MODE       asynchronous
   MODEL      MYSQL
   NAME       LogDB
   NR         161
   NTFY_ORDER 50-LogDB
   PID        486
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   UTF8       1
   VERSION    2.22.14
   dbconn     mysql:database=FHEM;host=li2nas1.fire.fly;port=3306
   dbuser     FHEM
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     OLDSTATE   connected
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   READINGS:
     2018-02-05 13:14:12   CacheUsage      0
     2018-02-05 13:14:12   NextSync        2018-02-05 13:14:42 or if CacheUsage 500 reached
     2018-01-19 16:32:55   countCurrent    15
     2018-01-19 16:32:55   countHistory    43
     2018-02-05 13:14:12   state           connected
   cache:
     index      7785
     memcache:
Attributes:
   DbLogSelectionMode Include
   DbLogType  Current/History
   asyncMode  1
   icon       edit_save
   room       System

[DS_Starter]

Kann es sein, dass überhaupt keine Events generiert werden ?

Es gibt im Zusammnspiel von Devices, notify und setreading eine Besonderheit zu beachten die in der commandref zu setreading beschrieben ist:

Achtung: setreading generiert kein Event für ein Gerät X, falls es aus einem notify für Gerät X aufgerufen wurde. In so einem Fall könnte man auf "sleep 0.1; setreading X Y Z" ausweichen.

Checke doch mal ob das evtl. bei dir zutrifft.

Grüße,
Heiko

[DeeSPe]

Ich würde an dieser Stelle lieber auf die (eigentlich für Entwickler gedachten) Funktionen readingsBeginUpdate/readingsBulkUpdate/readingsEndUpdate verweisen. Das ist beim Setzen von mehreren Readings einfach sinnvoller und er kann im readingsEndUpdate auch angeben das Events ausgelöst werden sollen.
Es erzeugt alles in allem auch durch die Nichtverwendung von sleep weniger Last in FHEM.

Also am Ende statt:

Code Auswählen Erweitern


  fhem "setreading Oeltank Oelstand $new_oelstand";
  fhem "setreading Oeltank last_Runtime1 $currentRuntime1";
  fhem "setreading Oeltank last_Runtime2 $currentRuntime2";
  fhem "setreading Oeltank last_consumption $verbrauch";
  fhem "setreading Oeltank verbrauch_seit_auffuellen $new_verbrauch";
lieber:

Code Auswählen Erweitern


  readingsBeginUpdate($defs{Oeltank});
  readingsBulkUpdate($defs{Oeltank},"Oelstand",$new_oelstand);
  readingsBulkUpdate($defs{Oeltank},"last_Runtime1",$currentRuntime1);
  readingsBulkUpdate($defs{Oeltank},"last_Runtime2",$currentRuntime2);
  readingsBulkUpdate($defs{Oeltank},"last_consumption",$verbrauch;
  readingsBulkUpdate($defs{Oeltank},"verbrauch_seit_auffuellen",$new_verbrauch);
                  readingsEndUpdate($defs{Oeltank},1)

Gruß
Dan

[helmut]

Ich würde an dieser Stelle lieber auf die (eigentlich für Entwickler gedachten) Funktionen readingsBeginUpdate/readingsBulkUpdate/readingsEndUpdate verweisen. Das ist beim Setzen von mehreren Readings einfach sinnvoller und er kann im readingsEndUpdate auch angeben das Events ausgelöst werden sollen.

Hallo Dan,

die Konstellation mit mehreren aufeinanderfolgenden setreadings habe ich auch. Werden mit dem
readingsBulkUpdate die setreadings gesammelt und mit dem readingsEndUpdate mit geringerer Last
in einem Rutsch ausgefuehrt?

Wenn nichts dagegen spricht, dass auch "normale" Nutzer diesen Mechanismus einsetzen, lohnt es
sich fuer mich, wenigstens die "Development Introduction" durchzuarbeiten?

Gruss Helmut

[DeeSPe]

Werden mit dem
readingsBulkUpdate die setreadings gesammelt und mit dem readingsEndUpdate mit geringerer Last
in einem Rutsch ausgefuehrt?

So ist es.

Wenn nichts dagegen spricht, dass auch "normale" Nutzer diesen Mechanismus einsetzen, lohnt es
sich fuer mich, wenigstens die "Development Introduction" durchzuarbeiten?

Da spricht absolut nichts dagegen wenn Du eh gern Deine notify(s)/Funktionen in Perl schreibst.
Helfen wird das Lesen der Doku immer.

Gruß
Dan

[helmut]

wenn Du eh gern Deine notify(s)/Funktionen in Perl schreibst.

Hallo Dan,

auf jeden Fall. Das erschliesst mir doch erst das maechtige Potential von fhem.

Mein perl ist zwar nicht so gut, als dass ich hier aktiv etwas dazu beitragen koennte,
aber wenn Du die Developer-Doku auch fuer Nichtentwickler als sinnvoll erachtest,
fange ich damit mal an. Danke fuer den Hinweis.

Gruss Helmut

[litronics]

Herzlichen Dank schon mal für die Antworten.
Aber ich geh mal wieder zurück zu dem eigentlichen Topic

Kann es sein, dass überhaupt keine Events generiert werden ?

Im Event-Monitor sehe ich schon Events - also würde ich mal davon ausgehen, dass es die gibt:

Code Auswählen Erweitern

2018-02-05 15:07:21 statistics myStatistics Updated stats for: Heizung_kessel
2018-02-05 15:07:21 statistics myStatistics Updated stats for: Oeltank
2018-02-05 15:07:21 dummy Oeltank Oelstand: 4571.998
2018-02-05 15:07:21 dummy Oeltank statistik_Oelstand: Hour: -0.401 Day: -9.810 Month: -60.478 Year: -404.632
2018-02-05 15:07:21 statistics myStatistics Updated stats for: Oeltank
2018-02-05 15:07:21 dummy Oeltank last_Runtime1: 841695
2018-02-05 15:07:21 statistics myStatistics Updated stats for: Oeltank
2018-02-05 15:07:21 dummy Oeltank last_Runtime2: 310482
2018-02-05 15:07:21 statistics myStatistics Updated stats for: Oeltank
2018-02-05 15:07:21 dummy Oeltank last_consumption: 0.401
2018-02-05 15:07:21 statistics myStatistics Updated stats for: Oeltank
2018-02-05 15:07:21 dummy Oeltank verbrauch_seit_auffuellen: 424.04

Ich würde an dieser Stelle lieber auf die (eigentlich für Entwickler gedachten) Funktionen readingsBeginUpdate/readingsBulkUpdate/readingsEndUpdate verweisen. Das ist beim Setzen von mehreren Readings einfach sinnvoller und er kann im readingsEndUpdate auch angeben das Events ausgelöst werden sollen.

Das werde ich gleich mal einbauen und hoffentlich hilft das.
Irgendwie habe ich so das Gefühl, das in dem Modul LogDB die dummy-Devices einfach ignoriert werden.

[CoolTux]

Statt mit setreading würde ich lieber mit setList und readingsList beim Dummy arbeiten. Ist sauberer.

[DS_Starter]

Irgendwie habe ich so das Gefühl, das in dem Modul LogDB die dummy-Devices einfach ignoriert werden.

Ganz bestimmt nicht 

[justme1968]

egal mit welcher methode man die readings aktualisiert: am ende werden immer die Begin/Bulk/End update funktionen verwendet. der overhead durch set/setreading selber ist vermutlich zu vernachlässigen wenn es um einige wenige readings geht, aber bei direktem Begin/Bulk/End wird geht intern einiges in einem rutsch. das hat auswirkung auf userReadings, loging, clonedummy und ähnliches.

unabhängig wie die readings geschrieben werden gilt die anmerkung bezüglich sleep aber immer. die zusätzlichen readings erzeugen nur dann zuvetlässig events wenn man mit sleep oder InternalTimer aus dem context des aktuellen notify ausbricht und die readings verzögert setzt.

[litronics]

Hallo Zusammen!

Schön mal vielen Dank für eure Hilfe!

Ich hab jetzt das Setzen der Readings auf Begin/Bulk/End umgebaut - aber leider auch ohne Erfolg. Es gibt immer noch keine Einträge im DBlog.

Kann es sein, dass ich noch irgendwo einen sleep setzen muss, wie es justme1968 erwähnt hat?

unabhängig wie die readings geschrieben werden gilt die anmerkung bezüglich sleep aber immer. die zusätzlichen readings erzeugen nur dann zuvetlässig events wenn man mit sleep oder InternalTimer aus dem context des aktuellen notify ausbricht und die readings verzögert setzt.

[litronics]

Irgendwie habe ich so das Gefühl, das in dem Modul LogDB die dummy-Devices einfach ignoriert werden.

Ganz bestimmt nicht 

So ein wenig Verwunderung darfst Du mir aber nicht aberkennen.

Bei identischer Konfiguration für das DBLog funktioniert ein HTTPMOD Device aber kein DUMMY Device - das ist doch schon seltsam - oder?

[justme1968]

eigentlich ist es ganz einfach

wenn ein device events generiert werden diese in eine interne struktur gesteckt und dann nacheinander alle 'listener' mit dieser struktur aufgerufen. listener sind alle dinge die auf die events reagieren. d.h. filelog, dblog, notify, ...

diese struktur gibt es in fhem nur genau ein mal. da fhem nicht multithreaded ist reicht das normalerweise.

wenn jetzt innerhalb eines notify durch das erzeugen neuer readings zusätzliche events erzeugt werden, landen die in genau der gleichen struktur. die listener die danach kommen sehen die zusätzlichen events, die losender die schon dran waren haben pech gehabt.

die reihenfolge der listener hängt unter anderem von den device namen bzw. deren alphabetischer reihenfolge ab. wenn dein httpmod device vor dem dblog device kommt passt es zufällig, wenn dein dummy device alphabetisch danach kommt passt es nicht. das ist vereinfacht und es gibt noch ein paar andere randbedingungen.

das ganze problem umgeht man in dem man das setzen der reading vom aktuellen durchlauf aller listener entkoppelt. da geht am einfachsten in dem man es mit einem winzigen sleep auf verzögert und einen eigenen event durchlauf anstößt statt im aktuellen durchlauf noch zusätzliche events hinten dran zu hängen.

[litronics]

danke für die ausführliche Erklärung.

Wenn ich das richtig verstanden habe, dann wird nicht überprüft ob jeder Listener auch alle Events erhält. Ergo werden Events, die später im Event-Zyklus generiert werden von den Listenern, die vorher schon "dran" waren, nicht wahrgenommen.

Oder vielleicht nochmal anders ausgedrückt - die Events, die innerhalb eines Event-Zyklus erzeugt werden (z.B. in meinem Notify), werden immer im gleichen Event-Zyklus behandelt und nicht in eine Warteschlange geschoben die dann im nächsten Event-Zyklus abgearbeitet werden.

Das mit dem Sleep leuchtet ein, da man die generierten Events auf den nächsten Event-Zyklus verschiebt. Allerdings hast Du auch geschrieben, dass FHEM nicht multithreaded ist. Würde ich dann nicht den kompletten Thread schlafen schicken und dann genau dort (also innerhalb des aktuellen Event-Zyklus) weitermachen wo ich das Sleep aufgerufen habe?

Unabhängig dieser Diskussion habe ich mal ein kurzes Sleep vor den readingsBeginUpdate-Block geschrieben - wäre das die richtige Stelle oder muss das vor das readingsEndUpdate?

[justme1968]

wichtig: das sleep um das es hier geht ist ein fhem sleep. kein perl sleep!

ein fhem sleep startet einen nicht blockierenden internen timer und führt dann nach timer ablauf etwas aus.
d.h. wenn du auf perl ebene bist musst du das selber mit InternalTimer machen. wenn du auf fhem ebene mit setreading bist reicht ein sleep 0.1; setreading