[Problem] ioBroker stürzt ab - Zugriff auf admin

[George_Best]

Hallo zusammen,

ioBroker läuft bei mir auf einem Raspberry 3.

Immer wieder stürzt mein ioBroker ab. D.h. ich habe keinen Zugriff mehr auf ioBroker und den Raspi selbst. Es ist dann kein Zugriff auf Weboberfläche, kein Zugriff via Putty möglich. Abhilfe schafft nur Versorgungspannung AUS-EIN. Dann startet ioBroker und ich habe ohne Probleme Zugriff.

Mir ist aufgefallen, dass die meisten Abstürze dann auftreten, wenn ich via Weboberfläche auf die Admin-Oberfläche zugreife. Die Oberfläche erscheint noch (kurz), dann sieht man aber die drehenden Kreise und der Raspbi ist (scheinbar) abgestürzt.

Das ioBroker-Log-File sieht so aus. Man sieht hier den Zeitpunkt kurz vor dem Absturz und den Boot:

018-09-02 16:21:01.208 - error: cloud.0 Ping timeout
2018-09-02 15:17:18.742 - info: host.ioBroker-RasPi iobroker.js-controller version 1.4.2 js-controller starting
2018-09-02 15:17:18.758 - info: host.ioBroker-RasPi Copyright (c) 2014-2018 bluefox, 2014 hobbyquaker
2018-09-02 15:17:18.759 - info: host.ioBroker-RasPi hostname: ioBroker-RasPi, node: v8.11.3
2018-09-02 15:17:18.768 - info: host.ioBroker-RasPi ip addresses: 192.168.178.120
2018-09-02 15:17:20.175 - info: host.ioBroker-RasPi inMem-objects listening on port 9001
2018-09-02 15:17:20.225 - info: host.ioBroker-RasPi InMemoryDB connected
2018-09-02 15:17:20.301 - info: host.ioBroker-RasPi 58 instances found
2018-09-02 15:17:20.522 - info: host.ioBroker-RasPi starting 41 instances
2018-09-02 16:23:17.686 - info: host.ioBroker-RasPi instance system.adapter.admin.0 started with pid 835
2018-09-02 16:23:17.946 - info: host.ioBroker-RasPi States connected to redis: 127.0.0.1:6379
2018-09-02 16:23:21.567 - info: host.ioBroker-RasPi instance system.adapter.web.0 started with pid 842
2018-09-02 16:23:24.152 - info: admin.0 States connected to redis: 127.0.0.1:6379
2018-09-02 16:23:24.509 - error: admin.0 setObject id missing!!
2018-09-02 16:23:24.530 - info: admin.0 starting. Version 3.5.6 in /opt/iobroker/node_modules/iobroker.admin, node: v8.11.3
2018-09-02 16:23:24.584 - info: admin.0 requesting all states
2018-09-02 16:23:24.590 - info: admin.0 requesting all objects
2018-09-02 16:23:24.594 - info: admin.0 Request actual repository...
2018-09-02 16:23:26.668 - info: web.0 States connected to redis: 127.0.0.1:6379
2018-09-02 16:23:27.267 - info: admin.0 received all states
2018-09-02 16:23:27.332 - error: web.0 setObject id missing!!
2018-09-02 16:23:27.353 - info: web.0 starting. Version 2.4.1 in /opt/iobroker/node_modules/iobroker.web, node: v8.11.3
2018-09-02 16:23:28.804 - info: web.0 socket.io server listening on port 8082
2018-09-02 16:23:28.813 - info: web.0 http server listening on port 8082
2018-09-02 16:23:29.208 - info: vis.0 States connected to redis: 127.0.0.1:6379
2018-09-02 16:23:29.473 - info: vis.0 starting. Version 1.1.7 in /opt/iobroker/node_modules/iobroker.vis, node: v8.11.3
2018-09-02 16:23:29.550 - info: host.ioBroker-RasPi instance system.adapter.history.0 started with pid 896
2018-09-02 16:23:29.829 - info: vis.0 vis license is OK.
2018-09-02 16:23:31.970 - info: admin.0 received all objects
2018-09-02 16:23:32.077 - info: history.0 States connected to redis: 127.0.0.1:6379
2018-09-02 16:23:32.312 - info: history.0 starting. Version 1.8.5 in /opt/iobroker/node_

