[gelöst] Nonblocking connect bei DevIo_OpenDev

Ralf9 · 17 August 2016, 18:47:19

Hallo,

kann es sein, daß das Nonblocking connect nur bei der HttpUtils.pm funktioniert?

Mir ist aufgefallen, daß bei der 00_HMUARTLGW.pm ein Nonblocking connect eingebaut wurde.
Ich habe versucht das Nonblocking connect auch in der 00_SIGNALduino.pm einzubauen, aber es scheint dort nicht zu funktionieren.

Wenn ein connect nicht möglich ist, erscheint im log:

Code Auswählen

2016.08.17 17:48:28 3: Opening sduinoE device 192.168.0.98:23
2016.08.17 17:48:31 3: Can't connect to 192.168.0.98:23: Die Wartezeit für die Verbindung ist abgelaufen

In der DevIo.pm wird ein Nonblocking connect unterstützt:

Code Auswählen

# callback is only meaningful for TCP/IP (Nonblocking connect), but can used in
# every cases. It will be called with $hash and a (potential) error message
sub
DevIo_OpenDev($$$;$)

Hier ist ein Auszug von der 00_SIGNALduino.pm:

Code Auswählen

sub SIGNALduino_Define($$)
{
...
$ret = DevIo_OpenDev($hash, 0, "SIGNALduino_DoInit", &SIGNALduino_Connect);
...
}


sub SIGNALduino_Ready($)
{
  my ($hash) = @_;

  return DevIo_OpenDev($hash, 1, "SIGNALduino_DoInit", &SIGNALduino_Connect)
                if($hash->{STATE} eq "disconnected");

  # This is relevant for windows/USB only
  my $po = $hash->{USBDev};
  my ($BlockingFlags, $InBytes, $OutBytes, $ErrorFlags);
  if($po) {
    ($BlockingFlags, $InBytes, $OutBytes, $ErrorFlags) = $po->status;
  }
  return ($InBytes && $InBytes>0);
}


sub SIGNALduino_Connect($$)
{
	my ($hash, $err) = @_;

	Log3($hash, 4, "SIGNALduino $hash->{NAME}: ${err}") if ($err);
}

Gruß Ralf

rudolfkoenig · 17 August 2016, 20:00:54

Zitatkann es sein, daß das Nonblocking connect nur bei der HttpUtils.pm funktioniert?

So pauschal kann das nicht sein, ich habe Nonblocking connect mit DevIo_OpenDev getestet.

ZitatCan't connect to 192.168.0.98:23: Die Wartezeit für die Verbindung ist abgelaufen

Da FHEM keine deutsche Meldungen kennt, kommt diese Fehlermeldung vom OS. Das duerfte bei einem Nonblocking connect mit numerische IP-Adresse, ohne SSL eigentlich nicht moeglich sein. Kannst du ein strace-Mitschnitt von diesem Vorgang erstellen? Ist DevIo.pm und HttpUtils.pm aktuell?

Ralf9 · 17 August 2016, 21:26:22

Zitat von: rudolfkoenig am 17 August 2016, 20:00:54
Da FHEM keine deutsche Meldungen kennt, kommt diese Fehlermeldung vom OS. Das duerfte bei einem Nonblocking connect mit numerische IP-Adresse, ohne SSL eigentlich nicht moeglich sein. Kannst du ein strace-Mitschnitt von diesem Vorgang erstellen? Ist DevIo.pm und HttpUtils.pm aktuell?

Müssten aktuell sein, ich habe heute Abend ein update gemacht.
fhem.pl 11922 2016-08-08 14:39:02Z
DevIo.pm 11786 2016-07-12 08:44:10Z
HttpUtils.pm 11935 2016-08-10 09:09:03Z

Zum Testen verwende ich meinen PC mit openSUSE 13.1 mit Intel i5-4570 CPU

Meinst Du mit strace das hier?

Code Auswählen

ralf@linux-ralf4:~/prog/fhem-5.5> strace -f -o strace.txt perl fhem.pl fhem.cfg

Code Auswählen


