Doif auf ein clonedummy device reagiert nicht

[Tom S]

Hallo Otto123,
ich bin ein Stück weiter: das DOIF wird getriggert, führt aber offenbar nicht alle Kommandos aus, da kein Ergebnis erscheint. Es werden eine Menge Readings gelesen und dann einiges berechnet. Der komplette Code (der evtl. auch eleganter prorammiert werden kann)  lautet :

Code Auswählen Erweitern


([Solarpumpe:"off"]) ({ my $tv1 = ReadingsVal("T_Vorlauf1","state","") ; my $tv2 = ReadingsVal("Vorlauf","temperature","") ; fhem "set T_Vorlauf2 $tv2" ; my $tv = ($tv1+$tv2)/2 ; fhem "set T_Vorlauf $tv" ; my $tr1 = ReadingsVal("T_Ruecklauf1","state","") ; my $tr2 = ReadingsVal("Ruecklauf","temperature","") ; fhem "set T_Ruecklauf2 $tr2" ; my $tr = ($tr1+$tr2)/2 ; fhem "set T_Ruecklauf $tr" ; my $C11 = AttrVal("Konstante_ST2","C11",0) ; my $C21 = AttrVal("Konstante_ST2","C21",0) ; my $C22 = AttrVal("Konstante_ST2","C22",0) ; my $C23 = AttrVal("Konstante_ST2","C23",0) ; my $C31 = AttrVal("Konstante_ST2","C31",0) ; my $tr_tv = ($tv-$tr) ; my $tr_tv_Quadrat = ($tr_tv * $tr_tv) ; my $Fm = AttrVal("Konstante_ST","Foerdermenge_h",0) ; my $dt = ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",0) ; fhem "set Delta_t_tmp $dt" ; my $delta_E = ($C11 + (($C21 + ($C22 * ($tr-20)) + ($C23 * ($tr-20) * ($tr-20))) * $tr_tv) + ($C31 * $tr_tv_Quadrat)) ; fhem "set Delta_E_tmp $delta_E" ; fhem "set FM_tmp $Fm" ; my $E  = ((($delta_E * $Fm) / 3600) * $dt) ; fhem "set Delta_E $E" } )


Seltsamerweise ist die ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",0) immer gleich 0, so dass das Ergebnis Delta_E auch 0 ist. Solarpumpe_Count ist ein Hour_Counter.

Definitiv steht in dem Reading etwas drin, z.B. ein Wert 75 und wenn ich diesen mit einem eigenen, separaten DOIF auslese, bekomme ich auch den Inhalt auch als Delta_t_tmp ausgegeben, nur nicht nicht in dem angegebenen DOIF. Kann es sein, dass die Anzahl der Kommandos oder die Länge des Kommandostrings beim DOIF begrenzt ist?

Ich bin etwas ratlos! Eine Idee?

[amenomade]

dass die Anzahl der Kommandos oder die Länge des Kommandostrings beim DOIF begrenzt ist?

Nicht dass ich wüsste. Du kannst selbst die timestamps auf Solarpumpe_Count kontrollieren, um zu sehen, ob es aktualisiert worden ist oder nicht.

Zeig mal ein "list Solarpumpe_Count"?

[Tom S]

Hier das Listing des HourCounters:

Code Auswählen Erweitern


Internals:
   CHANGED
   DEF        Solarpumpe:on Solarpumpe:off
   NAME       Solarpumpe_Count
   NR         103
   NTFY_ORDER 50-Solarpumpe_Count
   STATE      2 Starts, 3.0 Minuten, 0.01kWh, 102sek
   TYPE       HourCounter
   VERSION    1.0.1.2 - 24.12.2014
   READINGS:
     2017-05-17 13:05:01   clearDate       2017-05-17 13:05:01
     2017-08-26 10:31:31   countsOverall   3507
     2017-08-26 10:31:31   countsPerDay    2
     2017-08-26 10:31:31   pauseTimeEdge   1188
     2017-08-26 10:31:31   pauseTimeIncrement 0
     2017-08-26 10:31:31   pauseTimeOverall 8177011
     2017-08-26 10:31:31   pauseTimePerDay 37709
     2017-08-26 10:31:31   pulseTimeEdge   102
     2017-08-26 10:31:31   pulseTimeIncrement 102
     2017-08-26 10:31:31   pulseTimeOverall 423359
     2017-08-26 10:31:31   pulseTimePerDay 182
     2017-08-26 10:31:31   state           2
     2017-08-26 10:31:31   tickChanged     87
     2017-08-26 00:00:00   tickDay         1
     2017-08-26 10:00:00   tickHour        20
     2017-08-25 14:03:07   tickMonth       0
     2017-08-26 10:31:31   tickUpdated     676
     2017-08-25 14:03:07   tickWeek        0
     2017-08-25 14:03:07   tickYear        0
     2017-08-26 10:31:31   value           0
   helper:
     OFF_Regexp Solarpumpe:off
     ON_Regexp  Solarpumpe:on
     calledByEvent
     changedTimestamp 2017-08-26 10:31:31
     forceClear
     forceDayChange
     forceHourChange
     forceMonthChange
     forceWeekChange
     forceYearChange
     isFirstRun
     sdRoundHourLast 1503734400
     value      0
     cmdQueue:
Attributes:
   alias      Laufzeit, Energieverbrauch Solarpumpe
   event-on-change-reading pulseTimePerDay pulseTimeIncrement
   group      Solarthermie
   icon       general_an_fuer_zeit
   room       Solarthermie
   sortby     3
   stateFormat {sprintf("%.0f Starts",ReadingsVal("Solarpumpe_Count","countsPerDay",0)).sprintf(", %.1f Minuten",ReadingsVal("Solarpumpe_Count","pulseTimePerDay",0)/60).sprintf(", %.2fkWh",ReadingsVal("Solarpumpe_Count","pulseTimePerDay",0)*0.150/3600).sprintf(", %.0fsek",ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",0))}


Grüße
Tom

[Otto123]

Hallo Tom,

25 Einzelbefehle -> ich würde als erstes den Code in eine Sub in 99_myUtils auslagern. Diese kannst Du unabhängig vom DOIF einfach mal aufrufen und überprüfen.

Gruß Otto

[amenomade]

Und wenn Du folgendes machst, aktualisieren sich die Sachen auch nur teilweise?

Code Auswählen Erweitern

set <doifname> cmd_1

[Tom S]

 Hallo und vielen Dank für die vielen hilfreichen Tipps. Sie haben mich soweit gebracht, dass ich nun eindeutig sagen kann dass von den 25 Befehlen des DOIF genau einer nicht funktioniert und das Ergebnis zu Null macht:

Code Auswählen Erweitern


my $dt = ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",0)

Und dies, obwohl zu dem Zeitpunkt, in dem das Event "true" ist dort definitiv ein Wert , z.B. 91 (die Laufzeit des aktuellen Einschaltintervalls) drin steht.

Alle anderen Befehle werden ausgeführt und auch dass Triggerevent passt.
Ich bin jetzt seit Tagen an dieser Hürde und komme nicht drüber!
Freue mich über jeden Hinweis, der zum Ziel führt.

[amenomade]

Und dies, obwohl zu dem Zeitpunkt, in dem das Event "true" ist dort definitiv ein Wert , z.B. 91 (die Laufzeit des aktuellen Einschaltintervalls) drin steht.

Genau das bezweifle ich.

Falls nicht vorhanden, definiere mal eine FileLog auf Solarpumpe:pulseIncrement und dem Event:

Code Auswählen Erweitern

define testLog FileLog ./log/solarpulse-%Y-%U.log Solarpumpe:pulseIncrement.*|Solarpumpe.*(on|off).*, prüfe, dass du kein event-on-change-reading oder event-on-update-reading hast, das die Events ausfiltern könnte, und beobachte genau nur diese Werte im Laufe der Zeit.

[CoolTux]

Code Auswählen Erweitern


{ ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",'haste mist jebaut') }


Das mal bitte die Eingabezeile von FHEMWEB eingeben. Wenn du Mist erhälst stimmt was mit dem Devicenamen oder dem Reading nicht.

[amenomade]

@CoolTux: ich glaube aber eher, dass das Problem an die Reihenfolge von Events liegt. Da hatte er schon zu Solarpumpe das "list" geliefert, und dort war doch ein  Wert zu sehen:

Hier das Listing des HourCounters:

Code Auswählen Erweitern


Internals:
   CHANGED
   DEF        Solarpumpe:on Solarpumpe:off
   NAME       Solarpumpe_Count
   NR         103
   NTFY_ORDER 50-Solarpumpe_Count
   STATE      2 Starts, 3.0 Minuten, 0.01kWh, 102sek
   TYPE       HourCounter
   VERSION    1.0.1.2 - 24.12.2014
   READINGS:
...
     2017-08-26 10:31:31   pulseTimeEdge   102
     2017-08-26 10:31:31   pulseTimeIncrement 102
     2017-08-26 10:31:31   pulseTimeOverall 423359


Aber OK, das Test tut nicht weh


Oder hast du eine andere Quelle im Verdacht?

[CoolTux]

Noch nicht. Mich hatte die Aussage mit dem Ergebnis zu null macht etwas irritiert. Deswegen wollte ich mal schauen ob da wirklich was passiert.

[Tom S]

Hallo CoolTux,
ich habe mal das Filelog wie von dir beschrieben erstellt. Hier mal ein aktuelles LOG von heute:

Code Auswählen Erweitern


2017-08-28_19:26:54 Solarpumpe on
2017-08-28_19:26:56 Solarpumpe Longpress: on
2017-08-28_19:27:35 Solarpumpe off
2017-08-28_19:27:35 Solarpumpe Longpress: off


Im der fhem.log steht für die gleiche Zeit:

Code Auswählen Erweitern


2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=countsPerDay: 47
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=countsOverall: 3630
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pulseTimeIncrement: 0
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pulseTimeEdge: 41
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pulseTimePerDay: 4935
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pulseTimeOverall: 437445
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pauseTimeIncrement: 1344
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pauseTimeEdge: 1344
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pauseTimePerDay: 65079
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=pauseTimeOverall: 8367789
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=value: 1
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=47
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=tickUpdated: 979
2017.08.28 19:26:54 1: NAME=Solarpumpe_Count EVENT=tickChanged: 332
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=countsPerDay: 47
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=countsOverall: 3630
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pulseTimeIncrement: 41
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pulseTimeEdge: 41
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pulseTimePerDay: 4976
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pulseTimeOverall: 437486
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pauseTimeIncrement: 0
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pauseTimeEdge: 1344
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pauseTimePerDay: 65079
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=pauseTimeOverall: 8367789
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=value: 0
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=47
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=tickUpdated: 980
2017.08.28 19:27:35 1: NAME=Solarpumpe_Count EVENT=tickChanged: 333


Ich lese daraus, dass mit dem Event Pumpe on pulseTimeIncrement auf Null gesetzt wird und anfängt zu zählen. Mit Pumpe off zeigt pulseTimeIncrement den Wert in Sekunden, den ich benötige für meine Berechnung.
Trotzdem klappt halt das Auslesen des ReadingsVal nicht.

Grüße
Tom S

[amenomade]

Ah sorry, mein Schuld. Es fehlt etwas in der FileLog Definition:

Code Auswählen Erweitern

define testLog FileLog ./log/solarpulse-%Y-%U.log Solarpumpe_Count:pulseTimeIncrement.*|Solarpumpe.*(on|off).*

Aber ich glaube, es ist doch, was ich meinte. Fakt ist, dass der pulseTimeIncrement machmal gleich 0 ist. Jetzt müssen wir die Reihenfolge von den Events genauer beobachten. Aber ich vermute, es ist noch nicht aktualisiert (dann noch = 0) wenn das Event "off" kommt. Weil dieses "off" das auslösende Event für die Kalkulation von den anderen Readings ist. Das lässt sich dann vielleicht mit einem einfachen "attr <doifname> wait 1" lösen. Alternativ, das DOIF auf pulseTimeIncrement triggern

[Tom S]

Ich habe die Idee mit dem attr <...> wait 1 ausprobiert, ebenso das DOIF auf den HourCounter direkt zu triggern. Beides bringt leider keine Verbesserung: es lässt sich kein ReadingsVal des HourCounter per DOIF auslesen. Auch ein einfaches set <XY> [HourCounter:Reading] auf Kommandoebene bringt als Ergebnis stets 0.
Mache ich da noch einen Denkfehler?

[amenomade]

Kann man die Log mit allen Events sehen?

[Tom S]

Das Logfile sieht wie folgt aus:

Code Auswählen Erweitern


2017.08.30 09:13:18 3: get I2C_Device read 48 40 4 : received : 140 135 255 94  |  transmission: Ok
2017.08.30 09:13:19 3: GenShellSwitch command result: sending code[16762193]
2017.08.30 09:13:19 2: GenShellSwitch set Aussenbeleuchtung off
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=countsPerDay: 1
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=countsOverall: 3684
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pulseTimeIncrement: 0
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pulseTimeEdge: 55
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pulseTimePerDay: 0
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pulseTimeOverall: 443394
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pauseTimeIncrement: 51463
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pauseTimeEdge: 51463
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pauseTimePerDay: 33214
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=pauseTimeOverall: 8497327
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=value: 1
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=1
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=tickUpdated: 127
2017.08.30 09:13:34 1: NAME=Solarpumpe_Count EVENT=tickChanged: 440
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=countsPerDay: 1
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=countsOverall: 3684
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pulseTimeIncrement: 84
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pulseTimeEdge: 84
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pulseTimePerDay: 84
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pulseTimeOverall: 443478
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pauseTimeIncrement: 0
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pauseTimeEdge: 51463
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pauseTimePerDay: 33214
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=pauseTimeOverall: 8497327
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=value: 0
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=1
2017.08.30 09:14:58 1: NAME=Solarpumpe_Count EVENT=tickUpdated: 128
2017.08.30 09:14:59 1: NAME=Solarpumpe_Count EVENT=tickChanged: 441
2017.08.30 09:18:18 3: get I2C_Device read 48 40 4 : received : 140 152 255 96  |  transmission: Ok
2017.08.30 09:18:19 3: GenShellSwitch command result: sending code[16762193]


Interessanterweise liefert das stateFormat des devices

Code Auswählen Erweitern


stateFormat {sprintf("%.0f Starts",ReadingsVal("Solarpumpe_Count","countsPerDay",0)).sprintf(", %.1f Minuten",ReadingsVal("Solarpumpe_Count","pulseTimePerDay",0)/60).sprintf(", %.2f kWh",ReadingsVal("Solarpumpe_Count","pulseTimePerDay",0)*0.150/3600).sprintf(", %.0f sek",ReadingsVal("Solarpumpe_Count","pulseTimeIncrement",0))}

korrekte Werte für die Readings des HourCounter, z.B.:
Laufzeit, Energieverbrauch Solarpumpe:          1 Starts, 1.4 Minuten, 0.00 kWh, 84 sek

Warum also nicht das ReadingsVal im DOIF?