Credits werden durch häufige Zeitsynchronisierung sinnlos verbraucht

Begonnen von John, 16 Februar 2013, 09:56:43

Vorheriges Thema - Nächstes Thema

John

Nach einem mehrmaligen Neustart/reread tritt folgendes auf;


2013.02.16 09:39:01 3: CUL_MAX_BroadcastTime: payload 0d10092781
..
2013.02.16 09:41:40 3: CUL_MAX_SendQueueHandler: 5 items in queue
2013.02.16 09:41:40 3: CUL_MAX_SendQueueHandler: 4 items in queue
2013.02.16 09:41:40 2: CUL_MAX_SendQueueHandler: Not enough credit! credit10ms is 2, but we need 113. Waiting 111 seconds.


Sämtliche MAX-Komponenten (ausser Shutter-Contact) werden nach dem Neustart zeitlich synchronisiert.
Wenn man nun die cfg-Datei mehrmals ändert und testet, gehen die credits schnell in den Keller.

Das Problem wäre gelöst, wenn der Zeitstempel der Synchronisierung z.B. in den Readings der Max_Komponenten vermerkt wäre
und diese bei einem Neustart berücksichtigt werden würden.



CubieTruck Docker Node-Red Tasmota Shelly Homematic-IP

Matthias Gehre

Hab's etwas anders gelöst. Jetzt werden auch nicht mehr an alle Thermostate
auf einmal TimeInformation Nachrichten gesendet, sodass es kurzfristig zu
niedrigen Credits kommt.
Mit dem nächsten Update wird das Updaten der einzelnen Thermostate auf mehrere
Stunden verteilt, unabhängig von Neustarts.

traveltheworld

Hi,
der Thread ist zwar schon älter, aber ich glaube, mein Thema gehört hierzu:

ich beobachte seit längerer Zeit, dass immer wieder die Credits mit entsprechender Meldung im Log auslaufen, obwohl von fhem tagelang kein einziger Befehl versendet werden sollte, da die Heizungssteuerung durch die Wochenprogramme etc. eigenständig auch ohne Server läuft.

Daher habe ich das Logging am CUL_MAX aufgedreht und sehe, dass immer wieder offenbar Zeitinformationen versendet werden, die die Credits aufbrauchen und auch mehrmals täglich (etwa 3-4 mal) zu den "not enough credit" Meldungen führen.
In dem MAX-Setup sind 10 Thermostate+, 1 Thermostat(ohne plus) und ein Wandthermostat+ verbaut (sowie diverse Fensterkontakte).
Hier ein Auszug (nach CUL, Broadcast oder enough gegreppt) aus dem Log mit verbose 5 am CUL_MAX Gerät.

Zitat
2016.04.30 18:38:35 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:38:35 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:42 5: Broadcast time to 0ba63b
2016.04.30 18:42:42 5: CUL_MAX_Send: enqueuing 0fc504031011470ba63b00101e126a2a
2016.04.30 18:42:42 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:43 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:43 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:44 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:44 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:45 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:45 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:46 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:46 5: CUL_MAX_SendQueueHandler: Retry 0ba63b for 0fc504031011470ba63b00101e126a2a count: 3
2016.04.30 18:42:47 5: Broadcast time to 0ba63b
2016.04.30 18:42:47 5: CUL_MAX_Send: enqueuing 0fc604031011470ba63b00101e126a2f
2016.04.30 18:42:49 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:49 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:50 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:50 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:50 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:51 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:51 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:52 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:52 5: Broadcast time to 0ba63b
2016.04.30 18:42:52 5: CUL_MAX_Send: enqueuing 0fc704031011470ba63b00101e126a34
2016.04.30 18:42:52 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:53 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:53 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:54 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:54 5: CUL_MAX_SendQueueHandler: Retry 0ba63b for 0fc604031011470ba63b00101e126a32 count: 3
2016.04.30 18:42:57 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:57 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:58 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:58 5: CUL_MAX_SendQueueHandler: 2 items in queue
2016.04.30 18:42:58 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:42:58 2: CUL_MAX_SendQueueHandler: Not enough credit! credit10ms is 63, but we need 113. Waiting 50 seconds.
2016.04.30 18:43:48 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:43:49 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:43:49 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:43:50 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:53:59 5: Broadcast time to 0da724
2016.04.30 18:53:59 5: CUL_MAX_Send: enqueuing 0ff304031011470da72400101e12753b
2016.04.30 18:53:59 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:53:59 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:54:00 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:54:00 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:54:04 5: Broadcast time to 0da724
2016.04.30 18:54:04 5: CUL_MAX_Send: enqueuing 0ff404031011470da72400101e127604
2016.04.30 18:54:04 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:54:04 5: CUL_MAX_SendQueueHandler: 1 items in queue
2016.04.30 18:54:05 5: CUL_MAX_SendQueueHandler: 1 items in queue

