Discussion:
[ethersex-devel] Problem with YPort
Michael Späth
2015-10-20 09:56:24 UTC
Permalink
Hi!

First of all: Great software! I really love every tiny bit of it :-)

Buuuuuuut.... I have a problem which was very hard to tackle for me:
YPort drops incoming packets (Host -> EtherSex) when they are sent too fast.

I have built a very basic example: Arduino Nano Pro with ENC28J60 mini
board (eBay). TX and RX are shorted to enable a loopback. I tested
several modules, just to avoid hardware issues.

I can connect with

nc IP 7970

and it echoes just fine.


But when I run this simple python script:


#!/usr/bin/python3

import socket, time

host = your_ip_goes_here
port = 7970

s = socket.create_connection((host, port))

while True:
s.send(b'12345')
print(s.recv(5))
# time.sleep(0.05)


it will print exactly once 12345 and then it stalls: The reason is quite
simple, it runs the loop once and then the next send will NOT deliver
the packet. It will say so, and Wireshark also sees the packet, but
EtherSex somehow drops it.

If you comment in the "sleep", everything works fine. I found EtherSex
needs at least 20-30msec between ethernet packets, otherwise it just
drops them (huh? it's TCP!).

YPort was configured with all different settings: Buffer sizes 128, 256,
384 and Flush set to 0 and 1 - nothing changes.

I am also using a tuned 5V power supply with 2.4A - just to drop voltage
issues, too :-) All connections are either soldered or pins and sockets,
no flying wires.

Any ideas on this problem?
--
Michael
e***@users.sourceforge.net
2015-10-20 17:06:08 UTC
Permalink
Hallo Michael,
Post by Michael Späth
YPort drops incoming packets (Host -> EtherSex) when they are sent too fast.
[...]

