Hallo,
seit gestern bleibt FHEM ständig einfach stehen. Mal läuft es stundenlang, dann hängt es sich nach ein paar Minuten wieder auf. Aber im Log findet sich nichts, was damit zusammenhängen könnte. ???
Anbei Logs meiner Startversuche heute morgen. Nach dem ersten Start um 06:38 kommt auf einmal um 06:44 ein "Server shutdown". Dann startet FHEM einfach neu und 2 Minuten später wieder "Shutdown". So geht's dann weiter. Beim letzten Mal kommt dann kein Shutdown mehr im Log.
Das letzte Log ist mit "verbose 5". Da lief der Server vorher mal lange genug, um dran zu kommen und verbose hochzusetzen.
Interessant ist, das es jedes Mal an einer anderen Stelle stehen bleibt. Auch in den Systemlogs taucht um die Zeit des Crashs nichts auf. Gibt es irgendeine Möglichkeit, das Problem weiter einzugrenzen?
Edit: Nach dem letzten restart scheint FHEM jetzt in der Endloschleife neu zu starten. Ich lasse gerade mal mit tail das Log mitlaufen. :-\
1. keine Dateien anhängen. Die öffnet keiner... Stattdessen das log in codetags posten.
Das Log mit v5 hat 14152 Zeilen, bei denen ich ja nicht weiß, was ich ausfiltern soll. Das geht schlecht als Code inline.
Aber hier mal eins mit verbose 3:
2017.02.17 06:48:13.538 3: telnetPort: port 7072 opened
2017.02.17 06:48:13.935 3: WEB: port 8083 opened
2017.02.17 06:48:14.273 3: WEBphone: port 8084 opened
2017.02.17 06:48:14.280 3: WEBtablet: port 8085 opened
2017.02.17 06:48:15.193 2: eventTypes: loaded 5390 events from ./log/eventTypes.txt
2017.02.17 06:48:16.575 3: Opening CUBe_CUL_0 device /dev/serial/by-id/usb-03eb_AT91USBSerial0-if00
2017.02.17 06:48:16.683 3: Setting CUBe_CUL_0 serial parameters to 9600,8,N,1
2017.02.17 06:48:16.811 3: CUBe_CUL_0: Possible commands: BbCFiAZNEkGMKLUYRTVWXefhltxz
2017.02.17 06:48:16.834 3: CUBe_CUL_0 device opened
2017.02.17 06:48:16.867 2: Switched CUBe_CUL_0 rfmode to MAX
2017.02.17 06:48:16.940 3: CUL_MAX_Check: Detected firmware version 154 of the CUL-compatible IODev
2017.02.17 06:48:18.263 3: OIL: Defined with URL http://www.clever-tanken.de/tankstelle_details/40524 and interval 600
2017.02.17 06:48:18.417 3: Calpam: Defined with URL http://www.clever-tanken.de/tankstelle_details/5917 and interval 600
2017.02.17 06:48:18.531 3: ARAL: Defined with URL http://www.clever-tanken.de/tankstelle_details/5916 and interval 600
2017.02.17 06:48:18.683 3: ED: Defined with URL http://www.clever-tanken.de/tankstelle_details/16853 and interval 600
2017.02.17 06:48:18.883 3: Q8: Defined with URL http://www.q8-dasburg.lu/ and interval 600
2017.02.17 06:48:19.008 3: Raiffeisen: Defined with URL http://www.clever-tanken.de/tankstelle_details/39662 and interval 600
2017.02.17 06:48:19.159 3: wetter_rennerod: Defined with URL http://api.wunderground.com/weatherstation/WXDailyHistory.asp?ID=IRENNERO4&format=XML and interval 600
2017.02.17 06:48:20.036 1: PERL WARNING: Prototype mismatch: sub main::head: none vs ($) at (eval 58) line 1.
2017.02.17 06:48:20.146 3: Opening CUBe_CUL_1 device /dev/serial/by-id/usb-03eb_AT91USBSerial1-if00
2017.02.17 06:48:20.153 3: Setting CUBe_CUL_1 serial parameters to 9600,8,N,1
2017.02.17 06:48:20.281 3: CUBe_CUL_1: Possible commands: BbCFiAZNEkGMKLUYRTVWXefhltxz
2017.02.17 06:48:20.303 3: CUBe_CUL_1 device opened
2017.02.17 06:48:20.349 3: Opening nanoCUL device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600KGR0-if00-port0
2017.02.17 06:48:20.354 3: Setting nanoCUL serial parameters to 38400,8,N,1
2017.02.17 06:48:23.525 3: nanoCUL: Possible commands: ABCeFfGiKLlMNRTtUVWXx
2017.02.17 06:48:23.548 3: nanoCUL device opened
2017.02.17 06:48:26.081 3: Opening pilight device localhost:5000
2017.02.17 06:48:26.086 3: pilight device opened
2017.02.17 06:48:26.254 3: sduino: IDlist MS 0 1 13 14 15 17 2 22 23 25 3 32 33 35 38 4 41 45 51 55 6 7
2017.02.17 06:48:26.255 3: sduino: IDlist MU 13.1 16 20 21 24 26 27 28 29 30 31 34 36 37 39 40 42 44 44.1 46 48 49 5 50 56 59 8 9
2017.02.17 06:48:26.255 3: sduino: IDlist MC 10 11 12 18 43 47 52 57 58
2017.02.17 06:48:26.256 3: Opening sduino device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600HKN9-if00-port0
2017.02.17 06:48:26.260 3: Setting sduino serial parameters to 57600,8,N,1
2017.02.17 06:48:26.269 1: sduino/define: /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600HKN9-if00-port0@57600
2017.02.17 06:48:26.270 1: sduino/init: /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A600HKN9-if00-port0@57600
2017.02.17 06:48:26.271 3: sduino device opened
2017.02.17 06:48:26.275 3: sduino: IDlist MS 13 3
2017.02.17 06:48:26.276 3: sduino: IDlist MU 13.1 30 39 9
2017.02.17 06:48:26.276 3: sduino: IDlist MC 10
2017.02.17 06:48:27.127 1: PERL WARNING: "my" variable $host masks earlier declaration in same scope at ./FHEM/30_MilightBridge.pm line 72.
2017.02.17 06:48:27.613 3: Opening ZME_UZB1 device /dev/serial/by-id/usb-0658_0200-if00
2017.02.17 06:48:27.616 3: Setting ZME_UZB1 serial parameters to 115200,8,N,1
2017.02.17 06:48:28.715 3: ZME_UZB1 device opened
2017.02.17 06:48:30.046 1: PERL WARNING: each on reference is experimental at ./FHEM/70_JSONREADINGS.pm line 122.
2017.02.17 06:48:30.047 1: PERL WARNING: each on reference is experimental at ./FHEM/70_JSONREADINGS.pm line 126.
2017.02.17 06:48:30.048 1: PERL WARNING: main::toReadings() called too early to check prototype at ./FHEM/70_JSONREADINGS.pm line 121.
2017.02.17 06:48:30.609 3: MaxScanner MaxScanner Initialize.121 Init Done with Version 1.0.0.3 - 07.03.2016
2017.02.17 06:48:31.103 1: PERL WARNING: Subroutine toReadings redefined at ./FHEM/70_SpeedPortHybridReadings.pm line 234.
2017.02.17 06:48:31.287 3: TelegramBot_Define Telegram: called
2017.02.17 06:48:31.707 3: dash: listening
2017.02.17 06:48:32.655 3: Opening UPS device localhost:3493
2017.02.17 06:48:32.667 3: UPS device opened
2017.02.17 06:49:33.126 3: [STV] defined with host: 192.168.1.211 port: 55000 MAC: b8:27:eb:12:9b:cb
2017.02.17 06:49:33.328 3: Opening JeeLink device /dev/serial/by-id/usb-FTDI_FT232R_USB_UART_AL006PEM-if00-port0
2017.02.17 06:49:33.333 3: Setting JeeLink serial parameters to 57600,8,N,1
2017.02.17 06:49:34.344 3: JeeLink device opened
2017.02.17 06:49:34.396 3: LaCrosse_1A: I/O device is JeeLink
2017.02.17 06:49:34.409 3: LaCrosse_2D: I/O device is JeeLink
2017.02.17 06:49:34.490 3: WhatsApp: sending /disconnect
2017.02.17 06:49:34.503 3: WhatsApp: Disconnected
2017.02.17 06:49:37.546 3: CHROMECAST: Chromecast7180 initializing...
2017.02.17 06:49:38.099 2: Registering GEOFANCY geofancy for URL /geo...
2017.02.17 06:49:38.156 1: PERL WARNING: Scalar value @a[1] better written as $a[1] at ./FHEM/98_gcmsend.pm line 35.
2017.02.17 06:49:38.157 1: PERL WARNING: Scalar value @a[...] better written as $a[...] at ./FHEM/98_gcmsend.pm line 45.
2017.02.17 06:49:38.160 1: PERL WARNING: Scalar value @array[...] better written as $array[...] at ./FHEM/98_gcmsend.pm line 79.
2017.02.17 06:49:38.166 1: PERL WARNING: Using a hash as a reference is deprecated at ./FHEM/98_gcmsend.pm line 195.
2017.02.17 06:49:38.167 1: PERL WARNING: Using a hash as a reference is deprecated at ./FHEM/98_gcmsend.pm line 199.
2017.02.17 06:49:38.168 1: PERL WARNING: Using a hash as a reference is deprecated at ./FHEM/98_gcmsend.pm line 201.
2017.02.17 06:49:38.170 1: PERL WARNING: Scalar value @parts[0] better written as $parts[0] at ./FHEM/98_gcmsend.pm line 220.
2017.02.17 06:49:38.171 1: PERL WARNING: Scalar value @parts[1] better written as $parts[1] at ./FHEM/98_gcmsend.pm line 221.
2017.02.17 06:49:38.171 1: PERL WARNING: Scalar value @parts[2] better written as $parts[2] at ./FHEM/98_gcmsend.pm line 222.
2017.02.17 06:49:38.172 1: PERL WARNING: Scalar value @parts[3] better written as $parts[3] at ./FHEM/98_gcmsend.pm line 225.
2017.02.17 06:49:38.172 1: PERL WARNING: Scalar value @parts[3] better written as $parts[3] at ./FHEM/98_gcmsend.pm line 226.
2017.02.17 06:49:38.173 1: PERL WARNING: Scalar value @parts[3] better written as $parts[3] at ./FHEM/98_gcmsend.pm line 229.
2017.02.17 06:49:38.254 3: WEBhook: port 8088 opened
2017.02.17 06:49:38.280 3: LaCrosse_08: I/O device is JeeLink
2017.02.17 06:49:38.293 3: wunderground_upload: Defined with URL https://weatherstation.wunderground.com/weatherstation/updateweatherstation.php?ID=IRENNERO8&PASSWORD=%password%&dateutc=now&tempf=%tempf%&dewptf=%dewptf%&humidity=%humidity%&action=updateraw and interval 60
2017.02.17 06:49:38.789 3: tado: interval is 0, no periodic updates will done.
2017.02.17 06:49:38.790 3: tado: Defined with URL https://my.tado.com/api/v2/me
2017.02.17 06:49:39.639 3: LaCrosse_16: I/O device is JeeLink
2017.02.17 06:49:39.659 3: LaCrosse_33: I/O device is JeeLink
2017.02.17 06:49:39.898 3: kindleweb: new ext defined infix:kindle: dir:/opt/fhem/kindle:
2017.02.17 06:49:39.899 3: Registering HTTPSRV kindleweb for URL /kindle and assigned link kindle ...
2017.02.17 06:49:39.906 1: PERL WARNING: each on reference is experimental at ./FHEM/55_weco.pm line 96.
2017.02.17 06:49:39.907 1: PERL WARNING: Smartmatch is experimental at ./FHEM/55_weco.pm line 98.
2017.02.17 06:49:40.101 3: mitemp: I/O device is RaspBee
2017.02.17 06:49:40.105 3: mitemp2: I/O device is RaspBee
2017.02.17 06:49:40.108 3: mitemp3: I/O device is RaspBee
2017.02.17 06:49:40.124 3: HUEDevice1: I/O device is RaspBee
2017.02.17 06:49:40.131 3: HUEGroup1: I/O device is RaspBee
2017.02.17 06:49:40.137 3: HUE_motion_light: I/O device is RaspBee
2017.02.17 06:49:40.140 3: HUE_motion_presence: I/O device is RaspBee
2017.02.17 06:49:40.144 3: HUE_motion_switch: I/O device is RaspBee
2017.02.17 06:49:40.147 3: HUEDevice2: I/O device is RaspBee
2017.02.17 06:49:40.153 3: HUEGroup0: I/O device is RaspBee
2017.02.17 06:49:40.280 1: PERL WARNING: Prototype mismatch: sub main::to_json ($@) vs ($) at /usr/share/perl/5.20/Exporter.pm line 66.
2017.02.17 06:49:40.281 1: PERL WARNING: Prototype mismatch: sub main::from_json ($@) vs ($) at /usr/share/perl/5.20/Exporter.pm line 66.
2017.02.17 06:49:40.298 1: PERL WARNING: Prototype mismatch: sub main::url: none vs ($;$) at /usr/share/perl/5.20/Exporter.pm line 66.
2017.02.17 06:49:40.305 1: PERL WARNING: "my" variable $str masks earlier declaration in same scope at ./FHEM/72_Spritpreis.pm line 177.
2017.02.17 06:49:42.210 3: Opening LMS device 192.168.1.204:9090
2017.02.17 06:49:42.213 3: SB_SERVER_DoInit(LMS): STATE: opened power: ?
2017.02.17 06:49:42.214 3: SB_SERVER_DoInit(LMS): SB-Server is back again.
2017.02.17 06:49:42.229 3: LMS device opened
2017.02.17 06:49:42.232 3: Opening Mosquitto device 127.0.0.1:1883
2017.02.17 06:49:42.264 3: Mosquitto device opened
2017.02.17 06:49:45.531 3: dash: stopped
2017.02.17 06:49:45.546 3: dash: listening
2017.02.17 06:49:45.767 0: Featurelevel: 5.8
2017.02.17 06:49:45.767 0: Server started with 277 defined entities (fhem.pl:13411/2017-02-14 perl:5.020002 os:linux user:fhem pid:1815)
2017.02.17 06:49:46.244 3: sduino/init: disable receiver (XQ)
2017.02.17 06:49:46.255 3: sduino/init: get version, retry = 0
2017.02.17 06:49:46.267 2: ZWDongle_ProcessSendStack: no ACK, resending message 0107000301020100f9
2017.02.17 06:49:51.252 3: ABFALL_UPDATE
2017.02.17 06:49:51.341 1: PERL WARNING: Argument "-" isn't numeric in multiplication (*) at ./FHEM/98_statistics.pm line 554.
2017.02.17 06:49:51.342 1: PERL WARNING: Argument "-" isn't numeric in numeric lt (<) at ./FHEM/98_statistics.pm line 556.
2017.02.17 06:49:51.711 3: UWZ Unwetterzentrale: Run.964 Done fetching data
2017.02.17 06:49:52.225 3: NUT antwortet nicht
2017.02.17 06:49:52.225 1: localhost:3493 disconnected, waiting to reappear (UPS)
2017.02.17 06:49:52.246 1: localhost:3493 reappeared (UPS)
2017.02.17 06:49:53.438 0: Server shutdown
"Server shutdown" kommt, when man in FHEM shutdown eintippt, oder wenn FHEM ein SIG_TERM (z.Bsp. via kill <fhem-pid>) empfaengt. Der Linux-Kernel hat (hatte?) die Angewohnheit, bei Speicherknappheit die groessten Prozesse abzuschiessen.
Btw. ich bin bei groesseren Datenmenge eindeutig gegen quote/codetag oder einfaches Reinkopieren, und fuer die Verwendung von Anhang:
- Anhaenge werden nicht in der mail Benachrichtigung verschickt, wo viel Text in einem Code-Tag meist unlesbar ist.
- auch die Browser-Besucher dieser Seite muessen nicht Jahrelang MB-weise uninteressantes Zeug herunterladen. Insb. wenn man per Telefon mit beschraenkten Volumen liest, hilft das.
- Es kann nicht passieren, dass der Beitrag wg. Ueberlaenge abgeschnitten wird, und so alles ohne den Schless-Tag hier landet, was zu einer Scroll-Orgie fuehrt.
Ich bin nicht generell gegen Code, aber ab einer Groesse von 1-2k sollte man ueber einen Anhang nachdenken.
Deswegen hatte ich die Logs ja angehängt. ;)
Der Kernel hat da nix abgeschossen. Im Kernel-Log steht nix Auffälliges und Speicher ist auch genug frei. Ich hatte auch extra den Pi nochmal neu gestartet.
Der Shutdown kommt wohl auch nur, wenn FHEM in eine Restart-Schleife gerät. Bei einem Stillstand wie im letzten Log (mit verbose 5) kommt kein Shutdown mehr.
Wann wird denn beim Starten genau das PID-File angelegt? Ich habe nämlich "pidfilename" in global gesetzt und kann mich erinnern, daß ich schonmal eine Restart-Schleife hatte, weil FHEM die Datei nicht schreiben konnte. Jetzt kann "/var/run/fhem/fhem.pid" geschrieben werden, aber eventuell nicht schnell genug. Wäre das möglich? Allerdings würde das nicht die Crashs erklären.
FHEM alleine duerfte eine Restart-Schleife nicht produzieren. Das Starten eines zweiten FHEMs sollte schiefgehen: wenn FHEMWEB/telnet mit !$init_done ein belegtes Port entdecken, dann terminieren sie FHEM.
ZitatWann wird denn beim Starten genau das PID-File angelegt?
Nach abarbeiten der Configfile+Statefile, kurz vor dem triggern von global:INITIALIZED
Ich wuerde bei solchen Problemen FHEM "per Hand" (mit attr global logfile -) in einem Terminal-Fenster starten.
Ich habe FHEM auch zu Fuß mit "perl fhem.pl configDB" als User fhem gestartet. Zumindest die Restarts gab's dann nicht.
Aber den plötzlichen Stillstand behebt das auch nicht. Ich kann es leider an nichts festmachen. Zur Zeit läuft FHEM wieder seit über einer Stunde.
Ich werde mal beobachten, wielange es diesmal läuft. "verbose 5" macht das Logfile nicht gerade übersichtlich. ;)
Seit gestern morgen läuft FHEM wieder durch.
Scheinbar lag es an "98_CHROMECAST.pm". Zumindest hab ich das zugehörige Device gestern mal gelöscht, da ich einige Male die Meldung No handlers could be found for logger "pychromecast.socket_client" im Log gesehen habe. Merkwürdig ist, daß ich an der Konfiguration nichts geändert habe und auch das Modul bei mir seit dem 02.01. unverändert ist.