Ist meine Vermutung korrekt?
Kann man da etwas ändern?

Danke!

traveltheworld

#3
Hi,

da das Thema nach wie vor relevant ist, habe ich noch etwas weiter analysiert:

Anzahl versendeter Nachrichten bisher im Mai (also Zeitraum von 2 Wochen):
Zitat
homeserver [~/fhem/log]# grep CUL_MAX_Send: fhem-2016-05.log | wc -l
4623

Davon Zeit-Updates:
Zitat
homeserver [~/fhem/log]# grep "Broadcast time to" fhem-2016-05.log | cut -d: -f4- | wc -l
4577

Interessant dabei ist die Verteilung auf die einzelnen Geräte:
Zitat
MAX_FlurUntenHeizung: 91
MAX_BadObenHeizung: 90
MAX_FuerthzimmerHeizung: 90
MAX_OsloZimmerHeizung: 90
MAX_BadUntenHeizung: 90
MAX_ArbeitszimmerHeizung: 90
MAX_EnkelzimmerHeizung: 91
MAX_SchlafzimmerHeizung: 90
MAX_WohnzimmerWandthermostat: 1706
MAX_WhzWintergartenHeizung: 1691
MAX_WhzEckHeizung: 1681
MAX_KuecheHeizung: 1678

Die Geräte, die weit über 1000 Zeitupdates bekommen haben, sind alle über den einen Wandthermostat gesteuert.

Update: ich habe diesselbe Analyse auf einem anderen System gemacht, dort schaut es ganz normal aus, auch beim Wandthermostat und an dessen angeschlossenen Geräte (WohnzimmerHeizung und FlurHeizung):
Zitat
MAX_FlurHeizung: 89
MAX_WohnzimmerHeizung: 90
MAX_BadHeizung: 89
MAX_SchlafzimmerHeizung: 89
MAX_Steckdose1: 89
MAX_WohnzimmerWandthermostat: 88

Irgendwer eine Idee?

traveltheworld

#4
Ich habe anhand der Logs herausgefunden, was passiert:
- 1x stündlich werden wie geplant jeweils 2 Thermostate aktualisiert -> OK
- weiterhin empfängt der FHEM Server jede Stunde zurselben Zeit 4x3 TimeInformation Requests von immer denselben Thermostaten (Wandthermostat + damit verbundene Geräte)

Zitat
2016.05.01 00:17:51 5: CUL_MAX_BroadcastTime: payload 1001005173
2016.05.01 00:17:51 5: Broadcast time to 0da763
2016.05.01 00:17:51 5: Broadcast time to 0da741
2016.05.01 00:36:16 5: Broadcast time to 0da763
2016.05.01 00:36:21 5: Broadcast time to 0da763
2016.05.01 00:36:26 5: Broadcast time to 0da763
2016.05.01 00:38:24 5: Broadcast time to 0da5f5
2016.05.01 00:38:29 5: Broadcast time to 0da5f5
2016.05.01 00:38:34 5: Broadcast time to 0da5f5
2016.05.01 00:42:42 5: Broadcast time to 0ba63b
2016.05.01 00:42:47 5: Broadcast time to 0ba63b
2016.05.01 00:42:52 5: Broadcast time to 0ba63b
2016.05.01 00:53:59 5: Broadcast time to 0da724
2016.05.01 00:54:04 5: Broadcast time to 0da724
2016.05.01 00:54:09 5: Broadcast time to 0da724
2016.05.01 01:17:51 5: CUL_MAX_BroadcastTime: payload 1001015173
2016.05.01 01:17:51 5: Broadcast time to 0da5f5
2016.05.01 01:17:51 5: Broadcast time to 0c89a4
2016.05.01 01:36:16 5: Broadcast time to 0da763
2016.05.01 01:36:21 5: Broadcast time to 0da763
2016.05.01 01:36:26 5: Broadcast time to 0da763
2016.05.01 01:38:24 5: Broadcast time to 0da5f5
2016.05.01 01:38:29 5: Broadcast time to 0da5f5
2016.05.01 01:38:34 5: Broadcast time to 0da5f5
2016.05.01 01:42:42 5: Broadcast time to 0ba63b
2016.05.01 01:42:47 5: Broadcast time to 0ba63b
2016.05.01 01:42:52 5: Broadcast time to 0ba63b
2016.05.01 01:53:59 5: Broadcast time to 0da724
2016.05.01 01:54:04 5: Broadcast time to 0da724
2016.05.01 01:54:09 5: Broadcast time to 0da724
2016.05.01 02:17:51 5: CUL_MAX_BroadcastTime: payload 1001025173
2016.05.01 02:17:51 5: Broadcast time to 0da725
2016.05.01 02:17:51 5: Broadcast time to 0ba63b
2016.05.01 02:36:16 5: Broadcast time to 0da763
2016.05.01 02:36:21 5: Broadcast time to 0da763
2016.05.01 02:36:26 5: Broadcast time to 0da763
2016.05.01 02:38:24 5: Broadcast time to 0da5f5
2016.05.01 02:38:29 5: Broadcast time to 0da5f5
2016.05.01 02:38:34 5: Broadcast time to 0da5f5
2016.05.01 02:42:42 5: Broadcast time to 0ba63b
2016.05.01 02:42:47 5: Broadcast time to 0ba63b
2016.05.01 02:42:52 5: Broadcast time to 0ba63b
2016.05.01 02:53:59 5: Broadcast time to 0da724
2016.05.01 02:54:04 5: Broadcast time to 0da724
2016.05.01 02:54:09 5: Broadcast time to 0da724

