DBLog Mehrfacheinträge

PNinBB · 05 April 2018, 20:31:54

Seit Monaten nutze ich DBlog mit mehreren Funktionen, die darauf aufbauen (Plots. etc.); funktioniert alles so weit.
Nun zum speziellen Problem:
Ich messe ausserhalb von FHEM erreichbare Geschwindigkeiten meiner Internetverbindung (vom/bis Provider und auch zu anderen Messservern). Die Ergebnisse liegen in Textdateien.
Mittels eines 'at'-Befehls lese ich einige Werte und trage sie in zwei Dummies (Sender, Empfänger) ein. In diese Dummies werden auch Werte aus der Fritzbox eingetragen (Beispielbild für 'Sender').
Der 'at'-Befehl sieht wie folgt aus:

Code Auswählen


+*00:05:00
 {
  myNetzUtils_NetzRatenEintragen ();
  my $empf= ((ReadingsVal("FritzBox",".box_TodayBytesReceivedLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesReceivedHigh",0) * 4294967296 / (1000*1000) ) / 1000);
  fhem("setreading Empfaenger Empfangen $empf");
  my $ges= ((ReadingsVal("FritzBox",".box_TodayBytesSentLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesSentHigh",0) * 4294967296 / (1000*1000) ) / 1000);
  fhem("setreading Sender Gesendet $ges");
 }

Die Perlroutine 'myNetzUtils_NetzRatenEintragen ()' erldigt das Eintragen (mittels setreading ...) der anderen Werte in den Dummy.
Dies müssten für den Sender 5 und den Empfaenger 4 Einträge sein.
Es gibt aber mehrfache Einträge der gleichen Werte (siehe Bild). Nun kann man zwar die Datenbank von solchen Mehrfacheinträgen befreien, aber dies ist für mich eigentlich nicht zufriedenstellend.
Ich habe einmal die infrage kommenden Logwerte mit 'verbose=5' aufgenommen (siehe folgenden Ausschnitt), finde zwar die Bestätigung der Mehrfacheinträge, aber habe keine Erklärung; vor allem nicht wer hier durch was getriggert wird, also welches event der Auslöser ist.

Code Auswählen


