Dockerstart erfolgreich ... und nach zwei Minuten Shutdown

[cbl]

Hallo,

ich möchte FHEM in den Docker migrieren. Für den Anfang habe ich erstmal mit einer nackten Instanz begonnen, die minimalistisch ist. Der Start ist auch erfolgreich und der Container läuft. ... für ziemlich genau zwei Minuten. Dann gibt es

Code Auswählen Erweitern

2024-12-19T13:45:12.931313231Z 2024.12.19 14:45:12 0: Server started with 6 defined entities (fhem.pl:29402/2024-12-05 perl:5.036003 os:linux user:fhem pid:2252)
2024-12-19T13:45:14.608778023Z INFO: FHEM successfully started
2024-12-19T13:45:12.931305536Z 2024.12.19 14:45:12 0: Featurelevel: 6.3
2024-12-19T13:47:24.812482353Z INFO: Sending SIGTERM (equivalent to "shutdown" command) to FHEM (pid 2252).
2024-12-19T13:47:24.819895726Z INFO: Waiting up to 30s for FHEM process (pid 2252) to terminate.
2024-12-19T13:47:24.836205501Z 2024.12.19 14:47:24 0: Server shutdown
2024-12-19T13:47:25.831594940Z INFO: Stopping container. Bye!.

Dazu gab es hier auch schon mal einen Thread, der allerdings keine Ursache oder Lösung für dieses Thema nennt. Ich starte den Container (wie viele andere) über eine docker-compose:

Code Auswählen Erweitern

version: '3.6'

services:
  fhem:
    #image: ghcr.io/fhem/fhem-docker:latest
    image: ghcr.io/fhem/fhem-docker:4-bullseye
    restart: unless-stopped
    ports:
      - "8083:8083"
    volumes:
      - type: volume
        source: fhem
        target: /opt/fhem
        volume:
            nocopy: true 
    environment:
      FHEM_UID: 999
      FHEM_GID: 20
      TIMEOUT: 60
      TZ: Europe/Berlin

volumes:
  fhem:
     driver: local
     driver_opts:
      type: nfs
      o: "addr=nfs.fritz.box,nolock,soft,rw"
      device: ":/media/software/docker/fhem"   

Auf dem NFS-Share werden auch beim initialen Start alle Dateien abgelegt und bei jedem Neustart die fhem.cfg erneuert.

Was läuft hier, dass nach reproduzierbar zwei Minuten der Container (von außen?) beendet wird?
Alle meine anderen Container (Monitoring, Dokumentenverwaltung, FTUI-Oberfläche, ...) laufen stabil.

Viele Grüße
Christian

[passibe]

Vorab: Nutze kein NFS. Deshalb keine Ahnung, ob das nicht ein NFS-spezifisches Problem ist.

Aber: Mach dein compose-file erstmal noch minimalistischer. Also die zusätlichen env-Variablen wie UID/GID (wieso sind die gesetzt? Braucht das NFS-Share das?) und TIMEOUT (wieso ist das gesetzt?) rauslassen, NFS auch weg.
Dann schrittweise wieder hinzufügen.

Zum Log:
Die Zeile

2024-12-19T13:47:24.812482353Z INFO: Sending SIGTERM (equivalent to "shutdown" command) to FHEM (pid 2252).

kommt aus Zeile 927 der entry.sh, ist Teil der funktion stopFhemProcess(), die im Skript aber nur von der Funktion trapExitHandler() aufgerufen wird. trapExitHandler() wiederum wird laut Kommentar (Zeile 979 f.) nur aufgerufen, wenn irgendwo im Skript "exit" aufgerufen wird oder von außen ein SIGTERM kommt, der das Skript beenden soll.
Bei allen Aufrufen von "exit" innerhalb der entry .sh sehe ich immer eine zusätzliche Lognachricht, davon ist in deinem Log ja erstmal nichts zu sehen. Muss also ein externer SIGTERM sein, vielleicht aus der health-check.sh? Wobei ich da jetzt direkt auch nicht etwas sehe. Bestimmt übersehe ich irgendwo was.
Naja, das jedenfalls mal meine sehr unvollständigen Gedanken dazu, vielleicht hilft es ja weiter.