3754  write(3, "2016.08.17 20:50:02 3: Opening s"..., 62) = 62
3754  socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 32
3754  ioctl(32, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff605dcfe0) = -1 ENOTTY (Inappropriate ioctl for device)
3754  lseek(32, 0, SEEK_CUR)            = -1 ESPIPE (Illegal seek)
3754  ioctl(32, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff605dcfe0) = -1 ENOTTY (Inappropriate ioctl for device)
3754  lseek(32, 0, SEEK_CUR)            = -1 ESPIPE (Illegal seek)
3754  fcntl(32, F_SETFD, FD_CLOEXEC)    = 0
3754  fcntl(32, F_GETFL)                = 0x2 (flags O_RDWR)
3754  fcntl(32, F_SETFL, O_RDWR|O_NONBLOCK) = 0
3754  connect(32, {sa_family=AF_INET, sin_port=htons(23), sin_addr=inet_addr("192.168.0.98")}, 16) = -1 EINPROGRESS (Operation now in progress)
3754  stat("/usr/lib/perl5/site_perl/5.18.1/x86_64-linux-thread-multi/IO/Select.pmc", 0x7fff605dd110) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/site_perl/5.18.1/x86_64-linux-thread-multi/IO/Select.pm", 0x7fff605dd060) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/site_perl/5.18.1/IO/Select.pmc", 0x7fff605dd110) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/site_perl/5.18.1/IO/Select.pm", 0x7fff605dd060) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/vendor_perl/5.18.1/x86_64-linux-thread-multi/IO/Select.pmc", 0x7fff605dd110) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/vendor_perl/5.18.1/x86_64-linux-thread-multi/IO/Select.pm", 0x7fff605dd060) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/vendor_perl/5.18.1/IO/Select.pmc", 0x7fff605dd110) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/vendor_perl/5.18.1/IO/Select.pm", 0x7fff605dd060) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/5.18.1/x86_64-linux-thread-multi/IO/Select.pmc", 0x7fff605dd110) = -1 ENOENT (No such file or directory)
3754  stat("/usr/lib/perl5/5.18.1/x86_64-linux-thread-multi/IO/Select.pm", {st_mode=S_IFREG|0444, st_size=8247, ...}) = 0
3754  open("/usr/lib/perl5/5.18.1/x86_64-linux-thread-multi/IO/Select.pm", O_RDONLY) = 33
3754  ioctl(33, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff605dce10) = -1 ENOTTY (Inappropriate ioctl for device)
3754  lseek(33, 0, SEEK_CUR)            = 0
3754  read(33, "# IO::Select.pm\n#\n# Copyright (c"..., 8192) = 8192
3754  brk(0x2e46000)                    = 0x2e46000
3754  brk(0x2e67000)                    = 0x2e67000
3754  lseek(33, 4259, SEEK_SET)         = 4259
3754  lseek(33, 0, SEEK_CUR)            = 4259
3754  close(33)                         = 0
3754  getuid()                          = 1000
3754  geteuid()                         = 1000
3754  getgid()                          = 100
3754  getegid()                         = 100
3754  select(40, NULL, [32], [32], {3, 0}) = 0 (Timeout)
3754  fcntl(32, F_GETFL)                = 0x802 (flags O_RDWR|O_NONBLOCK)
3754  fcntl(32, F_SETFL, O_RDWR)        = 0
3754  close(32)                         = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  write(3, "2016.08.17 20:50:05 3: Can't con"..., 106) = 106
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  write(3, "2016.08.17 20:50:05 3: sduinoE: "..., 54) = 54
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  write(3, "2016.08.17 20:50:05 3: sduinoE: "..., 48) = 48
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  write(3, "2016.08.17 20:50:05 3: sduinoE: "..., 43) = 43
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  write(3, "2016.08.17 20:50:05 3: sduinoE: "..., 43) = 43
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
3754  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0

Gruß Ralf

rudolfkoenig · 18 August 2016, 11:39:16

1. Was meinst du mit "funktioniert nicht"? Dass die Verbindung nicht hergestellt wird, oder dass FHEM waehrend der 3 Sekunden blockiert?

2. Ich habe ein Testmodul mit DevIo_OpenDev nonblocking TCP open gebaut. Verbindung zu eine existierende Adresse/Port funktioniert ohne Fehler/sofort.

3. Verbindung mit diesem Testmodul zu eine nicht existente IP-Adresse (192.68.0.1) meldet nach 3 Sekunden "connect to http://192.68.0.1:23 timed out", das ist fuer mich nachvollzeihbar, es kommt aus HttpUtils.pm. Getestet unter OSX mit perl 5.16, 5.20, 5.24 und unter Linux mit perl 5.18.2.

4. In deinem Fall wird Select.pm geladen, mit meinem Testmodul laut meinem strace nicht. Den Code fuer Select.pm laden kann man in IO/Socket.pm, sub connect nachvollziehen, passiert aber nur wenn $sock->timeout gesetzt ist. Komisch: meine "print" Ausgaben in einem modifizierten IO/Socket.pm werden nicht ausgegeben, das verwirrt mich z.Zt. Wenn hier jemand eine Idee hat, bitte melden, wuerde mich freuen.

