Backup not starting : Cannot create directory , File exists (code: 17)

orogor · June 19, 2017, 2:32pm

server version 2.1.19
client version 2.0.34
other issues on previous version, but not this one
#==================================
The strange things :
Cannot read file tree from file “urbackup/clientlist_6.ub”
files are named clientlist_b_somenumber.ub
directory exists doesnt exists before i try to backup “/var/docker/data/urbackup-server/datas//urbackupclient/170619-1534”
after the failled backup, “/var/docker/data/urbackup-server/datas//urbackupclient/170619-1534” contains only a .hash folder
obiously i get the error if i try sub minute backup, but here it s the daily backup that fails (4 days in a row)
starting a full works, and subsequent full works afterward
these backups are hosted on amazon efs , i didnt spotted that on my other urbackupservers
28 days exponential backoff seems quite long, maybe max it to 1-2 day ?

#========================================

juin 19 15:34:44 urbackupserver urbackupsrv[455]: msg=START BACKUP INCR
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Starting unscheduled incremental file backup…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Doing backup with hashes…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Connecting for filelist…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Waiting for filelist
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “backup” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Indexing of “backup” done. 4 filesystem lookups 0 db lookups and 0 db updates
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “conf” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_bytes” to “/usr/lib/munin/plugins/mysql_bytes” confirms symlink backup target “.symlink_mysql_bytes” to “/usr/lib/munin/plugins/mysql_bytes”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_innodb” to “/usr/lib/munin/plugins/mysql_innodb” confirms symlink backup target “.symlink_mysql_innodb” to “/usr/lib/munin/plugins/mysql_innodb”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_queries” to “/usr/lib/munin/plugins/mysql_queries” confirms symlink backup target “.symlink_mysql_queries” to “/usr/lib/munin/plugins/mysql_queries”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_slowqueries” to “/usr/lib/munin/plugins/mysql_slowqueries” confirms symlink backup target “.symlink_mysql_slowqueries” to “/usr/lib/munin/plugins/mysql_slowqueries”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_threads” to “/usr/lib/munin/plugins/mysql_threads” confirms symlink backup target “.symlink_mysql_threads” to “/usr/lib/munin/plugins/mysql_threads”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Indexing of “conf” done. 56 filesystem lookups 0 db lookups and 0 db updates
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “.symlink_mysql_bytes” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “.symlink_mysql_innodb” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “.symlink_mysql_queries” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “.symlink_mysql_slowqueries” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Backing up “.symlink_mysql_threads” without snapshot.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Doing backup with hashed transfer…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Connecting to client…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Loading file list…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Flushing FileClient…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient Starting incremental backup…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: urbackupclient: Calculating file tree differences…
juin 19 15:34:44 urbackupserver urbackupsrv[455]: ERROR: Cannot read file tree from file “urbackup/clientlist_6.ub”
juin 19 15:34:44 urbackupserver urbackupsrv[455]: ERROR: Error while calculating tree diff. Doing full backup.
juin 19 15:34:44 urbackupserver urbackupsrv[455]: ERROR: Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1534 for backup (server error). File exists (code: 17)
juin 19 15:34:44 urbackupserver urbackupsrv[455]: Time taken for backing up client urbackupclient: 4ms
juin 19 15:34:44 urbackupserver urbackupsrv[455]: ERROR: Backup failed

#============================================================#