2018.04.05 19:32:38.987 4: DbLog myDbLog -> ################################################################
2018.04.05 19:32:38.988 4: DbLog myDbLog -> ###      New database processing cycle - asynchronous        ###
2018.04.05 19:32:38.988 4: DbLog myDbLog -> ################################################################
2018.04.05 19:32:38.988 4: DbLog myDbLog -> MemCache contains 14 entries to process
2018.04.05 19:32:38.988 4: DbLog myDbLog -> DbLogType is: Current/History
2018.04.05 19:32:38.989 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:07|Empfaenger|DUMMY|DL_IN-TK: 88.51|DL_IN-TK|88.51|
2018.04.05 19:32:38.989 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:07|Empfaenger|DUMMY|Empfangen_ges: 159.070787179|Empfangen_ges|159.070787179|
2018.04.05 19:32:38.989 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:07|Empfaenger|DUMMY|DL_TK-PN: 109.34|DL_TK-PN|109.34|
2018.04.05 19:32:38.989 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:07|Empfaenger|DUMMY|Empfangen_ges: 159.070787179|Empfangen_ges|159.070787179|
2018.04.05 19:32:38.989 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|ping: 13.777|ping|13.777|
2018.04.05 19:32:38.990 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|Gesendet_ges: 23.17385488|Gesendet_ges|23.17385488|
2018.04.05 19:32:38.990 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|UL_IN-TK: 27.82|UL_IN-TK|27.82|
2018.04.05 19:32:38.990 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|Gesendet_ges: 23.17385488|Gesendet_ges|23.17385488|
2018.04.05 19:32:38.990 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|UL_TK-PN: 35.20|UL_TK-PN|35.20|
2018.04.05 19:32:38.991 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|Gesendet_ges: 23.17385488|Gesendet_ges|23.17385488|
2018.04.05 19:32:38.991 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Empfaenger|DUMMY|Empfangen: 8.194468954|Empfangen|8.194468954|
2018.04.05 19:32:38.991 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Empfaenger|DUMMY|Empfangen_ges: 159.075922068|Empfangen_ges|159.075922068|
2018.04.05 19:32:38.991 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|Gesendet: 1.066215711|Gesendet|1.066215711|
2018.04.05 19:32:38.991 5: DbLog myDbLog -> MemCache contains: 2018-04-05 19:32:08|Sender|DUMMY|Gesendet_ges: 23.174059866|Gesendet_ges|23.174059866|
2018.04.05 19:32:39.012 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 86400
2018.04.05 19:32:39.043 5: DbLog myDbLog -> Start DbLog_PushAsync
2018.04.05 19:32:39.044 5: DbLog myDbLog -> DbLogType is: Current/History
2018.04.05 19:32:39.050 4: DbLog myDbLog -> AutoCommit mode: ON, Transaction mode: ON
2018.04.05 19:32:39.142 5: DbLog myDbLog -> Primary Key used in fhem.history: none
2018.04.05 19:32:39.142 5: DbLog myDbLog -> Primary Key used in fhem.current: none
2018.04.05 19:32:39.143 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:07, Device: Empfaenger, Type: DUMMY, Event: DL_IN-TK: 88.51, Reading: DL_IN-TK, Value: 88.51, Unit: 
2018.04.05 19:32:39.144 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:07, Device: Empfaenger, Type: DUMMY, Event: Empfangen_ges: 159.070787179, Reading: Empfangen_ges, Value: 159.070787179, Unit: 
2018.04.05 19:32:39.144 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:07, Device: Empfaenger, Type: DUMMY, Event: DL_TK-PN: 109.34, Reading: DL_TK-PN, Value: 109.34, Unit: 
2018.04.05 19:32:39.145 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:07, Device: Empfaenger, Type: DUMMY, Event: Empfangen_ges: 159.070787179, Reading: Empfangen_ges, Value: 159.070787179, Unit: 
2018.04.05 19:32:39.145 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: ping: 13.777, Reading: ping, Value: 13.777, Unit: 
2018.04.05 19:32:39.145 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: Gesendet_ges: 23.17385488, Reading: Gesendet_ges, Value: 23.17385488, Unit: 
2018.04.05 19:32:39.146 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: UL_IN-TK: 27.82, Reading: UL_IN-TK, Value: 27.82, Unit: 
2018.04.05 19:32:39.146 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: Gesendet_ges: 23.17385488, Reading: Gesendet_ges, Value: 23.17385488, Unit: 
2018.04.05 19:32:39.146 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: UL_TK-PN: 35.20, Reading: UL_TK-PN, Value: 35.20, Unit: 
2018.04.05 19:32:39.147 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: Gesendet_ges: 23.17385488, Reading: Gesendet_ges, Value: 23.17385488, Unit: 
2018.04.05 19:32:39.147 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Empfaenger, Type: DUMMY, Event: Empfangen: 8.194468954, Reading: Empfangen, Value: 8.194468954, Unit: 
2018.04.05 19:32:39.147 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Empfaenger, Type: DUMMY, Event: Empfangen_ges: 159.075922068, Reading: Empfangen_ges, Value: 159.075922068, Unit: 
2018.04.05 19:32:39.148 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: Gesendet: 1.066215711, Reading: Gesendet, Value: 1.066215711, Unit: 
2018.04.05 19:32:39.148 5: DbLog myDbLog -> processing event Timestamp: 2018-04-05 19:32:08, Device: Sender, Type: DUMMY, Event: Gesendet_ges: 23.174059866, Reading: Gesendet_ges, Value: 23.174059866, Unit: 
2018.04.05 19:32:39.166 4: DbLog myDbLog -> 14 of 14 events inserted into table history
2018.04.05 19:32:39.181 4: DbLog myDbLog -> insert table history committed by autocommit
2018.04.05 19:32:39.454 4: DbLog myDbLog -> 14 of 14 events updated in table current
2018.04.05 19:32:39.465 4: DbLog myDbLog -> insert / update table current committed by autocommit
2018.04.05 19:32:39.465 5: DbLog myDbLog -> DbLog_PushAsync finished
2018.04.05 19:32:39.480 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2018.04.05 19:32:39.571 5: DbLog myDbLog -> DbLog_PushAsyncDone finished

