FHEM hängt beim Start

Otto123 · 08 Juli 2017, 11:35:40

Ja läuft, habe es gerade probiert. Ok, er kann ein paar Logs nicht anlegen, da fehlen die Rechte. Ist aber eigentlich gut so, da entsteht kein Müll.

CoolTux · 08 Juli 2017, 12:15:16

Dann sind die Rechte wohl so das auch jeder lesen und ausführen darf. Aber zum testen ist es okay.

Morrino · 08 Juli 2017, 12:36:50

Hi,
vielen Dank für eure Unterstützung.

Das mit der Demo hatte ich noch nicht wieder probiert bisher.

Allerdings habe ich aus Verzweiflung einmal das Propalanta Modul in der cgf händisch rausgenommen, da dies immer als letzte Fehlermeldung aufgetreten ist.
Daraufhin konnte ich FHEM wieder einmal starten

Da ich irgendwie auf einen Zufall getippt habe hatte ich mit "shutdown restart" noch einen Versuch gewartet. Hier hat es wieder nicht gestartet und im Log kam folgende Meldung am Ende:

Code Auswählen

2017.07.08 12:24:35 1: BlockingInformParent (BlockingStart): Can't connect to localhost:36007: IO::Socket::INET: connect: Connection refused
2017.07.08 12:24:35 1: BlockingInformParent (LGTV_WebOS_PresenceDone): Can't connect to localhost:36007: IO::Socket::INET: connect: Connection refused
2017.07.08 12:24:36 5: Initializing Type Library:
2017.07.08 12:24:36 1: Including fhem.cfg
2017.07.08 12:24:36 5: Cmd: >attr global userattr DbLogExclude DbLogInclude alarmDevice alarmSettings alexaName alexaRoom cmdIcon devStateIcon devStateStyle genericDeviceType:security,ignore,switch,outlet,light,blind,thermometer,thermostat,contact,garage,window,lock homebridgeMapping:textField-long icon sortby webCmd widgetOverride<
2017.07.08 12:24:36 5: Cmd: >attr global autoload_undefined_devices 1<
2017.07.08 12:24:36 5: Cmd: >attr global exclude_from_update widget_fullcalview.js widget_weekprofile.js widget_calview.js widget_pagebutton.js 59_Wunderground.pm widget_weather.js<
2017.07.08 12:24:36 5: Cmd: >attr global latitude 53.618372<
2017.07.08 12:24:36 5: Cmd: >attr global logfile ./log/fhem-%Y-%m.log<
2017.07.08 12:24:36 5: Cmd: >attr global longitude 9.879606<
2017.07.08 12:24:36 5: Cmd: >attr global modpath .<
2017.07.08 12:24:36 5: Cmd: >attr global motd SecurityCheck:

WEBtablet has no associated allowed device with basicAuth.

Restart FHEM for a new check if the problem is fixed,
or set the global attribute motd to none to supress this message.
<
2017.07.08 12:24:36 5: Cmd: >attr global showInternalValues 1<
2017.07.08 12:24:36 5: Cmd: >attr global statefile ./log/fhem.save<
2017.07.08 12:24:36 5: Cmd: >attr global updateInBackground 1<
2017.07.08 12:24:36 5: Cmd: >attr global verbose 5<
2017.07.08 12:24:36 5: Cmd: >define telnetPort telnet 7072 global<
2017.07.08 12:24:36 5: Loading ./FHEM/98_telnet.pm
2017.07.08 12:24:36 1: telnetPort: Can't open server port at 7072: Address already in use. Exiting.

Nach einen erneuten restart, diesmal gezwungener Maßen wieder über Putty, hat FHEM wieder gestartet.

Also liegt es irgendwie an Propalanta oder an telnet allgemein?

Grüße

Otto123 · 08 Juli 2017, 13:11:11

Hi,

scheint an dem Modul Proplanta zu liegen. Das Log von Dir deutet eigentlich darauf hin, das FHEM noch läuft und der Port noch in Verwendung ist

