ESP RGBWW Wifi Led Controller - fhem - Modul

[pjakobs]

ok, @herrmanj, mir wird langsam klar, was da passiert, aber noch nicht warum.

mein test-Statement:

Code Auswählen Erweitern


set LED_Sc off;
set LED_Sc hsv 240,50,0 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;
set LED_Sc val 100 1 q;set LED_Sc val 0 1 q;


im Anhang Log und Packet Trace, beide am gleichen Host gezogen, die Zeiten sind also vergleichbar.

Was auffällt:

• die Abarbeitung der Befehlsliste beginnt im Log um 10:15:42.224
• der erste API Call wird um 14:15:42.234 abgeschickt (will sagen: es wird HttpUtils_NonblockingGet aufgerufen)
• die erste Response message taucht im Log um 10:15:48.264 auf

gleichzeitig sehe ich im Packet Trace

• der erste Request erscheint um 10:15:48.238 (sprich: in diesem Moment wird er vom fhem Server über das Interface übertragen)
• die Antwort darauf kommt um 10:15:48.263
• der nächste Request kommt um 10:15:48.386

es ist also imho offensichtlich, dass, warum auch immer,

Code Auswählen Erweitern


HttpUtils_NonblockingGet($param);

die Requests erst vier Sekunden später versendet, also nachdem die Queue völlig übermittelt wurde.
Bei diesem Test stand übrigens davor noch ein

Code Auswählen Erweitern


usleep(2000);
um ggf. dem Stack ein bisschen Zeit zu geben.
Seltsam...

pj

[herrmannj]

Ich bin da noch nicht so ganz überzeugt.

Unser logging ist auch sch....e, da müssen wir was tun.

der erste API Call wird um 14:15:42.234 abgeschickt (will sagen: es wird HttpUtils_NonblockingGet aufgerufen)

Yepp, sehe ich auch so.

der erste Request erscheint um 10:15:48.238

yepp, gehe mit.

(sprich: in diesem Moment wird er vom fhem Server über das Interface übertragen)

Das muss nicht so sein.

Weil der controller die Verbindung nach jedem req beendet ist der erste Schritt von HttpUtils_NonblockingGet ein connect (non-blocking). Wenn der connect 6 Sekunden benötigt bekommst Du genau dieses Bild. (Achtung: Arbeitshypothese!).

Ich habe da tatsächlich auch das "Problem" das der erste connect einige Sekunden braucht. Ich denke aber ich habe doof gelötet oder so.
Was passiert denn wenn Du das noch, sagen wir 10 Sekunden, nochmal machst. Gleiches timing ?

btw, ich würde beim ersten "off" das "q" rausnehmen.

vg
joerg

[pjakobs]

upps... jetzt hatte ich den Beitrag doch glatt erstmal neu geschrieben, weil ich mir das Verschwinden nicht erklären konnte, aber - ist besser hier!

Wenn Du in den Trace schaust (wireshark) dann siehst Du auch den zugehörigen tcp Verbindungsaufbau, der beginnt sofort:

10:15:42.239181 fhem->controller [syn]
10:15:42.246483 controller->fhem [syn, ack]
10:15:42.245545 fhem->controller [ack]

damit steht die tcp Session, danach dauert es ziemlich genau sechs Sekunden bis der POST request kommt.

10:15:48.238021 fhem->controller POST

Grüße

pj

[herrmannj]

hmm. Mysteriös.

Wenn der connect sofort kommt stimmt der AUfruf seitens des moduls.
Stell mal bitte den globalen loglevel auf 5 und schreibt in den (alle) param hash zusätzlich "loglevel    => 5,", dann schriebt httputils auch was ins log.

vg
joerg

upps... jetzt hatte ich den Beitrag doch glatt erstmal neu geschrieben, weil ich mir das Verschwinden nicht erklären konnte, aber - ist besser hier!

sorry. Ja , musste getrennt werden sonst werden wir ja verrückt