19/06/17 16:03 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_threads” to “/usr/lib/munin/plugins/mysql_threads” confirms symlink backup target “.symlink_mysql_threads” to “/usr/lib/munin/plugins/mysql_threads”
19/06/17 16:03 INFO Indexing of “conf” done. 74 filesystem lookups 0 db lookups and 0 db updates
19/06/17 16:03 INFO Backing up “.symlink_mysql_bytes” without snapshot.
19/06/17 16:03 INFO Backing up “.symlink_mysql_innodb” without snapshot.
19/06/17 16:03 INFO Backing up “.symlink_mysql_queries” without snapshot.
19/06/17 16:03 INFO Backing up “.symlink_mysql_slowqueries” without snapshot.
19/06/17 16:03 INFO Backing up “.symlink_mysql_threads” without snapshot.
19/06/17 16:03 DEBUG urbackupclient: Doing backup with hashed transfer…
19/06/17 16:03 INFO urbackupclient: Loading file list…
19/06/17 16:03 DEBUG urbackupclient Starting incremental backup…
19/06/17 16:03 INFO urbackupclient: Calculating file tree differences…
19/06/17 16:03 ERROR Error while calculating tree diff. Doing full backup.
19/06/17 16:03 ERROR Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1603 for backup (server error). File exists (code: 17)
19/06/17 16:03 INFO Time taken for backing up client urbackupclient: 180ms
19/06/17 16:03 ERROR Backup failed
19/06/17 16:03 WARNING Exponential backoff: Waiting at least 28 days 10h 40m before next file backup
19/06/17 16:03 INFO Time taken for backing up client urbackupclient: 190ms
19/06/17 16:03 ERROR Backup failed
19/06/17 16:03 WARNING Exponential backoff: Waiting at least 7 days 4h 17m 12s before next file backup
19/06/17 16:04 INFO Starting unscheduled incremental file backup…
19/06/17 16:04 DEBUG urbackupclient: Doing backup with hashes…
19/06/17 16:04 DEBUG urbackupclient: Connecting for filelist…
19/06/17 16:04 DEBUG urbackupclient: Waiting for filelist
19/06/17 16:04 INFO Backing up “.symlink_mysql_threads” without snapshot.
19/06/17 16:04 DEBUG urbackupclient: Doing backup with hashed transfer…
19/06/17 16:04 INFO urbackupclient: Loading file list…
19/06/17 16:04 DEBUG urbackupclient Starting incremental backup…
19/06/17 16:04 INFO urbackupclient: Calculating file tree differences…
19/06/17 16:04 ERROR Error while calculating tree diff. Doing full backup.
19/06/17 16:04 ERROR Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1604 for backup (server error). File exists (code: 17)
19/06/17 16:04 INFO Time taken for backing up client urbackupclient: 192ms
19/06/17 16:04 ERROR Backup failed
19/06/17 16:04 WARNING Exponential backoff: Waiting at least 14 days 8h 34m 25s before next file backup
19/06/17 16:04 ERROR Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1604 for backup (server error). File exists (code: 17)
19/06/17 16:04 INFO Time taken for backing up client urbackupclient: 1s
19/06/17 16:04 ERROR Backup failed
19/06/17 16:04 WARNING Exponential backoff: Waiting at least 28 days 17h 8m 50s before next file backup
19/06/17 16:05 INFO Backing up “conf” without snapshot.
19/06/17 16:05 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_bytes” to “/usr/lib/munin/plugins/mysql_bytes” confirms symlink backup target “.symlink_mysql_bytes” to “/usr/lib/munin/plugins/mysql_bytes”
19/06/17 16:05 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_innodb” to “/usr/lib/munin/plugins/mysql_innodb” confirms symlink backup target “.symlink_mysql_innodb” to “/usr/lib/munin/plugins/mysql_innodb”
19/06/17 16:05 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_queries” to “/usr/lib/munin/plugins/mysql_queries” confirms symlink backup target “.symlink_mysql_queries” to “/usr/lib/munin/plugins/mysql_queries”
19/06/17 16:05 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_slowqueries” to “/usr/lib/munin/plugins/mysql_slowqueries” confirms symlink backup target “.symlink_mysql_slowqueries” to “/usr/lib/munin/plugins/mysql_slowqueries”
19/06/17 16:05 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_threads” to “/usr/lib/munin/plugins/mysql_threads” confirms symlink backup target “.symlink_mysql_threads” to “/usr/lib/munin/plugins/mysql_threads”
19/06/17 16:05 INFO Indexing of “conf” done. 74 filesystem lookups 0 db lookups and 0 db updates
19/06/17 16:05 INFO Backing up “.symlink_mysql_bytes” without snapshot.
19/06/17 16:05 INFO Backing up “.symlink_mysql_innodb” without snapshot.
19/06/17 16:05 INFO Backing up “.symlink_mysql_queries” without snapshot.
19/06/17 16:05 INFO Backing up “.symlink_mysql_slowqueries” without snapshot.
19/06/17 16:05 INFO Backing up “.symlink_mysql_threads” without snapshot.
19/06/17 16:05 DEBUG urbackupclient: Doing backup with hashed transfer…
19/06/17 16:05 INFO urbackupclient: Loading file list…
19/06/17 16:05 DEBUG urbackupclient Starting incremental backup…
19/06/17 16:05 INFO urbackupclient: Calculating file tree differences…
19/06/17 16:05 ERROR Error while calculating tree diff. Doing full backup.
19/06/17 16:05 ERROR Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1605 for backup (server error). File exists (code: 17)
19/06/17 16:05 INFO Time taken for backing up client urbackupclient: 185ms
19/06/17 16:05 ERROR Backup failed
19/06/17 16:05 WARNING Exponential backoff: Waiting at least 7 days 17h 14m 54s before next file backup

