[Gelöst] "Connection refused" bei Blocking Call

[Jensc]

Hallo,
ich laufe beim DWD_OpenData auf ein Problem, bei dem ich nicht mehr weiter weiß: Bei einem get forecast kommt nach 30 Sek. die Meldung "forecast error: downloading and processing weather forecast data failed (Process died prematurely)", Readings werden nicht fegesetzt. Wenn man den Loglevel auf 5 setzt, kann man im Logfile folgendes finden:

Code Auswählen Erweitern

2019.11.24 20:45:08 5: Cmd: >get Inf_Wetter forecast<
2019.11.24 20:45:08 5: Inf_Wetter: GetForecast START (PID 855)
2019.11.24 20:45:08 5: Starting notify loop for Inf_Wetter, 1 event(s), first is updating forecasts
2019.11.24 20:45:08 4: DbLog DBLogging -> number of events received: 1 for device: Inf_Wetter
2019.11.24 20:45:08 4: DbLog DBLogging -> check Device: Inf_Wetter , Event: state: updating forecasts
2019.11.24 20:45:08 5: DbLog DBLogging -> parsed Event: Inf_Wetter , Event: state: updating forecasts
2019.11.24 20:45:08 4: DbLog DBLogging -> added event - Timestamp: 2019-11-24 20:45:08, Device: Inf_Wetter, Type: DWD_OPENDATA, Event: state: updating forecasts, Reading: state, Value: updating forecasts, Unit:
2019.11.24 20:45:08 4: DbLog DBLogging -> processing event Timestamp: 2019-11-24 20:45:08, Device: Inf_Wetter, Type: DWD_OPENDATA, Event: state: updating forecasts, Reading: state, Value: updating forecasts, Unit:
2019.11.24 20:45:08 5: End notify loop for Inf_Wetter
2019.11.24 20:45:08 5: Inf_Wetter: GetForecast END
2019.11.24 20:45:08 4: WEB: /fhem?detail=Inf_Wetter&dev.getInf_Wetter=Inf_Wetter&cmd.getInf_Wetter=get&arg.getInf_Wetter=forecast&val.getInf_Wetter=&XHR=1&addLinks=1&fwcsrf=csrf_250484318321244&fw_id=1490 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
2019.11.24 20:45:08 5: Inf_Wetter: GetForecastStart START (PID 1046): https://opendata.dwd.de/weather/local_forecasts/mos/MOSMIX_L/single_stations/10865/kml/MOSMIX_L_LATEST_10865.kmz
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast START
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast: data received, decoding ...
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast: parsing XML document
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast: extracting data
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast temp file /tmp/oiKl6UtMO7 forecast 3 size 17753
2019.11.24 20:45:09 5: Inf_Wetter: ProcessForecast END
2019.11.24 20:45:09 5: Inf_Wetter: GetForecastStart END
2019.11.24 20:45:38 3: Inf_Wetter: GetForecastAbort error: downloading and processing weather forecast data failed (Process died prematurely)
2019.11.24 20:45:38 5: Starting notify loop for Inf_Wetter, 1 event(s), first is forecast error: downloading and processing weather forecast data failed (Process died prematurely)


Wenn man sich den Code durchschaut, sieht es für mich so aus, als würde der GetForecast sauber beendet, aber der BlockingCall läuft  auf GetForecastAbort und eben nicht auf GetForecastFinish.

Zur Umgebung: Raspberry Pi 3, in einem Container läuft pivccu3, zum Logging wird mariaDB mit DBLog verwendet.

Code Auswählen Erweitern


  Operating System: Raspbian GNU/Linux 9 (stretch)
            Kernel: Linux 4.19.66-v7+
      Architecture: arm


forecastStation ist auf 10865 gesetzt (München Stadt)

Für Tipps wäre ich dankbar.

Workaround
Mit Hilfe von @CoolTux konnte ich das Problem umgehen (das nichts mit DWD_OpenData zu tun hat, sondern u.a. auch da auftritt). Wer keine Lust hat, den ganzen Thread durchzulesen, kann sich das Problem mit

Code Auswählen Erweitern

define telnetPort telnet 7072 global
shutdown restart
vom Hals schaffen. Allerdings hat man dann einen offenen telnet Port am FHEM, was u.U. zu Sicherheitslücken führen kann. Einen Vorschlag, wie man das durch eine einfache Codeänderung beheben kann, habe ich am 16.12.2019 in diesem Thread gepostet, aber der kommt natürlich ohne Gewähr.
Wer das Problem auch hat, kann bitte in diesem Thread einen kurzen Kommentar hinterlassen. Wenn zehn Betroffene zusammengekommen sind, melde ich das als Wunsch an. (Und wenn noch jemand eine Idee hat, wo ich ins Betriebssystem fassen kann, darf sich auch gerne melden).