Kann mir jemand den Sachverhalt erklären, bzw. wie ich die Mehrfacheinträge verhindern kann.
Besten Dank im Voraus und schönen Abend.
Peter

pumabaer · 05 April 2018, 20:52:56

Hallo,
dem Phänomen schließe ich mich an.
Allerdings ist es bei mir eine WLAN Steckdose (TPLink HS110) und auch nur das Gerät.
Die Readings (Watt und Volt) die ich in die Db log schreibe kommen doppelt (selber timestamp).

gent · 05 April 2018, 21:00:28

Hallo Peter, hallo pumabaer

als Datenbank-Admin würde ich sagen, dass ein unique-key auf der entsprechenden Datenbank helfen könnte und zwar auf die Spalten TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE (evtl. auch weniger)

Das würde die doppelten Einträge zuverlässig verhindern, aber wahrscheinlich einen Haufen Fehler im dbLog Device produzieren.

Ohne de Datenbank-Struktur zu ändern müsste man wirklich die Ursache finden. Vielleicht liegt es daran, dass durch das setReading wieder ein Event ausgelöst wird, der dann den doppelten Eintrag erzeugt.

Viele Grüße vom gent

DS_Starter · 05 April 2018, 21:52:10

Hallo zusammen,

wie gent schon schrieb, kann ein primary key die doppelten Einträge verhindern.
DbLog unterstützt seit einiger Zeit einen gesetzten PK. Wenn man es nutzen möchte setzt man am Besten verbose 2 im DbLog.
Die Meldungen, dass der PK ein Schreiben des Datensatzes verhinderte werden so nicht ausgegeben.

In MySQL kann man den PK so hinzufügen:

Code Auswählen


ALTER IGNORE TABLE `history` ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);

Mit dem "IGNORE" sollte es möglich sein den PK anzulegen obwohl es schon duplicate keys in der DB gibt ansonsten muss man das vorher bereinigen.
Meine produktiven DB's haben alle einen PK gesetzt.

Unabhängig davon kann man natürlich gerne mal auf die Suche gehen woher die mehrfachen Events kommen.

Grüße,
Heiko

PNinBB · 06 April 2018, 09:47:42

Zuerst Danke für die Hinweise.
Ich bin auf der "Pirsch":
@gent:

ZitatVielleicht liegt es daran, dass durch das setReading wieder ein Event ausgelöst wird, der dann den doppelten Eintrag erzeugt.

Das kann man wohl ausschliessen, da ich es auch ohne die Perl-Routine ausgeführt habe. Da fehlen dann natürlich meine "Spezialwerte", aber die Mehrfacheinträge gab es genauso wie im anderen Fall.
@DS_Starter:
Noch möchte ich nicht auf die 'primary key'-Option zurückgreifen.
Ich habe noch einmal die Anzeigen des Event-Monitors unter die Lupe genommen (Zeilennummern, Abstände und Einrückungen von mir):

Code Auswählen


Z01:  2018-04-06 08:56:25.062 dummy Empfaenger DL_IN-TK: 93.73
Z02:    2018-04-06 08:56:25.062 dummy Empfaenger Empfangen_ges: 163.208920311
Z03:  2018-04-06 08:56:25.145 dummy Empfaenger DL_TK-PN: 109.34
Z04:    2018-04-06 08:56:25.145 dummy Empfaenger Empfangen_ges: 163.208920311

