ESP RGBWW Wifi Led Controller - Firmware vbs

[pjakobs]

Stimme dir schon zu, dass ich das Problem auch irgendwo in der Ecke vermuten würde. Allerdings k.A. was genau.
Entweder muss man sich da in das lwip soweit selbst einarbeiten, dass man das analysieren kann oder eben das Problem so als Testfall reproduzierbar machen, dass man das entweder an Sming oder anlwip adressieren kann.

Wie aufwendig wäre es denn, eine minimale Testapp zu schreiben, von der man einfach nur einen großen Blob immer wieder herunterladen kann?

Oder anders: ich versuche mal, den Script Blob x mal per wget zu ziehen, vielleicht lässt sich ja etwas reproduzieren.

pj

Gesendet von meinem HTC U11 mit Tapatalk

[pjakobs]

ich hab mir den Trace nochmal angesehen und es ist immer der gleiche Ablauf:
Irgendwann (nach nicht reproduzierbarer Zeit) fehlt offensichtlich auf der Client Seite ein Paket, der Client hat das zuvor versandte Paket ge ACK'd

Code Auswählen Erweitern

28 0.701941384 192.168.29.80 192.168.29.88 TCP 54 55510 > http [ACK] Seq=139 Ack=16681 Win=63940 Len=0
und schickt jetzt, wo er ein out-of-sequence Paket bekommen hat das gleiche ACK nochmal, diesmal allerdings mit einem Window update

Code Auswählen Erweitern

30 1.027907165 192.168.29.80 192.168.29.88 TCP 54 [TCP Window Update] 55510 > http [ACK] Seq=139 Ack=16681 Win=65330 Len=0
Der Server schickt sein Retransmit

Code Auswählen Erweitern

31 1.745984284 192.168.29.88 192.168.29.80 TCP 1444 [TCP Retransmission] [TCP segment of a reassembled PDU]
der Client ACK'd dann das zuvor gesendete Paket, die Retransmission wird nie geACK'd denn der Server schließt die Verbindung

Code Auswählen Erweitern

32 1.746221581 192.168.29.80 192.168.29.88 TCP 54 55510 > http [ACK] Seq=139 Ack=19461 Win=65330 Len=0
33 2.299577586 192.168.29.88 192.168.29.80 TCP 60 http > 55510 [FIN, ACK] Seq=19461 Ack=139 Win=5422 Len=0


für mich sieht das wie ein Bug / ein merkwürdiges Verhalten im TCP Stack aus.

[edit] im Anhang noch ein capture file, diesmal auch mit einigen Übertragungen, bei denen es zwar zu Retransmissions, aber nicht zum Abbruch kam (streams 6, 8 und 9)

pj

[vbs]

Hab die OTA-URLs umgestellt, so dass die Updates ab sofort nur noch über HTTPS ausgeliefert werden.

[pjakobs]

Hab die OTA-URLs umgestellt, so dass die Updates ab sofort nur noch über HTTPS ausgeliefert werden.

ich hab's nicht getestet und mach's mir mal einfach: hast Du eine Umleitung auf der non-ssl url oder müssen die Nutzer die ota url manuell ändern?

pj

[vbs]

Ja, die war drin, aber ist jetzt wieder raus, also jetzt geht momentan beides parallel. Ich war etwas voreilig: der Update-Prozess ist ja zweistufig. Der Browser/FHEM lädt die version.json (gerne per HTTPS) und gibt die enthaltenen URLs an den Controller weiter. Das Problem ist, dass der kein SSL kann momentan. Also dürfen diese URLs momentan kein HTTPS sein. Vorraussetzungen dafür ist u.a. ein eingerichteter NTP-Server, damit er eine Chance auf die Zertifikatsprüfung hat...

[pjakobs]

Ja, die war drin, aber ist jetzt wieder raus, also jetzt geht momentan beides parallel. Ich war etwas voreilig: der Update-Prozess ist ja zweistufig. Der Browser/FHEM lädt die version.json (gerne per HTTPS) und gibt die enthaltenen URLs an den Controller weiter. Das Problem ist, dass der kein SSL kann momentan. Also dürfen diese URLs momentan kein HTTPS sein. Vorraussetzungen dafür ist u.a. ein eingerichteter NTP-Server, damit er eine Chance auf die Zertifikatsprüfung hat...

hmm... hinter jedem Eichhörnchen versteckt sich ein Elefant.