#============================================================#
i kept trying to start it and it worked on this one (or maybe i started a full by mistake)

19/06/17 15:57 INFO Backing up “.symlink_mysql_threads” without snapshot.
19/06/17 15:57 DEBUG urbackupclient: Doing backup with hashed transfer…
19/06/17 15:57 INFO urbackupclient: Loading file list…
19/06/17 15:57 DEBUG urbackupclient Starting incremental backup…
19/06/17 15:57 INFO urbackupclient: Calculating file tree differences…
19/06/17 15:57 ERROR Error while calculating tree diff. Doing full backup.
19/06/17 15:57 ERROR Cannot create directory /var/docker/data/urbackup-server/datas//urbackupclient/170619-1557 for backup (server error). File exists (code: 17)
19/06/17 15:57 INFO Time taken for backing up client urbackupclient: 4ms
19/06/17 15:57 ERROR Backup failed
19/06/17 15:57 WARNING Exponential backoff: Waiting at least 14 days 8h 34m 25s before next file backup
19/06/17 16:00 INFO Following symbolic link at “/urbackup/mlc-database/conf/munin/plugins/mysql_threads” to “/usr/lib/munin/plugins/mysql_threads” confirms symlink backup target “.symlink_mysql_threads” to “/usr/lib/munin/plugins/mysql_threads”
19/06/17 16:00 INFO Indexing of “conf” done. 56 filesystem lookups 0 db lookups and 0 db updates
19/06/17 16:00 INFO Backing up “.symlink_mysql_bytes” without snapshot.
19/06/17 16:00 INFO Backing up “.symlink_mysql_innodb” without snapshot.
19/06/17 16:00 INFO Backing up “.symlink_mysql_queries” without snapshot.
19/06/17 16:00 INFO Backing up “.symlink_mysql_slowqueries” without snapshot.
19/06/17 16:00 INFO Backing up “.symlink_mysql_threads” without snapshot.
19/06/17 16:00 DEBUG urbackupclient: Doing backup with hashed transfer…
19/06/17 16:00 INFO urbackupclient: Loading file list…
19/06/17 16:00 INFO urbackupclient: Started loading files…
19/06/17 16:00 DEBUG Starting shadowcopy “backup”.
19/06/17 16:00 INFO Referencing snapshot on “urbackupclient” for path “backup” failed: FAILED
19/06/17 16:00 DEBUG Loading file “base1_20170611_233001.gz”
19/06/17 16:00 DEBUG Stoping shadowcopy “backup”.
19/06/17 16:00 DEBUG Starting shadowcopy “conf”.
19/06/17 16:00 DEBUG Stoping shadowcopy “conf”.
19/06/17 16:00 INFO Waiting for file transfers…
19/06/17 16:00 DEBUG GT: Loaded file “base1_20170611_233001.gz”
19/06/17 16:00 DEBUG Loading file “base1_20170612_233001.gz”
19/06/17 16:00 DEBUG PT: Hashing file “base1_20170611_233001.gz”

