(Gelöst)PRESENCE: FHEM hängt sich oft auf, Raspberry PI mit SSH bleibt bedienbar

[isy]

Hallo zusammen,
nach etlichen Abstürzen möchte ich mich heute an euch wenden - vielleicht hat jemand einen Tip.
Bis auf (noch kurzfristig) vorhandene Probleme mit den Fensterkontakten von Homematic (kein Pearing wegen AES), funktioniert die Installation so, wie erwartet.

Problem: FHEM stürzt alle paar Tage ab, WEB unbedienbar und es werden keine Automatisierungen (Rollo (HM), Lampen(DECT) usw.) mehr durchgeführt. Der RasPi ist über SSH bedienbar, reboot funktioniert.

Ausstattung: RasPI 2 ( 2A Netzteil), CUL (SCC), FHEM 5.6, alle Updates. Homematic, AVM-DECT200, PRESENCE, VuPlus

Meldungen im fhem.log (nach shutdown restart) um 19:51 gestern:
2015.08.30 19:51:38 0: Server shutdown
2015.08.30 19:51:40 1: Including fhem.cfg
2015.08.30 19:51:40 3: telnetPort: port 7072 opened
2015.08.30 19:51:41 3: WEB: port 8083 opened
2015.08.30 19:51:41 3: WEBphone: port 8084 opened
2015.08.30 19:51:41 3: WEBtablet: port 8085 opened
2015.08.30 19:51:41 2: eventTypes: loaded 1032 events from ./log/eventTypes.txt
2015.08.30 19:51:41 3: Opening SCC device /dev/ttyAMA0
2015.08.30 19:51:41 3: Setting SCC serial parameters to 38400,8,N,1
2015.08.30 19:51:41 3: SCC device opened
2015.08.30 19:51:41 3: SCC: Possible commands: mBbCFiAZGMYRTVWXef*ltux
2015.08.30 19:51:41 2: Switched SCC rfmode to HomeMatic
2015.08.30 19:51:42 2: Tagesertrag will read from solarview at 192.168.178.20:15000 every 60 seconds
2015.08.30 19:51:42 2: Eingespeist will read from solarview at 192.168.178.20:15000 every 60 seconds
2015.08.30 19:51:42 2: Bezogen will read from solarview at 192.168.178.20:15000 every 60 seconds
2015.08.30 19:51:45 3: Opening Fritzbox device fritz.box:2002
2015.08.30 19:51:45 3: Fritzbox device opened
2015.08.30 19:51:45 1: FBAHA Fritzbox registered with handle: 00000091
2015.08.30 19:51:45 1: Including ./log/fhem.save
2015.08.30 19:51:46 3: Device HM_3545CF added to ActionDetector with 000:10 time
2015.08.30 19:51:46 3: Device HM_388C62 added to ActionDetector with 000:10 time
2015.08.30 19:51:46 3: Device ku_SW_Fenster_r added to ActionDetector with 001:05 time
2015.08.30 19:51:46 3: Device wz_SW_BalkonTuer added to ActionDetector with 001:05 time
2015.08.30 19:51:46 1: usb create starting
2015.08.30 19:51:46 1: usb create end
2015.08.30 19:51:46 0: Featurelevel: 5.6
2015.08.30 19:51:46 0: Server started with 79 defined entities (version $Id: fhem.pl 9141 2015-08-27 19:04:33Z rudolfkoenig $, os linux, user fhem, pid 7943)
2015.08.30 19:51:46 3: telnetForBlockingFn: port 55088 opened
2015.08.30 20:24:18 1: PERL WARNING: Use of uninitialized value in sprintf at ./FHEM/98_JsonList.pm line 213.
2015.08.30 20:27:08 3: CUL_HM set ku_SW_Fenster_r getConfig
2015.08.30 20:39:13 3: CUL_HM set au_Kamera on
2015.08.30 20:40:47 3: CUL_HM set au_Kamera off
2015.08.30 20:46:00 3: CUL_HM set wz_SW_BalkonTuer getConfig
2015.08.30 21:41:45 1: FHEMWEB SSL/HTTPS error:
2015.08.30 21:41:45 1: FHEMWEB SSL/HTTPS error:
2015.08.30 21:41:45 1: FHEMWEB SSL/HTTPS error:
2015.08.30 21:41:45 1: FHEMWEB SSL/HTTPS error:
2015.08.31 00:25:59 3: CUL_HM set ez_rollo_l off
2015.08.31 00:26:00 3: CUL_HM set ez_rollo_m off
2015.08.31 00:26:00 3: CUL_HM set ez_rollo_r off
2015.08.31 00:26:00 3: CUL_HM set ez_rollo_t off
2015.08.31 00:26:00 3: CUL_HM set ku_rollo_l off
2015.08.31 00:26:00 3: CUL_HM set ku_rollo_r off
2015.08.31 00:26:00 3: CUL_HM set wz_rollo_t off
2015.08.31 00:32:06 1: CallBlockingFn: Can't connect to localhost:55088: IO::Socket::INET: connect: Connection refused

