ESP RGBWW Wifi Led Controller - Firmware vbs

pjakobs · 15 Juli 2019, 16:23:16

Zitat von: vbs am 15 Juli 2019, 15:50:52
Ich hätte erwartet in "esprgbww-wget-content-header.pcapng" mindestens eine Retransmission und mindetens 2 HTTP-Requests zu finden. Sieht aber für mich nach einem einzelnen sauberen HTTP-Request aus?

Mist, ja, das ist offenbar eine falsche Datei. Argh!

vbs · 15 Juli 2019, 18:12:02

Wie simuliere ich denn mal den schlechten WLAN-Empfang um das Problem mal selbst zu sehen? Hab gerade ohne Erfolg naiv mit Alufolie rumhantiert

vbs · 15 Juli 2019, 21:39:42

Ich kann das Problem nicht nachstellen, aber ich hab mal eine Firmware gebaut mit verschiedene TCP-Debug-Ausgabe für LWIP. Vielleicht kannst du das mal laufen lassen:

Code Auswählen

http://rgbww.dronezone.de/unstable/version.json

Bau: https://travis-ci.org/verybadsoldier/esp_rgbww_firmware/builds/559090765

("unstable" ist ein neuer Kanal. Da landen alle Tags, die "-alpha" im Namen haben (andere mit "-..." gehen nach "testing" und alle ohne Kürzel nach "release").)

Es gibt noch viele andere Ausgabe-Optionen, aber das ist einfach mal ein erster Schuss... Ich werde das hier nachstellen müssen, um damit sinnvoll arbeiten zu können :/

pjakobs · 15 Juli 2019, 22:14:11

das sieht sehr hilfreich aus
aktuell spielt allerdings der Controller bzw. das Netz mit. bzw nicht mit. also - es funktioniert alles

pj

pjakobs · 15 Juli 2019, 22:25:54

ok drei test Runs, die ersten beiden jeweils mit mehreren wget runs (ohne --ignore-length). Beim -1 lief die Webapp noch im Browser, den Stream musst Du filtern.
In -2 sind mehrere (fünf oder sechs) Attempts drin, -3 ist nur ein einziger Lauf.

Interessante Beobachtung: es treten immer noch Retransmits auf, aber: die Verbindung wird nicht mehr abgebrochen.
Die Downloadzeiten für app.min.css liegen zwischen 2.6 und 27s, aber immer wird die Datei fehlerfrei geladen.

Code Auswählen