[Jensc]

Mittlerweile bin ich einen Schritt weiter: Das Problem scheint bei den telnet Verbindungen zu liegen, die Blocking.pm aufbaut. Wenn ich die Tests aus Blocking.pm ausführe (TestBlocking(3)) erhalte ich auf Log Level 5 folgende Einträge:

Code Auswählen Erweitern

2019.11.27 20:45:43 5: Cmd: >{TestBlocking(3)}<
2019.11.27 20:45:43 4: [b]BlockingCall (DoSleep)[/b]: created child (21533), uses telnetForBlockingFn_1574804640 to connect back
2019.11.27 20:45:43 4: WEB: /fhem&fw_id=101&room=ZZSystem&fwcsrf=csrf_172593289955663&cmd=%7BTestBlocking%283%29%7D / RL:1730 / text/html; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.11.27 20:45:43 1: [color=red]Connection refused from 192.168.178.56:51908[/color]
2019.11.27 20:45:43 4: WEB_192.168.178.36_62017 GET /fhem?XHR=1&inform=type=status;filter=;since=1574883942;fmt=JSON&fw_id=101×tamp=1574883943627; BUFLEN:0
2019.11.27 20:45:48 1: Aborted: AbortArg

Die Fehlermeldung taucht auch bei dem ursprünglichen Problem der DWD Anbindung auf. 192.168.178.56 ist die IP Adresse des raspi, auf dem FHEM läuft. Auf "list TYPE=telnet" bekomme ich folgende Konfiguration:

Code Auswählen Erweitern

Internals:
   CFGFN     
   CONNECTS   28
   DEF        0
   FD         16
   FUUID      5ddd9ca0-f33f-18f0-10d6-5c08145c9a983719
   NAME       telnetForBlockingFn_1574804640
   NR         59
   PORT       34435
   STATE      Initialized
   TEMPORARY  1
   TYPE       telnet
   READINGS:
     2019-11-26 22:44:00   state           Initialized
Attributes:
   allowfrom  127.0.0.1
   room       hidden

Und falls ich sicherheitshalber einen update versuche, erscheint ebenfalls:

Code Auswählen Erweitern

2019.11.27 21:31:11 1 : Connection refused from 192.168.178.56:53610
Insgesamt scheint also irgendetwas in der Konfiguration schief zu liegen, dass Blocking.pm nicht korrekt arbeiten kann. Hat jemand einen Tipp, wo ich suchen kann?

Nachtrag: Zumindest das ursprüngliche Problem von DWD_OpenData lässt sich eindeutig auf den BlockingCall zurück führen: Wenn man den Aufruf im Device selbst so hackt, dass er synchron erfolgt und nicht über BlockingCall, funktioniert die Abfragen der Wetterdaten (der update aber natürlich noch nicht). Also statt

Code Auswählen Erweitern

$hash->{".forecastBlockingCall"} = ::BlockingCall("DWD_OpenData::GetForecastStart", $hash, "DWD_OpenData::GetForecastFinish", 30, "DWD_OpenData::GetForecastAbort", $hash);

den folgenden Zeilen einsetzen:

Code Auswählen Erweitern

getForecastResult = GetForecastStart($hash);GetForecastFinish(@$getForecastResult);

und schon funktioniert die Abfrage der Wetterdaten. Ist IMHO aber eher ein ,,diagnostischer Hack" als eine echte Lösung des Problems.

[Jensc]

Mittlerweile konnte ich das Problem so weit identifizieren, dass es von einem einzeiligen Patch gelöst wird: In /opt/fhem/FHEM/Blocking.pm muss man die folgende Zeile in der Routine BlockingStart patchen (Ergänzungen in rot):

Code Auswählen Erweitern

72:    $attr{$BC_telnetDevice}{allowfrom} = "127.0.0.1[color=red]|raspberrypi.fritz.box[/color]";
Wobei man natürlich statt raspberrypi.fritz.box den Namen des Hosts eintragen muss, auf dem FHEM läuft. Vorsicht: Den Patch muss man nach jedem update wiederholen!

Hintergrund:
Die Funktion BlockingCall dient dazu, Aufrufe in einen eigenen Prozess auszulagern, die potenziell lange dauern, z.B. die Abfrage einer Webseite. Um die Ergebnisse zu bekommen, erzeugt BlockingCall ein temporäres telnet Device. Um Missbrauch zu verhindern, wird dabei das Attribut "allowfrom" auf "127.0.0.1" gesetzt, also den lokalen Host.