pj

[pjakobs]

moin @vbs, ich hab hier einen seltsamen Effekt, den ich so noch nicht kannte.
Einer der reparierten Controller, ich konnte ihn, mit neuem ESP, problemlos mit der vbs35 Firmware flashen und darauf zugreifen.
Dann habe ich ein OTA auf den Testing Pfad (4.2.0 rc1) gemacht und danach bekomme ich im Browser einen "error bad content encoding" und auf der Seriellen Konsole des Controllers folgendes:

Code Auswählen Erweitern


114713 fs.start: size:768 Kb, offset:0x300000

130621 mount res: 0

sleep disable
161826 SSID: IoT
162080 '*' registered
162293 '/' registered
162519 '/webapp' registered
162745 '/config' registered
162975 '/info' registered
164239 '/color' registered
166587 '/animation' registered
169262 '/networks' registered
171866 '/scan_networks' registered
174911 '/system' registered
177342 '/update' registered
179804 '/connect' registered
182264 '/generate_204' registered
185241 '/ping' registered
187504 '/stop' registered
189762 '/skip' registered
192014 '/pause' registered
194359 '/continue' registered
196965 '/blink' registered
199313 '/toggle' registered
mode : sta(cc:50:e3:2b:26:2c)
add if0
215651 mode: 0 -> 3

scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt

connected with IoT, channel 11
dhcp client start...
455605 connect to ssid IoT, channel 11

ip:192.168.29.110,mask:255.255.255.0,gw:192.168.29.1
1177861 ip:192.168.29.110,mask:255.255.255.0,gw:192.168.29.1
1178173

6771497 read errno -10017

6772829 read errno -10017

pm open,type:0 0

Der Trace ist schon nach komplettem, und erfolgreichem, zurückflashen auf vbs35
Ich werd mal das Flash komplett löschen und dann neu flashen, aber vielleicht kannst Du mit der Fehlermeldung was anfangen?

Grüße

pj

[edit] nach erase_flash und neu flashen, wie erwartet kein Problem. Danach wieder Update über OTA und selber Fehler.

[vbs]

Hm, nee sagt mir nicht viel. Errno 10017 bedeutet "Cannot roll back specified object."... Was auch immer da gemeint ist.

[vbs]

Ich hab nochmal etwas gelesen bzgl. TCP Retransmission und ich hab eine Theorie:

Code Auswählen Erweitern

     89 2.305896567    192.168.29.88         192.168.29.80         TCP      1444   80 → 44978 [ACK] Seq=63941 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]
     90 2.345534159    192.168.29.80         192.168.29.88         TCP      54     44978 → 80 [ACK] Seq=139 Ack=65331 Win=65330 Len=0
     91 2.403617188    192.168.29.88         192.168.29.80         TCP      1444   [TCP Previous segment not captured] 80 → 44978 [ACK] Seq=66721 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]

Also hier ist ja offenbar ein Paket verloren gegangen und der Empfänger mahnt das Paket mit dem folgenden ACK an (TCP Dup)

Code Auswählen Erweitern

     92 2.403643063    192.168.29.80         192.168.29.88         TCP      54     [TCP Dup ACK 90#1] 44978 → 80 [ACK] Seq=139 Ack=65331 Win=65330 Len=0

Der Sender schickt das Paket dementsprechend nun nochmal - alles gut soweit

Code Auswählen Erweitern


     93 3.678099064    192.168.29.88         192.168.29.80         TCP      1444   [TCP Retransmission] 80 → 44978 [ACK] Seq=65331 Ack=139 Win=5422 Len=1390
     94 3.678217286    192.168.29.80         192.168.29.88         TCP      54     44978 → 80 [ACK] Seq=139 Ack=68111 Win=65330 Len=0

Der Empfänger hat das Paket offenbar auch empfangen und bestätigt nun alle Bytes bis 68110 (also das gerade neu empfangene Paket und auch das darauf folgende, welches er ja auch schon empfangen hat).

Code Auswählen Erweitern


     95 3.992078748    192.168.29.88         192.168.29.80         TCP      1444   [TCP Spurious Retransmission] 80 → 44978 [FIN, ACK] Seq=66721 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]