Ich habe als Workaround nun einfach den Zeit-Update durch Request in der 14_CUL_MAX.pm deaktiviert (Zeile 324 auskommentiert).

Mir ist keine Konfiguration am (Wand)thermostat zur Anforderung von Zeitupdates bekannt. Hat hier jemand evtl. eine Ahnung?
Bei dem anderen FHEM-System habe ich dieses Verhalten nicht..


(P.S.: der MAX Code ist gut lesbar geschrieben und dokumentiert, man findet sich sehr schnell zurecht.)

Reinerlein

Hallo,

ich muss das Thema mal hochholen, da es bei mir für eine Totalauslastung meiner Credits sorgt.

Ich habe 9 Wandthermostate und 10 Heizungsstellwerke dazu.
Ich habe grundsätzlich keine Credits übrig, um selber etwas steuern zu können. Nur wenn ich den CUL resette, und Fhem wegen Leerung der SendQueue neugestartet habe, kann ich eine kurze Weile etwas tun...

Nach einer Logaufbohrung (mit Devicenamen) habe ich festgestellt, dass bei den Komponenten immer dreimal hintereinander eine TimeInformation gesendet wird, obwohl die Komponenten z.B. teilweise nur wenige Meter vom CUL entfernt sind. Das müssten dann doch eigentlich Missing Acks sein, oder? Dabon habe ich relativ wenige...
Was kann das sein?

Hier mal ein Log-Auszug über 2 Stunden:

2017.12.21 14:35:21 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 14:35:15 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 14:35:10 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 14:34:32 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 14:34:27 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 14:34:24 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 14:34:21 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 14:34:19 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 14:34:16 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 14:33:14 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 14:33:10 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 14:33:04 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 14:30:16 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 14:30:11 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 14:30:06 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 14:29:34 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 14:29:16 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 14:29:11 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 14:21:02 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 14:21:02 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 14:21:02 1: Broadcast time to 06c1b7 (heizung_Arbeitszimmer)
2017.12.21 14:15:56 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 14:15:54 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 14:15:46 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 13:58:39 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 13:58:31 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 13:58:26 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 13:35:20 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 13:35:16 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 13:35:16 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 13:34:29 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 13:34:27 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 13:34:27 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 13:34:26 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 13:34:17 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 13:33:14 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 13:33:09 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 13:33:04 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 13:30:16 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 13:30:11 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 13:30:06 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 13:29:26 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 13:29:26 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 13:29:11 1: Broadcast time to 07878e (heizung_Wohnzimmer_WT)
2017.12.21 13:21:30 2: CUL_MAX_SendQueueHandler: Missing ack from 11b7f8 for 0f9c040324651311b7f80011150dd51b
2017.12.21 13:21:02 1: Broadcast time to 071c07 (heizung_Gaestezimmer)
2017.12.21 13:21:02 1: Broadcast time to 11b7f8 (heizung_BadFussboden)
2017.12.21 13:21:02 1: Broadcast time to 0db02f (heizung_Jim_WT)
2017.12.21 13:21:02 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 13:15:56 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 13:15:55 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 13:15:46 1: Broadcast time to 090d6f (heizung_Schlafzimmer_WT)
2017.12.21 12:58:36 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 12:58:31 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 12:58:26 1: Broadcast time to 11ee77 (heizung_Flur_WT)
2017.12.21 12:35:20 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 12:35:15 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 12:35:13 1: Broadcast time to 0a0033 (heizung_Arbeitszimmer_WT)
2017.12.21 12:34:29 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 12:34:29 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 12:34:29 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 12:34:22 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 12:34:19 1: Broadcast time to 090e26 (heizung_GaesteWC_WT)
2017.12.21 12:34:16 1: Broadcast time to 0db787 (heizung_Gaestezimmer_WT)
2017.12.21 12:33:18 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 12:33:18 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 12:33:10 1: Broadcast time to 070c25 (heizung_Joe_WT)
2017.12.21 12:30:23 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 12:30:11 1: Broadcast time to 0dba79 (heizung_Bad_WT)
2017.12.21 12:30:06 1: Broadcast time to 0dba79 (heizung_Bad_WT)


