FHEM startet nicht mehr auf Raspi 4

Begonnen von Nemo0815, 16 August 2019, 17:13:42

Vorheriges Thema - Nächstes Thema

Nemo0815

Hallo zusammen,

habe ein seltsames PRoblem hier, mein FHEM startet irgendwie nicht mehr wenn ich den Raspi reboote. Vorher ging alles problemlos, jetzt ist selbst der Raspi oft nicht erreichbar (an dem liegts nicht, hab ich mit nem zweiten gegen gecheckt).

Wenn man es schafft und er bootet und er ist erreichbar, kann ich FHEM über service start in der Konsole auch starten, beim nächsten Raspi reboot ist aber alles wie vorher.

Für den Fall das FHEM nicht startet habe ich folgendes im Log (beim manuellen Start sind keine Fehler vorhanden):

019.08.16 17:03:37 1: Including fhem.cfg
2019.08.16 17:03:39 3: telnetPort: port 7072 opened
2019.08.16 17:03:39 3: WEB_Local: port 8084 opened
2019.08.16 17:03:39 2: eventTypes: loaded 5463 events from ./log/eventTypes.txt
2019.08.16 17:03:39 3: Opening nanoCUL device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A98ZJ51H-if00-port0
2019.08.16 17:03:39 1: nanoCUL: Can't open /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A98ZJ51H-if00-port0: No such file or directory
2019.08.16 17:03:39 3: define WifiLightGang: can't reach (IO::Socket::INET: connect: Network is unreachable)
2019.08.16 17:03:39 3: define TVLedHintergrund: can't reach (IO::Socket::INET: connect: Network is unreachable)
2019.08.16 17:03:39 3: define WifiLightCouch: can't reach (IO::Socket::INET: connect: Network is unreachable)
2019.08.16 17:03:40 1: PERL WARNING: Smartmatch is experimental at ./FHEM/47_OBIS.pm line 472, <$fh> line 828.
2019.08.16 17:03:40 1: PERL WARNING: main::OBIS_decodeTL() called too early to check prototype at ./FHEM/47_OBIS.pm line 785, <$fh> line 828.
2019.08.16 17:03:40 3: Opening HausstromZaehler device /dev/serial0
2019.08.16 17:03:40 3: Setting HausstromZaehler serial parameters to 9600,8,N,1
2019.08.16 17:03:40 3: Init done
2019.08.16 17:03:40 3: HausstromZaehler device opened
2019.08.16 17:03:41 3: Opening WaermepumpenZaehler device /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0
2019.08.16 17:03:41 1: WaermepumpenZaehler: Can't open /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0: No such file or directory
2019.08.16 17:03:41 3: define AquariumLED: can't reach (IO::Socket::INET: Bad hostname 'AquariumLED')
2019.08.16 17:03:41 3: define LEDLeiste: can't reach (IO::Socket::INET: Bad hostname 'WifiLightLED2')
2019.08.16 17:03:41 3: FHEM2FHEM opening RaspiZero at 192.168.178.43:7072
2019.08.16 17:03:41 3: Can't connect to 192.168.178.43:7072: Network is unreachable
2019.08.16 17:03:41 3: Opening nanoCUL433 device /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
2019.08.16 17:03:41 1: nanoCUL433: Can't open /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0: No such file or directory
2019.08.16 17:03:41 3: LGTV_WebOS (myLGTV) - defined with host 192.168.178.87
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by Nachttischlampe, copy llCmdQueue
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by Nachttischlampe, copy llCmdQueue
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by WZ_Licht_Rechts, copy llCmdQueue
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by WZ_Licht_Rechts, copy llCmdQueue
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by Nachttischlampe, copy llCmdQueue
2019.08.16 17:03:41 3: WifiLight: requested bridge bridge-V3 at 192.168.178.45 already in use by WZ_Licht_Links, copy llCmdQueue
2019.08.16 17:03:41 1: FULLY: [myFullyBroswer] Version 1.3 Opening device 192.168.178.41
2019.08.16 17:03:41 2: FULLY: [myFullyBroswer] Error during request. connect to http://192.168.178.41:2323: Network is unreachable
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_6fbf819b07d149f984b68fdc3005a626
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_G2A0RF0374350J32
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_G090U60883750BNJ
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_G090U60883750D1G
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_fbc72b8cc28e4e1381b603fa043d3345
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_G090L90964341A1W
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_4711993149b2464d81816346ab4b0ea3
2019.08.16 17:03:41 0: [echodevice] load ECHO Device ECHO_G090VC0783740J9X
2019.08.16 17:03:41 3: XiaomiBTLESens (XiaomiFlower1) - defined with BTMAC C4:7C:8D:66:0F:40
2019.08.16 17:03:41 3: XiaomiBTLESens (XiaomiFlower2) - defined with BTMAC C4:7C:8D:66:10:A0
2019.08.16 17:03:41 3: freezemon defined myFreezemon freezemon
2019.08.16 17:03:42 3: RoborockS5: initialized, using AES
2019.08.16 17:03:42 3: MQTT2_FHEM_Server: port 1882 opened
2019.08.16 17:03:42 1: Including ./log/fhem.save
Undefined address for Socket::pack_sockaddr_in at /usr/lib/arm-linux-gnueabihf/perl/5.28/Socket.pm line 164.