uroni · June 19, 2017, 2:48pm

You seem to have lost some clientlist_b_*.ub files. It tries to recover by automatically running a full file backup but there is a bug there. You’ll have to run full file backups manually.

orogor · June 19, 2017, 3:40pm

I would think that i have more than enought
There were client files from the 14 june, but it didnt liked them.
Anyhow issue was solved after doing one full, still kinda strange, will update if necessay if it happens again.

ls -la /var/docker/data/urbackup-server/*.ub
-rwxr-x— 1 urbackup urbackup 0 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_103.ub
-rwxr-x— 1 urbackup urbackup 0 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_104.ub
-rwxr-x— 1 urbackup urbackup 208729 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_106.ub
-rwxr-x— 1 urbackup urbackup 208729 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_107.ub
-rwxr-x— 1 urbackup urbackup 208729 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_108.ub
-rwxr-x— 1 urbackup urbackup 208729 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_109.ub
-rwxr-x— 1 urbackup urbackup 208729 22 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_110.ub
-rwxr-x— 1 urbackup urbackup 6847 14 juin 23:48 /var/docker/data/urbackup-server/clientlist_b_1149.ub
-rwxr-x— 1 urbackup urbackup 8688 14 juin 23:48 /var/docker/data/urbackup-server/clientlist_b_1150.ub
-rwxr-x— 1 urbackup urbackup 2859 14 juin 23:48 /var/docker/data/urbackup-server/clientlist_b_1151.ub
-rwxr-x— 1 urbackup urbackup 18552 19 juin 00:05 /var/docker/data/urbackup-server/clientlist_b_1199.ub
-rwxr-x— 1 urbackup urbackup 63332967 19 juin 10:37 /var/docker/data/urbackup-server/clientlist_b_1203.ub
-rwxr-x— 1 urbackup urbackup 31032692 19 juin 11:19 /var/docker/data/urbackup-server/clientlist_b_1204.ub
-rwxr-x— 1 urbackup urbackup 1097488 19 juin 13:06 /var/docker/data/urbackup-server/clientlist_b_1205.ub
-rwxr-x— 1 urbackup urbackup 6847 19 juin 16:07 /var/docker/data/urbackup-server/clientlist_b_1212.ub
-rwxr-x— 1 urbackup urbackup 13639 19 juin 16:26 /var/docker/data/urbackup-server/clientlist_b_1219.ub
-rwxr-x— 1 urbackup urbackup 8688 19 juin 16:29 /var/docker/data/urbackup-server/clientlist_b_1220.ub
-rwxr-x— 1 urbackup urbackup 40284073 1 déc. 2016 /var/docker/data/urbackup-server/clientlist_b_254.ub
-rwxr-x— 1 urbackup urbackup 63211638 8 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_50.ub
-rwxr-x— 1 urbackup urbackup 10459777 8 nov. 2016 /var/docker/data/urbackup-server/clientlist_b_51.ub

drwxr-x— 69 urbackup urbackup 6144 19 juin 13:06 client01
drwxr-x— 2 urbackup urbackup 6144 19 juin 16:29 clients
drwxr-x— 66 urbackup urbackup 6144 19 juin 16:07 client02
drwxr-x— 69 urbackup urbackup 6144 19 juin 16:29 client03
drwxr-x— 2 urbackup urbackup 6144 19 juin 01:11 urbackup
drwxr-x— 2 urbackup urbackup 6144 19 juin 16:31 urbackup_tmp_files
drwxr-x— 37 urbackup urbackup 6144 19 juin 17:18 client04
drwx------ 11 urbackup urbackup 6144 19 juin 16:26 ‘client04[mysql]’
drwxr-x— 65 urbackup urbackup 6144 19 juin 10:37 client05
drwx------ 8 urbackup urbackup 6144 19 juin 00:05 ‘client05[mysql]’