[Wernieman]

Was mir bei etwas immer einfällt ...
- ist der Port frei?
- auf was für ein System betreibst Du die Container?

[cbl]

Vorab: Nutze kein NFS. Deshalb keine Ahnung, ob das nicht ein NFS-spezifisches Problem ist.

Ich verwende das in meinem Docker Swarm, damit ich von verschiedenen Nodes auf die persistierten Daten zugreifen kann. Docker Swarm ist leider in diesem Punkt so komfortabel, dass auch Volumes im Swarm geteilt werden.
Aber das ist nicht die Ursache, da ich dasselbe Verhalten auch ohne NFS habe.

Aber: Mach dein compose-file erstmal noch minimalistischer. Also die zusätlichen env-Variablen wie UID/GID (wieso sind die gesetzt? Braucht das NFS-Share das?) und TIMEOUT (wieso ist das gesetzt?) rauslassen, NFS auch weg.
Dann schrittweise wieder hinzufügen.

Übriggeblieben ist jetzt nur noch:

Code Auswählen Erweitern

version: '3.6'

services:

  fhem:
    #image: ghcr.io/fhem/fhem-docker:latest
    image: ghcr.io/fhem/fhem-docker:4-bullseye
    restart: unless-stopped
    ports:
      - "8083:8083"
    volumes:
      - type: volume
        source: fhem
        target: /opt/fhem
        volume:
            nocopy: true 
    environment:
      TZ: Europe/Berlin

volumes:
  fhem:
     driver: local
     driver_opts:
      type: none
      device: "/opt/docker/fhem"
      o: bind     

Das Hostsystem ist ein 64-Bit Debian Bookworm. Das gleiche Verhalten habe ich aber auch auf einem 32-Debian Bullseye als Host.
Der Port ist nutzbar und FHEM startet auch sauber.

Zum Log:
Die Zeile

2024-12-19T13:47:24.812482353Z INFO: Sending SIGTERM (equivalent to "shutdown" command) to FHEM (pid 2252).

kommt aus Zeile 927 der entry.sh, ist Teil der funktion stopFhemProcess(), die im Skript aber nur von der Funktion trapExitHandler() aufgerufen wird. trapExitHandler() wiederum wird laut Kommentar (Zeile 979 f.) nur aufgerufen, wenn irgendwo im Skript "exit" aufgerufen wird oder von außen ein SIGTERM kommt, der das Skript beenden soll.
Bei allen Aufrufen von "exit" innerhalb der entry .sh sehe ich immer eine zusätzliche Lognachricht, davon ist in deinem Log ja erstmal nichts zu sehen. Muss also ein externer SIGTERM sein, vielleicht aus der health-check.sh? Wobei ich da jetzt direkt auch nicht etwas sehe. Bestimmt übersehe ich irgendwo was.

Auf die Idee hätte ich auch selbst kommen können. Wer könnte einen externen SIGTERM schicken? Einen Watchdog/HealthCheck habe ich im Stack (siehe Compose) nicht explizit, der sowas schicken könnte. Das Verhalten habe ich bei keinem anderen Container.

Viele Grüße
Christian

[passibe]

Hmm, ok. Habe das abgespeckte compose-file mal bei mir gestartet, das läuft problemlos, auch nach einigen Minuten noch.
Ich benutze aber keinen swarm mode, also würde ich mal stark vermuten, dass das irgendetwas damit zu tun hat. Was genau, hab ich jetzt aber keine Idee, dafür kenne ich mich zu wenig mit dem swarm mode aus, sorry.

Vielleicht machst du mal ein Issue auf GitHub auf, dann sieht sidey das und vielleicht hat der eine Idee/kann da weiter testen.