Ich vermute, dass du entweder irgendwo/irgendwie $sock->timeout setzt, oder einen anderen connect verwendest, durch andere "use ..." Anweisungen.

Ralf9 · 18 August 2016, 12:44:33

Zitat von: rudolfkoenig am 18 August 2016, 11:39:16
1. Was meinst du mit "funktioniert nicht"? Dass die Verbindung nicht hergestellt wird, oder dass FHEM waehrend der 3 Sekunden blockiert?

2. Ich habe ein Testmodul mit DevIo_OpenDev nonblocking TCP open gebaut. Verbindung zu eine existierende Adresse/Port funktioniert ohne Fehler/sofort.

3. Verbindung mit diesem Testmodul zu eine nicht existente IP-Adresse (192.68.0.1) meldet nach 3 Sekunden "connect to http://192.68.0.1:23 timed out", das ist fuer mich nachvollzeihbar, es kommt aus HttpUtils.pm. Getestet unter OSX mit perl 5.16, 5.20, 5.24 und unter Linux mit perl 5.18.2.

4. In deinem Fall wird Select.pm geladen, mit meinem Testmodul laut meinem strace nicht. Den Code fuer Select.pm laden kann man in IO/Socket.pm, sub connect nachvollziehen, passiert aber nur wenn $sock->timeout gesetzt ist. Komisch: meine "print" Ausgaben in einem modifizierten IO/Socket.pm werden nicht ausgegeben, das verwirrt mich z.Zt. Wenn hier jemand eine Idee hat, bitte melden, wuerde mich freuen.

Ich vermute, dass du entweder irgendwo/irgendwie $sock->timeout setzt, oder einen anderen connect verwendest, durch andere "use ..." Anweisungen.

Ich habe zum Testen eine freie IP-Adresse benutzt. Während der 3 Sekunden wird fhem blockiert.

Ich werde es heute Abend auch mal mit dem 00_HMUARTLGW.pm testen z.B.

Code Auswählen

define myHmUART HMUARTLGW uart://192.168.0.210:1000

Wenn ich Dein Testmodul haben kann, dann kann ich es auch damit mal testen.

ZitatIch vermute, dass du entweder irgendwo/irgendwie $sock->timeout setzt, oder einen anderen connect verwendest, durch andere "use ..." Anweisungen.

$sock->timeout wird nicht verwendet

es werden die folgenden use verwendet:

Code Auswählen

use strict;
use warnings;
use Time::HiRes qw(gettimeofday);
use Data::Dumper qw(Dumper);
use Scalar::Util qw(looks_like_number);

Gruß Ralf

rudolfkoenig · 18 August 2016, 13:01:34

ZitatWenn ich Dein Testmodul haben kann, dann kann ich es auch damit mal testen.

Usage: define d dtest 192.68.0.1:23

Ralf9 · 18 August 2016, 18:18:40

Mit Hilfe des Testmoduls habe ich nun herausgefunden, warum es beim 00_HMUARTLGW.pm und beim SIGNALduino mit dem nonBlocking nicht funktioniert hat.

So funktioniert es nicht:

Code Auswählen

sub HMUARTLGW_Define($$)
{
...
return DevIo_OpenDev($hash, 0, "HMUARTLGW_DoInit", &HMUARTLGW_Connect);
}

sub HMUARTLGW_Connect($$)
{
	my ($hash, $err) = @_;

	Log3($hash, 5, "HMUARTLGW $hash->{NAME}: ${err}") if ($err);
}

So funktioniert es:

Code Auswählen

sub HMUARTLGW_Define($$)
{
...
	return DevIo_OpenDev($hash, 0, "HMUARTLGW_DoInit", sub(){Log 1, "OD:".join("/",@_);});
}

damit

Code Auswählen

define d1 dtest 192.168.0.211:23
define d2 dtest 192.168.0.212:23
define d3 dtest 192.168.0.213:23
define myHmUART5 HMUARTLGW uart://192.168.0.215:23
define myHmUART6 HMUARTLGW uart://192.168.0.216:23

bekomme ich dann folgendes log:

Code Auswählen

