Konflikt zwischen Keyhelp-Update und Backup

Haben Sie einen Bug entdeckt? Teilen Sie es uns mit.
Post Reply
tab-kh
Posts: 683
Joined: Thu 22. Apr 2021, 23:06

Konflikt zwischen Keyhelp-Update und Backup

Post by tab-kh »

Ich bin sicher, dass die Ursache des Problems bei KeyHelp liegt
(z.B. Ja / Nein (Probleme ohne KeyHelp-Bezug gehören ins Offtopic-Forum))
Ja

Server-Betriebssystem + Version
(z.B. Ubuntu 24.04)
Debian 13.4 (64-bit)

Eingesetzte Server-Virtualisierung-Technologie
(z.B. keine, OpenVZ, KVM, XEN, etc.)
KVM

KeyHelp-Version + Build-Nummer
(z.B. 26.0 - Build 3582)
26.0 (Build 3618)

Problembeschreibung / Fehlermeldungen
Beim Keyhelp-Update in der Nacht auf den 8.4. sind sich nach meiner Einschätzung Keyhelp-Update und geplantes Backup (SFTP auf Hetzner Storage-Box) in die Quere gekommen. Im Endeffekt wurde das Backup nicht sauber beendet, das nächste Backup letzte Nacht lief nicht. Auch ein vorhin manuell im Keyhelp-Backend angestossenes "geplantes" Backup startete nicht. Erst nach Ausführung aller Optionen in der neue Problembehandlung, insbesondere Beseitigung des Locks, lief dann das manuell angestossene Backup (hoffentlich) fehlerfrei durch. Jedenfalls kamen keine neuen Fehlermeldungen im Logfile (/var/log/keyhelp/backup/backup-root.log)

Erwartetes Ergebnis
Laufendes Backup und Keyhelp-Update kommen sich nicht ins Gehege, Keyhelp-Update wartet ggf auf komplette Beendigung des Backup-Vorgangs.

Tatsächliches Ergebnis
Das Keyhelp-Update hat (nach meiner Einschätzung) einige Dateien entfernt oder geändert, auf die das Backup zugreifen wollte (siehe auch Log unten)

Schritte zur Reproduktion
Eventuell- ich kann es nicht mehr testen, weil das Update komplett durchgeführt ist - Start des Keyhelp-Updates während eines laufenden, geplanten vollständigen Systembackups (?).