Z05:  2018-04-06 08:56:25.228 dummy Sender ping: 15.647
Z06:    2018-04-06 08:56:25.228 dummy Sender Gesendet_ges: 23.751382067
Z07:  2018-04-06 08:56:25.309 dummy Sender UL_IN-TK: 31.29
Z08:    2018-04-06 08:56:25.309 dummy Sender Gesendet_ges: 23.751382067
Z09:  2018-04-06 08:56:25.392 dummy Sender UL_TK-PN: 35.20
Z10:    2018-04-06 08:56:25.392 dummy Sender Gesendet_ges: 23.751382067

Z11:  2018-04-06 08:56:25.474 dummy Empfaenger Empfangen: 3.174204642
Z12:    2018-04-06 08:56:25.474 dummy Empfaenger Empfangen_ges: 163.214286632

Z13:  2018-04-06 08:56:25.561 dummy Sender Gesendet: 0.432571635
Z14:    2018-04-06 08:56:25.561 dummy Sender Gesendet_ges: 23.751622016

Z15:  2018-04-06 08:56:25.646 at at_FBTraffic Next: 09:01:24

Man erkennt:
1. Gedoppelt werden nur die jeweiligen "Gesamtanzeigen" (..._ges).
2. Die Zeilen Z01 und Z03, bzw. Z05, Z07 und Z09 sind höchstwahrscheinlich von der Perl-Routine veranlasst und sind in Ordnung.
3. Die Zeilen Z11 bis Z15 werden von den anderen Maßnahmen im 'at'-Befehl veranlasst und wären auch OK.
4. Folglich wären die Events gemäß Zeilen Z02, Z04, Z06, Z08 und Z10 die 'Übeltäter'. Sie haben alle exakt den gleichen Zeitstempel die die Einträge der Perl-Routine; dort muss "irgendwie und -wo der Hund begraben liegen".
Ich werde dort einmal nur einen Eintrag vornehmen und sehen, was passiert.
Ich berichte weiter.
Peter

PNinBB · 06 April 2018, 18:21:43

Ich bin einen Schritt weiter, aber noch nicht am Ziel.
Die Ursache für die mehrfachen Einträge ist ein 'userReadings' zum kummulativen Wert der gesendeten und empfangenen Werte aus den Fritzbox (Bezug: https://waschto.eu/traffic/).

Code Auswählen


Gesendet_ges monotonic { ReadingsVal("Sender","Gesendet",0)}

Dahinter steht wohl der Ablauf, der in

Zitat
https://forum.fhem.de/index.php/topic,52165.30.html

angesprochen wird.
Wenn ich dieses 'userReadings' entferne, läuft alles korrekt, insbesondere ohne Mehrfacheinträge.
Nun weiß ich nicht, wie ich da raus komme; eventuell die Gesamtwerte im Perl-Module "selbst" berechnen, aber so richtig anfreunden kann ich mich damit nicht.
Die Hinweise in

Zitat
https://wiki.fhem.de/wiki/UserReadings

bringen mich auch nicht weiter.
Hat jemand einen "Triggerimpuls" für mich !?
Besten Dank
Peter

gent · 11 April 2018, 20:05:14

Hallo Peter,

na dann trigger ich mal, allerdings ohne das überprüft zu haben und auch eher als Frage: Wenn Du wie im https://waschto.eu/traffic/ Beitrag vorgegangen bist, wieso brauchst Du dann noch die Perl-Routine myNetzUtils_NetzRatenEintragen ()? Das setReading passiert doch bereits im at...

Viele Grüße vom gent

betateilchen · 11 April 2018, 20:28:31

Ersetze in Deinem at

Code Auswählen

fhem("setreading Empfaenger Empfangen $empf");

durch

Code Auswählen

readingsSingleUpdate($defs{'Empfaenger'}, 'Empfangen', $empf, 0);

PNinBB · 18 April 2018, 18:25:50

Da ich für einige Tage unterwegs war, komme ich erst heute dazu zu reagieren.
@gent:

Zitatna dann trigger ich mal, allerdings ohne das überprüft zu haben und auch eher als Frage: Wenn Du wie im https://waschto.eu/traffic/ Beitrag vorgegangen bist, wieso brauchst Du dann noch die Perl-Routine myNetzUtils_NetzRatenEintragen ()? Das setReading passiert doch bereits im at...

Die Werte aus der Firtzbox werden natürlich mit dem 'at-Befehl' eingetragen. Ich will aber in die Dummies noch weitere, außerhalb von FHEM gemessene Werte eintragen, um sie dann im Plot mit anzuzeigen; deshalb die Perl-Routine.
@betateilchen:

ZitatErsetze in Deinem at
fhem("setreading Empfaenger Empfangen $empf");
durch
readingsSingleUpdate($defs{'Empfaenger'}, 'Empfangen', $empf, 0);

Ich habe alle Varianten, wie im Wiki https://wiki.fhem.de/wiki/DevelopmentIntroduction dokumentiert, ausprobiert.
Alles ohne Erfolg: die Events werden immer erzeugt.
Ich habe schlussendlich aufgegeben und die PK in der Datenbank eingerichtet. Damit sind die Mehrfacheinträge natürlich verschwunden, aber die Events werden noch immer "fleissig" erzeugt. Im Event-Monitor sieht das dann so aus:

Code Auswählen

2018-04-18 18:05:27.682 dummy Empfaenger DL_IN-TK: 93.57
2018-04-18 18:05:27.682 dummy Empfaenger Empfangen_ges: 290.480741166001
2018-04-18 18:05:27.764 dummy Empfaenger DL_TK-PN: 109.34
2018-04-18 18:05:27.764 dummy Empfaenger Empfangen_ges: 290.480741166001
2018-04-18 18:05:27.848 dummy Sender ping: 14.462
2018-04-18 18:05:27.848 dummy Sender Gesendet_ges: 41.5768723239999
2018-04-18 18:05:27.929 dummy Sender UL_IN-TK: 31.50
2018-04-18 18:05:27.929 dummy Sender Gesendet_ges: 41.5768723239999
2018-04-18 18:05:28.011 dummy Sender UL_TK-PN: 35.47
2018-04-18 18:05:28.011 dummy Sender Gesendet_ges: 41.5768723239999
2018-04-18 18:05:28.116 dummy Empfaenger Empfangen: 6.024753721
2018-04-18 18:05:28.116 dummy Empfaenger Empfangen_ges: 290.480741166001
2018-04-18 18:05:28.277 dummy Sender Gesendet: 0.879158789
2018-04-18 18:05:28.277 dummy Sender Gesendet_ges: 41.5768723239999

Dabei werden die Werte von 'Ausserhalb' durch die Perl-Routine korrekt, also nur einmal, eingetragen, während die Werte aus der Firtzbox durch den 'at-Befehl' mehrere Male eingetragen werden.
Fazit: das Problem ist gelöst, aber nicht befriedigend, da ich nicht genau weiss, wass sich hier eigentlich "abspielt".
Auf jeden Fall euch Beiden herzlichen Dank für die Tipps.
Peter

PNinBB · 24 April 2018, 10:00:55

Das Problem hat mir keine Ruhe gelassen. Ich habe folgendes aufgebaut und damit getestet:
2 Dummies: T1

Code Auswählen


Internals:
   CFGFN      
   CHANGED    
   NAME       T1
   NR         90935
   STATE      7.40 GB - 7.40 GB
   TYPE       dummy
   .attraggr:
   .attreocr:
     .*
   .attrminint:
   .userReadings:
     HASH(0x42855b8)
   READINGS:
     2018-04-23 17:34:05   DL_IN-TK        76.342
     2018-04-23 17:34:05   DL_TK-PN        109.342
     2018-04-23 17:34:05   Empfangen       7.403731809
     2018-04-23 17:34:05   Empfangen_ges   7.403731809
Attributes:
   event-on-change-reading .*
   room       Testsuite
   stateFormat {sprintf("%.2f GB - %.2f GB",ReadingsVal("T1","Empfangen",0),ReadingsVal("T1","Empfangen_ges",0))}
   userReadings Empfangen_ges monotonic { ReadingsVal("T1","Empfangen",0)}

und T2:

Code Auswählen


 Internals:
   CFGFN      
   NAME       T2
   NR         91222
   STATE      0.91 GB - 0.91 GB
   TYPE       dummy
   .attraggr:
   .attreour:
     .*
   .attrminint:
   .userReadings:
     HASH(0x3dc3928)
   READINGS:
     2018-04-23 17:34:05   Gesendet        0.914992622
     2018-04-23 17:34:05   Gesendet_ges    0.914992622
     2018-04-23 17:34:05   UL_IN-TK        23.379
     2018-04-23 17:34:05   UL_TK-PN        34.342
     2018-04-23 17:34:05   ping            326
Attributes:
   event-on-update-reading .*
   room       Testsuite
   stateFormat {sprintf("%.2f GB - %.2f GB",ReadingsVal("T2","Gesendet",0),ReadingsVal("T2","Gesendet_ges",0))}
   userReadings Gesendet_ges monotonic { ReadingsVal("T2","Gesendet",0)}

Die ersten Werte waren schon eingetragen bevor ich die 'list'-Kommandos gegeben hatte. Dabei kommen 'Gesendet' und 'Empfangen' vom 'at'-Befehl

Code Auswählen

Internals:
   CFGFN      
   COMMAND    {
  my $empf= ((ReadingsVal("FritzBox",".box_TodayBytesReceivedLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesReceivedHigh",0) * 4294967296 / (1000*1000)) / 1000);
  fhem("setreading T1 Empfangen $empf");
  my $ges= ((ReadingsVal("FritzBox",".box_TodayBytesSentLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesSentHigh",0) * 4294967296 / (1000*1000) ) / 1000);
  fhem("setreading T2 Gesendet $ges");
  myTestUtils_T1 ();
 }
   DEF        +*00:10:00 {
  my $empf= ((ReadingsVal("FritzBox",".box_TodayBytesReceivedLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesReceivedHigh",0) * 4294967296 / (1000*1000)) / 1000);
  fhem("setreading T1 Empfangen $empf");
  my $ges= ((ReadingsVal("FritzBox",".box_TodayBytesSentLow",0) / (1000*1000) ) / 1000 + ( ReadingsVal("FritzBox",".box_TodayBytesSentHigh",0) * 4294967296 / (1000*1000) ) / 1000);
  fhem("setreading T2 Gesendet $ges");
  myTestUtils_T1 ();
 }
   NAME       at_T1
   NR         91174
   NTM        09:00:38
   PERIODIC   yes
   RELATIVE   yes
   REP        -1
   STATE      Next: 09:00:38
   TIMESPEC   00:10:00
   TRIGGERTIME 1524553238.74991
   TRIGGERTIME_FMT 2018-04-24 09:00:38
   TYPE       at
   .attraggr:
   .attrminint:
   READINGS:
     2018-04-24 08:50:39   state           Next: 09:00:38
Attributes:
   group      at
   room       Testsuite

gemäß der Anleitung in https://waschto.eu/traffic/.
Für die beiden Dummies wurden entsprechende FileLogs T1Log und T2Log eingerichtet.
Im 'at'-Befehl wird auch eine Perlroutine 'myTestUtils_T1 ()' gerufen, die die "FHEM-fremden" Einträge als 'readings' vornimmt.
Dabei habe ich mit zwei Varianten getestet.
Variante 1: mit "normalem" setreading:

Code Auswählen


. . . .
  fhem ("setreading T1 DL_IN-TK $DLINTK");           # Download IN --> TK in Empfaenger eintragen
  fhem ("setreading T1 DL_TK-PN $DLTKPN");          # Download IN --> TK in Empfaenger eintragen
  fhem ("setreading T2 ping $ping");                       # ping in Sender eintragen
  fhem ("setreading T2 UL_IN-TK $ULINTK");           # Download IN --> TK in Sender eintragen
  fhem ("setreading T2 UL_TK-PN $ULTKPN");           # Download IN --> TK in Sender eintragen
. . . .

Variante 2: mit "readingsSingleUpdate", welches mittels des dritten Parameters die Eventerzeugung unterbinden kann:

Code Auswählen


. . . .
$RC = readingsSingleUpdate (%defs->{"T1"}, "DL_IN-TK", $DLINTK,0);   # Download IN --> TK in Empfaenger eintragen
$RC = readingsSingleUpdate (%defs->{"T1"}, "DL_TK-PN", $DLTKPN,0);  # Download IN --> TK in Empfaenger eintragen
$RC = readingsSingleUpdate (%defs->{"T2"}, "ping", $ping, 0);              # ping in Sender eintragen
$RC = readingsSingleUpdate (%defs->{"T2"}, "UL_IN-TK", $ULINTK,0);   # Download IN --> TK in Sender eintragen
$RC = readingsSingleUpdate (%defs->{"T2"}, "UL_TK-PN", $ULTKPN,0);   # Download IN --> TK in Sender eintragen
. . . .

1. Test:
Es werden nur die Einträge aus der FritzBox übernommen und als readings (wie oben) eingetragen, d.h. die Perlroutine wird nicht gerufen. Dabei funktioniert alles korrekt: die Werte werden eingetragen; sie erscheinen in den beiden Logfiles und man kann auch ordentliche Plots aufbauen.
Der Event-Monitor zeigt die richtigen Ereignisse.

2. Test:
Nun wird die Perlroutine durch den 'at-Befehl' mit aufgerufen. In dieser Routine ordne ich den Werten, die ich im "echten" System aus meinen "externen" Messungen von Datenraten fülle, einfach konstante Werte zu. Damit trage ich diese Werte als readings ein. Zuerst mit Variante 1 ("normalem" setreading).
Der Event-Monitor zeigt die Mehrfachtriggerung:

Code Auswählen


2018-04-23 17:27:37.195 dummy T1 Empfangen: 7.397007589
2018-04-23 17:27:37.195 dummy T1 Empfangen_ges: 7.397007589
2018-04-23 17:27:37.351 dummy T2 Gesendet: 0.914773585
2018-04-23 17:27:37.351 dummy T2 Gesendet_ges: 0.914773585

2018-04-23 17:27:37.510 dummy T2 ping: 326
2018-04-23 17:27:37.510 dummy T2 Gesendet_ges: 0.914773585
2018-04-23 17:27:37.665 dummy T2 UL_IN-TK: 23.379
2018-04-23 17:27:37.665 dummy T2 Gesendet_ges: 0.914773585
2018-04-23 17:27:37.820 dummy T2 UL_TK-PN: 34.342
2018-04-23 17:27:37.820 dummy T2 Gesendet_ges: 0.914773585
2018-04-23 17:27:37.905 at at_T1 execNow

Die ersten vier Werte sind OK; sie werden direkt durch den 'at'-Befehl hervorgerufen.
Dann beginnt das "Mysterium": nach jedem in T2 einzutragenden Wert erscheint wieder der Trigger für 'Gesendet_ges'.

Die Logfiles zeigen nun klar das Problem.
T1Log:

Code Auswählen

2018-04-23_17:27:37 T1 Empfangen: 7.397007589
2018-04-23_17:27:37 T1 Empfangen_ges: 7.397007589

T2Log:

Code Auswählen

2018-04-23_17:27:37 T2 Gesendet: 0.914773585
2018-04-23_17:27:37 T2 Gesendet_ges: 0.914773585
2018-04-23_17:27:37 T2 ping: 326
2018-04-23_17:27:37 T2 Gesendet_ges: 0.914773585
2018-04-23_17:27:37 T2 UL_IN-TK: 23.379
2018-04-23_17:27:37 T2 Gesendet_ges: 0.914773585
2018-04-23_17:27:37 T2 UL_TK-PN: 34.342
2018-04-23_17:27:37 T2 Gesendet_ges: 0.914773585

Mit Variante 2 (mit "readingsSingleUpdate") bringt der Event-Monitor folgendes:

Code Auswählen

2018-04-24 09:30:38.911 dummy T1 Empfangen: 3.273143384
2018-04-24 09:30:38.911 dummy T1 Empfangen_ges: 12.715088234
2018-04-24 09:30:38.992 dummy T2 Gesendet: 0.426801984
2018-04-24 09:30:38.992 dummy T2 Gesendet_ges: 1.629184896
2018-04-24 09:30:39.038 at at_T1 Next: 09:40:38

D.h.: keine zusätzlichen Events
T1Log:

Code Auswählen

2018-04-24_09:30:38 T1 Empfangen: 3.273143384
2018-04-24_09:30:38 T1 Empfangen_ges: 12.715088234

T2Log:

Code Auswählen

2018-04-24_09:30:38 T2 Gesendet: 0.426801984
2018-04-24_09:30:38 T2 Gesendet_ges: 1.629184896

Also: keine Mehrfacheinträge.
In den Logfiles tauchen natürlich meine "Spezialwerte" nicht auf, da die "readingsSingleUpdate" keine Events generieren. Ich kann sie deshalb auch nicht in den Plots auswerten.

3. Test:
Jetzt habe ich im "readingsSingleUpdate" den dritten Parameter auf "1" gesetzt, also Events erzeugen lassen.
Der Event-Montor zeigt die von der Perlroutine vorgenommenen Einträge und Events, aber eben auch die Mehrfacheinträge !

Code Auswählen


2018-04-24 09:37:38.331 dummy T1 Empfangen: 3.279943806
2018-04-24 09:37:38.331 dummy T1 Empfangen_ges: 12.721888656
2018-04-24 09:37:38.415 dummy T2 Gesendet: 0.427046167
2018-04-24 09:37:38.415 dummy T2 Gesendet_ges: 1.629429079
2018-04-24 09:37:38.533 dummy T2 ping: 326
2018-04-24 09:37:38.533 dummy T2 Gesendet_ges: 1.629429079
2018-04-24 09:37:38.692 dummy T2 UL_IN-TK: 23.379
2018-04-24 09:37:38.692 dummy T2 Gesendet_ges: 1.629429079
2018-04-24 09:37:38.852 dummy T2 UL_TK-PN: 34.342
2018-04-24 09:37:38.852 dummy T2 Gesendet_ges: 1.629429079
2018-04-24 09:37:38.938 at at_T1 execNow

Die Logfiles sind wie beim 2. Test mit Eventtriggerung, also auch hier wieder die Mehrfachtriggerung und -einträge.
Der FHEM-Logfile leifert keine Anhaltspunkte; selbst bei 'Verbose 5'.

Mir sind 2 Dinge unklar:
1. Wie kommt es zu diesen zusätzlichen Triggerungen ?
2. Warum wird "nur" der Eintrag 'Gesendet_ges' mehrfach eingetragen ?
Vielleicht gibt es jemand, der sich mit mir weiter den Kopf verbrechen möchte; mir sind momentan die Ideen ausgegangen, vor allem natürlich auch, weil mir zu viele FHEM-spezifische Details unklar sind.
Auf jeden Fall: vielen Dank im Voraus.
Peter