Jetzt ist das interessant, dass der Sender einfach die Verbindung schließt. Eine Vermutung wäre, dass der Sender das ACK (#94) nicht empfangen hat un daher davon ausgeht, dass auch das Retransmission-Paket verloren gegangen ist. Vielleicht hat er nach zwei Versuchen die Nase voll und gibt auf.

Code Auswählen Erweitern


     96 4.031683650    192.168.29.80         192.168.29.88         TCP      54     [TCP ACKed unseen segment] 44978 → 80 [ACK] Seq=139 Ack=68112 Win=65330 Len=0


Es gibt eine LWIP-Option "TCP_MAXRTX: Maximum number of retransmissions of data segments." (https://github.com/esp8266/Arduino/blob/master/tools/sdk/lwip/include/lwipopts.h#L922). Vielleicht steht die auf 1?

Bei anderen Retransmission, die nicht zum Abbruch führen, sieht das alles ja ähnlich aus, aber dann geht's brav weiter:

Code Auswählen Erweitern

    135 14.822232074   192.168.29.80         192.168.29.88         TCP      54     45102 → 80 [ACK] Seq=139 Ack=13901 Win=58380 Len=0
    136 14.950282560   192.168.29.88         192.168.29.80         TCP      1444   [TCP Previous segment not captured] 80 → 45102 [ACK] Seq=15291 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]
    137 14.950396019   192.168.29.80         192.168.29.88         TCP      54     [TCP Window Update] 45102 → 80 [ACK] Seq=139 Ack=13901 Win=61160 Len=0
    138 15.650729830   192.168.29.88         192.168.29.80         TCP      1444   [TCP Retransmission] 80 → 45102 [ACK] Seq=13901 Ack=139 Win=5422 Len=1390
    139 15.650827703   192.168.29.80         192.168.29.88         TCP      54     45102 → 80 [ACK] Seq=139 Ack=16681 Win=63940 Len=0
    140 15.715762673   192.168.29.88         192.168.29.80         TCP      1444   80 → 45102 [ACK] Seq=16681 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]
    141 15.715864714   192.168.29.80         192.168.29.88         TCP      54     45102 → 80 [ACK] Seq=139 Ack=18071 Win=65330 Len=0
    142 15.733607172   192.168.29.88         192.168.29.80         TCP      1444   80 → 45102 [ACK] Seq=18071 Ack=139 Win=5422 Len=1390 [TCP segment of a reassembled PDU]



[pjakobs]

jetzt, wo Du's sagst, es ist natürlich auch denkbar, dass das ACK nach der Retransmission verloren geht. Ich capture ja nur auf der Client Seite.
allerdings würde ich *vermuten*, dass das "in flight" Retransmissions sind, also Segments die gleichzeitig zur neuen Übertragung anstehen.

Wenn es tatsächlich ein verlorenes ACK wäre, dann müssten wir ja ein relativ stabiles Timing zum FIN sehen, oder?

Ich hänge mal noch einen Satz Traces vom Freitag an (vielleicht hab ich das schon da mal angehäng?).
Interessant ist Stream 10, denn da passieren zwei Retransmits die problemlos funktionieren. Ich denke, Du bist auf dem richtigen Weg.

pj

[vbs]

Hast du schonmal versucht, das Problem mit wget zu reproduzieren? Z.b. einfach das CSS-File in einer endlosen Schleife runterladen? Ist die Frage, wie wget sich bei dem gleichen Fehler verhalten würde bzw. ob er das melden/loggen würde. Im Zweifel müsste man noch händisch die Länge des runtergeladenen Files prüfen.

Code Auswählen Erweitern

'--ignore-length'
Unfortunately, some HTTP servers (CGI programs, to be more precise) send out bogus Content-Length headers, which makes Wget go wild, as it thinks not all the document was retrieved. You can spot this syndrome if Wget retries getting the same document again and again, each time claiming that the (otherwise normal) connection has closed on the very same byte.

With this option, Wget will ignore the Content-Length header—as if it never existed.

Klingt so als würde es wget einfach nochmal probieren bis die Länge stimmt, so dass man den Fehler nciht mitbekommen würde. Also --ignore-length und dann selbst prüfen? 

[pjakobs]

Hast du schonmal versucht, das Problem mit wget zu reproduzieren? Z.b. einfach das CSS-File in einer endlosen Schleife runterladen? Ist die Frage, wie wget sich bei dem gleichen Fehler verhalten würde bzw. ob er das melden/loggen würde. Im Zweifel müsste man noch händisch die Länge des runtergeladenen Files prüfen.

