[verstanden] Log von strace interpretieren

Begonnen von KölnSolar, 26 April 2021, 12:50:21

Vorheriges Thema - Nächstes Thema

KölnSolar

Ich bin auf der Suche nach nicht nachvollziehbaren blockierenden Lesezugriffen. Das Ganze findet im Perl-Paket XML::Simple statt(glaube ich).

Mit strace hab ich mal den Prozess gelogged. Für mich aber böhmische Dörfer. Erkennt da jemand den Grund, warum nach dem Empfang von Daten von einem device 5s auf ein erfolgreiches weiteres Lesen/Datenempfang gewartet wird ? Was blockiert das Lesen(Datenempfang) ?

recvfrom(27, "NOTIFY * HTTP/1.1\r\nHOST: 239.255"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(3955), sin_addr=inet_addr("192.168.178.62")}, [4096->16]) = 359
openat(AT_FDCWD, "/etc/protocols", O_RDONLY|O_CLOEXEC) = 5
_llseek(5, 0, [0], SEEK_CUR)            = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2932, ...}) = 0
read(5, "# Internet (IP) protocols\n#\n# Up"..., 4096) = 2932
close(5)                                = 0
socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC, NETLINK_ROUTE) = 5
bind(5, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 0
getsockname(5, {sa_family=AF_NETLINK, nl_pid=13821, nl_groups=00000000}, [12]) = 0
gettimeofday({tv_sec=1619418856, tv_usec=406431}, NULL) = 0
sendto(5, {{len=20, type=0x16 /* NLMSG_??? */, flags=NLM_F_REQUEST|0x300, seq=1619418856, pid=0}, "\x00\x00\x00\x00"}, 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=76, type=0x14 /* NLMSG_??? */, flags=NLM_F_MULTI, seq=1619418856, pid=13821}, "\x02\x08\x80\xfe\x01\x00\x00\x00\x08\x00\x01\x00\x7f\x00\x00\x01\x08\x00\x02\x00\x7f\x00\x00\x01\x07\x00\x03\x00\x6c\x6f\x00\x00"...}, {{len=88, type=0x14 /* NLMSG_??? */, flags=NLM_F_MULTI, seq=1619418856, pid=13821}, "\x02\x18\x80\x00\x02\x00\x00\x00\x08\x00\x01\x00\xc0\xa8\xb2\x2f\x08\x00\x02\x00\xc0\xa8\xb2\x2f\x08\x00\x04\x00\xc0\xa8\xb2\xff"...}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 164
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{{len=72, type=0x14 /* NLMSG_??? */, flags=NLM_F_MULTI, seq=1619418856, pid=13821}, "\x0a\x80\x80\xfe\x01\x00\x00\x00\x14\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x14\x00\x06\x00"...}, {{len=72, type=0x14 /* NLMSG_??? */, flags=NLM_F_MULTI, seq=1619418856, pid=13821}, "\x0a\x40\x80\xfd\x02\x00\x00\x00\x14\x00\x01\x00\xfe\x80\x00\x00\x00\x00\x00\x00\xe8\x57\xbd\xc4\x38\x05\xad\xa0\x14\x00\x06\x00"...}], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 144
recvmsg(5, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base={{len=20, type=NLMSG_DONE, flags=NLM_F_MULTI, seq=1619418856, pid=13821}, 0}, iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 20
--------------> bis hier scheint die Welt in Ordnung wie ich aus seq=1619418856(scheint ja ein timestamp zu sein) schließe
                                sind die folgenden Zeilen schon Fehlerhinweise oder antwortet das device tatsächlich nicht ??????
close(5)                                = 0
socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 5
fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0
ioctl(5, TCGETS, 0xbe9ae2a0)            = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
_llseek(5, 0, 0xbe9ae2f0, SEEK_CUR)     = -1 ESPIPE (Nicht erlaubter Seek)
fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0
ioctl(5, TCGETS, 0xbe9ae2a0)            = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
_llseek(5, 0, 0xbe9ae2f0, SEEK_CUR)     = -1 ESPIPE (Nicht erlaubter Seek)
fcntl64(5, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(5, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
connect(5, {sa_family=AF_INET, sin_port=htons(9197), sin_addr=inet_addr("192.168.178.62")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
_newselect(8, NULL, [5], [5], {tv_sec=5, tv_usec=0}) = 0 (Timeout)
fcntl64(5, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(5, F_SETFL, O_RDWR)             = 0
close(5)                                = 0
gettimeofday({tv_sec=1619418861, tv_usec=570816}, NULL) = 0
gettimeofday({tv_sec=1619418861, tv_usec=574063}, NULL) = 0
gettimeofday({tv_sec=1619418861, tv_usec=581421}, NULL) = 0
gettimeofday({tv_sec=1619418861, tv_usec=582343}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(4, "2021.04.26 08:34:21 5: UPNPContr"..., 249) = 249

2021.04.26 08:34:21 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.178.62:9197 (Connection timed out) (Location: http://192.168.178.62:9197/dmr) at ./FHEM/98_UPNPController.pm line 220.


Danke&Grüße
Markus
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

connect(5, {sa_family=AF_INET, sin_port=htons(9197), sin_addr=inet_addr("192.168.178.62")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
_newselect(8, NULL, [5], [5], {tv_sec=5, tv_usec=0}) = 0 (Timeout)

Da versucht jemand Verbindung zu 192.168.178.62, Port 9197 aufzunehmen, das kommt aber innerhalb von 5s nicht zustande.
Vmtl. Rechner aus oder Firewall verhindert eine Antwort.

KölnSolar

#2
Hi Rudi,
danke für die Rückmeldung.
ZitatDa versucht jemand Verbindung zu 192.168.178.62, Port 9197 aufzunehmen, das kommt aber innerhalb von 5s nicht zustande.
Das ist korrekt.
ZitatVmtl. Rechner aus oder Firewall verhindert eine Antwort.
Aus kann eigentlich nicht sein. Gerät(TV) ist an und bei einem parallel laufenden System funktioniert auch alles einwandfrei. Firewall wird es vermutlich nicht geben bzw. kann ich am TV ja nichts einstellen. Aber ich hatte auch im Verdacht, dass der TV die IP blockiert, denn aufgetreten ist es "plötzlich" im laufenden Betrieb. Ich hatte das schon einmal und bin dran verzweifelt. Um irgendwelche OS-Unterschiede auszuschließen hatte ich auf beiden zugreifenden Systemen denselben Zustand hergestellt uns "plötzlich" war dieses seltsame Fehlverhalten weg.

Um es überhaupt etwas besser zu verstehen: Du erkennst in dem Logauszug, dass etwas gesendet wurde und dann 5s keine Antwort(im Gegensatz zu Antwort kam, wurde aber nicht verarbeitet) kam ? Dann müsste ich ja z.B. erst gar nicht gucken, ob tcpdump mir etwas anderes ausspuckt. Am TV gibt es eine debugging Möglichkeit. Vielleicht sollte ich da mal gucken, ob sich etwas feststellen lässt.

Grüße Markus

Edit: Du hattest gesehen, dass in Zeile 1 des Logauszugs genau von der IP eine message empfangen wurde ? Und wird dann nicht ein paar Zeilen später etwas an den TV gesendet und auch wieder empfangen ?

RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

ZitatDu erkennst in dem Logauszug, dass etwas gesendet wurde und dann 5s keine Antwort(im Gegensatz zu Antwort kam, wurde aber nicht verarbeitet) kam ?
Mir ist unklar, worauf Du hinauswillst. connect() beauftragt den Kernel, eine TCP/IP Verbindung auzubauen, und es zu melden, wenn es erfolgt ist. Dafuer sendet der Kernel ein Netzwerkpaket, und das wird wiederholt, falls kein ACK von der Gegenseite kommt. Das kam wohl innerhalb der 5 Sekunden nicht. Fuer mehr Details empfehle ich "TCP/IP Illustrated, Volume 1".
Btw., strace gibt mit --tt Zeitstempel aus, das hilft in solchen Faellen sehr.

ZitatEdit: Du hattest gesehen, dass in Zeile 1 des Logauszugs genau von der IP eine message empfangen wurde ?
Nein, beweist aber wenig, da in der Zwischenzeit ja jede Menge passieren koennte. Es kann auch sein, dass der Fernseher auf Port 9197 kein Port offen hat, und kein "Connection-Refused" sendet (aka Firewall).

KölnSolar

#4
ZitatMir ist unklar, worauf Du hinauswillst.
Nur verstehen, warum es mit dem einen System funktioniert und dem anderen nicht.  ;)

Zitatbeweist aber wenig, da in der Zwischenzeit ja jede Menge passieren koennte.
Es passiert nicht sporadisch, sondern dieses Verhalten ist permanent.

ZitatBtw., strace gibt mit --tt Zeitstempel aus, das hilft in solchen Faellen sehr.
Der hat mir gut geholfen, mal einen Vergleich beider Systeme zu fahren(und den genauen Zeitpunkt des timeouts zu erkennen(und gelernt, das timeout timeout bedeutet  ::) )):

funktioniert17:57:58.017729 connect(52, {sa_family=AF_INET, sin_port=htons(9197), sin_addr=inet_addr("192.168.178.62")}, 16) = -1 EINPROGRESS (Operation now in progress)
--------------> ab hier läuft es anders
------------------- kein timeout -----------------
17:57:58.018208 _newselect(56, NULL, [52], [52], {tv_sec=20, tv_usec=0}) = 1 (left {tv_sec=19, tv_usec=988584})
------------------- kein timeout -----------------
17:57:58.029962 getsockopt(52, SOL_SOCKET, SO_ERROR, [0], [256->4]) = 0
17:57:58.030258 fcntl64(52, F_GETFL)    = 0x802 (flags O_RDWR|O_NONBLOCK)
17:57:58.030449 fcntl64(52, F_SETFL, O_RDWR) = 0
17:57:58.030955 fcntl64(52, F_GETFL)    = 0x2 (flags O_RDWR)
17:57:58.031142 fcntl64(52, F_SETFL, O_RDWR|O_NONBLOCK) = 0
17:57:58.032507 write(52, "GET /dmr HTTP/1.1\r\nConnection: c"..., 97) = 97
17:57:58.033151 _newselect(56, [52], NULL, NULL, {tv_sec=20, tv_usec=0}) = 1 (in [52], left {tv_sec=19, tv_usec=974698})
17:57:58.058862 read(52, "HTTP/1.1 200 OK\r\nContent-Type: t"..., 1024) = 1024
17:57:58.060314 getpeername(52, {sa_family=AF_INET, sin_port=htons(9197), sin_addr=inet_addr("192.168.178.62")}, [256->16]) = 0
17:57:58.062584 _newselect(56, [52], NULL, NULL, {tv_sec=20, tv_usec=0}) = 1 (in [52], left {tv_sec=19, tv_usec=999981})
17:57:58.063054 read(52, "nufacturerURL>\n    <modelDescrip"..., 2454) = 2454
17:57:58.063636 close(52)               = 0
funktioniert nicht16:45:56.904090 connect(5, {sa_family=AF_INET, sin_port=htons(9197), sin_addr=inet_addr("192.168.178.62")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
------------------- timeout -----------------
16:45:56.906123 _newselect(8, NULL, [5], [5], {tv_sec=5, tv_usec=0}) = 0 (Timeout)
------------------- timeout -----------------16:46:01.912527 fcntl64(5, F_GETFL)     = 0x802 (flags O_RDWR|O_NONBLOCK)
16:46:01.913391 fcntl64(5, F_SETFL, O_RDWR) = 0
16:46:01.914898 close(5)                = 0


Du hast das vermutlich vorher schon so gesehen, ich erst durch die timestamps und den Vergleich. Also kommt das connect nicht beim TV an, wird "ignoriert" oder das ACK bleibt irgendwo hängen. Letzteres kann man doch ausschließen, wenn andere messages von der selben IP "durchkommen", oder ? Und wo ich so weiter denke, denk ich versuchs mal mit nem ping oder einem anderen FHEM-Modul oder curl....
Noch nicht einmal das ping geht durch !!!!!  :o

Nun die entsprechenden devices aus der config rausgenommen, ein restart des raspberry.. kein Ping möglich.

Kann im Raspberry was "verklemmt" sein ? ARP-Cache schon geflushed und ist auf beiden Systemen gleich.

Dann nochmal den TV komplett stromlos.....und die Überraschung: es pingt und auch mein UPNPController u. DLNAController läuft wieder wie er soll.

Verrückt. Wie immer in solchen Fällen, hab ich an einigen Stellen gesucht. Weil das Ding öfter mal etwas spinnt: Könnte es am Anschluss über powerline(genau der TestRPi u. der TV laufen über powerline) liegen, obwohl der normale Netzwerk-Traffic funktioniert ?

Danke & Grüße Markus
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt