#1064499 using lftp backend, backup fails with error message: mkdir: Access failed: 550 $dirname: File exists

Package:
duplicity
Source:
duplicity
Description:
encrypted bandwidth-efficient backup
Submitter:
Giuseppe Sacco
Date:
2024-02-24 08:15:05 UTC
Severity:
normal
#1064499#5
Date:
2024-02-23 09:13:15 UTC
From:
To:
Hello,
I had a backup configured and running since a few months. It is failing since
12 February with this error:
backupftp/backup-mantide/; put /srv/nfs/misc/tmp/duplicity-rf7ep785-
tempdir/mktemp-2uh27izg-4 -o backupftp/backup-mantide/duplicity-
full.20240223T070031Z.vol2.difftar.gpg"': returned 1, with output:

mkdir: Access failed: 550 backupftp/backup-mantide: File exists.
(backupftp/backup-mantide/)
put: /srv/nfs/misc/tmp/duplicity-rf7ep785-tempdir/mktemp-2uh27izg-4: Fatal
error: max-retries exceeded


The URL I am using is: ftp://user:password@host/backupftp/backup-mantide'

It seems that duplicity issues the mkdir command before copying any file, but
now this mkdir command is failing since the directory already exists. The
source might be a change in lftp command (lftp version is 4.9.2-2+b1).
This would be strange since lftp package hasn't changed since July 2022.

Thank you,
Giuseppe

#1064499#10
Date:
2024-02-23 14:56:15 UTC
From:
To:
Well,
it seems that message was a red herring.
Enabling more verbose logging, this is what is shown in the ltfp transmission:
---- Resolving host address... ---- IPv6 is not supported or configured ---- 1 address found: $NASIP ---- Connecting to nas ($NASIP) port 21 <--- 220 NAS FTP server ready. ---> FEAT <--- 211- Extensions supported: <--- AUTH TLS <--- PBSZ <--- PROT <--- CCC <--- SIZE <--- MDTM <--- REST STREAM <--- MFMT <--- TVFS <--- MLST <--- MLSD <--- 211 End. ---> USER $username <--- 331 Password required for mantide. ---> PASS $password <--- 230 User $username logged in. ---> PWD <--- 257 "/" is current directory. ---> MKD backupftp <--- 550 backupftp: Permission denied. ---> MKD backupftp/backup-mantide <--- 550 backupftp/backup-mantide: File exists. ---> MKD backupftp/backup-mantide/ <--- 550 backupftp/backup-mantide: File exists. mkdir: Access failed: 550 backupftp/backup-mantide: File exists. (backupftp/backup-mantide/) ---> TYPE I <--- 200 Type set to I. ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,122) ---- Connecting data socket to ($NASIP) port 55674 ---- Data connection established ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 349027744, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,21) ---- Connecting data socket to ($NASIP) port 55573 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346445592, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,47) ---- Connecting data socket to ($NASIP) port 55599 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346455728, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,13) ---- Connecting data socket to ($NASIP) port 55565 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346445592, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,163) ---- Connecting data socket to ($NASIP) port 55715 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346444144, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,216,246) ---- Connecting data socket to ($NASIP) port 55542 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346435456, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly ---> PASV <--- 227 Entering Passive Mode ($NASIP,217,144) ---- Connecting data socket to ($NASIP) port 55696 ---- Data connection established ---> REST 346300416 <--- 350 Restarting at 346300416. Send STORE or RETRIEVE to initiate transfer. ---> STOR backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 150 Opening BINARY mode data connection for 'backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg'. <--- 452 Error writing to file: No such file or directory. ---- Closing data socket ---> SIZE backupftp/backup-mantide/duplicity-full.20240223T070031Z.vol2.difftar.gpg <--- 213 346300416 copy: put rolled back to 346557840, seeking get accordingly copy: put rolled back to 346300416, seeking get accordingly put: /srv/nfs/misc/tmp/duplicity-asuietia-tempdir/mktemp-w5h4s33d-4: Fatal error: max-retries exceeded ---> QUIT <--- 221 Goodbye. You uploaded 0 bytes and downloaded 0 bytes. ---- Closing control socket From what I understand, here duplicity is trying to continue an interrupted (previous) backup where the second volume was only partially transferred. It connect to the NAS, it finds the file, it get the file size, it tries to resume the transfer from that offset. The error that comes from the NAS, when trying to resume the transfer, is "452 Error writing to file: No such file or directory." I believe this is the correct error message that should emerge in the log when not using the VERBOSITY=9 I just used now. BTW, I removed that second volume and run the full backup again. It is now still going on, but the problem seems solved. Bye, Giuseppe
#1064499#15
Date:
2024-02-24 08:04:42 UTC
From:
To:
On Fri, 23 Feb 2024 15:56:15 +0100, Giuseppe Sacco writes:

i'm sorry, but this does not look like a bug in duplicity: your ftp server claims
that the file does not exist, then that it does exist and that it has a nonzero size...
and then that it doesn't exist.

there is clearly something wrong but going from the logs you sent, the problem is not in
duplicity.

regards
az