[pjakobs]

hmm. Mysteriös.

Wenn der connect sofort kommt stimmt der AUfruf seitens des moduls.
Stell mal bitte den globalen loglevel auf 5 und schreibt in den (alle) param hash zusätzlich "loglevel    => 5,", dann schriebt httputils auch was ins log.

mach ich gleich mal

vg
joerg
sorry. Ja , musste getrennt werden sonst werden wir ja verrückt

vor allem verwässern wir Patricks nächste Sammelbestellung, das ist so schon besser. Danke

pj

[mrpj]

Wenn ich euch noch irgendwie unterstützen kann, dann sagt Bescheid. Ich werde immer mal wieder in den Thread gucken, falls ich etwas nicht sofort sehe oder ihr Feedback braucht, am besten per PN/Mail bescheid geben, dann geht es nicht verloren

[herrmannj]

Das ist super, Danke! "solid" hätte imho Prio, der endpoint mit den Infos über die queue Prio 2.

vg
joerg

[pjakobs]

leider gibt mir HttpUtils nicht so schrecklich viel Log Info raus:

Aufruf:

Code Auswählen Erweitern


2016.06.28 13:12:02.637 5: LED_Sc send API Call $VAR1 = {
   'callback' => sub { "DUMMY" },
   'data' => '{"hsv":{"v":"0","ct":"2700","h":"120","s":"40"},"q":"false","t":"0","cmd":"solid","d":"1"}',
   'hash' => {
     '.triggerUsed' => 0,
     'CFGFN' => '/opt/fhem/conf.d/MiLight.cfg',
     'CL' => {
       'Authenticated' => 0,
       'BUF' => '',
       'CD' => bless( \*Symbol::GEN227, 'IO::Socket::INET' ),
       'FD' => 24,
       'FW_ID' => '1581',
       'LASTACCESS' => 1467112322,
       'NAME' => 'WEB_192.168.29.43_58505',
       'NR' => 373,
       'PEER' => '192.168.29.43',
       'PORT' => 58505,
       'SNAME' => 'WEB',
       'SSL' => undef,
       'STATE' => 'Connected',
       'TEMPORARY' => 1,
       'TYPE' => 'FHEMWEB',
       'canAsyncOutput' => 1
     },
     'DEF' => '192.168.29.58',
     'DEVICEID' => '14063373',
     'FIRMWARE' => '0.3.0',
     'Helper' => {
       'DBLOG' => {
         'ct' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '2700'
           }
         },
         'hsv' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '120,40,0'
           }
         },
         'hue' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '120'
           }
         },
         'rgb' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '000000'
           }
         },
         'sat' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '40'
           }
         },
         'state' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => 'off'
           }
         },
         'val' => {
           'logdb' => {
             'TIME' => '1467112227.75171',
             'VALUE' => '0'
           }
         }
       }
     },
     'IP' => '192.168.29.58',
     'MAC' => '18fe34d6970d',
     'NAME' => 'LED_Sc',
     'NR' => 129,
     'NTFY_ORDER' => '50-LED_Sc',
     'READINGS' => {
       'ct' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => '2700'
       },
       'hsv' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => '120,40,0'
       },
       'hue' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => '120'
       },
       'rgb' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => '000000'
       },
       'sat' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => '40'
       },
       'state' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => 'off'
       },
       'val' => {
         'TIME' => '2016-06-28 13:10:27',
         'VAL' => 0
       }
     },
     'STATE' => 'off',
     'TYPE' => 'LedController',
     'helper' => {
       'cmdQueue' => [],
       'isBusy' => 1
     }
   },
   'header' => 'User-Agent: fhem^M
Accept: application/json',
   'loglevel' => 5,
   'method' => 'POST',
   'parser' => sub { "DUMMY" },
   'timeout' => 30,
   'url' => 'http://192.168.29.58/color?mode=HSV'
};


HttpUtils log Output:

Code Auswählen Erweitern