Code Auswählen Erweitern

'--ignore-length'
Unfortunately, some HTTP servers (CGI programs, to be more precise) send out bogus Content-Length headers, which makes Wget go wild, as it thinks not all the document was retrieved. You can spot this syndrome if Wget retries getting the same document again and again, each time claiming that the (otherwise normal) connection has closed on the very same byte.

With this option, Wget will ignore the Content-Length header—as if it never existed.

Klingt so als würde es wget einfach nochmal probieren bis die Länge stimmt, so dass man den Fehler nciht mitbekommen würde. Also --ignore-length und dann selbst prüfen? 

ich hab's auch mit wget, allerdings ohne das --ignore-length flag. Nur: der Fehler geschieht ja auf TCP Level, nicht HTTP, also dürfte der an dieser Stelle nichts ausmachen, oder?

pj

[vbs]

Doch doch, ist mMn relevant: Die TCP-Verbindung wird ja regulär geschlossen (FIN) und dadurch wird auch der HTTP-Request (erfolgreich) beendet. Dem Client fällt dann nur auf (wie deinem Browser ja auch), dass die Anzahl der übertragenen Bytes nicht zu der erwarteten Anzahl der Bytes aus dem HTTP-Header passt (Content-Length).
Ich finde es halt noch nach wie vor seltsam, dass das Problem zu keinem fehlgeschlagenen HTTP-Request führt, sondern offenbar wie ein normaler, erfolgreicher Request aussieht bei dem nur reale Datenlänge und "Content-Length"-Header nicht zusammen passen...  Bug oder Feature? 

Und von wget hätte ich eine Logmeldung erwartet, wenn Datenlänge und Header nicht zusammen passen:

"...claiming that the (otherwise normal) connection has closed on the very same byte..."

[pjakobs]

hier mal drei captures - eines ohne "--ignore-length" - da versucht wget immer wieder die Datei zu übertragen

Code Auswählen Erweitern


wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 15:18:16--  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« gespeichert.

app.min.css?rel=0.3.3-shojo7       74%[============================================>                ]  28,29K  13,8KB/s    in 2,1s   

2019-07-15 15:18:19 (13,8 KB/s) - Verbindung bei Byte 28972 geschlossen. Erneuter Versuch.

--2019-07-15 15:18:20--  (Versuch: 2)  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« gespeichert.

app.min.css?rel=0.3.3-shojo7       77%[==============================================>              ]  29,65K  7,94KB/s    in 3,7s   

2019-07-15 15:18:24 (7,94 KB/s) - Verbindung bei Byte 30362 geschlossen. Erneuter Versuch.

--2019-07-15 15:18:26--  (Versuch: 3)  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« gespeichert.

app.min.css?rel=0.3.3-shojo7       31%[==================>                                          ]  12,00K  3,08KB/s    in 3,9s   

2019-07-15 15:18:31 (3,08 KB/s) - Verbindung bei Byte 30362 geschlossen. Erneuter Versuch.

--2019-07-15 15:18:34--  (Versuch: 4)  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« gespeichert.

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

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

[pjakobs@linux ~]$ wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7
--2019-07-15 15:18:57--  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.1« gespeichert.

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

2019-07-15 15:19:00 (15,7 KB/s) - »app.min.css?rel=0.3.3-shojo7.1« gespeichert [39107/39107]


danach ein erfolgloser Anlauf mit --ignore-length

Code Auswählen Erweitern


wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7 --ignore-length
--2019-07-15 15:19:58--  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: übergangen [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.2« gespeichert.

app.min.css?rel=0.3.3-shojo7.2        [   <=>                                                       ]   3,86K  3,32KB/s    in 1,2s   

2019-07-15 15:20:00 (3,32 KB/s) - »app.min.css?rel=0.3.3-shojo7.2« gespeichert [3952]

und zuletzt ein Anlauf, in dem es funktionierte:

Code Auswählen Erweitern


wget 192.168.29.99/app.min.css?rel=0.3.3-shojo7 --ignore-length
--2019-07-15 15:21:23--  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: übergangen [text/css]
Wird in »app.min.css?rel=0.3.3-shojo7.3« gespeichert.

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

2019-07-15 15:21:34 (9,96 KB/s) - »app.min.css?rel=0.3.3-shojo7.3« gespeichert [39107]


[vbs]

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?