Bist Du sicher, dass Ethersex TCP-Pakete verwirft? Wenn es keine weiteren
Daten empfangen kann, sollte das TCP-Receive-Windows auf Null gehen.
Post by Michael Späth
it will print exactly once 12345 and then it stalls: The reason is quite
simple, it runs the loop once and then the next send will NOT deliver
the packet. It will say so, and Wireshark also sees the packet, but
EtherSex somehow drops it.
Konfiguriere mal den Debug für das YPort-Modul und lass Dir die Statistik
ausgeben. Wahrscheinlich gehen auf der USART die Zeichen verloren wegen
Pufferüberlauf.
Post by Michael Späth
If you comment in the "sleep", everything works fine. I found EtherSex
needs at least 20-30msec between ethernet packets, otherwise it just
drops them (huh? it's TCP!).
Völlig korrekt. Ethersex´ Zeitscheibe ist 20ms. Du könntest mal den Branch
new_timer_framework testen. Der zeigt ein deutlich besseres Zeitverhalten.

Du bist herzlich in unseren IRC-Kanal eingeladen! Adresse im WIKI.
Michael Späth
2015-10-21 06:07:51 UTC
Permalink
Hi!
Post by e***@users.sourceforge.net
Post by Michael Späth
YPort drops incoming packets (Host -> EtherSex) when they are sent too fast.
[...]
Bist Du sicher, dass Ethersex TCP-Pakete verwirft? Wenn es keine weiteren
Daten empfangen kann, sollte das TCP-Receive-Windows auf Null gehen.
Ja, bin ich. Wireshark zeigt sie an, und sie kommen weder per Loopback zurück noch wenn ich ein serielles Modul dranhänge zum Debuggen -> sie sind weg. Lustigerweise sagt mir die Netzwerk API auch sie wären ge'ACKt worden...
Post by e***@users.sourceforge.net
Post by Michael Späth
it will print exactly once 12345 and then it stalls: The reason is quite
simple, it runs the loop once and then the next send will NOT deliver
the packet. It will say so, and Wireshark also sees the packet, but
EtherSex somehow drops it.
Konfiguriere mal den Debug für das YPort-Modul und lass Dir die Statistik
ausgeben. Wahrscheinlich gehen auf der USART die Zeichen verloren wegen
Pufferüberlauf.
Habe ich natürlich auch schon gemacht, keine Überläufe. Bei 5 Bytes und 384 Byte Puffer auch unwahrscheinlich... er stirbt ja schon beim zweiten Versuch, 5 Bytes zu senden.
Post by e***@users.sourceforge.net
Post by Michael Späth
If you comment in the "sleep", everything works fine. I found EtherSex
needs at least 20-30msec between ethernet packets, otherwise it just
drops them (huh? it's TCP!).
Völlig korrekt. Ethersex´ Zeitscheibe ist 20ms. Du könntest mal den Branch
new_timer_framework testen. Der zeigt ein deutlich besseres Zeitverhalten.
Das er sammelt und schickt ist ja ok... aber droppen sollte er doch nie?

new timer framework kannte ich gar nicht, habe es gerade gefunden, werde es heute Abend direkt testen und berichten.
Post by e***@users.sourceforge.net
Du bist herzlich in unseren IRC-Kanal eingeladen! Adresse im WIKI.
Danke, ich schau mal vorbei!
--
Michael
Michael Späth
2015-10-22 21:16:53 UTC
Permalink
Hallo!
Post by e***@users.sourceforge.net
Post by Michael Späth
YPort drops incoming packets (Host -> EtherSex) when they are sent too fast.
[...]
Bist Du sicher, dass Ethersex TCP-Pakete verwirft? Wenn es keine weiteren
Daten empfangen kann, sollte das TCP-Receive-Windows auf Null gehen.
Hier der Wireshark Mitschnitt, zweimal wird 12345 gesendet, zweimal empfangen, zweimal geackt, das dritte Mal verschwindet es im Nirwana (No. 13 ist das dritte Paket, No. 14 der Ack, aber es kommt einfach nix mehr zurück...)

Ich habe es mehrfach wiederholt, es sind immer exakt diese Pakete...

Erhöhe ich den Delay zwischen Paketen auf ca. 35msec dann gehen alle ohne Verlust raus...


(69 ist der EtherSex Knoten, 81 ein Ubuntu Host):



No. Time Source Destination Protocol Length Info
3 2.411121000 192.168.178.81 192.168.178.69 TCP 74 42582 > 7970 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=844640 TSecr=0 WS=128

No. Time Source Destination Protocol Length Info
4 2.412610000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [SYN, ACK] Seq=0 Ack=1 Win=330 Len=0 MSS=330

No. Time Source Destination Protocol Length Info
5 2.412673000 192.168.178.81 192.168.178.69 TCP 54 42582 > 7970 [ACK] Seq=1 Ack=1 Win=29200 Len=0

No. Time Source Destination Protocol Length Info
6 2.412771000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=1 Ack=1 Win=29200 Len=5

Data: 3132333435
[Length: 5]

No. Time Source Destination Protocol Length Info
7 2.414668000 192.168.178.69 192.168.178.81 TCP 60 [TCP ZeroWindow] 7970 > 42582 [ACK] Seq=1 Ack=6 Win=0 Len=0

No. Time Source Destination Protocol Length Info
8 2.423967000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [PSH, ACK] Seq=1 Ack=6 Win=255 Len=5

Data: 3132333435
[Length: 5]

No. Time Source Destination Protocol Length Info
9 2.424096000 192.168.178.81 192.168.178.69 TCP 54 42582 > 7970 [ACK] Seq=6 Ack=6 Win=29200 Len=0

No. Time Source Destination Protocol Length Info
10 2.424328000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=6 Ack=6 Win=29200 Len=5

Data: 3132333435
[Length: 5]

No. Time Source Destination Protocol Length Info
11 2.426127000 192.168.178.69 192.168.178.81 TCP 60 [TCP ZeroWindow] 7970 > 42582 [ACK] Seq=6 Ack=11 Win=0 Len=0

No. Time Source Destination Protocol Length Info
12 2.443925000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [PSH, ACK] Seq=6 Ack=11 Win=255 Len=5

Data: 3132333435
[Length: 5]

No. Time Source Destination Protocol Length Info
13 2.444213000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=11 Ack=11 Win=29200 Len=5

Data: 3132333435
[Length: 5]

No. Time Source Destination Protocol Length Info
14 2.445596000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [ACK] Seq=11 Ack=16 Win=255 Len=0
Post by e***@users.sourceforge.net
Völlig korrekt. Ethersex´ Zeitscheibe ist 20ms. Du könntest mal den Branch
new_timer_framework testen. Der zeigt ein deutlich besseres Zeitverhalten.
Habe ich getestet, passiert das gleiche. Oben ist das Ergebnis dieses Branches.

Ich habe auch den Hop über meinen Gigabit Switch mal eliminiert und direkt angeklemmt -> das gleiche Verhalten.


Hat jemand ne Idee wie ich das eventuell anders testen kann? Gibt es dafür Testskripte?
--
Michael
Michael Brakemeier
2015-10-22 21:28:27 UTC
Permalink
Hallo Michael,

mit wieviel Ticks/s hast du getestet? Standardeinstellung 50? Dann
sollte auch mit dem neuen Timer Framework das gleiche rauskommen.
Dreh doch bitte mal die "Periodic ticks per second" hoch, Größenordnung
500 Hz oder mehr, und wiederhole den Test.

VG michaelb
Post by Michael Späth
Hallo!
Post by e***@users.sourceforge.net
Post by Michael Späth
YPort drops incoming packets (Host -> EtherSex) when they are sent too fast.
[...]
Bist Du sicher, dass Ethersex TCP-Pakete verwirft? Wenn es keine weiteren
Daten empfangen kann, sollte das TCP-Receive-Windows auf Null gehen.
Hier der Wireshark Mitschnitt, zweimal wird 12345 gesendet, zweimal empfangen, zweimal geackt, das dritte Mal verschwindet es im Nirwana (No. 13 ist das dritte Paket, No. 14 der Ack, aber es kommt einfach nix mehr zurück...)
Ich habe es mehrfach wiederholt, es sind immer exakt diese Pakete...
Erhöhe ich den Delay zwischen Paketen auf ca. 35msec dann gehen alle ohne Verlust raus...
No. Time Source Destination Protocol Length Info
3 2.411121000 192.168.178.81 192.168.178.69 TCP 74 42582 > 7970 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=844640 TSecr=0 WS=128
No. Time Source Destination Protocol Length Info
4 2.412610000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [SYN, ACK] Seq=0 Ack=1 Win=330 Len=0 MSS=330
No. Time Source Destination Protocol Length Info
5 2.412673000 192.168.178.81 192.168.178.69 TCP 54 42582 > 7970 [ACK] Seq=1 Ack=1 Win=29200 Len=0
No. Time Source Destination Protocol Length Info
6 2.412771000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=1 Ack=1 Win=29200 Len=5
Data: 3132333435
[Length: 5]
No. Time Source Destination Protocol Length Info
7 2.414668000 192.168.178.69 192.168.178.81 TCP 60 [TCP ZeroWindow] 7970 > 42582 [ACK] Seq=1 Ack=6 Win=0 Len=0
No. Time Source Destination Protocol Length Info
8 2.423967000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [PSH, ACK] Seq=1 Ack=6 Win=255 Len=5
Data: 3132333435
[Length: 5]
No. Time Source Destination Protocol Length Info
9 2.424096000 192.168.178.81 192.168.178.69 TCP 54 42582 > 7970 [ACK] Seq=6 Ack=6 Win=29200 Len=0
No. Time Source Destination Protocol Length Info
10 2.424328000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=6 Ack=6 Win=29200 Len=5
Data: 3132333435
[Length: 5]
No. Time Source Destination Protocol Length Info
11 2.426127000 192.168.178.69 192.168.178.81 TCP 60 [TCP ZeroWindow] 7970 > 42582 [ACK] Seq=6 Ack=11 Win=0 Len=0
No. Time Source Destination Protocol Length Info
12 2.443925000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [PSH, ACK] Seq=6 Ack=11 Win=255 Len=5
Data: 3132333435
[Length: 5]
No. Time Source Destination Protocol Length Info
13 2.444213000 192.168.178.81 192.168.178.69 TCP 59 42582 > 7970 [PSH, ACK] Seq=11 Ack=11 Win=29200 Len=5
Data: 3132333435
[Length: 5]
No. Time Source Destination Protocol Length Info
14 2.445596000 192.168.178.69 192.168.178.81 TCP 60 7970 > 42582 [ACK] Seq=11 Ack=16 Win=255 Len=0
Post by e***@users.sourceforge.net
Völlig korrekt. Ethersex´ Zeitscheibe ist 20ms. Du könntest mal den Branch
new_timer_framework testen. Der zeigt ein deutlich besseres Zeitverhalten.
Habe ich getestet, passiert das gleiche. Oben ist das Ergebnis dieses Branches.
Ich habe auch den Hop über meinen Gigabit Switch mal eliminiert und direkt angeklemmt -> das gleiche Verhalten.
Hat jemand ne Idee wie ich das eventuell anders testen kann? Gibt es dafür Testskripte?
--
Michael Brakemeier
***@brakemeier.de
Michael Späth
2015-10-24 10:33:41 UTC
Permalink
Hallo Michael :-)
Post by Michael Brakemeier
mit wieviel Ticks/s hast du getestet? Standardeinstellung 50? Dann
sollte auch mit dem neuen Timer Framework das gleiche rauskommen.
Dreh doch bitte mal die "Periodic ticks per second" hoch, Größenordnung
500 Hz oder mehr, und wiederhole den Test.
Ok, habe ich gemacht (500): Es ändert sich garnichts. Wenn ich nicht
ziemlich genau 40msec zwischen den Requests warte droppt er die Pakete.

Zusätzlich habe ich eine andere Linux Distro probiert - absolut gleicher
Effekt.

Um Python auszuschließen habe ich den Test in C geschrieben - exakt
gleiches Resultat. Zwei Pakete gehen durch, drittes wurde gedroppt.

Und zum Schluß habe ich alles noch wiederholt mit einer zweiten Hardware
- einem Pollin NetIO (mit Original MEGA32) - der *exakt* das gleiche
Phänomen zeigt. Ich glaube jetzt habe ich restlos alles ausgeschlossen:
Branches, Client OS, Hardware und Client Software.


Zusätzlich habe ich noch andere Tests gefahren: Wenn ich die serielle
Schnittstelle zu mache nach einem Send/Receive, dann kann ich mit
beliebiger Speed das tun. Nur wenn ich sie offen lasse, dann passiert das.

Außerdem kann ich per ECMD auf Port 2701 auch mit beliebiger Speed
Kommandos absetzen: Alle kommen an und werden umgesetzt (Durschnittliche
Zeit: 2,4msec bei meinen Tests - also deutlich schneller als 40msec).


Ich habe auch ein bisschen gestöbert in yport*.c und habe die Funktion
yport_rxstart gefunden, die im zweiten if Teil gar kein ISR Lock macht -
damit könnte doch theoretisch die Interruptroutine Daten falsch senden
während dem memmove?

Ich habe mal einen provisorischen semlock drum gebastelt -> hat aber nix
geholfen. Denke, der Fall wird auch nur sehr selten passieren.

Aber genau dieser Teil müsste bei mir benutzt werden: Ich schreibe ja so
schnell, dass er dort umkopieren muss weil er vorher noch nicht fertig
ist, aber schon ein paar Bytes gesendet hat.


Ich bin ratlos und kurz davor, das YPort von Ethersex mit uip selbst
nach zu schreiben... :-( Bringt mir aber auch nicht viel, ich brauche
auch den Rest von EtherSex...
--
Michael
Udo1
2015-10-24 11:04:34 UTC
Permalink
Wenn ich die serielle Schnittstelle zu mache nach einem Send/Receive,
dann kann ich mit beliebiger Speed das tun. Nur wenn ich sie offen
lasse, dann passiert das.
Ändert sich was wenn du die Baudrate der seriellen Schnittstelle veränderst?

Gruß
Udo
Michael Späth
2015-10-24 12:21:10 UTC
Permalink
Hi!
Post by Udo1
Wenn ich die serielle Schnittstelle zu mache nach einem Send/Receive,
dann kann ich mit beliebiger Speed das tun. Nur wenn ich sie offen
lasse, dann passiert das.
Ändert sich was wenn du die Baudrate der seriellen Schnittstelle veränderst?
9600 und 115200 getestet. No change.
--
Michael
Michael Späth
2015-10-24 12:45:55 UTC
Permalink
Hi!

Habe weitere Tests gemacht: yport_rxstart wird erst gar nicht aufgerufen
beim Empfangen des dritten Paketes (habe einen Counter mitlaufen lassen
den ich in die ersten 4 Bytes jedes Antwort Paketes reingefummelt habe...)

D.h. uip_newdata() liefert 0 beim dritten Paket... habe das auch mal
debugged, und ja, es wird wirklich beim dritten Paket nicht aktiv (und
beim fünften, siebten, usw...)
--
Michael
Michael Späth
2015-10-24 13:12:47 UTC
Permalink
Hi!
Post by Michael Späth
Habe weitere Tests gemacht: yport_rxstart wird erst gar nicht aufgerufen
beim Empfangen des dritten Paketes (habe einen Counter mitlaufen lassen
den ich in die ersten 4 Bytes jedes Antwort Paketes reingefummelt habe...)
D.h. uip_newdata() liefert 0 beim dritten Paket... habe das auch mal
debugged, und ja, es wird wirklich beim dritten Paket nicht aktiv (und
beim fünften, siebten, usw...)
Ich habs gefixt. Es läuft nun alles wie gewünscht und sehr flott: 1.97msec für 4 bytes, keine drops.

Würde mich freuen wenn es jemand eincheckt, bin noch nicht so fit mit git (oder es mir kurz erklärt wie ich ein request mache, würde mich auch freuen).

(Fehler war: else if (uip_newdata()) übersprang einfach die neuen Daten wenn gleichzeitig ein anderes Event war (z.B. ACK von gesendeten Daten - was damit nix zu tun hat!!!))

Ich denke, das ist nie aufgefallen weil es nur passiert wenn im exakt gleichen Moment Daten ankommen und geschickt werden (loopback oder sehr schnelles Protokoll).

Gefunden habe ich den Fehler übrigens weil ich mir den Code vom Telnet und I2C Slave Protocol angeguckt habe... da ist übrigens richtig ;-)


Ach ja, hier ist es eventuell auch falsch:


protocols/ems/ems_net.c: } else if (uip_newdata()) {
protocols/modbus/modbus_net.c: } else if (uip_newdata()) {
protocols/mqtt/mqtt.c: else if (uip_newdata() && uip_len) {
protocols/irc/irc.c: else if (uip_newdata() && uip_len) {
protocols/bsbport/bsbport_net.c: else if (uip_newdata())

MQTT und ModBus gucke ich mir später eventuell noch an, da ich die selbst in meinem Haus als Bus verwende und dafür auch den EtherSex testen wollte. Aber ich denke "else" dort überall wegzunehmen sollte ok sein...



diff --git a/protocols/yport/yport_net.c b/protocols/yport/yport_net.c
index 6eb27a8..a1a10cf 100755
--- a/protocols/yport/yport_net.c
+++ b/protocols/yport/yport_net.c
@@ -85,8 +85,10 @@ yport_net_main(void)
if (yport_conn == uip_conn)
yport_conn = NULL;
}
- else if (uip_newdata())
+
+ if (uip_newdata())
{
+
if (uip_len <= YPORT_BUFFER_LEN &&
yport_rxstart(uip_appdata, uip_len) != 0)
{
--
Michael
e***@users.sourceforge.net
2015-10-24 13:46:50 UTC
Permalink
Hallo Michael,
Post by Michael Späth
Ich habs gefixt. Es läuft nun alles wie gewünscht und sehr flott: 1.97msec für 4 bytes, keine drops.
super Einsatz. Danke für die Analyse.
Post by Michael Späth
Würde mich freuen wenn es jemand eincheckt, bin noch nicht so fit mit git (oder es mir kurz erklärt wie ich ein request mache, würde mich auch freuen).
Leg wenigstens ein neues Issue im Projekt auf GH an. Ich kümmere
mich um den PR.
[...]

Schau ich mir an.
Bastian Bittorf
2015-10-26 06:23:34 UTC
Permalink
Post by Michael Späth
Würde mich freuen wenn es jemand eincheckt, bin noch nicht so fit mit git (oder es mir kurz erklärt wie ich ein request mache, würde mich auch freuen).
Der Weg ist so:

1) git clone $ethersex
2) eigenen zweig machen: git checkout -b meinzweig
3) deine aenderungen machen
4) git commit ...dein_text...
5) git push

beim letzten gibt es eine fehlermeldung und die anweisung
befolgst du dann einfach ("remote branches...")

und NUN kannst du im webinterface von github einen pullrequest machen
("compare and merge"). versuchs mal und sag woran es hakt.

bye, bastian

Bastian Bittorf
2015-10-26 06:19:52 UTC
Permalink
Post by Michael Späth
Gefunden habe ich den Fehler übrigens weil ich mir den Code vom Telnet und I2C Slave Protocol angeguckt habe... da ist übrigens richtig ;-)
Danke! bye, bastian
Loading...