Ansonsten:
Das einzige, was mir spontan auffällt, ist, dass es bei mir sagt:

Code Auswählen Erweitern

Server started with 7 defined entitieswährend es bei dir nur 6 entities sind.
Ich habe:

Code Auswählen Erweitern

DockerImageInfo
Logfile
WEB
WEB_<IP>_<PORT>
autocreate
eventTypes
global
initialUsbCheckKannst du mal, in der Zeit in der der Container läuft, ein

Code Auswählen Erweitern

list (.*) ausführen?

Und vielleicht mal noch just for fun das gesamte Log beim Containerstart posten? Also ab

Code Auswählen Erweitern

INFO: Preparing initial container setup

[cbl]

Hallo,

nach Weihnachten komme ich nun weiter. Ich war vor den Feiertagen offenbar zu ungeduldig. Nach weiteren Startversuchen hat dann die docker-compose auch bei mir funktioniert.
Damit habe ich ein prinzipiell im Container laufendes (aber gerade noch leeres) FHEM.

Da ich seit Jahren configDB einsetze, möchte ich das auch im zukünftigen Container nutzen. Mit dem leeren Demosystem kann ich auch problemlos auf configDB umstellen/ migrieren. Verwende ich jedoch einen Dump meiner produktiven configDB-Tabellen hängt FHEM abermals nach dem bereits verlängerten

Code Auswählen Erweitern

TIMEOUT_STARTING: 240. Dabei vermisse ich leider irgendeinen Hinweis, was in meiner umfangreichen configDB hier das Problem ist. Bei den ersten beiden Starts gab es Probleme mit zwei Perl-Modulen, die ich für meine Roomba-Staubsauger manuell ergänzen musste, da sie in einer 99_RoombaUtils.pm verwendet wurden. Das wurde im Log auch entsprechend kund getan und führte zum sauber kommentierten Shutdown von FHEM.

Das vollständige Log sieht so aus:

Code Auswählen Erweitern

2025-01-02T21:16:59.344465809Z INFO: Preparing initial container setup
2025-01-02T21:16:59.360417392Z INFO: Updating existing FHEM installation in /opt/fhem
2025-01-02T21:16:59.395877870Z INFO:   Patching fhem.cfg Logfile configuration
2025-01-02T21:16:59.420663492Z  HINT: Make sure to have your FHEM configuration properly prepared for compatibility with this Docker Image _before_ using configDB !
2025-01-02T21:16:59.433992024Z INFO: Initial container setup done
2025-01-02T21:16:59.475752970Z INFO: Preparing user environment
2025-01-02T21:16:59.559533193Z INFO: Creating group 'fhem' with GID 6061
2025-01-02T21:16:59.645079233Z INFO: Enforcing GID for group 'bluetooth' to 6001
2025-01-02T21:16:59.674450389Z INFO: Creating user 'fhem' with UID 6061
2025-01-02T21:17:01.387736758Z INFO: Creating log directory /opt/fhem/log
2025-01-02T21:17:01.410585000Z INFO: Creating PID directory /opt/fhem/log
2025-01-02T21:17:01.431300188Z INFO: Enforcing user and group ownership for /opt/fhem to fhem:fhem
2025-01-02T21:17:01.544302453Z INFO: Enforcing file and directory permissions for /opt/fhem
2025-01-02T21:17:18.305062932Z INFO: Correcting group ownership for /dev/tty*
2025-01-02T21:17:18.394306701Z INFO: Found GPIO: Correcting group permissions in /dev and /sys to 'gpio' with GID 6002
2025-01-02T21:17:18.902309760Z INFO: Found I2C: Correcting group permissions in /dev to 'i2c' with GID 6003
2025-01-02T21:17:19.168240562Z INFO: Updating /etc/sudoers.d/fhem-docker
2025-01-02T21:17:19.208137201Z INFO: Patching /etc/hosts file with DOCKER_HOST and DOCKER_GW'
2025-01-02T21:17:19.353512262Z INFO: Adding 172.18.0.1 host.docker.internal to /etc/hosts
2025-01-02T21:17:19.368221043Z 172.18.0.1 host.docker.internal
2025-01-02T21:17:19.375281972Z INFO: Adding 172.18.0.1 gateway.docker.internal to /etc/hosts
2025-01-02T21:17:19.389125135Z 172.18.0.1 gateway.docker.internal
2025-01-02T21:17:19.397638812Z INFO: Pre-authorizing SSH to Docker host for user 'fhem'
2025-01-02T21:17:19.743104978Z INFO: Updating SSH key pinning and SSH client permissions for user 'fhem'
2025-01-02T21:17:19.796668322Z INFO: Preparing user environment done
2025-01-02T21:17:19.853665805Z INFO: Starting FHEM
2025-01-02T21:17:20.833289941Z 2025.01.02 22:17:20 3: logfile is readonly, it is set in the FHEM_GLOBALATTR environment
2025-01-02T21:18:09.686426664Z 2025.01.02 22:18:09 3: pidfilename is readonly, it is set in the FHEM_GLOBALATTR environment
In der Docker-Compose habe ich gegenüber oben nur die configDB eingefügt sowie in die Datenbank meinen Dump der bestehenden Installation importiert.