2016.08.18 17:56:28 1: Including fhem.cfg
2016.08.18 17:56:28 3: telnetPort: port 7072 opened
2016.08.18 17:56:28 3: WEB: port 8083 opened
2016.08.18 17:56:28 3: Opening d1 device 192.168.0.211:23
2016.08.18 17:56:28 3: Opening d2 device 192.168.0.212:23
2016.08.18 17:56:28 3: Opening d3 device 192.168.0.213:23
2016.08.18 17:56:28 3: Opening myHmUART5 device 192.168.0.215:23
2016.08.18 17:56:28 3: Opening myHmUART6 device 192.168.0.216:23
2016.08.18 17:56:28 1: Including ./log/fhem.save
2016.08.18 17:56:28 0: Featurelevel: 5.7
2016.08.18 17:56:28 0: Server started with 10 defined entities (fhem.pl:11922/2016-08-08 perl:5.018001 os:linux user:ralf pid:2755)
2016.08.18 17:56:31 3: Can't connect to 192.168.0.211:23: 
2016.08.18 17:56:31 1: OD:HASH(0x2a390d8)/connect to http://192.168.0.211:23 timed out
2016.08.18 17:56:31 3: Can't connect to 192.168.0.212:23: 
2016.08.18 17:56:31 1: OD:HASH(0x2a441e0)/connect to http://192.168.0.212:23 timed out
2016.08.18 17:56:31 3: Can't connect to 192.168.0.213:23: 
2016.08.18 17:56:31 1: OD:HASH(0x2a45b58)/connect to http://192.168.0.213:23 timed out
2016.08.18 17:56:31 3: Can't connect to 192.168.0.215:23: 
2016.08.18 17:56:31 1: OD:HASH(0x2a468e8)/connect to http://192.168.0.215:23 timed out
2016.08.18 17:56:31 3: Can't connect to 192.168.0.216:23: 
2016.08.18 17:56:31 1: OD:HASH(0x2a42be0)/connect to http://192.168.0.216:23 timed out
2016.08.18 17:56:32 1: HMUARTLGW myHmUART6 Reopen
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:32 1: HMUARTLGW myHmUART5 Reopen
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:32 1: HMUARTLGW myHmUART6 Reopen
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:32 1: HMUARTLGW myHmUART5 Reopen
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:32 1: Ready Called
2016.08.18 17:56:33 1: HMUARTLGW myHmUART6 Reopen
2016.08.18 17:56:33 1: Ready Called
2016.08.18 17:56:33 1: HMUARTLGW myHmUART5 Reopen
2016.08.18 17:56:33 1: Ready Called
2016.08.18 17:56:33 1: Ready Called
2016.08.18 17:56:33 1: HMUARTLGW myHmUART6 Reopen
2016.08.18 17:56:33 1: Ready Called
2016.08.18 17:56:33 1: HMUARTLGW myHmUART5 Reopen
2016.08.18 17:56:33 1: Ready Called
2016.08.18 17:56:33 1: Ready Called

Gruß Ralf

Ralf9 · 19 August 2016, 08:56:37

Inzwischen habe ich den Fehler gefunden.
Wenn ich in dem DevIo_OpenDev Aufruf das &HMUARTLGW_Connect durch 'HMUARTLGW_Connect' ersetze, dann funktioniert das nonBlocking connect.
Beim SIGNALduino und beim HM-wired funktioniert damit das nonBlocking connect auch.

Gruß Ralf

rudolfkoenig · 19 August 2016, 09:08:15

ZitatDevIo_OpenDev($hash, 0, "HMUARTLGW_DoInit", &HMUARTLGW_Connect);

Das ruft erst HMUARTLGW_Connect auf, und uebergibt dann DevIo_OpenDev als vierten Parameter den Rueckgabewert (vmtl. undef).
Richtig ist \&HMUARTLGW_Connect, "HMUARTLGW_Connect" geht offensichtlich auch.

Ralf9 · 21 August 2016, 12:25:57

Danke für die Hilfe, es funktioniert jetzt wie gewünscht.

Bei einem disconnected stand ca alle 60 Sek das "... timed out" im log:

Code Auswählen

2016.08.20 22:34:46 4: HttpUtils url=http://192.168.0.90:1000/
2016.08.20 22:34:49 3: xyz: connect to http://192.168.0.90:1000 timed out
2016.08.20 22:35:51 4: HttpUtils url=http://192.168.0.90:1000/
2016.08.20 22:35:54 3: xyz: connect to http://192.168.0.90:1000 timed out

Mit dem folgenden Code wird das "... timed out" nur einmal ausgegeben.
Das 'HttpUtils url .." ist zwar weiterhin ca alle 60 Sek im log, das stört mich aber nicht, da das verbose normalerweise max auf 3 steht.

Code Auswählen

sub xyz_Connect($$)
{
	my ($hash, $err) = @_;

	# damit wird die err-msg nur einmal ausgegeben
	if (!defined($hash->{disConnFlag}) && $err) {
		Log3($hash, 3, "xyz $hash->{NAME}: ${err}");
		$hash->{disConnFlag} = 1;
	}
}

und in die sub xyz_DoInit() habe ich folgendes eingetragen:

Code Auswählen

delete($hash->{disConnFlag}) if defined($hash->{disConnFlag});

Gruß Ralf