For the last week or two, I’ve noticed that my system backups seem to be taking an abnormally long time. They’re scheduled to run at 0100, and the incremental backups usually report an elapsed time of < 10 minutes–but the overall process ends up taking several hours. Here’s a recent example:
OpenVPN, the same connection it’s been using for over a year. This is a recent change in behavior with no changes to configuration, with the possible exception of updates being installed on my Neth box.
Appreciate the suggested workarounds, but they don’t seem to really address the fact that there are about five hours unaccounted for–the backup started at 0100, but Duplicity didn’t start running until 0552. I don’t see anything remarkable in the log:
Feb 23 01:00:03 neth esmith::event[31344]: Event: pre-backup-data backup-data
Feb 23 01:00:04 neth esmith::event[31344]: ===== Report for configuration backup =====
Feb 23 01:00:04 neth esmith::event[31353]: Event: pre-backup-config
Feb 23 01:00:04 neth esmith::event[31353]: expanding /etc/backup-config.d/nethserver-sssd.include
Feb 23 01:00:05 neth esmith::event[31353]: WARNING in /etc/e-smith/templates//etc/backup-config.d/nethserver-sssd.include/20kerberos: Use of uninitialized value in string ne at /etc/e-smith/templates//etc/backup-config.d/nethserver-sssd.include/20kerberos line 5.
Feb 23 01:00:05 neth esmith::event[31353]: WARNING: Template processing succeeded for //etc/backup-config.d/nethserver-sssd.include: 1 fragment generated warnings
Feb 23 01:00:05 neth esmith::event[31353]: Action: /etc/e-smith/events/pre-backup-config/S20nethserver-directory-dump-ldap SUCCESS [0.067925]
Feb 23 01:00:05 neth esmith::event[31353]: Action: /etc/e-smith/events/pre-backup-config/S40nethserver-mail-shrmbx-cfgbackup SUCCESS [0.019083]
Feb 23 01:00:05 neth esmith::event[31353]: Action: /etc/e-smith/events/pre-backup-config/S40nethserver-sssd-backup-tdb SUCCESS [0.005655]
Feb 23 01:00:08 neth esmith::event[31353]: Action: /etc/e-smith/events/pre-backup-config/S50nethserver-backup-config-list-packages SUCCESS [3.491743]
Feb 23 01:00:08 neth esmith::event[31353]: Event: pre-backup-config SUCCESS
Feb 23 01:00:08 neth esmith::event[31344]: Event pre-backup-config: SUCCESS
Feb 23 01:00:08 neth esmith::event[31344]: Action backup-config-execute: SUCCESS
Feb 23 01:00:08 neth esmith::event[31436]: Event: post-backup-config
Feb 23 01:00:08 neth esmith::event[31436]: Event: post-backup-config SUCCESS
Feb 23 01:00:08 neth esmith::event[31344]: Event post-backup-config: SUCCESS
Feb 23 01:00:08 neth esmith::event[31344]: Action: /etc/e-smith/events/pre-backup-data/S20nethserver-backup-config-predatabackup SUCCESS [5.187651]
Feb 23 01:00:35 neth esmith::event[31566]: Event: pre-backup-config
Feb 23 01:00:35 neth esmith::event[31566]: expanding /etc/backup-config.d/nethserver-sssd.include
Feb 23 01:00:35 neth esmith::event[31566]: WARNING in /etc/e-smith/templates//etc/backup-config.d/nethserver-sssd.include/20kerberos: Use of uninitialized value in string ne at /etc/e-smith/templates//etc/backup-config.d/nethserver-sssd.include/20kerberos line 5.
Feb 23 01:00:35 neth esmith::event[31566]: WARNING: Template processing succeeded for //etc/backup-config.d/nethserver-sssd.include: 1 fragment generated warnings
Feb 23 01:00:35 neth esmith::event[31566]: Action: /etc/e-smith/events/pre-backup-config/S20nethserver-directory-dump-ldap SUCCESS [0.076493]
Feb 23 01:00:35 neth esmith::event[31566]: Action: /etc/e-smith/events/pre-backup-config/S40nethserver-mail-shrmbx-cfgbackup SUCCESS [0.009553]
Feb 23 01:00:35 neth esmith::event[31566]: Action: /etc/e-smith/events/pre-backup-config/S40nethserver-sssd-backup-tdb SUCCESS [0.003954]
Feb 23 01:00:38 neth esmith::event[31566]: Action: /etc/e-smith/events/pre-backup-config/S50nethserver-backup-config-list-packages SUCCESS [2.816837]
Feb 23 01:00:38 neth esmith::event[31566]: Event: pre-backup-config SUCCESS
Feb 23 01:00:38 neth esmith::event[31597]: Event: post-backup-config
Feb 23 01:00:38 neth esmith::event[31597]: Event: post-backup-config SUCCESS
Feb 23 01:00:40 neth esmith::event[31344]: Action: /etc/e-smith/events/pre-backup-data/S20nethserver-restore-data-duc-index SUCCESS [31.121832]
Feb 23 01:01:05 neth esmith::event[31344]: Action: /etc/e-smith/events/pre-backup-data/S50mysql-dump-tables SUCCESS [25.424749]
Feb 23 01:01:05 neth esmith::event[31344]: Action: /etc/e-smith/events/pre-backup-data/S80nethserver-sogo-backup-users SUCCESS [0.452736]
Feb 23 01:01:05 neth esmith::event[31344]: Event: pre-backup-data SUCCESS
…but then nothing (other than pre-config-backup events every 15 minutes, which I presume are related to hotsync) until it deletes the outdated backup files and completes the backup at 0601.
I’ve checked on a server that do backup via VPN and all is working as expected.
Any news on your installation?
When backup was working fine, there was already the customization with the template (that generates a warning due to a variable not initialized) ?
I don’t recall any custom templates relating to the backup, and when I look in /etc/e-smith/templates-custom/, I only see one for default-virtualhost.inc.
Where can I look to find out what it’s doing for several hours between the completion of the pre-backup event and when Duplicity actually starts backing up?
It seems that all the spent time is on duplicity itself.
Try to launch the backup from the command line to see if there duplicity outputs something interesting.
Bear in mind that if duplicity doesn’t find the local cache, it tries to download it again each time. Take a look inside /var/lib/nethserver/backup/duplicity/ dir and check there is a directory named as you backup with all duplicity cache files.
Directories 67e88beee0169764f8686b7aa8457d2d and fd4a01b80efbc1e7ca39754633aed5b6 shouldn’t be there.
Are you sure to have the latest package installed?
From the first post, it seems not. Latest is nethserver-backup-data-1.5.1-1.ns7.noarch.
Edit: just to be clear, the latest package should cleanup the unused directories and make sure to not download the cache multiple times. The cleanup is done on the post-backup-data event.
“No packages marked for update”. Apparently the new backup package hasn’t been pushed to the subscription repo yet. (and there’s absolutely no sense in doing yum update && yum upgrade; yum isn’t apt).
OK, two backups have run since I installed the update. The first, like the last several backups before it, took several hours, and cleaned up the directories that shouldn’t have been there. The second, this morning, took about 10 minutes, as had been typical before. Still going to watch for a few more days, but it’s looking like the 1.5.1 update solved this.
Are there new insights into this problem in the meantime? I have had a similar delay for a few days. (However, my backup is saved to a local server via CIFS / SMB).