Beim erfolgreichen Start (mit frisch migrierter Demo-Datenbank) geht es nach "Starting FHEM" so weiter:

Code Auswählen Erweitern

2025.01.02 14:41:51.667 3: From the FHEM_GLOBALATTR environment: attr global logfile log/fhem-%Y-%m-%d.log
2025.01.02 14:41:51.666 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
2025.01.02 14:41:52.850 0: Server started with 7 defined entities (fhem.pl:29402/2024-12-05 perl:5.036003 os:linux user:fhem pid:4487)
2025.01.02 14:41:52.241 3: WEB: port 8083 opened
2025.01.02 14:41:52.361 2: eventTypes: loaded 1 lines from ./log/eventTypes.txt
2025.01.02 14:41:52.579 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1
2025.01.02 14:41:52.580 3: From the FHEM_GLOBALATTR environment: attr global pidfilename log/fhem.pid
2025.01.02 14:41:52.581 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
2025.01.02 14:41:52.582 3: From the FHEM_GLOBALATTR environment: attr global logfile log/fhem-%Y-%m-%d.log
2025.01.02 14:41:52.585 1: Messages collected while initializing FHEM:SecurityCheck:
  WEB is not password protected
Protect this FHEM installation by defining an allowed device with define allowed allowed
You can disable this message with attr global motd none
2025.01.02 14:41:52.776 1: usb create starting
2025.01.02 14:41:52.847 1: usb create end
2025.01.02 14:41:52.849 0: Featurelevel: 6.3
INFO: FHEM successfully started
In der produktiven Umgebung verwende ich DBLog. Da bei Verwendung von configDB die DBLog-Konfiguration aus der Datenbank geholt wird, habe ich getestet, dass ich aus dem Container auch die (noch alte) Datenbank mit der DBLog erreiche (mit denselben Zugangsdaten, die nicht auf den Hostname limitiert sind, damit es nicht daran scheitert).

Hat jemand noch einen Hinweis, woran ich hier scheitere? Ich habe in der Dokumentation zum FHEM-Docker-Image keinen Hinweis gefunden, wie ich eventuell das Loglevel noch weiter erhöhen kann, damit der Container noch gesprächiger wird.

Viele Grüße
Christian

[Sidey]

Im Log steht folgender Hinweis:

HINT: Make sure to have your FHEM configuration properly prepared for compatibility with this Docker Image _before_ using configDB

Hast Du deine config_DB denn vorher angepasst?
Bei Verwendung von fhem.cfg kann das der container übernehmen, aber bei Verwendung von configDB kann er das nicht.

Grüße Sidey