Des Weiteren wäre es wohl eine gute Idee, wenn eine TimeInformation-Sendung nur dann in die SendQueue gelegt wird, wenn nicht schon eine für das Gerät drinliegt.
Momentan schaukelt sich das ungebremst auf, wenn es einmal den Blockadepunkt erreicht hat, und rettet sich niemals mehr.

Vielleicht hat ja jemand eine Idee wegen der Sendewiederholungen...

Grüße
Reinerlein

traveltheworld

Hi,

endlich mal jemand, der das gleiche Problem teilt.. ich hätte zur Vergleichbarkeit ein paar Fragen:

- bei mir war es so, dass ich zuerst auch einen Fehler im MAX Code gesucht hatte, aber dann über das aufgedrehte Logging festgestellt habe, dass die Geräte tatsächlich so oft Time-Update-Requests schicken. Kannst du das bei dir auch verifizieren?
Wenn ich im Code das Beantworten dieser Requests abschalte (dann gibt's auch keine Time-Broadcasts mehr), sieht man aber an den Thermostaten, wie dort das Funksymbol ständig blinkt, weil sie eine Antwort erwarten, aber keine bekommen.

- Seltsamerweise geschieht obiges Verhalten nur bei Geräten, die mit dem Wandthermostat verknüpft sind. Alle anderen senden nicht ständig diese Time-Update-Requests. Wie ist das bei dir?


Bei ELV hatte ich übrigens mal vor über einem Jahr eine Anfrage gestellt zur Firmware bzgl. Time-Update-Requests, aber außer ein "bitte warten, bis das ticket bearbeitet wird" ist da nie trotz Nachfrage irgendein Feedback zurückgekommen.

Reinerlein

Hi traveltheworld,

das mit den Requests kann ich mal testweise einbauen...

Meine Thermostate sind natürlich alle gekoppelt, da die eigentliche Steuerung Max-Autark laufen soll, sodass ich keine Geräte ohne Kopplung habe...

Hmm... wenn das so ist, wie kann man das denn in den Griff bekommen? Keine Antwort auf einen Geräte-Request zu senden ist ja irgendwie auch keine dauerhafte Lösung...

Grüße
Reiner

Reinerlein

Hi,

nochmal ein Nachtrag:
kann es sein, dass diese Zeitanfrage an jeden gekoppelten Peer gesendet wird?

Dann müsste man doch in dem Paket erkennen, wer diese Anfrage eigentlich beantworten sollte, und das CUL-Modul dürfte nur Anfragen beantworten, die auch an die Zentrale gesendet wurde...

Alternativ könnte das Modul ja wiederholte Anfragen (die unterhalb einer Stunde reinkommen) einfach ignorieren?
Dann wird wenigstens nur eins gesendet (und nicht drei innerhalb von ein paar Sekunden).

Grüße
Reiner

Reinerlein

Hi,

sooo, habe ein bißchen mehr geloggt. Wo genau steht eigentlich, dass der MessageType "TimeInformation" eine Anforderung für eine TimeInformation ist?
Könnte dort als Antwort nicht auch ein einfacher Ack reichen?

Ich habe mir zu den Paketen, die an die Zentrale adressiert werden (werden tatsächlich alle drei, also ist meine andere Theorie hinfällig :) ), mal den Payload ausgeben lassen. Der ist dann immer ein Zeitstempel, der sehr gut zur Sendezeit passt.
Kann es sein, dass der Original-Cube die Aufgabe hat, diesen Stempel zu prüfen, und bei größerer Abweichung (ein paar Sekunden Unterschied sind das bei mir sowieso immer) ein eigenes TimeInformation-Paket zurückzusenden, und sonst ein einfaches Ack?