Insbesondere die "unreachable" und die letzte Zeile mit dem Socket machen mich stutzig, denn eigentlich ist alles erreichbar im Netzwerk (die anderen Fehler kommen nur daher dass keine USB Geräte angeschlossen sind, nicht relevant hier).

Sowas ähnliches hatte ich mal mit dem WifiLight Module das versucht hat auf ein Gerät beim FHEM Start zuzugreifen was nicht verfügbar war, worauf sich dann FHEM auch verabschiedet hat. Nur diesmal kann ich das Problem hier ausschliessen...

Bin ziemlich ratlos im Moment... :-[

Christoph Morrison


Nemo0815

#2
Kernel IP routing table
Destination     Gateway         Genmask         Flags   MSS Window  irtt Iface
0.0.0.0         192.168.178.1   0.0.0.0         UG        0 0          0 wlan0
192.168.178.0   0.0.0.0         255.255.255.0   U         0 0          0 wlan0

Schaut auf den ersten Blick ganz normal aus, oder?

Das ganz ist passiert als ich meinen Speedport Hybrd Router neu gestartet habe (hängt vor meiner Fritzbox welche als WiFi Router dient). Aber könnte auch Zufall gewesen sein...

Christoph Morrison

Nur wenn dein Raspberry wirklich über Wifi angebunden ist.

Nemo0815

#4
Zitat von: Christoph Morrison am 16 August 2019, 21:55:52
Nur wenn dein Raspberry wirklich über Wifi angebunden ist.

Ja, ist er.

Zur info, damit ich den Raspi überhaupt zum laufen kriege muss ich fhem möglichst schnell nach dem booten stoppen. Wenn ich's danach starte läuft es auch. Tue ich das dagegen nicht hängt sich der Raspi komplett auf und ist auch nicht im Netzwerk erreichbar (nichtmal über Ping).

frank

eventuell wird dein fhem beim booten zu früh gestartet, so dass die netzwerkkomponenten nocht nicht zur verfügung stehen. also im sys.log schauen und eventuell verzögern über systemd.

ist fhem auch nach vielleicht 10min warten immer noch nicht erreichbar?
attr global dnsServer sollte auch gesetzt sein.
FHEM: 6.0(SVN) => Pi3(buster)
IO: CUL433|CUL868|HMLAN|HMUSB2|HMUART
CUL_HM: CC-TC|CC-VD|SEC-SD|SEC-SC|SEC-RHS|Sw1PBU-FM|Sw1-FM|Dim1TPBU-FM|Dim1T-FM|ES-PMSw1-Pl
IT: ITZ500|ITT1500|ITR1500|GRR3500
WebUI [HMdeviceTools.js (hm.js)]: https://forum.fhem.de/index.php/topic,106959.0.html

Nemo0815

Zitat von: frank am 16 August 2019, 22:43:09
eventuell wird dein fhem beim booten zu früh gestartet, so dass die netzwerkkomponenten nocht nicht zur verfügung stehen. also im sys.log schauen und eventuell verzögern über systemd.

ist fhem auch nach vielleicht 10min warten immer noch nicht erreichbar?
attr global dnsServer sollte auch gesetzt sein.

Nein da tut sich auch nach Stunden nichts, der ganze Raspi ist blockiert wenn ich fhem nicht stoppe. Das Attribut hab ich jetzt gesetzt, bringt aber nichts

Nemo0815

Wenn ich mir das syslog so anschaue sind da schon etwas seltsame Einträge enthalten: 

Aug 17 11:54:56 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:54:59 raspberrypi java[610]: 2019-08-17 11:54:59,488 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:55:01 raspberrypi CRON[6342]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Aug 17 11:55:01 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:06 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:11 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:16 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:19 raspberrypi java[610]: 2019-08-17 11:55:19,509 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:55:21 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:26 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:31 raspberrypi ntpd[682]: error resolving pool 2.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:55:31 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:36 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:39 raspberrypi java[610]: 2019-08-17 11:55:39,530 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:55:42 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:46 raspberrypi ntpd[682]: error resolving pool 0.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:55:46 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:47 raspberrypi ntpd[682]: error resolving pool 3.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:55:52 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:52 raspberrypi ntpd[682]: error resolving pool 1.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:55:57 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:55:59 raspberrypi java[610]: 2019-08-17 11:55:59,552 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:56:02 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:07 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:12 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:17 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:19 raspberrypi java[610]: 2019-08-17 11:56:19,573 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:56:22 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:27 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:32 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:37 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:38 raspberrypi ntpd[682]: error resolving pool 2.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:56:39 raspberrypi java[610]: 2019-08-17 11:56:39,594 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:56:42 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:47 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:52 raspberrypi ntpd[682]: error resolving pool 3.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:56:52 raspberrypi ntpd[682]: error resolving pool 0.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:56:52 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:57 raspberrypi ntpd[682]: error resolving pool 1.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Aug 17 11:56:57 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:56:59 raspberrypi java[610]: 2019-08-17 11:56:59,616 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:57:02 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:07 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:08 raspberrypi motion: [1:ml1] [NTC] [ALL] Above message repeats 1 times
Aug 17 11:57:08 raspberrypi motion: [1:ml1] [NTC] [ALL] motion_detected: Motion detected - starting event 5
Aug 17 11:57:13 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:18 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:19 raspberrypi java[610]: 2019-08-17 11:57:19,637 [main] WARN  com.bwssystems.HABridge.upnp.UpnpListener - UpnpListener encountered an error sending upnp notify packet. IP: 239.255.255.250 with message: Das Netzwerk ist nicht erreichbar (sendto failed)
Aug 17 11:57:23 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:28 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:33 raspberrypi rc.local[598]: Can't connect to localhost:7072
Aug 17 11:57:38 raspberrypi rc.local[598]: Can't connect to localhost:7072

Christoph Morrison

Ich würde ja mal einen A/B-Test machen und den Raspberry über Ethernet anschließen, neu starten und dann schauen was passiert. Einfach mal um Wifi-Probleme auszuschließen.

Helmi55

#9
guten Abend ich hänge mich hier dran.
Habe meinen RPi4 mit 4GB heute neu mit Buster light aufgesetzt. Einiges nachinstalliert und dann das BU des alten RPi's aufgespielt.
Am Mac in der Konsole bekomme ich eine Verbindung zum Pi aber FHEM kann ich nicht erreichen.

ein sudo systemctl status fhem

bringt folgendes und sagt mir leider nix.....  sorry
● fhem.service - FHEM Home Automation
   Loaded: loaded (/etc/systemd/system/fhem.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sat 2019-08-17 16:31:36 CEST; 8min ago

Aug 17 16:31:36 RPiGarageneu systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Aug 17 16:31:36 RPiGarageneu systemd[1]: fhem.service: Scheduled restart job, restart counter is at 5.
Aug 17 16:31:36 RPiGarageneu systemd[1]: Stopped FHEM Home Automation.
Aug 17 16:31:36 RPiGarageneu systemd[1]: fhem.service: Start request repeated too quickly.
Aug 17 16:31:36 RPiGarageneu systemd[1]: fhem.service: Failed with result 'exit-code'.
Aug 17 16:31:36 RPiGarageneu systemd[1]: Failed to start FHEM Home Automation.



Was kann ich da bitte noch versuchen??

PS: vor der Installation von OWServer und des HM USB Cfg Models konnte ich FHEM noch erreichen da ich da ein Update durchgeführt habe????

Gruß
Helmut
System1 fhem 6.1 auf RPi 4B mit 4GB, HMUSBConfig, DS9490R-1Wire, Busware USB 868, Pool-Solarsteuerung mit FHEM. System2 fhem 6.1 auf RPi 4B mit 4GB (Bullseye) mit Busware USB 868 und 433 und HMUARTLGW für Haussteuerung

https://www.flickr.com/photos/canonhelmi/

Wernieman

@Nemo0815

Kleiner Hinweis:
Du kannst einem Dienst (wie FHEm) auch sagen, das er beim booten NICHT starten soll. Solltest Du mal für die Fehlersuche probieren. Kann mir eigentlich nicht vorstellen, das es an FHEm liegt, dass Du nicht per ssh auf den PI kommst

@Helmi55
Aug 17 16:31:36 RPiGarageneu systemd[1]: Failed to start FHEM Home Automation.

Kucke mal in die Logfiles. Allerdings ... dürfte es ein anderer Fehler sein un damit möchte ich Dich bitten einen neuen Thread aufzumachen

P.S.
PS: vor der Installation von OWServer und des HM USB Cfg Models konnte ich FHEM noch erreichen da ich da ein Update durchgeführt habe?
Hatten wir vor kurzen mit buster nicht so etwas hier im Forum??
- Bitte um Input für Output
- When there is a Shell, there is a Way
- Wann war Dein letztes Backup?

Wie man Fragen stellt: https://tty1.net/smart-questions_de.html

Christoph Morrison

Zitat von: Helmi55 am 17 August 2019, 18:39:23
guten Abend ich hänge mich hier dran.

Warum? Mach doch lieber einen eigenen Thread auf bzw. verschiebe deinen Beitrag in einen neuen Thread falls du das kannst.
Das sind ziemlich sicher zwei unterschiedliche Probleme.

Nemo0815

Zitat von: Wernieman am 17 August 2019, 20:47:55
@Nemo0815

Kleiner Hinweis:
Du kannst einem Dienst (wie FHEm) auch sagen, das er beim booten NICHT starten soll. Solltest Du mal für die Fehlersuche probieren. Kann mir eigentlich nicht vorstellen, das es an FHEm liegt, dass Du nicht per ssh auf den PI kommst

@Helmi55
Aug 17 16:31:36 RPiGarageneu systemd[1]: Failed to start FHEM Home Automation.

Kucke mal in die Logfiles. Allerdings ... dürfte es ein anderer Fehler sein un damit möchte ich Dich bitten einen neuen Thread aufzumachen

P.S.
PS: vor der Installation von OWServer und des HM USB Cfg Models konnte ich FHEM noch erreichen da ich da ein Update durchgeführt habe?
Hatten wir vor kurzen mit buster nicht so etwas hier im Forum??

Ich hab's jetzt mit dem ntp fix irgendwie geschafft dass es manchmal startet, allerdings nur wenn ich den Stecker ziehen. Mit restart aus der Konsole verliere ich die Verbindung ( weiss aber nicht ob er noch runter fährt oder nicht richtig rauf.

Wenn ich den fhem Service  deaktiviere fährt der Pi auch ganz normal hoch und ist erreichbar.

Wernieman

Dann startet FHEM einfach zu schnell ....

Was für ein System?
(init.d oder system.d, alternativ welches Linux-System)
- Bitte um Input für Output
- When there is a Shell, there is a Way
- Wann war Dein letztes Backup?

Wie man Fragen stellt: https://tty1.net/smart-questions_de.html

Nemo0815

#14
Zitat von: Wernieman am 19 August 2019, 08:08:28
Dann startet FHEM einfach zu schnell ....

Was für ein System?
(init.d oder system.d, alternativ welches Linux-System)

Es ist ein RaspberrryPi 4 mit Raspbian Buster (systemd).

Verstehe nur nicht wieso das jetzt plötzlich - ohne Änderungen oder Updates am System, nur nach einem Router neustart so auftritt. Macht irgendwie keinen Sinn, weils vorher immer problemlos funktioniert hatte...(aber evtl. braucht der Raspi jetzt länger bis er seine IP bekommt...)


Update: Versuche es jetzt mal mit

After=network-online.target
Wants=network-online.target