[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:12:01--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.8« gespeichert.

app.min.css?rel=0.3.3-shojo7.8    100%[============================================================>]  38,19K  14,6KB/s    in 2,6s    

2019-07-15 22:12:03 (14,6 KB/s) - »app.min.css?rel=0.3.3-shojo7.8« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:12:06--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.9« gespeichert.

app.min.css?rel=0.3.3-shojo7.9    100%[============================================================>]  38,19K  8,90KB/s    in 4,3s    

2019-07-15 22:12:10 (8,90 KB/s) - »app.min.css?rel=0.3.3-shojo7.9« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:12:12--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.10« gespeichert.

app.min.css?rel=0.3.3-shojo7.10   100%[============================================================>]  38,19K  8,72KB/s    in 4,4s    

2019-07-15 22:12:18 (8,72 KB/s) - »app.min.css?rel=0.3.3-shojo7.10« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:15:12--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.11« gespeichert.

app.min.css?rel=0.3.3-shojo7.11   100%[============================================================>]  38,19K  3,26KB/s    in 12s     

2019-07-15 22:15:25 (3,26 KB/s) - »app.min.css?rel=0.3.3-shojo7.11« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:15:28--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.12« gespeichert.

app.min.css?rel=0.3.3-shojo7.12   100%[============================================================>]  38,19K  1,75KB/s    in 27s     

2019-07-15 22:15:56 (1,42 KB/s) - »app.min.css?rel=0.3.3-shojo7.12« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:17:44--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.13« gespeichert.

app.min.css?rel=0.3.3-shojo7.13   100%[============================================================>]  38,19K  1,55KB/s    in 24s     

2019-07-15 22:18:14 (1,62 KB/s) - »app.min.css?rel=0.3.3-shojo7.13« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:18:19--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.14« gespeichert.

app.min.css?rel=0.3.3-shojo7.14   100%[============================================================>]  38,19K  4,77KB/s    in 8,0s    

2019-07-15 22:18:28 (4,77 KB/s) - »app.min.css?rel=0.3.3-shojo7.14« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:18:32--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.15« gespeichert.

app.min.css?rel=0.3.3-shojo7.15   100%[============================================================>]  38,19K  3,32KB/s    in 12s     

2019-07-15 22:18:44 (3,32 KB/s) - »app.min.css?rel=0.3.3-shojo7.15« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:18:46--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.16« gespeichert.

app.min.css?rel=0.3.3-shojo7.16   100%[============================================================>]  38,19K  4,86KB/s    in 7,9s    

2019-07-15 22:18:55 (4,86 KB/s) - »app.min.css?rel=0.3.3-shojo7.16« gespeichert [39107/39107]

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 22:20:00--  http://192.168.29.99/app.min.css?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: 39107 (38K) [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.17« gespeichert.

app.min.css?rel=0.3.3-shojo7.17   100%[============================================================>]  38,19K  4,04KB/s    in 9,5s    

2019-07-15 22:20:09 (4,04 KB/s) - »app.min.css?rel=0.3.3-shojo7.17« gespeichert [39107/39107]

Wenn das debug log wirklich die einzige Änderung ist, dann haben wir es wohl mit einem Timing Problem zu tun.

pj

pjakobs · 15 Juli 2019, 22:35:07

ich hab noch einen run gemacht, diesmal mit der .js Datei und --ignore-legnth:

Code Auswählen


[pjakobs@linux ~]$ wget 192.168.29.99/app.min.js?rel=0.3.3-shojo7 --ignore-length
--2019-07-15 22:31:41--  http://192.168.29.99/app.min.js?rel=0.3.3-shojo7
Verbindungsaufbau zu 192.168.29.99:80 ... verbunden.
HTTP-Anforderung gesendet, auf Antwort wird gewartet ... 200 OK
Länge: übergangen [text/javascript]
Wird in »app.min.js?rel=0.3.3-shojo7.3« gespeichert.

app.min.js?rel=0.3.3-shojo7.3         [                                                       <=>   ] 182,93K  --.-KB/s    in 30s     

2019-07-15 22:32:11 (6,17 KB/s) - »app.min.js?rel=0.3.3-shojo7.3« gespeichert [187324]

debug-run-5

dauert ewig, aber bricht nicht mehr ab.

pjakobs · 15 Juli 2019, 22:40:47

blöd ist nur, ich kann die ACK sequenzen zwischen Trace und Log nicht übereinander bringen - sind das im Log wirklich die ACK nummer?

pj

vbs · 15 Juli 2019, 22:58:50

Hm, ich vermute, dass die ACK-Nummern in Wireshark um die ISN bereinigt sind. Wireshark nennt sich auch "relative ack number". Die LWIP-Logs zeigen vermutlich die Roh-ACK-Nummern. Ist aber mindestens halb geraten...

Ich hab nochmal eine Verison gepusht ohne Logausgaben:
https://travis-ci.org/verybadsoldier/esp_rgbww_firmware/builds/559127016

Erstmal rausfinden, ob wirklich das Logging das Verhalten verändert hat. Was ich nicht glaube/hoffe, weil ich dann echt schlechte Laune kriege

vbs · 15 Juli 2019, 23:03:27

Genau, hier steht's:
https://wiki.wireshark.org/TCP_Relative_Sequence_Numbers

Ich find's überraschend, dass der Controller ~800 ms braucht, um auf die Retransmission zu reagieren und das fehlende Paket nachzusenden:

Code Auswählen

    221 20.781577023   192.168.29.99         192.168.29.101        TCP      1444   [TCP Previous segment not captured] 80 → 46826 [ACK] Seq=151511 Ack=163 Win=5398 Len=1390 [TCP segment of a reassembled PDU]
    222 20.781653453   192.168.29.101        192.168.29.99         TCP      54     [TCP Dup ACK 220#1] 46826 → 80 [ACK] Seq=163 Ack=150121 Win=65535 Len=0
    223 21.613624850   192.168.29.99         192.168.29.101        TCP      1444   [TCP Retransmission] 80 → 46826 [ACK] Seq=150121 Ack=163 Win=5398 Len=1390
    224 21.613729177   192.168.29.101        192.168.29.99         TCP      54     46826 → 80 [ACK] Seq=163 Ack=152901 Win=65535 Len=0

Das Verfahren nennt sich ja eigentl. "Fast Retransmission"...

EDIT:
Hier sogar 1,4 s:

Code Auswählen

    189 18.532154501   192.168.29.99         192.168.29.101        TCP      1444   [TCP Previous segment not captured] 80 → 46826 [ACK] Seq=129271 Ack=163 Win=5398 Len=1390 [TCP segment of a reassembled PDU]
    190 18.532216966   192.168.29.101        192.168.29.99         TCP      54     [TCP Dup ACK 188#1] 46826 → 80 [ACK] Seq=163 Ack=127881 Win=65535 Len=0
    191 19.946226440   192.168.29.99         192.168.29.101        TCP      1444   [TCP Retransmission] 80 → 46826 [ACK] Seq=127881 Ack=163 Win=5398 Len=1390

wtf macht der Controller zwischendurch?

pjakobs · 15 Juli 2019, 23:28:16

Zitat von: vbs am 15 Juli 2019, 23:03:27
wtf macht der Controller zwischendurch?

Pakete nach China schicke? scnr

aber egal was: ich kann mit der 'unstable' das Problem nicht reporduzieren. Es dauert manchmal lange, die Seite zu laden aber sie wird geladen. im anhängenden Trace sind wieder ein paar Retransmits, aber kein vorschnelles FIN.

Whatever you changed: keep that

pj

pjakobs · 15 Juli 2019, 23:36:58

ich hab mal meine beiden WLAN Repeater neu gestartet und das Netz komplett miserabel gemacht, und selbst in der Situation liefert die "unstable" Firmware das File korrekt und vollständig aus - wenn auch in gemächlichen 88s.

[edit] so ganz nebenbei hab ich auch ne Ahnung, was an meinem IoT WLAN so grottig schlecht ist. Aber das Problem löse ich jetzt noch nicht sonst haben wir kein Testbed

vbs · 15 Juli 2019, 23:42:00

Gefällt mir nicht

Könntest du das zur Absicherung noch einmal getestet gegen die 4.2.0-rc1 bitte? Gerne auch beide nochmal identisch per seriell aufspielen oder so.

Die unstables sind halt nicht mehr von mir gebaut, sondern von Travis. Eigentlich der gleiche Quellcode. Ein Unterschied ist, dass ich bei Travis eine fertige Binary-Toolchain aus dem Nodemcu-Projekt benutze und ich mir hier die Toolchain irgendwann mal selbst kompiliert habe... sollte aber *eigentlich* keinen Unterschied machen...

EDIT:
Was noch viel besser wäre: eine Idee, wie ich das Problem hier bei mir provozieren könnte? Metalldose um den Controller oder sowas?

pjakobs · 15 Juli 2019, 23:44:34

gerade sehe ich dass beim *ganz extrem schlechten* wlan doch zwei Übertragungen vorab abgebrochen wurden.
Allerdings unter krass üblen Bedingungen. (ich glaube dass der Access Point ein Problem hat, möglicherweise auch seine Netzanbindung)

pjakobs · 15 Juli 2019, 23:56:49

jetzt hab ich mir das Netz ganz zerschossen - also zumindest für die 29.99

Aktuell ist er zwar mit irgendeinem AP des WLAN verbunden, aber der Client schickt wie blöd ARP Requests. Ich glaub, ich mach mal für heut Feierabend.

Wenn Du sagst, der Travis Build unterscheidet sich primär durch die ESP toolchain - da sind aber doch die libraries und rtos binaries auch mit compiliert - ob das einfach nur andere Versionen sind? Ich vermute ja, dass LwIP in SMING steckt und deshalb als Teil Deines Builds daher kommt?

Es ist schon wieder viel zu viel Software auf so nem Controller. Ich hab mal damit angefangen, weil ich die Tatsache mochte, dass es kein Betriebssystem gibt, das überall reinfummelt.

also: schluss für heut.

Danke erstmal

pj

vbs · 16 Juli 2019, 13:17:34

Hm, aus deinem WorstCase werde ich nciht so ganz schlau... sieht ziemlich wild aus...

Die maximale Anzahl an Retransmissions liegt bei 12. Bin immer noch nicht ganz sicher, was denn im Normalfall passiert, wenn man die 12 erreicht. Wird wirklich die Verbindung ganz regulär per FIN beendet? Würde halt bedeuten (wie es bei uns ja auch ist), dass der Client gar nicht mitbekommt, dass die Verbindung aufgrund eines Fehler vorzeitig geschlossen wurde und er könnte denken, dass alle Daten wie gewünscht fertig übertragen worden sind. Bei HTTP rettet einen da eben der Content-Length-Header vor dieser Schlussfolgerung...

Nach wie vor wäre interessant, ob sich wirklich der Travis-Bau anders verhält als mein Bau. Wenn ja dann würde ich auch mal mit der Binary-Toolchain bauen bei mir (wie Travis) und dann gucken, ob es sich dann identisch verhält.

Code Auswählen

Wenn Du sagst, der Travis Build unterscheidet sich primär durch die ESP toolchain - da sind aber doch die libraries und rtos binaries auch mit compiliert - ob das einfach nur andere Versionen sind? Ich vermute ja, dass LwIP in SMING steckt und deshalb als Teil Deines Builds daher kommt?

Das ESP SDK besteht eigentlich aus Toolchain + SDK. Den SDK-Teil bringt Sming jedoch selbst auch mit und den benutzen wir auch (identisch bei mir und bei Travis). Nur die Toolchain unterscheidet sich zwischen meinen Builds und den Travis-Builds.