Ich werde das mal probieren...

Grüße
Reiner

Reinerlein

Hi,

soo, habe gerade mal versucht mit einem Ack zu antworten. Leider kapier ich nicht so richtig, was ich senden muß.
Ich habe mal einfach ein

CUL_MAX_Send($shash, "Ack", $src, $payload, '00');

gesendet. Wobei ich auch nicht weiß, was ich in payload reinschreiben muss...

Da kommt dann aber im Log kurze Zeit später eine Missing-Ack Meldung dieser Devices im Log. Allerdings blinkt das Symbol am Wandthermostat nicht mehr (aber trotzdem kommen die Anfragen dreimal).
Es scheint also prinzipiell etwas zu klappen, nur muss man dem Modul beim Senden wohl irgendwie mitteilen, dass auf diesen Ack kein Ack mehr erwartet wird, und vermutlich einen korrekten Payload mitsenden :)
Das habe ich aber nicht herausgefunden. Vielleicht kann Matthias dazu ja eine Hilfestellung geben?

Grüße
Reiner

LuBeDa

Hallo zusammen,
ich habe auch ein Problem mit den Credits. Bin mir aber nicht sicher ob ich auf unter dem "TimeInformation" Thema leide.

Habe mal versuchsweise folgenden Code in die 14_CUL_MAX.pm in der Funktion CUL_MAX_Send(@) ca. Zeile 402 eingefügt.

  if ($cmd eq "TimeInformation ")
  {
      my ($credit10ms) = (CommandGet("","$hash->{IODev}{NAME} credit10ms") =~ /[^ ]* [^ ]* => (.*)/);
      if ($credit10ms <  450) {
        Log3 $hash, 5, "Dropped CUL_MAX_Send : $cmd => $dst = $payload";
        return undef;
      }
  }


Morgen kann ich vergleichen ob dieses Verwerfen der TimeInformation etwas geholfen hat.

Ludger

traveltheworld

@LuBeDa:
schau doch erstmal, ob bei dir überhaupt so viele TimeInformation Nachrichten versendet werden, indem du am CUL_MAX Gerät das Logging auf 5 stellst.
Falls ja, solltest du entsprechende Broadcast time Einträge im Log sehen (siehe vorhergehende Posts).

@Reiner: kann es sein, dass der MAX Cube nicht der privaten 1%-Regelung unterliegt, und ihm somit dieses Verhalten (Bug?) egal ist?

Reinerlein

Hi traveltheworld,

dann wäre dieser aber vermutlich sehr weit über dem zulässigen Wert.
Ich habe mal testweise die culfw angepasst, und den Grenzwert für credit10ms auf 9000 hochgestellt (also das zehnfache). Damit beginnt der Kreditwert bei 4500 und kann sich bis 9000 hocharbeiten.

Nach spätestens 6-8 Stunden wird meine Warteschlange wieder langsam befüllt, weil die Credits abgelaufen sind... Das bedeutet, das der Wert immer noch zu gering für meine 19 TimeInformation-Geräte ist...
Eine dreier-Sende-Session (diese drei Geräte-Broadcasts pro Stunde) verbraucht direkt mal 600-900 Einheiten. Das bedeutet, dass alleine diese stündlichen Broadcasts alle Credits aufbrauchen würden...

Ich vermute, dass wir mit einer Überprüfung der Zeitabweichung, und bei einer zu geringen Abweichung mit einem einfachen ACK zu antworten, besser hinkommen würden... wenn das überhaupt so gehen sollte :)
Und vielleicht könnte man diese Broadcasts auf einmal täglich verlagern...?

Grüße
Reiner

LuBeDa

Bei mir war es ein MAX-Tür/Fensterkontakt der immer beim öffnen bzw. schließen zu den Problemen führte.

Jetzt habe ich ihn mal wieder neu gepairt und momentan läuft es.

Fraglich nur wie lange.....

traveltheworld

@Reiner:

bzgl. der Broadcasts und deren Verteilung über den Tag: die "Broadcast time to .." Nachricht kommt bei zwei verschiedenen Ereignissen:

a) stündlicher Broadcast: wenn das MAX-Modul in FHEM entscheidet, dass die TimeInformation an Thermostate verteilt werden sollen. Das macht das Modul eh schon per modulo. So wie ich es im Code sehe, fix kodiert auf 6 Stunden verteilt. D.h. jedes Thermostat bekommt 4x täglich die aktuelle Zeit.