Wenn der ausgelagerte Prozess nun fertig ist, meldet er sich über dieses telnet Device mit dem Ergebnis. Dabei überprüft das telnet Device in TcpServer Utils.pm, ob diese Verbindung überhaupt zulässig ist:

Code Auswählen Erweitern

       my $hostname = gethostbyaddr($iaddr, AF_INET);
      if(!$hostname || $hostname !~ m/$af/) {
        Log3 $name, 1, "Connection refused from $caddr:$port";
        close($clientinfo[0]);
        return undef;
      }

Dabei bekommt er - zumindest bei meiner Konfiguration - den Hostname, also "raspberrypi.fritz.box" zurück und eben nicht die IP Adresse von localhost und lehnt den Aufbau der Verbindung ab.

Bitte um Hilfe
Mir ist immer noch nicht klar, ob das Problem vor dem Computer sitzt, es also irgendein Problem mit der Konfiguration gibt. So, wie der Code bei mir läuft, kann er nicht funktionieren, was ich mir aber bei einer so grundlegenden Funktion nicht vorstellen kann. Bevor ich also eine Fehlermeldung einstellen, erstmal die Anfängerfrage: Was liegt schief in meiner Konfiguration, bzw. Wo müsste ich noch hinfassen, damit sich BlockingCall anders verhält? Oder ist das ein Fall für einen Bugreport? Wenn ja, wo stelle ich den ein?

[CoolTux]

Bitte entferne erstmal den Unsinn den Du als Patch bezeichnest, als nächstes machst du bitte ein ip add auf Deinem FHEM Host und zwar mit root rechten. Die Ausgabe hier posten und dann bitte noch cat /etc/hosts und die Ausgabe hier posten.


Grüße

[Jensc]

Bitte entferne erstmal den Unsinn den Du als Patch bezeichnest...

Ach, gelobt sei, was funktioniert  Und danke, dass Du mir hilfst!

Hier der ip add:

Code Auswählen Erweitern

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default qlen 1000
    link/ether b8:27:eb:53:d2:e4 brd ff:ff:ff:ff:ff:ff
3: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether b8:27:eb:06:87:b1 brd ff:ff:ff:ff:ff:ff
    inet 192.168.178.56/24 brd 192.168.178.255 scope global wlan0
       valid_lft forever preferred_lft forever
    inet6 2a02:810d:1500:175c:ba27:ebff:fe06:87b1/64 scope global mngtmpaddr dynamic
       valid_lft 4041sec preferred_lft 1341sec
    inet6 fe80::ba27:ebff:fe06:87b1/64 scope link
       valid_lft forever preferred_lft forever
4: br0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether fe:da:f3:90:03:e0 brd ff:ff:ff:ff:ff:ff
    inet 192.168.253.1/24 brd 192.168.253.255 scope global br0
       valid_lft forever preferred_lft forever
    inet6 fe80::a7:c0ff:fe62:b74a/64 scope link
       valid_lft forever preferred_lft forever
6: vethpivccu@if5: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue master br0 state UP group default qlen 1000
    link/ether fe:da:f3:90:03:e0 brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet6 fe80::fcda:f3ff:fe90:3e0/64 scope link
       valid_lft forever preferred_lft forever

Und hier die /etc/hosts:

Code Auswählen Erweitern

127.0.0.1       localhost
::1             localhost ip6-localhost ip6-loopback
ff02::1         ip6-allnodes
ff02::2         ip6-allrouters

127.0.0.1       raspberrypi
127.0.0.1       respberrypi.fritz.box 


Was spannend ist: Das telnet Device versucht die Verbindung nicht über 127.0.0.1 aufzubauen, sondern über die vom DNS Server zugewiesene IP Adresse 192.168.178.56.

[CoolTux]

Ändere bitte einmal das

Code Auswählen Erweitern


127.0.0.1       raspberrypi
127.0.0.1       respberrypi.fritz.box


in

Code Auswählen Erweitern


192.168.178.56   respberrypi.fritz.box  respberrypi


Zu mindest wäre dann der hosts Eintrag schon mal korrekt.
Der Name ist doch noch respberrypi oder?

[Jensc]

Hab vor vielen Jahren mal gelernt, dass man nicht spät Nachts noch an Systemfiles rumfummeln soll... Danke für den Hinweis, der "respberrypi" war natürlich Quatsch. Die /etc/hosts lautet nun

Code Auswählen Erweitern

[b]pi@raspberrypi:~[/b] $ cat /etc/hosts
127.0.0.1       localhost
::1             localhost ip6-localhost ip6-loopback
ff02::1         ip6-allnodes
ff02::2         ip6-allrouters

