2018-01-10 10:48 GMT+01:00 intrigeri <intrig...@debian.org>: > Control: tag -1 + moreinfo > > Hi, > > Thomas D: > > I have been using backupninja for a long time and it is really helpful. > > After upgrading to Debian 9 I started seing a lot of errors such as > > these in my syslog: > > > 2017-10-23T01:00:15.795982+02:00 fer systemd[1]: user@500.service: > Start request repeated too quickly. > > 2017-10-23T01:00:15.796132+02:00 fer systemd[1]: Failed to start > User Manager for UID 500. > > 2017-10-23T01:00:15.796271+02:00 fer systemd[1]: user@500.service: > Unit entered failed state. > > 2017-10-23T01:00:15.796409+02:00 fer systemd[1]: user@500.service: > Failed with result 'start-limit-hit'. > > 2017-10-23T01:00:15.796702+02:00 fer su[11455]: > pam_systemd(su:session): Failed to create session: Start job for unit > user@500.service failed with 'failed' > > 2017-10-23T01:00:21.594947+02:00 fer systemd[1]: user@500.service: > Start request repeated too quickly. > > 2017-10-23T01:00:21.595070+02:00 fer systemd[1]: Failed to start > User Manager for UID 500. > > 2017-10-23T01:00:21.595212+02:00 fer systemd[1]: user@500.service: > Failed with result 'start-limit-hit'. > > 2017-10-23T01:00:21.596172+02:00 fer su[11486]: > pam_systemd(su:session): Failed to create session: Start job for unit > user@500.service failed with 'failed' > > > A bit of investigation with help from the IRC lead to the conclusion > > that this is caused by backupninja's postgresql jobs. > > Can you please share the output of `backupninja --now --debug'? > (Make sure it does not contain any password :) > >
Please find the output below. Server and database names has been changed. ~ # time backupninja --now --debug [R0 J0 L:0.12 0.20 0.16 U:12+11:12 pts/12 3674H] Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/10.sys Debug: perms: -rw------- Debug: gperm: --- Debug: wperm: --- Info: >>>> starting action /etc/backup.d/10.sys (because of --now) Debug: yes Debug: executing handler in locked section controlled by /var/lock/backupninja/_etc_backup.d_10.sys Debug: Debian detected Debug: /usr/bin/dpkg --get-selections * > /var/backups/dpkg-selections.txt Debug: /usr/bin/debconf-get-selections > /var/backups/debconfsel.txt Getting information about the kernel. Getting disk and filesystem information. Debug: /usr/sbin/hwinfo --short --cpu --network --disk --pci >> /var/backups/hardware.txt Debug: Using /usr/sbin/hwinfo to get all available disk information Info: <<<< finished action /etc/backup.d/10.sys: SUCCESS Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/10.sys.disabled Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: Skipping /etc/backup.d/10.sys.disabled Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/10.tar.disabled Debug: perms: -rw------- Debug: gperm: --- Debug: wperm: --- Info: Skipping /etc/backup.d/10.tar.disabled Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/20.mysql Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: >>>> starting action /etc/backup.d/20.mysql (because of --now) Debug: yes Debug: executing handler in locked section controlled by /var/lock/backupninja/_etc_backup.d_20.mysql Info: Initializing SQL dump method Debug: su root -c "/usr/bin/mysqldump --defaults-extra-file=/etc/mysql/debian.cnf --lock-tables --complete-insert --add-drop-table --quick --quote-names --skip-lock-tables information_schema | /bin/gzip --rsyncable > '/data/backup/local/mysql/ninja/sqldump/information_schema.sql.gz'" Info: Successfully finished dump of mysql database information_schema Debug: su root -c "/usr/bin/mysqldump --defaults-extra-file=/etc/mysql/debian.cnf --lock-tables --complete-insert --add-drop-table --quick --quote-names DATABASE_001 | /bin/gzip --rsyncable > '/data/backup/local/mysql/ninja/sqldump/DATABASE_001.sql.gz'" Info: Successfully finished dump of mysql database DATABASE_001 Debug: su root -c "/usr/bin/mysqldump --defaults-extra-file=/etc/mysql/debian.cnf --lock-tables --complete-insert --add-drop-table --quick --quote-names mysql | /bin/gzip --rsyncable > '/data/backup/local/mysql/ninja/sqldump/mysql.sql.gz'" Info: Successfully finished dump of mysql database mysql Debug: su root -c "/usr/bin/mysqldump --defaults-extra-file=/etc/mysql/debian.cnf --lock-tables --complete-insert --add-drop-table --quick --quote-names --skip-lock-tables --skip-events performance_schema | /bin/gzip --rsyncable > '/data/backup/local/mysql/ninja/sqldump/performance_schema.sql.gz'" Info: Successfully finished dump of mysql database performance_schema Debug: su root -c "/usr/bin/mysqldump --defaults-extra-file=/etc/mysql/debian.cnf --lock-tables --complete-insert --add-drop-table --quick --quote-names DATABASE_002 | /bin/gzip --rsyncable > '/data/backup/local/mysql/ninja/sqldump/DATABASE_002.sql.gz'" Info: Successfully finished dump of mysql database DATABASE_002 Info: <<<< finished action /etc/backup.d/20.mysql: SUCCESS Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/20.mysql.disabled Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: Skipping /etc/backup.d/20.mysql.disabled Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/20.pgsql Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: >>>> starting action /etc/backup.d/20.pgsql (because of --now) Debug: yes Debug: executing handler in locked section controlled by /var/lock/backupninja/_etc_backup.d_20.pgsql Debug: chown 500 /data/backup/local/pgsql/ninja Debug: chmod 700 /data/backup/local/pgsql/ninja Debug: execstr Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dumpall -g | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/globals.sql.gz'" Info: Successfully finished pgsql globals (roles and tablespaces) dump Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 postgres | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/postgres.pg_dump.gz'" Info: Successfully finished dump of pgsql database postgres Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_003 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_003.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_003 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_003dev | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_003dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_003dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_007 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_007.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_007 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_008dev | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_008dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_008dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_009 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_009.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_009 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_011 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_011.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_011 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004dev | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_004dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004prod | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_004prod.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004prod Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004test | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_004test.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004test Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_006 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_006.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_006 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_005 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_005.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_005 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_010 | /bin/gzip --rsyncable > '/data/backup/local/pgsql/ninja/DATABASE_010.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_010 Info: <<<< finished action /etc/backup.d/20.pgsql: SUCCESS Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/20.pgsql.disabled Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: Skipping /etc/backup.d/20.pgsql.disabled Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/21.pgsql Debug: perms: -rw------- Debug: gperm: --- Debug: wperm: --- Info: >>>> starting action /etc/backup.d/21.pgsql (because of --now) Debug: yes Debug: executing handler in locked section controlled by /var/lock/backupninja/_etc_backup.d_21.pgsql Debug: chown 500 /var/backups/postgres Debug: chmod 700 /var/backups/postgres Debug: execstr Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dumpall -g | /bin/gzip --rsyncable > '/var/backups/postgres/globals.sql.gz'" Info: Successfully finished pgsql globals (roles and tablespaces) dump Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 postgres | /bin/gzip --rsyncable > '/var/backups/postgres/postgres.pg_dump.gz'" Info: Successfully finished dump of pgsql database postgres Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_003 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_003.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_003 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_003dev | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_003dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_003dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_007 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_007.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_007 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_008dev | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_008dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_008dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_009 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_009.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_009 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_011 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_011.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_011 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004dev | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_004dev.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004dev Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004prod | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_004prod.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004prod Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_004test | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_004test.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_004test Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_006 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_006.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_006 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_005 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_005.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_005 Debug: su - postgres -s /bin/bash -c "set -o pipefail ; /usr/bin/pg_dump --format=custom --compress=0 DATABASE_010 | /bin/gzip --rsyncable > '/var/backups/postgres/DATABASE_010.pg_dump.gz'" Info: Successfully finished dump of pgsql database DATABASE_010 Info: <<<< finished action /etc/backup.d/21.pgsql: SUCCESS Debug: check_perms /etc/backup.d Debug: perms: drwx------ Debug: gperm: --- Debug: wperm: --- Debug: check_perms /etc/backup.d/90.dup Debug: perms: -r-------- Debug: gperm: --- Debug: wperm: --- Info: >>>> starting action /etc/backup.d/90.dup (because of --now) Debug: yes Debug: executing handler in locked section controlled by /var/lock/backupninja/_etc_backup.d_90.dup Debug: ssh -o PasswordAuthentication=no backuphost.example.com -l backup-fer 'echo -n 1' Debug: Connected to backuphost.example.com as backup-fer successfully Debug: Data will be encrypted using symmetric encryption. Debug: Data won't be signed. Debug: duplicity cleanup --force --volsize 1000 --no-print-statistics --scp-command 'scp ' --sftp-command 'sftp ' --full-if-older-than 30D --extra-clean --archive-dir /var/cache/backupninja/duplicity scp:// backup-...@backuphost.example.com//data/backup/example.com/fer/duplicity Debug: Synchronizing remote metadata to local cache... Deleting local /var/cache/backupninja/duplicity/d379f7fb87ea9c0a2da40ad2ba49c941/duplicity-inc.20180122T000215Z.to.20180123T000159Z.manifest (not authoritative at backend). Deleting local /var/cache/backupninja/duplicity/d379f7fb87ea9c0a2da40ad2ba49c941/duplicity-new-signatures.20180122T000215Z.to.20180123T000159Z.sigtar.gz (not authoritative at backend). Last full backup date: Sat Jan 13 16:11:18 2018 Deleting this file from backend: duplicity-full-signatures.20180113T151118Z.sigtar.gz Info: Duplicity cleanup finished successfully. Debug: duplicity remove-older-than 60D --force --volsize 1000 --no-print-statistics --scp-command 'scp ' --sftp-command 'sftp ' --full-if-older-than 30D --extra-clean --archive-dir /var/cache/backupninja/duplicity scp:// backup-...@backuphost.example.com//data/backup/example.com/fer/duplicity Debug: Synchronizing remote metadata to local cache... Copying duplicity-full-signatures.20180113T151118Z.sigtar.gpg to local cache. Last full backup date: Sat Jan 13 16:11:18 2018 There are backup set(s) at time(s): Tue Nov 21 02:06:39 2017 Which can't be deleted because newer sets depend on them. No old backup sets found, nothing deleted. Info: Duplicity remove-older-than finished successfully. Debug: duplicity --volsize 1000 --no-print-statistics --scp-command 'scp ' --sftp-command 'sftp ' --full-if-older-than 30D --extra-clean --archive-dir /var/cache/backupninja/duplicity --exclude '/data/backup/virtual' --exclude '/data/luks/*' --exclude '/data/tmp' --exclude '/data/www/virtual/mirror.example.com/htdocs' --exclude '/data/www/virtual/thearchdruidreport.example.com' --exclude '/home/*/.aMule' --exclude '/home/*/.beagle' --exclude '/home/*/gtk-gnutella-downloads' --exclude '/home/*/.local/share/Trash' --exclude '/home/*/.thumbnails' --exclude '/home/*/.Trash' --exclude '/var/cache' --exclude '/var/cache/backupninja/duplicity' --exclude '/var/tmp' --include '/boot' --include '/data' --include '/etc' --include '/home' --include '/root' --include '/usr/local' --include '/var' --include '/var/lib/dpkg/status*' --include '/var/spool/cron/crontabs' --exclude '**' / scp:// backup-...@backuphost.example.com//data/backup/example.com/fer/duplicity Info: Local and Remote metadata are synchronized, no sync needed. Info: Last full backup date: Sat Jan 13 16:11:18 2018 Info: Duplicity finished successfully. Info: <<<< finished action /etc/backup.d/90.dup: SUCCESS Info: FINISHED: 5 actions run. 0 fatal. 0 error. 0 warning. Debug: send /var/log/backupninja.log to backup-...@backuphost.example.com: /data/backup/example.com/fer/reports backupninja --now --debug 1152,57s user 1297,26s system 96% cpu 42:10,19 total Med venlig hilsen/Kind regards Thomas
