[docker] Start bricht ab

[gregor]

Hallo zusammen!
FHEM lief jetzt ein halbes Jahr in einer Docker-Installation. Vor etwa einem Monat hat fhem leider den Dienst eingestellt. Ich habe keine Ahnung wo ich anfangen könnte zu suche. Google spuck auf anhieb nichts brauchbares aus, deshalb versuche ich mal hier mein Glück:

Hier das Log des Container-starts:

Preparing user environment ...,
1. Creating group 'fhem' with GID 6061 ...,
2. Enforcing GID for group 'bluetooth' to 6001 ...,
3. Creating user 'fhem' with UID 6061 ...,
4. Creating log directory /opt/fhem/./log ...,
5. Enforcing user and group ownership for /opt/fhem to fhem:fhem ...,
6. Enforcing file and directory permissions for /opt/fhem ...,
7. Correcting group ownership for /dev/tty* ...,
8. Found GPIO: Correcting group permissions in /dev and /sys to 'gpio' with GID 6002 ...,
9. Found I2C: Correcting group permissions in /dev to 'i2c' with GID 6003 ...,
10. Updating /etc/sudoers.d/fhem-docker ...,
11. Adding gateway.docker.internal to /etc/hosts ...,
12. Adding host.docker.internal to /etc/hosts ...,
13. Pre-authorizing SSH to Docker host for user 'fhem' ...,
14. Updating SSH key pinning and SSH client permissions for user 'fhem' ...,
,
,
,
Preparing configuration ... done,
,
Starting FHEM ...,
2021.07.24 23:39:28.200 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log,
2021.07.24 23:39:28.201 3: From the FHEM_GLOBALATTR environment: attr global nofork 0,
2021.07.24 23:39:28.201 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid,
2021.07.24 23:39:28.201 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1,
2021.07.24 23:39:28.204 1: Including fhem.cfg,
2021.07.24 23:39:28.396 3: WEB: port 8083 opened,
2021.07.24 23:39:28.440 2: eventTypes: loaded 793 events from ./log/eventTypes.txt,
2021.07.24 23:39:28.455 3: Opening CUL8 device /dev/ttyUSB1,
2021.07.24 23:39:28.479 3: Setting CUL8 serial parameters to 38400,8,N,1,
2021.07.24 23:39:31.623 3: CUL8: Possible commands: BCFiAZEkGMKUYRTVWXefltx,
2021.07.24 23:39:31.633 3: CUL8 device opened,
2021.07.24 23:39:31.634 3: Opening CUL4 device /dev/ttyUSB0,
2021.07.24 23:39:31.638 3: Setting CUL4 serial parameters to 38400,8,N,1,
2021.07.24 23:39:34.784 3: CUL4: Possible commands: BCFiAZEkGMKUYRTVWXefltx,
2021.07.24 23:39:34.794 3: CUL4 device opened,
2021.07.24 23:39:35.228 3: AptToDate (fhemServerApt) - defined,
2021.07.24 23:39:35.768 3: telnetPort: port 7072 opened,
2021.07.24 23:39:52.865 1: Including ./log/fhem.save,
2021.07.24 23:39:53.102 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log,
2021.07.24 23:39:53.103 3: From the FHEM_GLOBALATTR environment: attr global nofork 0,
2021.07.24 23:39:53.103 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid,
2021.07.24 23:39:53.103 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1,
2021.07.24 23:39:57.019 2: SubProcess: onRun returned error: Couldn't use APT: Too many open files,
,
Can't call method "run" on unblessed reference at ./FHEM/42_npmjs.pm line 795.,

wenn ich diese Datei umbenenne, gibts die tollsten anderen Fehlermeldungen, die ich schon wieder nicht lösen kann:

Starting FHEM ...,
2021.07.24 23:26:33.921 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log,
2021.07.24 23:26:33.922 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1,
2021.07.24 23:26:33.922 3: From the FHEM_GLOBALATTR environment: attr global nofork 0,
2021.07.24 23:26:33.922 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid,
2021.07.24 23:26:33.925 1: Including fhem.cfg,
2021.07.24 23:26:34.123 3: WEB: port 8083 opened,
2021.07.24 23:26:34.166 2: eventTypes: loaded 793 events from ./log/eventTypes.txt,
2021.07.24 23:26:34.180 3: Opening CUL8 device /dev/ttyUSB1,
2021.07.24 23:26:34.206 3: Setting CUL8 serial parameters to 38400,8,N,1,
2021.07.24 23:26:37.351 3: CUL8: Possible commands: BCFiAZEkGMKUYRTVWXefltx,
2021.07.24 23:26:37.361 3: CUL8 device opened,
2021.07.24 23:26:37.362 3: Opening CUL4 device /dev/ttyUSB0,
2021.07.24 23:26:37.365 3: Setting CUL4 serial parameters to 38400,8,N,1,
2021.07.24 23:26:40.511 3: CUL4: Possible commands: BCFiAZEkGMKUYRTVWXefltx,
2021.07.24 23:26:40.521 3: CUL4 device opened,
2021.07.24 23:26:41.017 3: AptToDate (fhemServerApt) - defined,
2021.07.24 23:26:41.629 3: telnetPort: port 7072 opened,
2021.07.24 23:26:58.224 1: Including ./log/fhem.save,
2021.07.24 23:26:58.584 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log,
2021.07.24 23:26:58.584 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1,
2021.07.24 23:26:58.585 3: From the FHEM_GLOBALATTR environment: attr global nofork 0,
2021.07.24 23:26:58.585 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid,
2021.07.24 23:27:03.321 1: Accept failed (telnetPort: Too many open files),
[...] +4520 weitere Zeilen...
2021.07.24 23:27:03.991 1: Accept failed (telnetPort: Too many open files),
Can't call method "run" on unblessed reference at ./FHEM/98_Installer.pm line 788.,

Hier meine Docker config:

version: '3.7'
##########################################################
#                                                        #
#                      F H E M                           #
#                                                        #
#  vorher von  http://www.jadahl.com/                    #
#  UsbSerialDrivers_apollolake-6.2_6-7.spk installieren  #
#                                                        #
##########################################################
networks:
  net4traefik:
    external: false
    name: net4traefik
services:
  fhem2:
    image: "fhem/fhem:latest"
    container_name: fhem2
    restart: always
    devices:
      - /dev/ttyUSB0:/dev/ttyUSB0
      - /dev/ttyUSB1:/dev/ttyUSB1
    volumes:
      - /volume1/docker/container-data/fhem/opt_fhem:/opt/fhem
    labels:
      - traefik.enable=true
      - traefik.docker.network=net4traefik
      - traefik.http.routers.fhem2_web443.entrypoints=web443
      - traefik.http.routers.fhem2_web443.rule=Host(`***`) && PathPrefix(`/fhem`)
      - traefik.http.routers.fhem2_web443.tls.certresolver=letsencrypt
      - traefik.http.routers.fhem2_web443.middlewares=mdlw_fhem2_auth
      - traefik.http.middlewares.mdlw_fhem2_auth.basicauth.realm="Zugang zu FHEM"
      - traefik.http.middlewares.mdlw_fhem2_auth.basicauth.users=***:***
      - traefik.http.services.srv_fhem2.loadbalancer.server.port=8083
    networks:
      - net4traefik

Ich bin für jeden Lösungsvorschlag dankbar!

Viele Grüße, Gregor

[Wernieman]

2021.07.24 23:39:57.019 2: SubProcess: onRun returned error: Couldn't use APT: Too many open files,

Erhöhe mal die Anzahl erlaubter "OpenFiles" .. wobei mich wundert, das Du solche Probleme hast .... also erstmal nur, um es zum laufen zu kriegen und eine Ursache ausschließen zu können.
https://www.tecmint.com/increase-set-open-file-limits-in-linux/
https://askubuntu.com/questions/1049058/how-to-increase-max-open-files-limit-on-ubuntu-18-04