b) bei expliziter Anfrage (was unser Problem hier ist): bei mir kommen von 11 Thermostaten die Anfragen von genau denen, die mit dem Wandthermostat verbunden sind (plus dem Wandthermostat selbst). Bei mir ist es auch so, dass die Anfragen mehrfach stündlich kommen, und dann jedesmal exakt dreimal mit exakt 5s Abstand voneinander.
Seltsam ist, dass in einem zweiten MAX-Setup von mir dieses Verhalten nicht zu beobachten ist. Einzigen Unterschied, den ich sehe, ist, dass in dem fehlerfreien Setup keine Thermostat+, sondern die älteren Thermostate verbaut sind. Keine Ahnung, ob das einen Unterschied macht.

Eine Frage an dich: inwiefern hilft es, nur einen ACK zu senden? Zählt dieser nicht zur 1%-Regelung, oder ist einfach die Anzahl der notwendigen Credits für diesen viel geringer?

Noch eine Frage/Idee zur Diskussion: würde es evtl. helfen, die Zeitrequests erstmal zu puffern und nur zu beantworten, wenn innerhalb von z.B. 1min kein weiterer identischer Request kommt?

Reinerlein

Hi traveltheworld,

das mit dem Ack ist nur eine Idee, und der Gedanke dahinter ist tatsächlich der, dass dafür hoffentlich weniger Credits verbraucht werden würden :)
Des Weiteren: Brauchen die Geräte wirklich viermal am Tag eine Zeitsynchronisation? Laufen die wirklich so schnell signifikant auseinander?
Sonst würde doch einmal täglich reichen. Wie geschrieben, verbrauchen die drei (bzw. einmal vier) Geräte, die da jede Stunde versorgt werden, zwischen 600 und 900 Credits. Die müssen ja auch erstmal mühsam wieder angespart werden...

Bei mir sind in jedem Raum Wandthermostate (9 Stk.) und Heizungssteller (10 Stk.), die natürlich jeweils miteinander gepeert sind. In einem Raum befinden sich dann zwei Steller...

Das mit dem Puffern der Zeitrequests würde sich mit meiner Idee erledigen, bei der man nur dann mit einer TimeInformation antwortet, wenn die übertragene Zeit nicht korrekt ist (sagen wir mal: mehr als zwei/drei Sekunden Abstand hat).
Bei deiner Variante hat man auch erstmal das Problem, dass die Geräte eine Antwort erwarten, und die Funkanzeige vor sich hin blinkt... Das wollte ich mit der Idee des ACKs in den Griff bekommen...

Grüße
Reiner

Reinerlein

Hallo zusammen,

kann mir denn jemand helfen, wie ich ein passendes Ack-Paket für die TimeInformation erzeuge?
Ich bekomme das nicht irgendwie hin.

Danke schon mal...

Grüße
Reiner

traveltheworld

Hi Reiner,

bist du sicher, dass ein ACK helfen wird?
Wenn ich mir die eingehenden ACKs zu verschiedenen Befehlen anschaue, sind die eigentlich immer 14 Bytes lang, manchmal 11 Bytes.
Die Timeinformation Messagelänge ist 15 Bytes..

evtl. schau ich auch nicht richtig zu später Stunde..?

Reinerlein

Hi traveltheworld.

hmm, das wäre ja blöd... Dann hilft ja doch nur unterdrücken (bei nahezu korrekter Zeit), und diesen stündlichen, unaufgeforderten Versand weiter ausdünnen.
Und natürlich damit leben, dass die Teile eine Weile blinken. Die hören ja anscheinend irgendwann auf, ich habe nur noch nicht beobachtet wann...

OK, ich schaue mal, was sich machen läßt...

Grüße
Reiner

traveltheworld

Nun, allein der Header hat schon 10 Bytes, plus dann halt noch die payload mit den eigentlichen Daten.

http://culfw.de/commandref.html#cmd_Z
ZitatSend out an MORITZ message. <hex> is a hex string of the following form: llnnccttssssssddddddpp...
ll - length
nn - msg counter
cc - control byte
tt - msg type
ss - sender address (3byte)
dd - destination address (3byte - 000000 for broadcast)
pp - payload...

traveltheworld

Hat sich bei dir inzwischen etwas ergeben?

ich habe noch etwas getestet: ich habe zwei MAX-Setups, völlig unabhängig voneinander. Bei dem einen habe ich massiv das hier thematisierte Problem, in dem anderen gar nicht.
Dort, wo ich das Problem nicht habe, hatte ich erst nur die HT im Einsatz (kein HT+), jetzt habe ich allerdings einen defekten HT durch einen HT+ ausgetauscht, und zack, nach wie vor kein Problem. Daran kann es also nicht liegen.