2016.06.28 13:12:02.640 5: HttpUtils url=http://192.168.29.58/color?mode=HSV

und dann

Code Auswählen Erweitern


2016.06.28 13:12:09.078 5: HttpUtils http://192.168.29.58/color?mode=HSV: Got data, length: 16
2016.06.28 13:12:09.079 4: LED_Sc: got HSV color response


- das natürlich für jedes Setting.

Ich habe den Verdacht, dass zumindest Teile des Systems hier single threaded sind.

PERL-Ausdrücke und FHEM-Kommandos werden im Haupt-"thread" ausgeführt

damit blockieren wir den Haupt Thread so lange, bis das gesamte Kommando ausgeführt ist.
hierzu passend auch dies

FHEM führt Module normalerweise nicht parallel aus. Daher wäre es ungünstig wenn Module Werte von einem Gerät abfragen und dann auf die Antwort des Geräts warten. In dieser Zeit wäre der Rest von FHEM blockiert. Die Ein- und Ausgabe sollte ohne Blockieren erfolgen und die Verarbeitung mehrerer Ein- und Ausgabekanäle quasi parallel ermöglichen.

dies scheint aber für fhem Kommandos nicht zu gelten.

Ich meine: so lange wir die Kommandozeile auswerten bleibt der fhem Hauptthread im LedController Modul, zwischenzeitlich werden die http calls innerhalb von HttpUtils oder LWP gequeued und erst, wenn wir den Hauptthread freigeben, weil das Kommando abgearbeitet ist geht's weiter.

Ich beginne zu glauben, dass das ein Verhalten ist, dass wir nicht ändern können.

pj

PS: ich konnte keinen Weg finden, dem fhem-Hauptthread kurzfristig die Kontrolle zurückzugeben (also sowas wie ein "sleep" in kooperativen Multitasking Systemen oder ein "relinquish control" damals bei NetWare (ok, jetzt wisst Ihr wie alt ich bin ) ) - ich sage wir akzeptieren das einfach.
In der Doku sollten wir dann kurz was dazu schreiben, à la "wenn die Beleuchtung direkt auf ein Ereignis reagieren soll, dann ist es ggf. sinnvoll die set Befehle für die animation einzeln abzusetzen
Dieses Problem spricht sehr für Patricks Idee vom "Animationset", denn das könnte man ggf. mit einem einzigen Call übertragen und dann ausführen.

[mrpj]

Für die Zukunft gibt es ja noch weitere Lösungsmöglichkeiten: MQTT und Websockets  - braucht zwar noch etwas Zeit bis das ganze umgesetzt werden kann, eine einfache Testversion für z.B. MQTT oder Websockets lässt sich die Woche sicher zusammenschustern bevor die komplette Implementierung angepasst wird

Das ist super, Danke! "solid" hätte imho Prio, der endpoint mit den Infos über die queue Prio 2.

Solid steht weit oben auf der Liste - die Queue Geschichte wird evtl etwas dauern da ich mir noch nicht sicher bin, in welcher Schnitstelleebene ich eingreife, oder ob ich sogar die Queue aus der LED Library rausnehme und auf Anwendungsebene verschiebe

[herrmannj]

Oh, immer langsam mit den jungen Pferden