Was Du uns leider nicht erzählt hast, welches Betriebsystem fährst Du auf dem Docker-Host?
Auf was für einer Hardware läuft es überhaupt?
Hast Du mehrere Docker-Container laufen? Unterschiedliche oder alle unter dem gleichen User?

[gregor]

Erhöhe mal die Anzahl erlaubter "OpenFiles" .. wobei mich wundert, das Du solche Probleme hast .... also erstmal nur, um es zum laufen zu kriegen und eine Ursache ausschließen zu können.

root@ds918:~# cat /proc/sys/fs/file-nr
14272   0   1205540
root@ds918:~# cat /proc/sys/fs/file-max
1205540

Sagt: 14k offene Files von möglichen 1,15M

Im ganzen FHEM Verzeichnis sind nicht so viele Dateien:
root@ds918:/volume1/docker/container-data/fhem/opt_fhem# ls -1R|wc -l
5673

Was Du uns leider nicht erzählt hast, welches Betriebsystem fährst Du auf dem Docker-Host?
Auf was für einer Hardware läuft es überhaupt?

Synology DS918+
12GB RAM
i686 Celeron J3455 4x1,5GHz
und der hat fast immer lange Weile...

root@ds918:~# uname -a
Linux ds918 4.4.59+ #25556 SMP PREEMPT Thu Mar 18 13:00:35 CST 2021 x86_64 GNU/Linux synology_apollolake_918+

Hast Du mehrere Docker-Container laufen? Unterschiedliche oder alle unter dem gleichen User?

Ja, etliche. Der FHEM-Container erzeugt sich beim Start ja seinen eigene UID und GID.

Schreibt FHEM ein eigenes Startup-Log? Wo?

[gregor]

Fehler eingegrenzt:

Code: [Auswählen]

2021.06.21 01:27:29.122 4: CUL_Parse: CUL4 r54AEE900143201A25A8D8069 -21.5
2021.06.21 01:27:29.123 5: CUL4: dispatch r54aee900143201a25a8d80
2021.06.21 01:27:32.641 5: CUL/RAW: /r54AEEA00143201A25A8D806A

2021.06.21 01:27:32.641 4: CUL_Parse: CUL4 r54AEEA00143201A25A8D806A -21
2021.06.21 01:27:32.642 5: CUL4: dispatch r54aeea00143201a25a8d80
2021.06.21 01:27:37.281 5: CUL/RAW: /r57C2EB00223202594B746253

2021.06.21 01:27:37.281 4: CUL_Parse: CUL4 r57C2EB00223202594B746253 -32.5
2021.06.21 01:27:37.282 5: CUL4: dispatch r57c2eb00223202594b7462
2021.06.21 01:27:38.740 5: CUL/RAW: /r54AEEA00143201A95A8D806A

2021.06.21 01:27:38.740 4: CUL_Parse: CUL4 r54AEEA00143201A95A8D806A -21
2021.06.21 01:27:38.740 5: CUL4: dispatch r54aeea00143201a95a8d80
2021.06.21 01:27:45.623 5: CUL/RAW: /r0D4CEA00003200016467D522