Vermutung: kann es evtl. daran liegen, wie die Geräte miteinander gepairt / associated sind?
In der fehlerfreien Installation schaut es wie folgt aus:
- WTs und HTs sind alle direkt mit FHEM gepaired
- WTs und HTs sind beidseitig associated
- HTs und FKs sind einseitig associated (HT associate FK, d.h. HT empfängt Befehle von FK)

In der Installation mit dem seltsamen TimeInformation Verhalten hätte ich gedacht, habe ich das genauso aufgesetzt, bin mir aber nicht mehr sicher.
Wie hast du das aufgesetzt?

Reinerlein

#22
Hi,

also ich habe alle Geräte miteinander assoziiert.
HT <-> WT
FK <-> HT
FK <-> WT
jeweils in die eine und die andere Richtung.

Das soll auch laut Beschreibung so, da sonst nicht auf die jeweilige Antworten (ACKs) gewartet wird (und sonst auch keine Wiederholungssendung durchgeführt wird).
Nur Fhem ist nur mitlauscher :)

Im Anhang mal meine CUL_MAX. Bei mir läuft das stabil. Ich habe keine nennenswerten Verluste an Credits mehr, und die Geräte blinken auch nicht wild rum...

Ich habe dort:
- Die Push-Aktualisierung der Zeit auf 10 Slots erweitert (bei mir also nur noch 2 Geräte pro Slot)
- Wenn eine Uhrzeit-Anforderung kommt, wird der mitgelieferte Zeitstempel auf eine Abweichung größer 10 Sekunden geprüft, und nur dann beantwortet
- Das Logging dazu entsprechend erweitert (Ausgabe erfolgt auf Verbose-Level 1)
- Im Log sieht man auch, dass die Geräte untereinander Zeitinformationen austauschen (auch auf Level 1)

Einmalig sollte man die Slot-Informationen in den Devices zurücksetzen, damit sie einen neuen zugeordnet bekommen. Sonst hast du zwar 10 Slots, aber es werden nur die alten 6 verwendet. Das sollte man auch machen, wenn man seine Installation nachträglich signifikant erweitert:

deletereading TYPE=MAX:FILTER=r:TimeInformationHour=.* TimeInformationHour
Das löscht in allen Max-Geräten, die dieses Reading gesetzt haben, ebendieses Reading weg...

Grüße
Reinerlein

traveltheworld

Hallo Reinerlein,

Danke für die schnelle Antwort.
Deine Modifikation werde ich möglichst bald austesten und Dir dann auch Feedback geben.
Verstehe ich richtig, dass du im Falle von einer Zeitabweichung <=10s ein ACK schickst, ansonsten die gewünschte Zeitinformation (auch wenn beide Nachrichten ca. gleich lang sind), und das den wesentlichen Unterschied in der Kommunikation macht?

In der fehlerfreien Installation sehe ich auch, dass die Geräte untereinander die Informationen austauschen (vom WT zum HT), allerdings auf Debug Level 5 :)

Der Punkt mit dem ACK an den FK ist valide, denn es kommt tatsächlich manchmal (wenn auch sehr selten) vor, dass ein Öffnen/Schließen nicht erkannt wird.

LG

Reinerlein

Hi,

ich sende keine ACKs, da wir ja festgestellt haben, dass die genauso groß sind :)
Ich ignoriere einfach die Anfrage, wenn die Zeitabweichung geringer als 10s ist.

Das mit dem Debug-Level habe ich absichtlich gemacht, damit ich nicht alle 5er Infos sehen muss, ich es aber immer noch abschalten kann...

Grüße
Reinerlein

traveltheworld

Guten Morgen,

okay, d.h. wir sind nach wie vor bei der Symptombekämpfung..
Wie oft beantwortest du nun tatsächlich einen Zeitupdate-Request? D.h. wie oft kommt es vor, dass die Zeit >10s abweicht? Driften die Zeiten in den Thermostaten so schnell ab?
Genau das (nur ohne die 10s-Abweichung-Bedingung) hatte ich auch schon getestet, aber ich wundere mich nun, wieso bei dir die Funksymbole nicht blinken ohne Antwort..

LG

traveltheworld

die modifizierte CUL_MAX ist leer.. da ist wohl was schiefgegangen.

Reinerlein

Hi,

ich habe die Datei mal neu angehangen...

Eine Aktualisierung kommt vor, teilweise auch zweimal hintereinander, aber nicht so oft, das es meine Credits kaputt macht... Komisch ist das aber schon, die Mikroprozessoren scheinen teilweise eine echt signifikante Abweichung zu besitzen...