A: Generell ist fhem ein thread (fast - dasss System ist kooperatives Multitasking.
B: Deswegen machen wir die ganzen calls ja asynchron, da klemmt auch nix
C: Klar bekommen wir das in den Griff (!!!)

Da es keinen "Hauptthread" gibt sind auch Konzepte wie Kontrolle an anderen thread geben obsolet.

Lass uns auf die Ursache fokusieren. Zwischen dem call und der response liegen ja wieder 6 Sekunden, da müssen wir suchen.

Ich schlage vor das testen wir mal so:
temporär nehmen wir das HttpUtils mal raus und bilden das Händisch mit inet (dann blockierend) nach. Da messen wir mal die Zeiten. Ich muss heute Abend aber erst mal isländisch essen

vg
joerg

[pjakobs]

Oh, immer langsam mit den jungen Pferden

A: Generell ist fhem ein thread (fast - dasss System ist kooperatives Multitasking.
B: Deswegen machen wir die ganzen calls ja asynchron, da klemmt auch nix
C: Klar bekommen wir das in den Griff (!!!)

ich bin gespannt.
Hier braucht's jetzt mehr fhem Kenntnis als ich habe

Da es keinen "Hauptthread" gibt sind auch Konzepte wie Kontrolle an anderen thread geben obsolet.

der wird aber, z.B. der Doku, immer wieder erwähnt. Verwirrend.

Lass uns auf die Ursache fokusieren. Zwischen dem call und der response liegen ja wieder 6 Sekunden, da müssen wir suchen.

was wir wissen:

• diese Zeit steckt nicht in unsrem Modul sondern irgendwo in HttpUtils
• der Controller antwortet innerhalb von 25ms und das Paket geht auch beim Linux IP Stack ein (siehe tcpdump capture)
• HttpUtils http://192.168.29.58/color?mode=HSV: Got data, length: 16 kommt erst nachdem das letzte "set" abgeschickt wurde

Ich wette, wenn wir die Abfolge in einzelne fhem Kommandos zerlegen passt das alles.

Die fhem Doku sagt, dass Kommandozeilen (ich interpretiere: alles, was ich auf einen Schlag z.B. über das GUI Kommandoformularfeld absende) im "Haupt-Thread" ausgeführt werden - ich vermute: blocking.

Ich schlage vor das testen wir mal so:
temporär nehmen wir das HttpUtils mal raus und bilden das Händisch mit inet (dann blockierend) nach. Da messen wir mal die Zeiten.

ich schau mir mal HttpUtil ein bisschen  an, mal sehen, wie asynchrone Events dort gehandhabt werden.

Ich muss heute Abend aber erst mal isländisch essen

Brexit feiern?

vg
joerg

[herrmannj]

Für die Zukunft gibt es ja noch weitere Lösungsmöglichkeiten: MQTT und Websockets  - braucht zwar noch etwas Zeit bis das ganze umgesetzt werden kann, eine einfache Testversion für z.B. MQTT oder Websockets lässt sich die Woche sicher zusammenschustern bevor die komplette Implementierung angepasst wird

Ja, aber nicht verrennen bitte.

Hier gibt es genau zwei Möglichkeiten:
- es ist auf fhem Seite falsch (anders, komisch, linksdrehend, whatever) implementiert. Danan kann und wird es dort gelöst.
- der Webserver im sming macht Mist. Dann muss es da gelöst werden (bzw wir schauen wo work arounds liegen).

Lass uns das mal in Ruhe und systematisch eingrenzen ohne jetzt neue Baustellen aufzumachen. Ist doch immer so das Herrausforderungen in der Umsetzung auftauchen. Suchen, finden, beseitigen. Ganz easy !

Solid steht weit oben auf der Liste - die Queue Geschichte wird evtl etwas dauern da ich mir noch nicht sicher bin, in welcher Schnitstelleebene ich eingreife, oder ob ich sogar die Queue aus der LED Library rausnehme und auf Anwendungsebene verschiebe

Ja, das wäre super. Soweit ich lese steht ja Dein echtes Leben im Augenblick sehr im Mittelpunkt. Passt. Solid wäre schön.

vg
joerg

[pjakobs]

Ja, aber nicht verrennen bitte.

Hier gibt es genau zwei Möglichkeiten:
- es ist auf fhem Seite falsch (anders, komisch, linksdrehend, whatever) implementiert. Danan kann und wird es dort gelöst.
- der Webserver im sming macht Mist. Dann muss es da gelöst werden (bzw wir schauen wo work arounds liegen).

das halte ich, anhand des Packet Trace, für ausgeschlossen.
Wie gesagt: die Antwortpakete kommen beim fhem Server an, der kann sie nur nicht zeitig verarbeiten.

Lass uns das mal in Ruhe und systematisch eingrenzen ohne jetzt neue Baustellen aufzumachen. Ist doch immer so das Herrausforderungen in der Umsetzung auftauchen. Suchen, finden, beseitigen. Ganz easy !Ja, das wäre super. Soweit ich lese steht ja Dein echtes Leben im Augenblick sehr im Mittelpunkt. Passt. Solid wäre schön.

das unterschreib ich - also Leben & Solid

vg
joerg

pj

[herrmannj]

ich bin gespannt.
Hier braucht's jetzt mehr fhem Kenntnis als ich habeder wird aber, z.B. der Doku, immer wieder erwähnt. Verwirrend.was wir wissen:

• diese Zeit steckt nicht in unsrem Modul sondern irgendwo in HttpUtils
• der Controller antwortet innerhalb von 25ms und das Paket geht auch beim Linux IP Stack ein (siehe tcpdump capture)
• HttpUtils http://192.168.29.58/color?mode=HSV: Got data, length: 16 kommt erst nachdem das letzte "set" abgeschickt wurde

Ich wette, wenn wir die Abfolge in einzelne fhem Kommandos zerlegen passt das alles.

Die fhem Doku sagt, dass Kommandozeilen (ich interpretiere: alles, was ich auf einen Schlag z.B. über das GUI Kommandoformularfeld absende) im "Haupt-Thread" ausgeführt werden - ich vermute: blocking.
ich schau mir mal HttpUtil ein bisschen  an, mal sehen, wie asynchrone Events dort gehandhabt werden.Brexit feiern?

Schau ich mir an und mache einen synchronen POC. Dann sehen wir das ganz genau. Ist auch kein rocketscience

Zu "Haupt-thread": fhem ist primär singlle threaded. Es gibt Ausnahmen (fork) daher nicht ganaz schwarz weiß. Aber im Prinzip schon.

Ergo führt jedes sleep (und co) dazu das der haupptthread (aka fhem blockiert. Alle guten Module implementieren daher Mechanismen um eventbasiert zu arbeiten. Httputils ist eines der Mittel. Dort wird eben nicht gesendet und auf die Antwort gewartet. Dort wird gesendet und dann die Controlle an den "Hauptthread" (aka fhem) zurückgegeben.

Wenn die Antwort kommt sorgt eine sllelect schleife in fhem.pl dafür das sie HTTPUtils die Antwort verarbeitet, die Callbacks geben dann die Ergebnisse in das aufrufende Module zurück.

Das alles hat aber überhauot nichts damit zu tun das zwischen Frage und Antwort 6 Sekunden vergehen Ind er Theorie kommen da DNS bzw gethostbyname und co in Frage. Aber: wir werden das eingrenzen und lösen. versprochen !

vg
joerg

[pjakobs]

so, gerade nochmal schnell getestet, mit doppelt so langer Kommandozeile.
16:52:03.133670 fhem->controller [SYN]
16:52:03.207991 controller-fhem [SYN, ACK]
16:52:03.208139 fhem->controller [ACK]
16:52:15.076211 fhem->controller POST /color?mode=HSV HTTP/1.0
                                                               Host: 192.168.29.58
                                                               User-Agent: fhem
                                                               Accept: application/json
                                                               Content-Length: 90
                                                               Content-Type: application/x-www-form-urlencoded
                                                               {"cmd":"solid","d":"1","hsv":{"v":"0","ct":"2700","s":"50","h":"240"},"q":"false","t":"0"}
16:52:15.105670 controller-fhem    HTTP/1.1 200 OK
                                                               Connection: close
                                                               Access-Control-Allow-Origin: *
                                                               Content-Length: 16
                                                               Content-Type: application/json
                                                               {"success":true}

also: doppelte Anzahl set Befehle führt inetwa zu doppelter Zeit.

pj