192.168.178.56  respberrypi.fritz.box  respberrypi

Shutdown restart auf FHEM habe ich ebenfalls durchgeführt. Allerdings kommt auf {TestBlocking(3)} noch immer der Log-Eintrag

Code Auswählen Erweitern

2019.12.08 11:43:40 1: Connection refused from 192.168.178.56:40380

Problem besteht also weiter...

[CoolTux]

Mach mal bitte

list TYPE=allowed
und
list TYPE=telnet


Grüße

[Jensc]

list TYPE=allowed

Code Auswählen Erweitern

Internals:
   FUUID      5dc81011-f33f-18f0-6482-75f4acb90d5da820
   NAME       allowed_WEB
   NR         14
   STATE      validFor:WEB
   TYPE       allowed
   validFor   WEB
   READINGS:
     2019-12-08 11:41:26   state           validFor:WEB
Attributes:
   basicAuth  amVuc2M6ZmhlbQ==
   room       ZZSystem
   validFor   WEB

list TYPE=telnet:

Code Auswählen Erweitern

Internals:
   CFGFN     
   CONNECTS   18
   DEF        0
   FD         12
   FUUID      5decd35e-f33f-18f0-b4f1-ec54d782b5757d4a
   NAME       telnetForBlockingFn_1575801694
   NR         62
   PORT       35647
   STATE      Initialized
   TEMPORARY  1
   TYPE       telnet
   READINGS:
     2019-12-08 11:41:34   state           Initialized
Attributes:
   allowfrom  127.0.0.1
   room       hidden

11:41 war der letzte Restart

[CoolTux]

Erweitere mal beim telnet das allowedFrom auf die IP vom FHEM Server

[Jensc]

Hm, das telnet device wird automatisch in Blocking.pm definiert (siehe Code unten) und dabei wird das allowfrom ebenfalls gesetzt. Ich hab's jetzt mal händisch über die Oberfläche gesetzt:

Code Auswählen Erweitern

telnetForBlockingFn_1575812813
telnetForBlockingFn_1575815203
telnetForBlockingFn_1575815514


Was aber nicht wirklich hilft:

Code Auswählen Erweitern

2019.12.08 15:26:43 3: telnetForBlockingFn_1575815203: port 46761 opened
2019.12.08 15:26:43 1: Connection refused from 192.168.178.56:55196
2019.12.08 15:26:48 1: Aborted: AbortArg


Grund ist, dass der BlockingCall einfach ein neues Device anlegt, wenn das telnet ein anderes allowfrom hat (4. Zeile im foreach-Block).

Ich könnte schon auch an der Stelle rumfummeln, wo es erzeugt wird, aber dann sind wir wieder genau bei dem Hack, der Dir eingangs nicht so wirklich gefallen hat. (Damit es funktioniert, müsste man nicht die IP Adresse, sondern den Hostname dort eintragen).

Stelle in Blocking.pm, wo das device definiert wird (Dritte Zeile von unten):

Code Auswählen Erweitern

sub
BC_searchTelnet($)
{
  my ($blockingFn) = @_;

  if($BC_telnet) {
    $BC_telnetDevice = $BC_telnet;
    return;
  }

  $BC_telnetDevice = undef;
  foreach my $d (sort keys %defs) { #
    my $h = $defs{$d};
    next if(!$h->{TYPE} || $h->{TYPE} ne "telnet" || $h->{SNAME});
    next if(AttrVal($d, "SSL", undef) ||
            AttrVal($d, "allowfrom", "127.0.0.1") ne "127.0.0.1");
    next if($h->{DEF} !~ m/^\d+( global)?$/);
    next if($h->{DEF} =~ m/IPV6/);

    my %cDev = ( SNAME=>$d, TYPE=>$h->{TYPE}, NAME=>$d.time() );
    next if(Authenticate(\%cDev, undef) == 2);    # Needs password
    $BC_telnetDevice = $d;
    last;
  }

  # If not suitable telnet device found, create a temporary one
  if(!$BC_telnetDevice) {
    $BC_telnetDevice = "telnetForBlockingFn_".time();
    my $ret = CommandDefine(undef, "-temporary $BC_telnetDevice telnet 0");
    if($ret) {
      $ret = "BlockingCall ($blockingFn): ".
                "No telnet port found and cannot create one: $ret";
      Log 1, $ret;
      return undef;
    }
    $attr{$BC_telnetDevice}{room} = "hidden"; # no red ?, Forum #46640
    $attr{$BC_telnetDevice}{allowfrom} = "127.0.0.1";
  }
}


Hack, der funktioniert:

Code Auswählen Erweitern

     
$attr{$BC_telnetDevice}{allowfrom} = "127.0.0.1|raspberrypi.fritz.box";


[CoolTux]

Ah, OK jetzt verstehe ich. Hatte ich auf dem Handy nicht gesehen. Aber irgendwas passt bei Dir einfach nicht.
Abhilfe schafft eventuell das definieren eines telnet Devices. Es sollte aber auch ohne gehen.
Zum testen lege aber einfach mal eines an.

[Jensc]

Hi,

Das eigene telnet Device mag er nicht (diesmal Loglevel 5):

Code Auswählen Erweitern

2019.12.08 17:20:48 5: Cmd: >{TestBlocking(3)}<
2019.12.08 17:20:49 4: BlockingCall (DoSleep): created child (4078), uses telnetForBlockingFn_1575818839 to connect back
2019.12.08 17:20:49 4: WEB: /fhem&fw_id=75&room=ZZSystem&fwcsrf=csrf_180474433264716&cmd=%7BTestBlocking%283%29%7D / RL:1499 / text/html; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.12.08 17:20:49 1: Connection refused from 192.168.178.56:43686
2019.12.08 17:20:49 4: WEB_192.168.178.36_57609 GET /fhem?XHR=1&inform=type=status;filter=;since=1575822048;fmt=JSON&fw_id=75&timestamp=1575822049183; BUFLEN:0
2019.12.08 17:20:54 1: Aborted: AbortArg


Das ist unabhängig davon, ob ich das testTelnet per Default definiere, oder ihm ein allowfrom gebe, weil der BlockingCall ohnehin sein eigenes generiert.

Was ich nicht verstehe: Warum arbeitet er bei meiner Installation mit der IP Adresse des Hosts und nicht mit 127.0.0.1 als Local Host? In TcpServerUtils.pm holt er sich die Adresse von Socket - und hat da offensichtlich keinen localhost drin. 

Code Auswählen Erweitern

my ($port, $iaddr) = $hash->{IPV6} ?
      sockaddr_in6($clientinfo[1]) :
      sockaddr_in($clientinfo[1]);
  my $caddr = $hash->{IPV6} ?
                inet_ntop(AF_INET6(), $iaddr) :
                inet_ntoa($iaddr);


Könnte es damit zusammen hängen, dass ich vor FHEM das pivccu installiert habe, das in einem lxc Container läuft und sich wild Netzwerkbridges aufgebaut hat?

[CoolTux]

Hi,

Das eigene telnet Device mag er nicht (diesmal Loglevel 5):

Code Auswählen Erweitern

2019.12.08 17:20:48 5: Cmd: >{TestBlocking(3)}<
2019.12.08 17:20:49 4: BlockingCall (DoSleep): created child (4078), uses telnetForBlockingFn_1575818839 to connect back
2019.12.08 17:20:49 4: WEB: /fhem&fw_id=75&room=ZZSystem&fwcsrf=csrf_180474433264716&cmd=%7BTestBlocking%283%29%7D / RL:1499 / text/html; charset=UTF-8 / Content-Encoding: gzip
/ Cache-Control: no-cache, no-store, must-revalidate

2019.12.08 17:20:49 1: Connection refused from 192.168.178.56:43686
2019.12.08 17:20:49 4: WEB_192.168.178.36_57609 GET /fhem?XHR=1&inform=type=status;filter=;since=1575822048;fmt=JSON&fw_id=75&timestamp=1575822049183; BUFLEN:0
2019.12.08 17:20:54 1: Aborted: AbortArg


Das ist unabhängig davon, ob ich das testTelnet per Default definiere, oder ihm ein allowfrom gebe, weil der BlockingCall ohnehin sein eigenes generiert.

Was ich nicht verstehe: Warum arbeitet er bei meiner Installation mit der IP Adresse des Hosts und nicht mit 127.0.0.1 als Local Host? In TcpServerUtils.pm holt er sich die Adresse von Socket - und hat da offensichtlich keinen localhost drin. 

Code Auswählen Erweitern

my ($port, $iaddr) = $hash->{IPV6} ?
      sockaddr_in6($clientinfo[1]) :
      sockaddr_in($clientinfo[1]);
  my $caddr = $hash->{IPV6} ?
                inet_ntop(AF_INET6(), $iaddr) :
                inet_ntoa($iaddr);


Könnte es damit zusammen hängen, dass ich vor FHEM das pivccu installiert habe, das in einem lxc Container läuft und sich wild Netzwerkbridges aufgebaut hat?

Mach mal bitte ein list vom definierten telnet Device

[CoolTux]

Code Auswählen Erweitern

defmod telnetPort telnet 7072 global