Zusätzliche Informationen
(z.B. kürzlich durchgeführte Änderungen am Server, Auszüge aus Protokolldateien (/var/log/*, /var/log/keyhelp/php-error.log, etc.))

Aktualisierungshinweise (im Dashboard)

KeyHelp wurde auf Version 26.0 aktualisiert.
Mittwoch, 08. April 2026 um 03:51:26

(/var/log/keyhelp/backup/backup-root.log)

Code: Select all

[2026-04-07 03:50:02] INFO | Create repository lock
[2026-04-07 03:50:04] INFO | Looking for pending operations for repository: mail-System-SB1 (SFTP) / #1
[2026-04-07 03:50:04] INFO | Operation found: backup
[2026-04-07 03:50:04] INFO | Prepare backup...
[2026-04-07 03:50:53] INFO | Backup created
[2026-04-07 03:50:53] INFO | Cleanup
[2026-04-07 03:50:53] INFO | Operation found: prune
[2026-04-07 03:50:53] INFO | Remove old snapshots
[2026-04-07 03:51:03] INFO | Operation found: check
[2026-04-07 03:51:03] INFO | Integrity check
[2026-04-07 03:51:10] INFO | Update snapshot data / stats
[2026-04-07 03:51:20] INFO | Update repository stats
[2026-04-07 03:51:30] INFO | Size 'raw': 3.12 GiB
[2026-04-07 03:51:30] INFO | Size 'restore': 6.05 GiB
[2026-04-07 03:51:33] INFO | All finished, releasing lock.
====
[2026-04-08 03:50:02] INFO | Create repository lock
[2026-04-08 03:50:04] INFO | Looking for pending operations for repository: mail-System-SB1 (SFTP) / #1
[2026-04-08 03:50:04] INFO | Operation found: backup
[2026-04-08 03:50:04] INFO | Prepare backup...
[2026-04-08 03:51:01] INFO | Backup created
[2026-04-08 03:51:01] WARN | The backup operation finished successfully, but problems have been reported.
{"message_type":"error","error":{"message":"open /home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/services.mo: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/services.mo"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/template_account.po: xattr.list /home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/template_account.po: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/template_account.po"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/traffic.po: xattr.list /home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/traffic.po: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp/locale/sv/LC_MESSAGES/traffic.po"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp/pages/admin_mail_log.php: xattr.list /home/keyhelp/www/keyhelp/pages/admin_mail_log.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp/pages/admin_mail_log.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/theme/bulma/assets/vendor/trumbowyg/plugins/template/trumbowyg.template.min.js: xattr.list /home/keyhelp/www/keyhelp_tmp/theme/bulma/assets/vendor/trumbowyg/plugins/template/trumbowyg.template.min.js: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/theme/bulma/assets/vendor/trumbowyg/plugins/template/trumbowyg.template.min.js"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/microsoftTpmCollection.pem: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/microsoftTpmCollection.pem: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/microsoftTpmCollection.pem"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/solo.pem: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/solo.pem: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/rootCertificates/solo.pem"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/server.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/server.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/lbuchs/webauthn/_test/server.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/TelegramBotHandler.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/TelegramBotHandler.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/TelegramBotHandler.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/ZendMonitorHandler.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/ZendMonitorHandler.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Handler/ZendMonitorHandler.php"}
{"message_type":"error","error":{"message":"open /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/PsrLogMessageProcessor.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/PsrLogMessageProcessor.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessorInterface.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessorInterface.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessorInterface.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/TagProcessor.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/TagProcessor.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/TagProcessor.php"}
{"message_type":"error","error":{"message":"incomplete metadata for /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessIdProcessor.php: xattr.list /home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessIdProcessor.php: no such file or directory"},"during":"archival","item":"/home/keyhelp/www/keyhelp_tmp/vendor/monolog/monolog/src/Monolog/Processor/ProcessIdProcessor.php"}
{"message_type":"exit_error","code":3,"message":"Warning: at least one source file could not be read"}
[2026-04-08 03:51:01] INFO | Cleanup
====
l_fish
Posts: 193
Joined: Tue 15. Aug 2017, 11:49

Re: Konflikt zwischen Keyhelp-Update und Backup

Post by l_fish »

Moin!

Ähnliches Problem bei uns. Allerdings lief hier das Backup am 8.6. noch korrekt durch und auch die Jobs "Repository bereinigen" und "Integritätsprüfung / Datensynchronisation" wurden laut Anzeige in Keyhelp "grün" beendet (obwohl das zeitlich laut Logs in das Updatezeitfenster hineinlief). Es gab in der Nacht auch keine Warnmail.

Danach hingen aber alle Backup-Jobs in der Warteschleife und heute gab es die Warnmail "Ausstehende Backup-Vorgänge nehmen zu" weshalb das Ganze dann aufgefallen ist. Nach Ausführen der Aufgaben in der Problembehandlung ließ sich ein neues Backup problemlos starten.

Auszug aus den Logs:

Backup:

Code: Select all

[2026-04-08 03:00:02] INFO | Create repository lock
[2026-04-08 03:00:02] INFO | Looking for pending operations for repository: Keydisc 1000 GB (KeyDisc) / #2
[2026-04-08 03:00:02] INFO | Operation found: backup
[2026-04-08 03:00:02] INFO | Prepare backup...
[2026-04-08 03:08:31] INFO | Backup created
[2026-04-08 03:08:31] INFO | Cleanup
[2026-04-08 03:08:31] INFO | Operation found: prune
[2026-04-08 03:08:31] INFO | Remove old snapshots
[2026-04-08 03:09:41] INFO | Operation found: check
[2026-04-08 03:09:41] INFO | Integrity check
[2026-04-08 03:10:17] INFO | Update snapshot data / stats
[2026-04-08 03:10:39] INFO | Update repository stats
[2026-04-08 03:29:30] INFO | Size 'raw': 211.90 GB
[2026-04-08 03:29:30] INFO | Size 'restore': 33.89 TB
[2026-04-08 03:29:36] INFO | All finished, releasing lock.
Panel Update:

Code: Select all

[2026-04-08 03:00:03] INFO | waiting 00:11:06 before connecting to the update server
[2026-04-08 03:11:17] INFO | maintenance connection okay
[2026-04-08 03:11:17] INFO | trying to connect to updateserver
[2026-04-08 03:11:32] ERROR | Failed to fetch information from update server. (Curl: SSL connection timeout (https://install.keyhelp.de/get_version.php?php_version=8.2&current_version=25.3&operating_system=debian_12))
[2026-04-08 03:11:32] INFO | attempt #1 failed ... sleeping till next attempt
[2026-04-08 03:11:42] INFO | trying to connect to updateserver
[2026-04-08 03:11:53] INFO | enable full access to temporary directories
[2026-04-08 03:11:53] INFO | new version detected - starting update process from "25.3" to "26.0"
[2026-04-08 03:11:53] INFO | first update step: "26.0" | total steps to reach latest version: 1
[2026-04-08 03:11:53] INFO | create folder for panel update "/home/keyhelp/www/keyhelp_tmp/"
[2026-04-08 03:11:53] INFO | start download of "https://install.keyhelp.de/files/releases/26.0/26.0-php82.tar.gz"
[2026-04-08 03:12:22] INFO | file saved to "/home/keyhelp/www/keyhelp_tmp/26.0.tar.gz"
[2026-04-08 03:12:22] INFO | checksum check successful
[2026-04-08 03:12:22] INFO | lock panel
[2026-04-08 03:12:22] INFO | log out all users
[2026-04-08 03:12:22] INFO | run --force="update" one last time before new files and db structure may change things
[2026-04-08 03:12:24] INFO | checking running maintenance intervals ...
[2026-04-08 03:12:24] INFO | all maintenance intervals finished, so we can go on
[2026-04-08 03:12:24] INFO | archive extraction finished
[2026-04-08 03:12:24] INFO | changed owner of "/home/keyhelp/www/keyhelp_tmp/" to "keyhelp"
[2026-04-08 03:12:24] INFO | Setup backup directory "/home/keyhelp/keyhelp.backup/panel_updates"
[2026-04-08 03:12:24] INFO | Database backup saved to "/home/keyhelp/keyhelp.backup/panel_updates/keyhelp_25.3_2026-04-08_03-12-24.sql"
[2026-04-08 03:12:25] INFO | File backup saved to "/home/keyhelp/keyhelp.backup/panel_updates/keyhelp_25.3_2026-04-08_03-12-24.tar.gz"
[2026-04-08 03:12:26] INFO | remove old keyhelp folder
[2026-04-08 03:12:28] INFO | copy from "/home/keyhelp/www/keyhelp_tmp/" to "/home/keyhelp/www/keyhelp/" 
[2026-04-08 03:12:28] INFO | remove "/home/keyhelp/www/keyhelp_tmp/"
[2026-04-08 03:12:29] INFO | run update file "/home/keyhelp/www/keyhelp/install/updates/update_25.3.php"
[2026-04-08 03:12:29] INFO | [KeyHelp Database] Add keys to columns
[2026-04-08 03:12:29] INFO | [KeyHelp Database] Update scheduled_tasks -> php_interpreter column
[2026-04-08 03:12:29] INFO | [KeyHelp Database] Add columns for PHP environment variables
[2026-04-08 03:12:29] INFO | [KeyHelp Database] Add Fail2Ban whitelist setting
[2026-04-08 03:12:29] INFO | [KeyHelp Database] Update backup_repository -> max_snapshot column
[2026-04-08 03:12:29] INFO | [Backup] Add new rotation policies
[2026-04-08 03:12:29] INFO | [Maintenance Intervals] Update job name
[2026-04-08 03:12:29] INFO | [KeyHelp] Delete outdated client statistics
[2026-04-08 03:12:30] INFO | [KeyHelp] Delete outdated panel backups
[2026-04-08 03:12:30] INFO | [Postfix] Update configuration
[2026-04-08 03:12:32] INFO | [PHP-FPM] Rename keyhelp pool directory
[2026-04-08 03:12:32] INFO | Reload PHP-FPM
[2026-04-08 03:12:32] INFO | [Rclone] Update to version 1.73.3
[2026-04-08 03:13:57] INFO | [SourceGuardian] Update loaders
[2026-04-08 03:14:31] INFO | [ionCube] Update loaders
[2026-04-08 03:15:34] INFO | [Redis] Add password protected Redis instance for Rspamd
[2026-04-08 03:15:51] INFO | [rspamd] ensure classifier-bayes.conf exists
[2026-04-08 03:15:51] INFO | [Adminer] Update to version 5.4.2
[2026-04-08 03:16:01] INFO | [Adminer] Update complete
[2026-04-08 03:16:01] INFO | [Roundcube] Update to version 1.6.15
[2026-04-08 03:16:16] INFO | [Roundcube] Setup configuration files
[2026-04-08 03:16:16] INFO | [Roundcube] Update complete
[2026-04-08 03:16:16] INFO | unlock panel
[2026-04-08 03:16:16] INFO | update process finished, you are now running on version "26.0"
[2026-04-08 03:16:16] INFO | restore access to temporary directories
Grüße,
Lars
Post Reply