Die Zeitverschiebung ist vermutlich darauf zurückzuführen, dass der Raspbi sich während des Boots die aktuelle Zeit holt.

Man sieht das der Cloud-Service vor dem Absturz nicht erreichbar war````
018-09-02 16:21:01.208 - error: cloud.0 Ping timeout

Der syslog des Raspbis sieht so aus:

Sep 2 15:17:02 ioBroker-RasPi CRON[29768]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Sep 2 16:13:54 ioBroker-RasPi kernel: [415455.785145] INFO: task kworker/1:2:8978 blocked for more than 120 seconds.
Sep 2 16:14:09 ioBroker-RasPi kernel: [415455.785157] Not tainted 4.9.35-v7+ #1014
Sep 2 16:14:17 ioBroker-RasPi kernel: [415455.785161] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 2 16:14:27 ioBroker-RasPi kernel: [415455.785167] kworker/1:2 D 0 8978 2 0x00000000
Sep 2 16:14:35 ioBroker-RasPi kernel: [415455.785194] Workqueue: events_freezable mmc_rescan
Sep 2 16:14:46 ioBroker-RasPi kernel: [415455.785228] [<807146b0>] (__schedule) from [<80714bd4>] (schedule+0x50/0xa8)
Sep 2 16:14:58 ioBroker-RasPi kernel: [415455.785244] [<80714bd4>] (schedule) from [<805b6c5c>] (__mmc_claim_host+0xb8/0x1cc)
Sep 2 16:15:09 ioBroker-RasPi kernel: [415455.785259] [<805b6c5c>] (__mmc_claim_host) from [<805b6da0>] (mmc_get_card+0x30/0x34)
Sep 2 16:15:17 ioBroker-RasPi kernel: [415455.785274] [<805b6da0>] (mmc_get_card) from [<805bf830>] (mmc_sd_detect+0x2c/0x80)
Sep 2 16:15:25 ioBroker-RasPi kernel: [415455.785290] [<805bf830>] (mmc_sd_detect) from [<805b9a64>] (mmc_rescan+0x1c8/0x38c)
Sep 2 16:15:31 ioBroker-RasPi kernel: [415455.785308] [<805b9a64>] (mmc_rescan) from [<80136660>] (process_one_work+0x158/0x454)
Sep 2 16:15:36 ioBroker-RasPi kernel: [415455.785327] [<80136660>] (process_one_work) from [<801369c0>] (worker_thread+0x64/0x568)
Sep 2 16:15:48 ioBroker-RasPi kernel: [415455.785342] [<801369c0>] (worker_thread) from [<8013c8c8>] (kthread+0x10c/0x124)
Sep 2 16:15:57 ioBroker-RasPi kernel: [415455.785360] [<8013c8c8>] (kthread) from [<80108148>] (ret_from_fork+0x14/0x2c)
Sep 2 16:16:09 ioBroker-RasPi kernel: [415578.665281] INFO: task kworker/1:2:8978 blocked for more than 120 seconds.
Sep 2 16:16:21 ioBroker-RasPi kernel: [415578.665293] Not tainted 4.9.35-v7+ #1014
Sep 2 16:16:28 ioBroker-RasPi kernel: [415578.665297] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 2 16:16:35 ioBroker-RasPi kernel: [415578.665302] kworker/1:2 D 0 8978 2 0x00000000
Sep 2 16:16:41 ioBroker-RasPi kernel: [415578.665331] Workqueue: events_freezable mmc_rescan
Sep 2 16:16:51 ioBroker-RasPi kernel: [415578.665364] [<807146b0>] (__schedule) from [<80714bd4>] (schedule+0x50/0xa8)
Sep 2 15:17:04 ioBroker-RasPi rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="360" x-info="http://www.rsyslog.com"] start
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Booting Linux on physical CPU 0x0
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Linux version 4.9.35-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #1014 SMP Fri Jun 30 14:47:43 BST 2017
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] CPU: div instructions available: patching division code
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] OF: fdt:Machine model: Raspberry Pi 3 Model B Rev 1.2
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] cma: Reserved 8 MiB at 0x3a800000
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Memory policy: Data cache writealloc
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] On node 0 totalpages: 241664
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] free_area_init_node: node 0, pgdat 80c6ee40, node_mem_map b9faa000
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Normal zone: 2124 pages used for memmap
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Normal zone: 0 pages reserved
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] Normal zone: 241664 pages, LIFO batch:31
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] percpu: Embedded 14 pages/cpu @b9f64000 s25600 r8192 d23552 u57344
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] pcpu-alloc: s25600 r8192 d23552 u57344 alloc=14*4096
Sep 2 15:17:04 ioBroker-RasPi kernel: [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3

Da sich der Raspi die Zeit erst während des Boots holt, sieht man auch hier einen Zeitsprung.

Der Raspi ist vermutlich bei __16:16:51__ abgestürzt.

Diese Zeile kommt mir verdächtig vor:````
INFO: task kworker/1:2:8978 blocked for more than 120 seconds.

top sieht jetzt nach dem Boot so aus:````
top - 17:14:20 up 51 min, 1 user, load average: 0,32, 0,16, 0,19
Tasks: 153 total, 1 running, 152 sleeping, 0 stopped, 0 zombie
%Cpu(s): 8,1 us, 2,0 sy, 0,0 ni, 89,9 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
KiB Mem: 945512 total, 869672 used, 75840 free, 37340 buffers
KiB Swap: 102396 total, 600 used, 101796 free. 119016 cached Mem

Hat jemand eine Idee?

[Stabilostick]

Könnte was mit der SD-Karte oder den Treibern/OS sein.

Macht der folgende Befehl eventuell auch nach einigen Minuten Probleme? Mehrmalige Ausführung?

sudo dd if=/dev/mmcblk0 bs=4M status=progress >/dev/null

[George_Best]

@Stabilostick:

sudo dd if=/dev/mmcblk0 bs=4M status=progress >/dev/null
```` `  

Was macht der Befehl denn genau? Ist das nicht ein Bitkopie des kompletten Systems? Aber wohin?!

status=progress
````geht glaub ich nur auf Ubuntu. Das ioBroker ist doch Jessie, oder?

[Stabilostick]

Wieso soll es nicht funktionieren? Der Befehl liest die SD und schreibt den gelesenen Inhalt dann ins Nirwana. Mehr nicht.

[Stabilostick]

Und dann kucken wir mal, ob das OS nach ein paar Anläufen dabei abstürzt.

[George_Best]

Ich habe das````
status=progress

ioBroker läuft noch, im Terminal seh ich halt jetzt keinen Fortschritt o.ä.

[George_Best]

Hab den Befehl nun zweimal hintereinander ausgeführt. ioBroker läuft noch völlig normal… :roll:

[Stabilostick]

Hmm, wenn man wüsste, was der Prozess 8978 aus Deinem Fehlerlog oben war… Siehst Du da mehr im Log?

[Stabilostick]

Ist das ein fertiges ioBroker-Image gewesen?

[George_Best]

@Stabilostick:

Ist das ein fertiges ioBroker-Image gewesen? `
Erstmal vielen, herzlichen Dank für Deine Hilfe.

Ja - ich das Rasbian-Image verwendet.

@Stabilostick:

Hmm, wenn man wüsste, was der Prozess 8978 aus Deinem Fehlerlog oben war… Siehst Du da mehr im Log? `
Leider nein. Im Log steht sonst nichts zu diesem "8978". Bis auf die von mir beschriebenen Einträge is das Log recht unspektakulär. Zumindest bis zum (Wieder-)Start des Rapsis. Dann sind die (scheinbar) normalen Hochlaufprozeduren beschrieben.