Zitat2017.07.08 12:24:36 5: Cmd: >define telnetPort telnet 7072 global<
2017.07.08 12:24:36 5: Loading ./FHEM/98_telnet.pm
2017.07.08 12:24:36 1: telnetPort: Can't open server port at 7072: Address already in use. Exiting.

Da hat offenbar der shutdown restart nicht funktioniert.

Gruß Otto

CoolTux · 08 Juli 2017, 13:15:00

Mein LG Modul scheint bei Dir auch nicht sauber zu laufen. Aber das könnten auch alles Folgefehler sein.
Hast Du eine Veränderung in letzter Zeit durchgeführt? Neue Netzwerkkarte oder irgendwas mit Netzwerk?
Zeig Mal bitte den Inhalt von /etc/hosts

Morrino · 08 Juli 2017, 16:05:56

Hi

ansich habe ich nichts geändert gehabt.
Habe nach mehreren Wochen (unter anderem Urlaub) nur alle updates gezogen (FHEM inkl. Raspberry pi etc)

Ansonsten hatte ich nur Alexa noch die neueste Version aufgespielt.

Dein LG Modul scheint aber ansonsten soweit zu funktionieren.

Habe zum testen Proplanta noch einmal neu eingerichtet, danach wieder das Problem das FHEM nicht gestartet werden kann.
Aber es kann doch nicht sein dass nur ich damit ein Problem habe oder? Würde darum schon eher den Fehler bei mir suchen.

Morrino · 23 September 2017, 17:23:08

Hallo,

ich packe meine alten Thread mal wieder aus, da ich das Problem bisher leider noch immer nicht lösen konnte und mittlerweile FHEM auch gar nicht mehr startet.
Allerdings nur wenn ich das Modul "XiaomiSmartHome" installieren.

Ich habe das im Thread des Moduls auch schon angesprochen leider konnte mir der Entwickler hier nicht bei meinem Problem helfen.
Anbei die Aussage von ihm:

Zitat von: torte am 22 September 2017, 09:02:23
Hi Morrino,

so hab mal verglichen was das Modul macht bis zum Abbruch bzw. bis zum BlockingInformParent
Die letzte Meldung im Log ist
Code Auswählen Erweitern
Xiaomi_Gateway: connecting
Nach dieser Meldung versucht das Modul einen Ping auf die IP abzusetzen um zu entscheiden ob es mit dem Modul weitergeht oder nicht.
Entweder Connect oder Disconnect wird dann ausgelöst.
Aber keines der beiden passiert. Perl schaft es wohl nicht den Ping abzusetzen oder das BlockingInformParent haut irgendwie dazwischen.

Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused

Das solltest Du mal klären scheint was spezifisches von Deiner Installation zu sein.
Weiß jetzt nicht was ich da Modul technisch noch abfangen kann.
Such mal hier im Forum nach BlockingInformParent da gibt es schon ein paar Einträge dazu evtl. kann man das Problem ja so einkreisen.
Im Moment fällt mir dazu nichts ein, sorry.

Grüße
Torte

Darum wollte ich es hier noch einmal probieren, eventuell was jemand etwas womit er mir helfen könnte.

Anbei noch das Log und das Fehlerverhalten:

Der Fehler passiert nicht immer aber oft. Einmal auch nachdem ich das Modul neu aufgesetzt habe und ein update des Moduls durchgeführt habe.
Ansonsten hängt es (fast) immer bei jedem Neustart, wenn einmal doch FHEM komplett startet funktioniert alles tadellos, auch das Xiaomi Modul.

Anbei ein Verbose 5 log, wobei hier sich nichts unterscheidet zum Log ohne Verbose. FHEm startet ja nicht korrekt:

Code Auswählen

2017.09.21 22:05:06 3: Opening Mosquitto device 192.168.178.50:1883
2017.09.21 22:05:06 3: Mosquitto device opened
2017.09.21 22:05:06 3: WZ.Harmony: connected
2017.09.21 22:05:07 3: WZ.WifiLight low level cmd queue send ERROR 3100000000000f40, qlen 1 (reconnect giving up)
2017.09.21 22:05:07 5: Xiaomi_Gateway: Notify> NotifyStart
2017.09.21 22:05:07 5: Xiaomi_Gateway: Notify> Starting Connect after global
2017.09.21 22:05:07 1: usb create starting
2017.09.21 22:05:08 3: Probing CUL device /dev/ttyAMA0
2017.09.21 22:05:08 3: Probing TCM_ESP3 device /dev/ttyAMA0
2017.09.21 22:05:08 3: Probing ZWDongle device /dev/ttyAMA0
2017.09.21 22:05:08 3: Probing FRM device /dev/ttyAMA0
2017.09.21 22:05:13 1: usb create end
2017.09.21 22:05:13 3: roku: ssdp responder started
2017.09.21 22:05:14 3: roku: listener started
2017.09.21 22:05:14 2: SecurityCheck:  WEBtablet has no associated allowed device with basicAuth. telnetForBlockingFn has no associated allowed device with password/globalpassword.  Restart FHEM for a new check if the problem is fixed, or set the global attribute motd to none to supress this message. 
2017.09.21 22:05:14 0: Featurelevel: 5.8
2017.09.21 22:05:14 0: Server started with 310 defined entities (fhem.pl:15091/2017-09-18 perl:5.020002 os:linux user:fhem pid:3302)
2017.09.21 22:05:15 3: DbRep DbRep - connected
2017.09.21 22:05:17 1: PERL WARNING: Can't exec "hddtemp": No such file or directory at (eval 487) line 1.
2017.09.21 22:05:17 1: PERL WARNING: Argument "cat: /sys/class/power_supply/ac/voltage_now: No such fil..." isn't numeric in division (/) at (eval 488) line 1.
2017.09.21 22:05:17 1: PERL WARNING: Argument "cat: /sys/class/power_supply/ac/current_now: No such fil..." isn't numeric in division (/) at (eval 489) line 1.
2017.09.21 22:05:17 5: Xiaomi_Gateway: connect> ConnectStart
2017.09.21 22:05:17 4: Xiaomi_Gateway: connecting
[u][b]send: Invalid argument at ./FHEM/71_XiaomiSmartHome.pm line 277.[/b][/u]
2017.09.21 22:05:17 3: UWZ Wetter_UWZ: Run.1000 Done fetching data
2017.09.21 22:05:17 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:17 1: BlockingInformParent (UWZ_Done): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:17 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:17 1: BlockingInformParent (FRITZBOX_Readout_Done): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:20 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:23 1: BlockingInformParent (BlockingStart): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused
2017.09.21 22:05:23 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:39275: IO::Socket::INET: connect: Connection refused

Entferne ich das Modul wieder funktioniert alles normal. Auch die Fehlermeldungen wie

Code Auswählen

2017.09.21 22:00:00 1: BlockingInformParent (BlockingStart): Can't connect to localhost:44017: IO::Socket::INET: connect: Connection refused

kommen dann beim starten von FHEM nicht mehr.

Gateway und FHEM sind im selben Netz.

Bin über jede Hilfe / Idee dankbar, ich bin mit meinem (leider relativ geringem) Latein am Ende.
Danke für deine Unterstützung.

Grüße

Morrino · 24 September 2017, 12:06:05

Hi,

vielleicht hilft ja folgende Meldung noch weiter.

Ich hatte es jetzt auch zweimal das mir FHEM direkt (ca. 5 Sekunden) nach dem installieren des Xiaomi Moduls abgestürzt ist.
Ale er dabei war die Sensoren per autocreate anzulegen.
Ich wollte gerade das Passwort des Moduls eingeben und weg war FHEM.

Habe momentan das globale attribut Verbosse auf 5 gesetzt.

Das Log hört mit folgendem Eintrag auf. Danach kommt nichts mehr:

Beim ersten Mal kam folgender Eintrag.

Code Auswählen

2017.09.24 09:22:21 5: IP: api.telegram.org -> 149.154.167.200
2017.09.24 09:22:21 5: TelegramBot_UpdatePoll TelegramBot: - Ende > next polling started
2017.09.24 09:22:21 4: TelegramBot_Callback TelegramBot: resulted in SUCCESS from Polling
2017.09.24 09:22:21 5: TelegramBot_Callback TelegramBot: - Ende > Control back to FHEM
2017.09.24 09:22:21 3: XMI_158d00015845b4: DEV_updateSReading> for 158d00015845b4
2017.09.24 09:22:21 4: Xiaomi_Gateway: Write> {"cmd":"read","sid":"158d00015845b4"} 192.168.178.46
send: Invalid argument at ./FHEM/71_XiaomiSmartHome.pm line 484.

Beim zweiten Mal nachfolgender:

Code Auswählen

2017.09.24 11:05:40 2: autocreate: define XMI_158d00015846be XiaomiSmartHome_Device 158d00015846be magnet Xiaomi_Gateway
2017.09.24 11:05:40 4: Xiaomi_Gateway: DEV_Define> XMI_158d00015846be: magnet I/O device is Xiaomi_Gateway
2017.09.24 11:05:40 4: Xiaomi_Gateway: DEV_Define> XMI_158d00015846be: defined as magnet
2017.09.24 11:05:40 4: Xiaomi_Gateway: DEV_Define> XMI_158d00015846be Init Done set InternalTimer for Update
2017.09.24 11:05:40 2: autocreate: define FileLog_XMI_158d00015846be FileLog ./log/XMI_158d00015846be-%Y.log XMI_158d00015846be
2017.09.24 11:05:41 5: End notify loop for global
2017.09.24 11:05:41 4: <hidden>: HTTP response code 200
2017.09.24 11:05:41 4: HttpUtils <hidden>: Got data, length: 23
2017.09.24 11:05:41 5: HttpUtils response header:
HTTP/1.1 200 OK
Server: nginx/1.10.0
Date: Sun, 24 Sep 2017 09:05:40 GMT
Content-Type: application/json
Content-Length: 23
Connection: close
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: GET, POST, OPTIONS
Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection
Strict-Transport-Security: max-age=31536000; includeSubdomains
2017.09.24 11:05:41 5: TelegramBot_Callback TelegramBot: called from Polling
2017.09.24 11:05:41 5: TelegramBot_Callback TelegramBot: data returned :{"ok":true,"result":[]}:
2017.09.24 11:05:41 5: TelegramBot_Deepencode TelegramBot: found an ARRAY
2017.09.24 11:05:41 5: TelegramBot_Deepencode TelegramBot: encoded a String from :true: to :true:
2017.09.24 11:05:41 5: TelegramBot_Deepencode TelegramBot: found a HASH
2017.09.24 11:05:41 5: TelegramBot_Callback TelegramBot: after encoding
2017.09.24 11:05:41 5: TelegramBot_Callback TelegramBot: polling returned result? 0
2017.09.24 11:05:41 5: UpdatePoll TelegramBot: number of results 0
2017.09.24 11:05:41 5: TelegramBot_UpdatePoll TelegramBot: called 
2017.09.24 11:05:41 5: TelegramBot_UpdatePoll TelegramBot: - Initiate non blocking polling - With callback set
2017.09.24 11:05:41 5: TelegramBot_readToken: Read Telegram API token from file
2017.09.24 11:05:41 4: TelegramBot_UpdatePoll TelegramBot: initiate polling with nonblockingGet with 120s
2017.09.24 11:05:41 4: HttpUtils url=<hidden>
2017.09.24 11:05:41 5: IP: api.telegram.org -> 149.154.167.199
2017.09.24 11:05:41 5: TelegramBot_UpdatePoll TelegramBot: - Ende > next polling started
2017.09.24 11:05:41 4: TelegramBot_Callback TelegramBot: resulted in SUCCESS from Polling
2017.09.24 11:05:41 5: TelegramBot_Callback TelegramBot: - Ende > Control back to FHEM
2017.09.24 11:05:41 3: XMI_158d0001291479: DEV_updateSReading> for 158d0001291479
2017.09.24 11:05:41 4: Xiaomi_Gateway: Write> {"cmd":"read","sid":"158d0001291479"} 192.168.178.46
send: Invalid argument at ./FHEM/71_XiaomiSmartHome.pm line 484.

Dazwischen hat es auch einmal funktioniert ohne absturz. Hier dann erst wieder beim Restart von FHEM.

Grüße