2021.06.21 01:27:45.623 4: CUL_Parse: CUL4 r0D4CEA00003200016467D522 -57
2021.06.21 01:27:45.623 5: CUL4: dispatch r0d4cea00003200016467d5
2021.06.21 01:27:46.231 2: AptToDate (fhemServerApt) - update in progress, process aborted.
Can't call method "run" on unblessed reference at ./FHEM/98_Installer.pm line 788.
2021.06.21 01:27:58.650 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log
2021.06.21 01:27:58.651 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1
2021.06.21 01:27:58.651 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid
2021.06.21 01:27:58.651 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
2021.06.21 01:27:58.654 1: Including fhem.cfg
2021.06.21 01:27:58.880 3: WEB: port 8083 opened
2021.06.21 01:27:58.957 2: eventTypes: loaded 793 events from ./log/eventTypes.txt
2021.06.21 01:27:58.981 3: Opening CUL8 device /dev/ttyUSB1
2021.06.21 01:27:59.034 3: Setting CUL8 serial parameters to 38400,8,N,1
2021.06.21 01:28:02.178 3: CUL8: Possible commands: BCFiAZEkGMKUYRTVWXefltx
2021.06.21 01:28:02.189 3: CUL8 device opened
2021.06.21 01:28:02.190 3: Opening CUL4 device /dev/ttyUSB0
2021.06.21 01:28:02.192 3: Setting CUL4 serial parameters to 38400,8,N,1
2021.06.21 01:28:05.340 3: CUL4: Possible commands: BCFiAZEkGMKUYRTVWXefltx
2021.06.21 01:28:05.350 3: CUL4 device opened
2021.06.21 01:28:05.939 3: AptToDate (fhemServerApt) - defined
2021.06.21 01:28:06.646 3: telnetPort: port 7072 opened
2021.06.21 01:28:23.205 1: Including ./log/fhem.save
2021.06.21 01:28:23.441 3: From the FHEM_GLOBALATTR environment: attr global logfile ./log/fhem-%Y-%m-%d.log
2021.06.21 01:28:23.441 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1
2021.06.21 01:28:23.441 3: From the FHEM_GLOBALATTR environment: attr global pidfilename ./log/fhem.pid
2021.06.21 01:28:23.441 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
2021.06.21 01:28:27.430 2: SubProcess: onRun returned error: Couldn't use APT: Too many open files

Can't call method "run" on unblessed reference at ./FHEM/42_npmjs.pm line 795.
(END)

Ich versuche mal eine Sicherung des Verzeichnisses vom Tag zuvor aufzutreiben...

Wäre es nicht besser, den Updateprozess erst dann zu comitten, wenn er erfolgreich beendet ist? Also Updates bereitstellen, wenn RC=0 --> drüber kopieren...

[gregor]

Im Backup war die fhem.cfg nur 250kB groß. Aktuell 509kB. Von den über "erkannte Geräte auto-Einrichtung" hinzugefügten Zeilen (insgesamt 9216) habe ich nur die ersten 340 Zeilen selbst angelegt. Es scheint, als könnte fhem die tausende Geräte, die der Empfänger so zu empfangen meint, nicht mehr verwalten?
Ich habe in der aktuellen Installation (die, deren Update abgebrochen war), nun die fhem.cfg auf das ursprünglich von mir definierte Format gekürzt und fhem fährt wieder hoch...

Damit stellt sich akut die Frage, an welcher Stelle das Update fehlgeschlagen ist und ob der Fehler abgefangen werden kann?! Im Anhang mal die Malheur verursachende fhem.cfg...

Danke für die Hilfe. (Auch über das Ausschlussverfahren sich dem Ziel zu nähern, trägt zur Lösung bei.)  Vielleicht hilft dieser Thread ja trotzdem noch dem einen oder anderen, der google benutzt. Und vielleicht kann fhem diesen Fehler in Zukunft abfangen.

Viele Grüße, Gregor

[gregor]

PS: Es unterscheiden sich keinerlei Dateien auf /opt/fhem zwischen dem aktuellsten Stand und der Vortagessicherung vor dem Fehler. Änderungen sind ausschließlich fhem.cfg und /opt/fhem/log/*.

[Wernieman]

Sorry, aber bei dem "Offiziellen" Fhem-Container kenne ich mich nicht aus. Da ich (aus beruflichen Gründen) lieber mit Docker-Container-Versionen arbeite (und kleinen Container bevorzuge), verwende ich diesen Container nicht...

[kadettilac89]

PS: Es unterscheiden sich keinerlei Dateien auf /opt/fhem zwischen dem aktuellsten Stand und der Vortagessicherung vor dem Fehler. Änderungen sind ausschließlich fhem.cfg und /opt/fhem/log/*.

Wenn du einen ganz neuen Container anlegst, startet der mit der Demo-Config? Komplett nackt, Docker-Compose ohne eigenes Netz, ohne irgend welche zusätzlichen Settings ...
- Ja, deine Config, Fileberechtigung ...
- Nein, Problem mit dem Framework, ...