Morgens dann FHEM aufgehangen, wie oben beschrieben. Mit SSH verbunden, sudo reboot und alles läuft wieder. Die FM aus dem Presence Modul kommt eigentlich sehrt oft.....

Bislang gemacht: Netzteil und SD-Karte gewechselt. RasPI und FHEM neu aufgesetzt (FHEM Config zurückgeladen), 
PRESENCE umgestellt von "ping" auf "bluetooth" hat nichts gebracht (naja: warum auch).
Ich werde mal PRESENSE abschalten und schauen, was passiert.

Habt ihr einen Tip?
Beste Grüße, Helmut

[isy]

Noch ein Nachtrag. FM von heute Nachmittag:

2015.08.31 16:42:48 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 107.
2015.08.31 16:42:48 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'
2015.08.31 16:42:53 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 107.
2015.08.31 16:42:53 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

Sieht irgendwie alles nach Presence Modul aus.
Gruß Helmut

[isy]

Ohne PRESENCE Modul läuft die Installation stabil. Keine Fehlermeldungen im Log.

Hat jemand eine Idee?

Prüfung Anwesenheit
define S4 PRESENCE local-bluetooth C8:14:79:D4:8B:D7 60 90
attr S4 devStateIcon absent:control_building_empty present:control_building_filled
attr S4 event-on-change-reading state
attr S4 group Anwesenheit
attr S4 icon people_sensor
attr S4 room Haus

Dann noch das gleiche mit "S5" und der DOIF:

define Niemand_Da DOIF ([S4i:state] eq "absent" and [S5:state] eq "absent") (set au_Kamera on) DOELSE (set au_Kamera #off)

[frank]

hast du die neueste version von presence?

[isy]

Hallo!

Fhem "version" meldet
# $Id: 73_PRESENCE.pm 9111 2015-08-22 16:46:24Z markusbloch $
(heute kein Update gemacht)

Sofort nach dem Aktivieren:
2015.09.03 19:46:59 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.03 19:46:59 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

Beim 2. Mal "shutdown restart" keine FM im Log

[frank]

ich hatte mit der vorherigen probleme, wenn es den fehler "cannot fork" gab. das kam, wenn auf der fritzbox zu wenig speicher vorhanden war. im augenblick funktioniert es bei mir.

[dev0]

Ob es das Problem löst oder nicht, aber zumindest sieht es so aus, dass der Eintrag für localhost in /etc/hosts fehlt.

[isy]

Hmm. Sieht so aus, wie u.a., meines Erachtens nach in Ordnung.Müsteriös.
Vielen Dank auf alle Fälle schon mal für euer Einschalten in das Problem!
Support hier im Forum ist prima.

Hatte weiter oben die AES Probleme  mit den Fensterkontakten erwähnt, die sind mittlerweile gefixt und "hminfo" hat keine Fehler mehr.
Werde mal "apptime" erneut starten.

Raspberry PI (FHEM)
127.0.0.1   localhost
::1      localhost ip6-localhost ip6-loopback
fe00::0      ip6-localnet
ff00::0      ip6-mcastprefix
ff02::1      ip6-allnodes
ff02::2      ip6-allrouters

127.0.1.1   fhem

Im Vergleich dazu meine Suse:
127.0.0.1   localhost

# special IPv6 addresses
::1             localhost ipv6-localhost ipv6-loopback

fe00::0         ipv6-localnet

ff00::0         ipv6-mcastprefix
ff02::1         ipv6-allnodes
ff02::2         ipv6-allrouters
ff02::3         ipv6-allhosts

[dev0]

Die /etc/hosts sieht gut aus. Wird denn auf Linuxebene localhost richtig aufgelöst?

[isy]

Yepp. Sieht auch gut aus.

pi@fhem ~ $ ping localhost
PING localhost (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost (127.0.0.1): icmp_req=1 ttl=64 time=0.153 ms
64 bytes from localhost (127.0.0.1): icmp_req=2 ttl=64 time=0.134 ms
64 bytes from localhost (127.0.0.1): icmp_req=3 ttl=64 time=0.120 ms
64 bytes from localhost (127.0.0.1): icmp_req=4 ttl=64 time=0.138 ms


Habe gerade gesehen. dass apptime mit dem "Solarview" Interface auf über 2 Sekunden liegt.

[dev0]

Poste mal ein List vom Presence device in Code Tags.

[isy]

Habe PRESENCE wieder entfernt, danach Solarview im 20ms Bereich. Modul Enigma war in der Zeit auch bei über 2000, ohne PRESENCE bei 20ms.
Also macht PRESENCE den Delay.

MIttlerweile folgende FM
2015.09.03 21:10:36 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.03 21:10:36 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'
2015.09.03 21:10:37 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.03 21:10:37 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

Denke, der Fehler liegt in "line 105" bzw, dort tritt der Fehler auf. "Bad hostname" ist nur die Konsequenz.

Hier der Code für PRESENCE:

Code Auswählen Erweitern

define Helmut PRESENCE lan-ping 192.168.178.30 60 90
attr Helmut devStateIcon absent:control_building_empty present:control_building_filled
attr Helmut event-on-change-reading state
attr Helmut group Anwesenheit
attr Helmut icon people_sensor
attr Helmut room Haus


In 73_PRESENCE.pm lautet Zeile 105 "elseif.....". Das wäre korrekt, da ich im Device ja "lan-ping" eingetragen habe. Nur der Code danach zeigt auf Fritzbox ctlmgr-ctl. Das sieht seltsam aus, da PRESENCE nicht auf der Fritzbox läuft.

Code Auswählen Erweitern

elsif($a[2] eq "lan-ping")
        {
            if(-X "/usr/bin/ctlmgr_ctl" and not $username eq "root")
            {
                my $msg = "FHEM is not running under root (currently $username) This check can only performed with root access to the FritzBox";
                Log 2, "PRESENCE ($name) - ".$msg;
                return $msg;
            }


[frank]

FHEM/Blocking.pm line 105.

schau im modul blocking.pm zeile 105. 

schalte global stacktrace ein und global verbose 3, dann siehst du von wo der fehler kam.

[isy]

Ups, vertan. Danke, ist ja logisch.
Zeile 105 lautet

Code Auswählen Erweitern

    my $addr = "localhost:$defs{$telnetDevice}{PORT}";

Telnet Port im Fhem ist auf 7072 definiert. Siehe:

Code Auswählen Erweitern

define telnetPort telnet 7072 global
attr telnetPort SSL 1
attr telnetPort password ********

[frank]

dein problem ist doch auch nicht grundsätzlich, dachte ich. ich habe verstanden, dass es eine zeit funktioniert, und irgend wann hakelt es.

[isy]

Ja, das stimmt. Letzte Zeit jede Nacht. Morgens ist der RasPi  mit reboot (zum Glück, ansonsten ist irgendwann das OS defekt) wieder zu erwecken. FHEM komplett aufgehangen.

Ich habe apptime laufen. Wenn die PRESENCE Fehlermeldungen kommen, dann gehen die WEB basierten Verbindungen (u.a. Solarview, Enigma) alle auf über 2s Responsetime.
PRESENCE aus, alles OK.

Werde mal versuchen. das blocking.pm modul zu debuggen. Muss ich mich einlesen.

Code Auswählen Erweitern

attr global stacktrace 1
ist eingetragen.

Die Homematic Fehler mit den Fensterkontakten sind  seit 2 Tagen gelöst, ich habe AES abgeschaltet. Es könnte durchaus sein, dass die "getconfig" Anfragen der nicht richtig gepairten Fensterkontakte zu Timeouts führten.
Morgen früh bin ich schlauer.

[isy]

Schon zugeschlagen:

2015.09.03 23:19:06 5: PRESENCE (S4) - ping command returned with output:
PING 192.168.178.25 (192.168.178.25) 56(84) bytes of data.
64 bytes from 192.168.178.25: icmp_req=1 ttl=64 time=357 ms
64 bytes from 192.168.178.25: icmp_req=2 ttl=64 time=225 ms
64 bytes from 192.168.178.25: icmp_req=3 ttl=64 time=140 ms
64 bytes from 192.168.178.25: icmp_req=4 ttl=64 time=64.0 ms

--- 192.168.178.25 ping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 3003ms
rtt min/avg/max/mdev = 64.078/196.984/357.816/109.087 ms
2015.09.03 23:19:06 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.03 23:19:06 3: stacktrace:
2015.09.03 23:19:06 3:     main::__ANON__                      called by FHEM/Blocking.pm (105)
2015.09.03 23:19:06 3:     main::BlockingInformParent          called by FHEM/Blocking.pm (92)
2015.09.03 23:19:06 3:     main::BlockingCall                  called by ./FHEM/73_PRESENCE.pm (535)
2015.09.03 23:19:06 3:     main::PRESENCE_StartLocalScan       called by ./FHEM/98_apptime.pm (104)
2015.09.03 23:19:06 3:     main::apptime_getTiming             called by ./FHEM/98_apptime.pm (45)
2015.09.03 23:19:06 3:     main::HandleTimeout                 called by fhem.pl (583)
2015.09.03 23:19:06 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

2015.09.03 23:19:16 5: PRESENCE (Helmut) - ping command returned with output:
PING 192.168.178.30 (192.168.178.30) 56(84) bytes of data.

--- 192.168.178.30 ping statistics ---
4 packets transmitted, 0 received, 100% packet loss, time 3010ms

2015.09.03 23:19:16 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.03 23:19:16 3: stacktrace:
2015.09.03 23:19:16 3:     main::__ANON__                      called by FHEM/Blocking.pm (105)
2015.09.03 23:19:16 3:     main::BlockingInformParent          called by FHEM/Blocking.pm (92)
2015.09.03 23:19:16 3:     main::BlockingCall                  called by ./FHEM/73_PRESENCE.pm (535)
2015.09.03 23:19:16 3:     main::PRESENCE_StartLocalScan       called by ./FHEM/98_apptime.pm (104)
2015.09.03 23:19:16 3:     main::apptime_getTiming             called by ./FHEM/98_apptime.pm (45)
2015.09.03 23:19:16 3:     main::HandleTimeout                 called by fhem.pl (583)
2015.09.03 23:19:16 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

Danach hängt das PRESENCE Modul:
presence present
2015-09-03 23:17:49 state present 2015-09-03 23:17:49

Das war der letzte Status, danach keiner mehr.

Danach "shutdown restart" und siehe da:
2015.09.03 23:28:32 5: PRESENCE (Helmut) - ping command returned with output:
PING 192.168.178.30 (192.168.178.30) 56(84) bytes of data.

--- 192.168.178.30 ping statistics ---
4 packets transmitted, 0 received, 100% packet loss, time 2999ms

2015.09.03 23:28:32 4: Connection accepted from telnet:127.0.0.1:49419
2015.09.03 23:28:32 5: Cmd: >{PRESENCE_ProcessLocalScan('Helmut|0|absent')}<
2015.09.03 23:28:32 5: PRESENCE (Helmut) - blocking scan result: Helmut|0|absent
2015.09.03 23:28:32 4: PRESENCE (Helmut) - rescheduling next check in 60 seconds

[frank]

Das war der letzte Status, danach keiner mehr.

eventuell wird der fehlgeschlagene connect versuch unzureichend abgefangen, sodass presence aussteigt. da müsste markus mal schauen.

versuch doch mal nach dem fehler eine änderung im presence modul auf der detailseite zu machen. zb modify der def, um das modul erneut "anzuschubsen".

[isy]

Heute läuft super. Keine Hänger, alle Werte in apptime < 200ms. PRESENCE auch normal, keine FM im Log.
Werde mal Räucherstäbchen entzünden. Das machen wir in der IT immer so, wenn alles ohne Change dann doch wieder läuft.
Wenn das Thema zuschlägt, melde ich mich wieder.

Euch allen vielen Dank, ich weiß das zu schätzen!

[isy]

Habe noch eine Frage:
Nach "shutdown restart" meldet sich sofort neben dem "save config" button ein rotes Ausrufezeichen (2 Änderungen an fhem.cfg zu bestätigen).

Ist das beim aktivierten PRESENCE Modul bei euch auch so?

[isy]

Neue Feststellung - kann das jemand bestätigen?

Wenn ich bei aktiviertem PRESENCE Modul im FHEM Editor in der fhem.cfg nur einen Buchstaben ändere, wird fhem neu gestartet und folgendes Log erzeugt:

Code Auswählen Erweitern

2015.09.04 23:14:33 1: Including ./log/fhem.save
2015.09.04 23:14:36 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.04 23:14:36 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'
2015.09.04 23:14:38 3: Device HM_3545CF added to ActionDetector with 000:10 time
2015.09.04 23:14:38 3: Device HM_388C62 added to ActionDetector with 000:10 time
2015.09.04 23:14:38 3: Device au_Bew_Garage added to ActionDetector with 000:10 time
2015.09.04 23:14:38 3: Device ku_SW_Fenster_r added to ActionDetector with 001:05 time
2015.09.04 23:14:38 3: Device wz_SW_BalkonTuer added to ActionDetector with 001:05 time
2015.09.04 23:14:46 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at FHEM/Blocking.pm line 105.
2015.09.04 23:14:46 1: CallBlockingFn: Can't connect to localhost:: IO::Socket::INET: Bad hostname 'localhost:'

Danach steht PRESENCE (aufgehangen). Wen ich FHEM neu starte (shutdown restart), dann erfolgt ein ordentlicher, fehlerfreier Neustart.

[dev0]

Kann es sein, dass du die fhem.cfg schon mal manuell bearbeitest? Ich vermute, dass ein Port bei einer Gerätedefinition fehlt. Schau dir mal die Devices vom Typ FHEMWEB und telnet an. Ggf. auch andere Devices, die einen Port in der Definition benötigen.

[isy]

Ja, manchmal trage ich Kommentare ein. Über die eigene Web-Oberfläche, aber auch über ext. Editor von meinem Linux System aus.

Ich habe jetzt mal meine alte fhem.cfg gesichert und die fhem_demo umbenannt.
Als erstes das PRESENCE aktiviert. Läuft problemlos, aber in der demo Version ist auch kein SSL Port bem telnet eingetragen.
Weiterhin den gesammten "global" Teil Zeile für Zeile aus meiner gesicherten fhem.cfg rübergenommen.
Läuft.
Die Telnet Einträge habe ich komplett aus der demo übernommen und nur mein SSL Passwort eingetragen.
Läuft auch, jetzt kommt das Ausrufezeichen neben dem "save config" button nach dem shutdown restart
Gibt keinen Ärger mit dem PRESENCE Modul.

Dann noch den Rest der fhem Installation übernommen.
Läuft derzeit auch. Muss ich abwarten.

Evtl. gibt es ein Zeichen in der fhem.cfg, welches unsichtbar am Editor ist, aber intern Ärger verursacht.

[isy]

Habe das Problem abgestellt, aber die Ursache bleib unklar.
Also im Telnet Device "ssl" deaktiviert, brauche ich intern nicht. Danach keine Probleme mehr.

Danke noch mal an alle, die mitgeholfen haben!