ECONNRESET triggert Amok-Lauf von select/read auf Socket-Verbindung

[Dr. Boris Neubert]

Hallo,

in http://forum.fhem.de/index.php/topic,31307.30.html hat ein Anwender folgendes Problem: Er hat per ECMD/ECMDDevice eine Socket-Verbindung zu einem entfernten Rechner. Wenn der entfernte Rechner den Port schließt, löst dies ein ECONNRESET aus, welches FHEM in einen Amok-Lauf schickt. Das ist unten ganz gut zu sehen: select auf Filehandle 4 liefert immer wieder 1, aber der read auf Filehandle 4 liest nichts mehr. Da ECMD DevIO verwendet auf die globale select-Schleife zugreift, gehe ich davon aus, dass es sich um select und read in der fhem-MAIN-Loop handelt.

An welcher Stelle muss eingegriffen werden, um den Amoklauf zu stoppen?

Viele Grüße
Boris

Code Auswählen Erweitern

10:27:17.384651 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4 <0.000287>
10:27:17.385548 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbec958ec) = -1 ENOTTY (Inappropriate ioctl for device) <0.000092>
10:27:17.385976 _llseek(4, 0, 0xbec95948, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000142>
10:27:17.386485 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbec958ec) = -1 ENOTTY (Inappropriate ioctl for device) <0.000081>
10:27:17.386828 _llseek(4, 0, 0xbec95948, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000071>
10:27:17.387217 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 <0.000079>
10:27:17.388309 fcntl64(4, F_GETFL)     = 0x2 (flags O_RDWR) <0.000145>
10:27:17.388808 fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000076>
10:27:17.389307 connect(4, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.xxx.xxx.205")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000290>
10:27:17.391680 select(8, NULL, [4], NULL, {3, 0}) = 1 (out [4], left {2, 999976}) <0.000283>
10:27:17.392834 connect(4, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.xxx.xxx.205")}, 16) = 0 <0.000121>
10:27:17.393791 fcntl64(4, F_GETFL)     = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000100>
10:27:17.394302 fcntl64(4, F_SETFL, O_RDWR) = 0 <0.000082>
10:27:17.394986 setsockopt(4, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000126>
10:27:17.395927 gettimeofday({1423387637, 396111}, NULL) = 0 <0.000223>
10:27:17.396545 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000109>
10:27:17.398062 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 47776}) <0.052365>
####### 10:27:17.451444 read(4, 0x3bfc560, 4096) = -1 ECONNRESET (Connection reset by peer) <0.000126>    ####### HIER passiert's
10:27:17.452215 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99976}) <0.000130>
10:27:17.452920 read(4, "", 4096)       = 0 <0.000184>
10:27:17.453536 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99985}) <0.000110>
10:27:17.454196 read(4, "", 4096)       = 0 <0.000102>
10:27:17.454702 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99985}) <0.000110>
10:27:17.455477 read(4, "", 4096)       = 0 <0.000099>
10:27:17.455926 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99983}) <0.000106>
10:27:17.456541 read(4, "", 4096)       = 0 <0.000100>
10:27:17.456984 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99987}) <0.000072>
10:27:17.457586 read(4, "", 4096)       = 0 <0.000095>
10:27:17.458014 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99983}) <0.000113>
10:27:17.458809 read(4, "", 4096)       = 0 <0.000098>
10:27:17.459300 select(8, [4], NULL, NULL, {0, 100000}) = 1 (in [4], left {0, 99986}) <0.000106>

[rudolfkoenig]

Ich habe keine Idee, wie die Schleife entsteht:

- DevIo_SimpleRead wuerde in diesem Fall DevIo_DoSimpleRead, DevIo_SimpleReadWithTimeout, DevIo_DoSimpleRead und DevIo_Disconnected aufrufen. Die Moeglichkeit einer Schleife sehe ich nicht.
- DevIo_Expect haette DevIo_SimpleWrite aufrufen sollen, das sieht man aber nicht.
- DevIo_SimpleReadWithTimeout aus ECMD_SimpleExpect duerfte auch nicht sein.
- DevIo_TimeoutRead aus ECMD_Clear koennte zwar sowas verursachen, allerdings wird hier select mit 0.1s aufgerufen, und nicht mit 1s wie im log

Koenntest du mit mehr debugging rausfinden, welcher der DevIo Funktionen hier aufgerufen wird?

[Dr. Boris Neubert]

Hallo,

habe alle Routinen in DevIo.pm mit einer Debug-Ausgabe versehen und den Anwender um einen neuen Crashtest gebeten. Hier der relevante Teil aus dem globalen Log (modifiziertes DevIO.pm im Thread, auf dem ich im ersten Post verwies).

Grüße
Boris

Code Auswählen Erweitern

2015.02.08 13:48:25.476 1: DEBUG>SimpleRead: EBUS
2015.02.08 13:48:25.477 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.477 1: DEBUG>DoSimpleRead: zero length buffer
2015.02.08 13:48:25.478 1: DEBUG>DoSimpleReadWithTimeout: 1, EBUS
2015.02.08 13:48:25.478 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.479 1: DEBUG>Disconnected: EBUS
2015.02.08 13:48:25.479 1: 192.xxx.xxx.205:8888 disconnected, waiting to reappear (EBUS)
2015.02.08 13:48:25.480 1: DEBUG>CloseDev: EBUS
2015.02.08 13:48:25.481 5: Triggering EBUS (1 changes)
2015.02.08 13:48:25.482 5: Notify loop for EBUS DISCONNECTED
2015.02.08 13:48:25.498 1: DEBUG>OpenDev: EBUS     ######## Wie kommt das zustande? Der Benutzer reagiert nicht auf DISCONNECTED und wir sind auch nicht in Expect
2015.02.08 13:48:25.501 1: 192.xxx.xxx.205:8888 reappeared (EBUS)
2015.02.08 13:48:25.502 1: DEBUG>TimeoutRead: 0.1, EBUS
2015.02.08 13:48:25.579 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.580 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.581 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.581 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.582 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.582 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.583 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.583 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.584 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.584 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.585 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.585 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.586 1: DEBUG>DoSimpleRead: EBUS
2015.02.08 13:48:25.586 1: DEBUG>DoSimpleRead: EBUS
usw. usw. usw.

[rudolfkoenig]

Habe TimeoutRead angepasst und eingecheckt.

[Dr. Boris Neubert]

Anwender hat getestet, Problem beseitigt, ich danke auch.

Viele Grüße
Boris