Nachrichten werden falschem Device zugeordnet (expandJSON / MQTT)

Begonnen von alpha1974, 01 September 2018, 11:12:04

Vorheriges Thema - Nächstes Thema

alpha1974

Werte FHEM-Gemeinde,

ich habe zwei WLAN-Steckdosen, die unter Tasmota laufen und fleißig Daten per MQTT an FHEM übermitteln. Leider funktioniert die Zuordnung der eingehenden Nachrichten zum richtigen Device (also demjenigen, dass die MQTT-Nachricht abschickt) nicht richtig. Nachrichten, die das Device SP111-1 sendet, werden von expandJSON zusätzlich dem Device SP111-2 zugeordnet (siehe Logs unten). Umgekehrt taucht der Fehler nicht auf, d.h. Nachrichten von SP111-2 werden NICHT auch dem Device SP111-1 zugeordnet.

Vielleicht hat jemand einen Tipp für mich, wo der Fehler liegen könnte. Da beim MQTT-Broker jeweils nur eine Nachricht des richtigen Devices ankommt, vermute ich ein Problem mit expandJSON (Def siehe unten).

Hier die Log-Files, um das Problem zu verdeutlichen:

FHEM-Log (MQtt-Broker und expandJSON jeweils auf Verbose 5):
2018.09.01 10:57:24 5: MQTT mqttServer message received: Publish/at-most-once tele/SP111-1/SENSOR
  7b 22 54 69 6d 65 22 3a 22 32 30 31 38 2d 30 39  {"Time":"2018-09
  2d 30 31 54 31 30 3a 35 37 3a 32 30 22 2c 22 45  -01T10:57:20","E
  4e 45 52 47 59 22 3a 7b 22 54 6f 74 61 6c 22 3a  NERGY":{"Total":
  31 2e 34 35 34 2c 22 59 65 73 74 65 72 64 61 79  1.454,"Yesterday
  22 3a 30 2e 35 33 38 2c 22 54 6f 64 61 79 22 3a  ":0.538,"Today":
  30 2e 32 34 36 2c 22 50 6f 77 65 72 22 3a 32 31  0.246,"Power":21
  2c 22 46 61 63 74 6f 72 22 3a 30 2e 33 37 2c 22  ,"Factor":0.37,"
  56 6f 6c 74 61 67 65 22 3a 32 33 33 2c 22 43 75  Voltage":233,"Cu
  72 72 65 6e 74 22 3a 30 2e 32 34 35 7d 7d        rrent":0.245}}
2018.09.01 10:57:24 5: expandJSON ej_sonoff: Found sonoffSP111_1:SENSOR: {"Time":"2018-09-01T10:57:20","ENERGY":{"Total":1.454,"Yesterday":0.538,"Today":0.246,"Power":21,"Factor":0.37,"Voltage":233,"Current":0.245}}
2018.09.01 10:57:24 5: expandJSON ej_sonoff: Yield decode: HASH(0x2fbf0e8) | sonoffSP111_1 | SENSOR | {"Time":"2018-09-01T10:57:20","ENERGY":{"Total":1.454,"Yesterday":0.538,"Today":0.246,"Power":21,"Factor":0.37,"Voltage":233,"Current":0.245}}
2018.09.01 10:57:24 5: expandJSON ej_sonoff: Found sonoffSP111_2:SENSOR: {"Time":"2018-09-01T10:57:20","ENERGY":{"Total":1.454,"Yesterday":0.538,"Today":0.246,"Power":21,"Factor":0.37,"Voltage":233,"Current":0.245}}
2018.09.01 10:57:24 5: expandJSON ej_sonoff: Yield decode: HASH(0x2fbf0e8) | sonoffSP111_2 | SENSOR | {"Time":"2018-09-01T10:57:20","ENERGY":{"Total":1.454,"Yesterday":0.538,"Today":0.246,"Power":21,"Factor":0.37,"Voltage":233,"Current":0.245}}


mosquitto_sub Log aus der Console zeigt ebenfalls, dass nur die eine Nachricht von SP111-1 angekommen ist:
Client mosqsub/10310-rpiaquari received PUBLISH (d0, q0, r0, m0, 'tele/SP111-2/SENSOR', ... (141 bytes))
tele/SP111-2/SENSOR {"Time":"2018-09-01T10:57:12","ENERGY":{"Total":0.003,"Yesterday":0.001,"Today":0.002,"Power":0,"Factor":0.00,"Voltage":239,"Current":0.099}}
Client mosqsub/10310-rpiaquari received PUBLISH (d0, q0, r0, m0, 'tele/SP111-1/SENSOR', ... (142 bytes))
tele/SP111-1/SENSOR {"Time":"2018-09-01T10:57:20","ENERGY":{"Total":1.454,"Yesterday":0.538,"Today":0.246,"Power":21,"Factor":0.37,"Voltage":233,"Current":0.245}}
Client mosqsub/10310-rpiaquari received PUBLISH (d0, q0, r0, m0, 'tele/SP111-2/STATE', ... (150 bytes))
tele/SP111-2/STATE {"Time":"2018-09-01T10:57:34","Uptime":"0T14:46:12","Vcc":3.152,"POWER":"ON","Wifi":{"AP":1,"SSId":"7270e1312","RSSI":78,"APMac":"34:81:C4:DC:C8:5C"}}
Client mosqsub/10310-rpiaquari received PUBLISH (d0, q0, r0, m0, 'tele/SP111-2/SENSOR', ... (152 bytes))
tele/SP111-2/SENSOR {"Time":"2018-09-01T10:57:34","ENERGY":{"Total":0.003,"Yesterday":0.001,"Today":0.002,"Period":0,"Power":0,"Factor":0.00,"Voltage":238,"Current":0.000}}


Hier das expandJSON-Device:
Internals:
   CFGFN     
   DEF        sonoff.*:.*:.{.*}
   NAME       ej_sonoff
   NR         37
   NTFY_ORDER 50-ej_sonoff
   STATE      2018-09-01 11:07:06
   TYPE       expandJSON
   s_regexp   sonoff.*:.*:.{.*}
   t_regexp   .*
   version    1.13
   READINGS:
     2018-08-31 17:00:43   state           active
   helper:
Attributes:
   room       MQTT


Stimmt die s_regexp nicht? Merkwürdig finde ich, dass es sonoffSP111_2 richtig ausgewertet wird, während sonoffSP111_1 gleichzeitig auch als sonoffSP111_2 behandelt wird.

Danke und viele Grüße
alpha1974
FHEM/Z-Wave USB-Dongle + div. Devices

dev0

Kann ich nicht nachvollzihen, bitte ein konkretes Beispiel mit dummy Devices zeigen, wie ich das reproduzieren kann.


define sonoffSP111_1 dummy

define sonoffSP111_2 dummy

define ejX expandJSON sonoff.*:.*:.{.*}

setreading sonoffSP111_1 JSON {"Time":"2018-09-01T10:57:12","ENERGY":{"Total":0.003,"Yesterday":0.001,"Today":0.002,"Power":0,"Factor":0.00,"Voltage":239,"Current":0.099}}

list sonoffSP111_1
Internals:
   CFGFN     
   NAME       sonoffSP111_1
   NR         101
   STATE      ???
   TYPE       dummy
   .attraggr:
   .attrminint:
   READINGS:
     2018-09-01 13:56:34   ENERGY_Current  0.099
     2018-09-01 13:56:34   ENERGY_Factor   0
     2018-09-01 13:56:34   ENERGY_Power    0
     2018-09-01 13:56:34   ENERGY_Today    0.002
     2018-09-01 13:56:34   ENERGY_Total    0.003
     2018-09-01 13:56:34   ENERGY_Voltage  239
     2018-09-01 13:56:34   ENERGY_Yesterday 0.001
     2018-09-01 13:56:34   JSON            {"Time":"2018-09-01T10:57:12","ENERGY":{"Total":0.003,"Yesterday":0.001,"Today":0.002,"Power":0,"Factor":0.00,"Voltage":239,"Current":0.099}}
     2018-09-01 13:56:34   Time            2018-09-01T10:57:12
Attributes:

list sonoffSP111_2
Internals:
   CFGFN     
   NAME       sonoffSP111_2
   NR         103
   STATE      ???
   TYPE       dummy
Attributes:



Btw: ist die s_regex nicht besonders geschickt, da so jedes Reading 'inspiziert' wird und nicht nur das/die Relevanten.

alpha1974

Dummy-Devices habe ich leider nicht parat, aber Listing des MQTT_DEVICE. Unten das Listung für sonoffSP111_1 (=MQTT Topic: SP111-1), analoge Konfiguration für SP111-2.

Ich glaube, dass ich das Problem zwischenzeitlich eingrenzen konnte: Wenn ich in den Geräten, die die MQTT-Nachrichten verschicken (WLAN-Steckdosen mit Tasmota), die MQTT-Geräte-Topics von SP111-1 auf SP111_1 und von SP111-2 auf SP111_2 ändere, klappt alles so, wie es soll. Vielleicht kommt meine s_regex nicht mit dem Bindestrich im Topic klar, wohl aber mit einem Unterstrich.

Die sehr weite s_regex ist erst einmal so gewollt, da ich damit beide Devices mit allen Readings bekomme; dies erst einmal nur zu Testzwecken, später kann ich dann ja noch eingrenzen (und dabei mangels ausreichender RegEx-Expertise sicher wieder neue Fehler einbauen  :o)

Internals:
   CFGFN     
   IODev      mqttServer
   NAME       sonoffSP111_1
   NR         40
   STATE      ON 14 A
   TYPE       MQTT_DEVICE
   Helper:
     DBLOG:
       POWER:
         logdb:
           TIME       1535794928.66649
           VALUE      ON
   READINGS:
     2018-09-01 16:04:50   ENERGY_Current  0.196
     2018-09-01 16:04:50   ENERGY_Factor   0.31
     2018-09-01 16:03:33   ENERGY_Period   2
     2018-09-01 16:04:50   ENERGY_Power    14
     2018-09-01 16:04:50   ENERGY_Today    0.361
     2018-09-01 16:04:50   ENERGY_Total    1.569
     2018-09-01 16:04:50   ENERGY_Voltage  234
     2018-09-01 16:04:50   ENERGY_Yesterday 0.538
     2018-09-01 11:42:08   POWER           ON
     2018-09-01 16:04:50   SENSOR          {"Time":"2018-09-01T16:04:49","ENERGY":{"Total":1.569,"Yesterday":0.538,"Today":0.361,"Power":14,"Factor":0.31,"Voltage":234,"Current":0.196}}
     2018-09-01 16:04:50   Time            2018-09-01T16:04:49
     2018-09-01 11:42:08   state           ON
     2018-09-01 16:04:50   transmission-state incoming publish received
   message_ids:
   publishSets:
     :
       topic      cmnd/SP111-1/power
       values:
         publishSet
         ON
         OFF
   sets:
     OFF       
     ON         
     publishSet
   subscribe:
     stat/SP111-1/POWER
     tele/SP111-1/SENSOR
   subscribeExpr:
     ^stat\/SP111-1\/POWER$
     ^tele\/SP111-1\/SENSOR$
   subscribeQos:
     stat/SP111-1/POWER 0
     tele/SP111-1/SENSOR 0
   subscribeReadings:
     stat/SP111-1/POWER:
       cmd       
       name       POWER
     tele/SP111-1/SENSOR:
       cmd       
       name       SENSOR
Attributes:
   DbLogInclude POWER
   IODev      mqttServer
   alias      Bodenfluter
   publishSet publishSet ON OFF cmnd/SP111-1/power
   room       Strom,MQTT
   stateFormat POWER ENERGY_Power A
   subscribeReading_POWER stat/SP111-1/POWER
   subscribeReading_SENSOR tele/SP111-1/SENSOR
   webCmd     ON:OFF
FHEM/Z-Wave USB-Dongle + div. Devices

dev0

ZitatDummy-Devices habe ich leider nicht parat
Dann werde ich Dir nicht wirklich weiterhelfen können.

Das expandJSON Modul verarbeitet stumpf Readings eines Devices, wenn ein Event dafür erzeugt wird. Die Namen der neuen Readings werden ggf. so angepasst, dass sie den FHEM Konventionen entsprechen. Devicenamen werden nicht geändert, auch wenn sie Sonderzeichen enthalten, an denen FHEM sich stört. MQTT Topics interessieren an der Stelle auch nicht weiter.

Von daher gehe ich davon aus, dass die Ursache nicht am expandJSON Modul liegt und bin (vorläufig?) raus.

alpha1974

Vielen Dank für deine Antwort! Seit der Umbenennung der MQTT-Topics (jetzt mit Unterstrich statt Bindestrich) taucht das Problem auch nicht mehr auf.

Wenn es nicht am expandJSON liegt, könnte die Ursache evtl. bei der Verarbeitung der eingehenden MQTT-Nachrichten durch das FHEM-   
MQTT-Broker-Device gelegen haben? Aus den Log-Files (siehe mein Posting #1) geht ja hervor, dass tatsächlich nur eine einzige externe Nachricht empfangen wurde, die dann vielleicht durch das MQTT-Broker-Device doppelt verteilt wurde (auf beide MQTT_DEVICEs)?

Der in FHEM definierte MQTT-Broker ist ziemlich simpel definiert:
Internals:
   CFGFN     
   DEF        127.0.0.1:1883
   DeviceName 127.0.0.1:1883
   FD         18
   NAME       mqttServer
   NOTIFYDEV  global
   NR         34
   NTFY_ORDER 50-mqttServer
   PARTIAL   
   STATE      opened
   TYPE       MQTT
   buf       
   msgid      11
   ping_received 1
   timeout    60
   READINGS:
     2018-09-02 09:06:57   connection      active
     2018-08-31 16:59:11   state           opened
   messages:
Attributes:
   room       MQTT
FHEM/Z-Wave USB-Dongle + div. Devices

dev0

Um die Ursache zu ermitteln könnte es helfen den Event Monitor (incl. Log) laufen zu lassen, um zu sehen welche Events was auslösen...

alpha1974

So, ich habe die Ursache wohl gefunden, nachdem ich alles aus Neugier nochmals nachgestellt habe: Ich habe das zweite MQTT-Device erstellt, indem ich das erste MQTT-Device einfach kopiert und dann die Attribute angepasst habe, also copy sonoffSP111_1 sonoffSP111_2 und anschließend für sonoffSP111_2 die SubscribeReading-Attribute manuell geändert.

Die SubcribeReading-Attribute von sonoffSP111_1 wurden dabei für das Device sonoffSP111_2 auch nach manueller Änderung beibehalten, allerdings nicht im WebIF angezeigt (wohl aber über den List-Befehl). Im Ergebnis gab es dann im kopierten Device doppelte subscribeReading-Attribute, wodurch das kopierte Device auch auf MQTT-Nachrichten des ersten Devices reagiert hat. Erst nach einem FHEM-Neustart waren die subscribeReadings so, wie auch im WebIF angezeigt, d.h. die "unsichtbaren" Attribute aus der Kopieraktion waren verschwunden.

Memo an mich selbst für diesen Fall: Wenn man MQTT-Devices per copy-Befehl erstellt, nicht nur die Subscribe-Attribute anpassen, sondern danach zusätzlich per list-Befehl kontrolieren, ob die Subscribe-Attribute stimmen. Falls nicht: FHEM neustarten.
FHEM/Z-Wave USB-Dongle + div. Devices