Die blinken sicherlich mal kurz, aber nicht ständig... auf jeden Fall ist irgendwann alles wieder normal...

Es wäre ja auch interessant zu wissen, ob man diese Zeitinformation nicht auch einfach als Broadcast an alle gleichzeitig senden kann. Das müsste ja nicht unbedingt als Unicast über die (Broadcast-)Funkschnittstelle laufen.
Wenn ich mir das Protokoll hätte ausdenken müssen, hätte ich sowas auf jeden Fall eingebaut :)
Ich kann ja mal versuchen, was passiert, wenn man das einfach an alle sendet...

Grüße
Reinerlein

Edi77

Master FHEM 6 als VM auf ESX Ubuntu 20.04 LTS mit MAXCube/MAX!/FS20|TabletUI|Flightradar|Tasmota|TTN Lora|CCU3 HomematicIP|RPi mit GammaScout|MQTT EasyESP 8266|LuftdatenInfo|deCONZ HUEDev|probemon|Siemens Logo|P4D|3D PRINTER RAISE3D

Reinerlein

Hi Edi77,

du kannst einfach mal die Moduldatei von mir ausprobieren. Die zentrale Änderung sind zusätzliche Logausgaben auf Level 1 und die Verhinderung von Timeinformations-Antworten bei einer Abweichung kleiner 10 Sekunden...
Außerdem werden die regelmäßigen Zeitaktualisierungen auf 10 Slots verteilt (dazu nicht vergessen das Reading "TimeInformationHour" zu löschen).

Das macht also nix kaputt. Wenn es hilft, dann sollten wir das mal Richtung offizielles Release bringen. Vielleicht konfigurierbar...

Grüße
Reinerlein

P.S.: Als Crack würde ich mich aber bei weitem nicht bezeichnen wollen :)

LuBeDa

Hallo,

falls die 14_CUL_MAX.pm aus dem Repository angepasst wird wäre es schon wenn:
readingsBulkUpdate($hash, "Serial", $serial);
in Zeile 342 eingefügt wird.

Dadurch wird beim pairen die Seriennummer des MAX-Gerätes als Reading angelegt.

Finde ich sehr hilfreich.


traveltheworld

#31
die Idee mit der Seriennummer finde ich gut (auch wenn off-topic hier).

Bzgl. der von Reinerlein modifizierten CUL_MAX Datei:
- die Erweiterung von 6 auf 10 Slots für die proaktiven Time-Updates: finde ich gut, würde ich direkt übernehmen. Evtl. noch abwarten, was sein Test bzgl. des allgemeinen Time-Broadcasts ergibt. Dann bräuchte man den ganzen Kram gar nicht mehr, wenn das funktioniert
- das Ignorieren von Time-Update-Requests, wenn sie <10s abweichen: behebt mit Nebenwirkung (die Funksymbole blinken an den Thermostaten, weil keine Antwort kommt) ein Symptom, aber nicht die Ursache. In der Installation, in welcher bei mir dieses Problem nicht auftritt, habe ich diesen Code auch nicht aktiviert, in der anderen mit dem Problem schon (besser die Symbole blinken, als dass alle credits für time-update-request-Antworten verbraucht werden)

traveltheworld

#32
@Reinerlein: die Ursache für die ständigen TimeInformation Requests konnte ich beheben, indem ich einen Werksreset am Wandthermostat durchgeführt habe (Batterien raus, 1min warten, untere drei Tasten gleichzeitig drücken beim Einschalten, es wird "res" angezeigt), anschließend den WT mit dem CUL neu gepaired und die associations zu den Thermostaten und FK wiederhergestellt habe.

Interessanterweise mußte ich an den Thermostaten auch das associate zum WT neu ausführen, sonst haben diese keinen ACK an den WT zurückgeschickt (eigentlich ist dieses associate doch noch drin gewesen..?)

Seit drei Stunden sehe ich nun nur noch die stündlichen Broadcasts, aber keinen einzigen TimeInformationRequest von den Thermostaten mehr.
Mal weiter beobachten.

Update: nach einem Tag weiterhin erfolgreich, d.h. kein einziger TimeInformationRequest von keinem der Thermostate, die mit dem (werksresetteten) Wandthermostat verbunden sind.
Die Credits sind, so wie es sein soll, immer voll (außer kurz beim stündlichen Time-Broadcast an das/die jeweils nächste(n) Device(s)).

Mir ist zwar schleierhaft, wie technisch gesehen der Werksreset des WT das Verhalten der (mit ihm verbundenen) HT beeinflußt, aber es hat geholfen.