Server Cannot start inMem-objects on port 9001

[David G.]

@apollon77 sagte in Server Cannot start inMem-objects on port 9001:

@david-g Am Ende ist mehr Interessant was DAVOR passiert ist. Also wie hört das Log auf wo es stehen geblieben ist? Was steht ggf in /var/log/syslog? Wie gross sind die Dateien /opt/iobroker/iobroker-data/*.jsonl ?

Ingo

So, hab jetzt mal alles rausgesucht.
Anbei die beiden Logs ab Mitternacht bis zum Absturz um 0:20 und dem ersten Logeintrag nach dem reboot um 6:02.

iobroker.2022-09-01.log (hoffe habe alles an persönlichen Daten gefunden und ersetzt ^^)

syslog.txt
Hier fällt mir auf:

Sep  1 00:20:56 pi systemd[1]: iobroker.service: Main process exited, code=exited, status=24/n/a
Sep  1 00:20:56 pi systemd[1]: iobroker.service: Failed with result 'exit-code'.

Größe der jsonl:
objects.jsonl 26,6MB
states.jsonl 41,2MB

Laut History waren ausreichend Systemressourcen vorhanden.
Ram und CPU waren kaum ausgelastet.

[apollon77]

@david-g Also ein Log wie dieses was nach einem Log mit 00:44 dann plötzloc mit fakehwclock und einer alten Uhrzeit startet bedeutet nprmalerweise das das system neu gestartet wurde. Also Power war weg oder irgendein so harter kernel crash das es ohne log zum reboot geführt hat.

Sieht man auch an den folgenden Log Ausgaben.

Und danach gab es dann den Fehler. Ok also jetzt schauen warum.
Wenn Du "iob stop" und "iob start" mchst tut es dann wieder? oder kommt immer noch der Fehler?
Falls ja, dann bitte "iob stop "und schauen das er wirlich aus ist und aus bleibt. Dann was sagt "iob status"?

[David G.]

@apollon77

Seit dem crash läuft das System stabil.
Musste es leider vom Strom trennen, da kein Zugriff mehr möglich war (habe leider keinen Bildschirm zu Verfügung am Pi), kein Ping kein ssh.

Ein reboot klappt ohne Probleme. Samt Start vom iobroker.

Dann war es ja vermutlich keine "Fehlfunktion" vom iobroker.
Wenn sowas nochmal passiert, Vergleiche ich mal die logs (hatte ich eigentlich erst einmal, vor 3 Wochen oder so).

[apollon77]

@david-g Ok, ich hab eine Vermutung die ich gerade prüfe ... die vllt auch genrell hier und da in soclhen Situationen probleme erklären kann. Hintergrund ist die Uhrzeit ... Wenn das lock File von 00:44:00 ist weil es da gecrasht ist und danach ist de Zeit aber 00:20:00 ... dann erkennt vermutlich die Library das Lockfile als "gültig" und nicht als Stale ... erst quasi 24 Minuten später wäre das valide

[David G.]

@apollon77
Hab zwar keine Ahnung von, klingt aber plausibel ^^.

Hatte mich auch gewundert, warum die telegram mit "restarting" so lange nach dem crash gekommen ist.
Im Log war mir das mit dem Zeitversatz nicht aufgefallen.

[apollon77]

@Thomas-Braun Wenn nochmal ein "jsonl lock file "fehler kommt mal die aktuelle uhrzeit mit dem timstamp des lock dirs vergleichen lassen ... Ich denke das das die Ursache ist

[Thomas Braun]

@apollon77
Sollte aber nur ein Problem bei Systemen ohne RTC sein.

[apollon77]

@thomas-braun Exakt.Ist aber ein weiterer Punkt zum "Abfragen beim User" bei solchen Issues den wir bisher nicht auf dem Radar hatten

[Thomas Braun]

@apollon77

Zeitreisen sind auch immer doof. Frag mal Marty McFly.

[apollon77]

@thomas-braun

[Thomas Braun]

@david-g

Interessant wäre auch ein syslog von der Zeit. Vielleicht sieht man da was zum Flipper führt.

[David G.]

@thomas-braun

Ist das eine andere Datei?

Das gepostete syslog ist ja von 0 Uhr bis zum reboot morgens.

[Thomas Braun]

@david-g

Sorry, hatte ich übersehen. Nur das iobroker.log gefunden.
Im sys.log steht nix wirklich erhellendes drin.
Vielleicht in einer der /var/log/kern.log ?

[apollon77]

@thomas-braun sieht mir nach nem Power-outage aus, ggf Netzteil prüfen

[Thomas Braun]

@apollon77

Aber da läuft eine USV...
Gut, wenn das Netzteil einen weg hat...

[David G.]

@thomas-braun sagte in Server Cannot start inMem-objects on port 9001:

@david-g

Sorry, hatte ich übersehen. Nur das iobroker.log gefunden.
Im sys.log steht nix wirklich erhellendes drin.
Vielleicht in einer der /var/log/kern.log ?

Kann es leider grad nicht kürzen.
kern.log

@apollon77 sagte in Server Cannot start inMem-objects on port 9001:

@thomas-braun sieht mir nach nem Power-outage aus, ggf Netzteil prüfen

Bestelle mal ein neues. Ist aber ein original Netzteil vom Raspberry.

[apollon77]

@thomas-braun ALso bei Kernel Panix oder sowas hab ich meistens mnoch komische Null Zeichen im Log gesehen ... aber hier ist da gar nix ... aber ja es ist definitiv ein Reboot.

[apollon77]

@david-g sieht man auch nix ... geht direkt quasi mit dem Reboot los

EDIT:
Und das hier sagt das auf jeden Fall was vorher nicht sauber war:

Sep  1 00:20:51 pi kernel: [    2.257844] EXT4-fs (sda2): INFO: recovery required on readonly filesystem
Sep  1 00:20:51 pi kernel: [    2.257887] EXT4-fs (sda2): write access will be enabled during recovery
Sep  1 00:20:51 pi kernel: [    2.489092] EXT4-fs (sda2): orphan cleanup on readonly fs
Sep  1 00:20:51 pi kernel: [    2.504177] EXT4-fs (sda2): 7 orphan inodes deleted
Sep  1 00:20:51 pi kernel: [    2.504220] EXT4-fs (sda2): recovery complete
Sep  1 00:20:51 pi kernel: [    2.511628] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.

Aber ja ... fals vorher das Filesystem auf Read only gegangen ist dann ist es ja klar das im log nix steht Also vllt auch ein Filesystem issue

[Thomas Braun]

@apollon77

Da fehlt auch ein ganzer Tag:

Aug 30 17:03:57 pi kernel: [   31.832347] cam-dummy-reg: disabling
Sep  1 00:20:51 pi kernel: [    0.000000] Booting Linux on physical CPU 0x0

[Edit:] Kann aber sein, das kern.log ist nicht sooooo geschwätzig. Das hält auch schon mal lange den Rand

[Rene 3]

@thomas-braun 2802 info run @abandonware/bluetooth-hci-socket@0.5.3-8 install node_modules/@abandonware/bluetooth-hci-socket node-pre-gyp install --fallback-to-build
2803 info run @abandonware/noble@1.9.2-15 install node_modules/@abandonware/noble node-gyp rebuild
2804 info run @serialport/bindings-cpp@10.7.0 install node_modules/@serialport/bindings-cpp node-gyp-build
2805 info run diskusage@1.1.3 install node_modules/diskusage node-gyp rebuild
2806 info run @serialport/bindings-cpp@10.7.0 install { code: 0, signal: null }
2807 timing build:run:install:node_modules/@serialport/bindings-cpp Completed in 777ms
2808 info run iobroker.js-controller@4.0.23 install node_modules/iobroker.js-controller node iobroker.js setup first
2809 info run @abandonware/noble@1.9.2-15 install { code: 0, signal: null }
2810 timing build:run:install:node_modules/@abandonware/noble Completed in 5409ms
2811 info run iobroker.vis@1.4.15 install node_modules/iobroker.vis node main.js --install
2812 info run diskusage@1.1.3 install { code: 0, signal: null }
2813 timing build:run:install:node_modules/diskusage Completed in 9604ms
2814 info run unix-dgram@2.0.4 install node_modules/unix-dgram node-gyp rebuild
2815 info run @abandonware/bluetooth-hci-socket@0.5.3-8 install { code: 0, signal: null }
2816 timing build:run:install:node_modules/@abandonware/bluetooth-hci-socket Completed in 11107ms
2817 info run ursa-optional@0.9.10 install node_modules/ursa-optional node rebuild.js
2818 info run unix-dgram@2.0.4 install { code: 0, signal: null }
2819 timing build:run:install:node_modules/unix-dgram Completed in 7218ms
2820 info run usb@1.9.2 install node_modules/usb node-gyp-build
2821 info run iobroker.vis@1.4.15 install { code: 0, signal: null }
2822 timing build:run:install:node_modules/iobroker.vis Completed in 12268ms
2823 info run ursa-optional@0.9.10 install { code: 0, signal: null }
2824 timing build:run:install:node_modules/ursa-optional Completed in 7634ms
2825 info run iobroker.js-controller@4.0.23 install { code: 22, signal: null }
2826 info run usb@1.9.2 install { code: 1, signal: null }
2827 verbose reify failed optional dependency /opt/iobroker/node_modules/usb
2828 silly reify mark deleted [ '/opt/iobroker/node_modules/usb' ]
2829 verbose reify failed optional dependency /opt/iobroker/node_modules/usb/node_modules/node-addon-api
2830 silly reify mark deleted [ '/opt/iobroker/node_modules/usb/node_modules/node-addon-api' ]
2831 timing build:run:install:node_modules/usb Completed in 17022ms
2832 timing reify:rollback:createSparse Completed in 4803ms
2833 timing reify:rollback:retireShallow Completed in 0ms
2834 timing command:i Completed in 111659ms
2835 verbose stack Error: command failed
2835 verbose stack at ChildProcess.<anonymous> (/usr/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/lib/index.js:63:27)
2835 verbose stack at ChildProcess.emit (events.js:400:28)
2835 verbose stack at maybeClose (internal/child_process.js:1088:16)
2835 verbose stack at Socket.<anonymous> (internal/child_process.js:446:11)
2835 verbose stack at Socket.emit (events.js:400:28)
2835 verbose stack at Pipe.<anonymous> (net.js:686:12)
2836 verbose pkgid iobroker.js-controller@4.0.23
2837 verbose cwd /opt/iobroker
2838 verbose Linux 5.15.61-v7l+
2839 verbose node v14.20.0
2840 verbose npm v8.18.0
2841 error code 22
2842 error path /opt/iobroker/node_modules/iobroker.js-controller
2843 error command failed
2844 error command sh -c -- node iobroker.js setup first
2845 error No connection to databases possible ...
2846 verbose exit 22
2847 timing npm Completed in 111982ms
2848 verbose unfinished npm timer reify 1661968356534
2849 verbose unfinished npm timer reify:build 1661968431876
2850 verbose unfinished npm timer build 1661968431885
2851 verbose unfinished npm timer build:deps 1661968431886
2852 verbose unfinished npm timer build:run:install 1661968433965
2853 verbose unfinished npm timer build:run:install:node_modules/iobroker.js-controller 1661968434911
2854 verbose code 22
2855 error A complete log of this run can be found in:
2855 error /home/iobroker/.npm/_logs/2022-08-31T17_52_36_224Z-debug-0.log
vielleicht hilft das ( der Pfad ) ?