System.IO.IOException: Lock violation

skoch · December 15, 2017, 6:11am

Hi, I’m just starting with duplicati as replacement for crashplan.

After some days now I always get this error message: System.IO.IOException: Lock violation on path /media/nas/duplicati/home/duplicati-b578616b04365430ba03c7e51795c01e9.dblock.zip.aes.

After each run this is in the log. How do I have to handle with the error?

My system: Ubuntu 17.10

Complete message:

Fatal error
System.IO.IOException: Lock violation on path /media/nas/duplicati/home/duplicati-b578616b04365430ba03c7e51795c01e9.dblock.zip.aes
  at Duplicati.Library.Main.BackendManager.Delete (System.String remotename, System.Int64 size, System.Boolean synchronous) [0x0004b] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.RemoteListAnalysis (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x004a8] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x00000] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify (Duplicati.Library.Main.BackendManager backend, System.String protectedfile) [0x00066] in <118ad25945a24a3991f7b65e7a45ea1e>:0

JonMikelV · December 16, 2017, 3:10pm

Hello, and welcome to the forum @skoch!

I haven’t run into that error before so, yay! I get to learn something new!

I have a few questions to hopefully narrow down what’s going on. They don’t all need to be answered, but the more you can respond to the easier it will hopefully be to figure out what’s up:

Is it always the same file in the error? (In guessing it is.)
Did the job work for a while then start with this message? (I’m guessing yes.)
What version of Duplicati are you running and is it running as a service or the tray icon?
Is /media/nas being processed by anything else (rsync, antivirus, Syncthing, etc.)?

It sounds like you have a dblock (archive) file needing to be deleted because it’s too small (likely due to version cleanup or tail end of a backup) but something else have the file open.

Depending on why Duplicati is trying to delete the file we can try a few parameters to not do that step and see if that stops the error from happening. (Not as a fix, just a confirmation of the problem).

skoch · December 18, 2017, 6:00am

Thanks for your reply.

It is always the same file, but when I delete this file, it is just another file but the error is the same.
It worked for a while (“Last successful run: Last Thursday at 7:10 AM”)
“You are currently running Duplicati - 2.0.2.1_beta_2017-08-01” and I installed it as a service in ubuntu with “sudo systemctl enable duplicati” because I needed root permission for some folders
No, there is no other process on my /media/nas.

Very strange!

And it get’s even more strange. I disabled the schedule for this job and created a new one working on the same folder (my home folder) but storing into a new backup path and it get’s the same behaviour. How can this be?

This is the log of the new job:

Dec 18, 2017 6:32 AM: Message

Fatal error
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at Duplicati.Library.Main.BackendManager.Delete (System.String remotename, System.Int64 size, System.Boolean synchronous) [0x0004b] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.RemoteListAnalysis (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x004a8] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x00000] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify (Duplicati.Library.Main.BackendManager backend, System.String protectedfile) [0x00066] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Warning

Überwinden eines Fehlers beim Löschen der Datei duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes fehlgeschlagen
System.NullReferenceException: Object reference not set to an instance of an object
  at Duplicati.Library.Main.BackendManager.ThreadRun () [0x0036a] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Message

Löschung der Datei fehlgeschlagen duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes, prüfe ob Datei existiert
Dec 18, 2017 6:32 AM: Retry
Operation Delete with file duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes attempt 5 of 5 failed with message: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at Duplicati.Library.Main.BackendManager.Delete (System.String remotename, System.Int64 size, System.Boolean synchronous) [0x0004b] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.RemoteListAnalysis (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x004a8] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x00000] in <118ad25945a24a3991f7b65e7a45ea1e>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify (Duplicati.Library.Main.BackendManager backend, System.String protectedfile) [0x00066] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Retry

Operation Delete with file duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes attempt 4 of 5 failed with message: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at System.IO.File.Delete (System.String path) [0x00082] in <8f2c484307284b51944a1a13a14c0266>:0 
  at Duplicati.Library.Backend.File.Delete (System.String remotename) [0x00007] in <597a42d267414b2785d434b5a5f9e510>:0 
  at Duplicati.Library.Main.BackendManager.DoDelete (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x0001b] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Retry

Operation Delete with file duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes attempt 3 of 5 failed with message: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at System.IO.File.Delete (System.String path) [0x00082] in <8f2c484307284b51944a1a13a14c0266>:0 
  at Duplicati.Library.Backend.File.Delete (System.String remotename) [0x00007] in <597a42d267414b2785d434b5a5f9e510>:0 
  at Duplicati.Library.Main.BackendManager.DoDelete (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x0001b] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Retry

Operation Delete with file duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes attempt 2 of 5 failed with message: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at System.IO.File.Delete (System.String path) [0x00082] in <8f2c484307284b51944a1a13a14c0266>:0 
  at Duplicati.Library.Backend.File.Delete (System.String remotename) [0x00007] in <597a42d267414b2785d434b5a5f9e510>:0 
  at Duplicati.Library.Main.BackendManager.DoDelete (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x0001b] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:32 AM: Retry

Operation Delete with file duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes attempt 1 of 5 failed with message: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
System.IO.IOException: Lock violation on path /media/cns-store/duplicati/skoch/duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes
  at System.IO.File.Delete (System.String path) [0x00082] in <8f2c484307284b51944a1a13a14c0266>:0 
  at Duplicati.Library.Backend.File.Delete (System.String remotename) [0x00007] in <597a42d267414b2785d434b5a5f9e510>:0 
  at Duplicati.Library.Main.BackendManager.DoDelete (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x0001b] in <118ad25945a24a3991f7b65e7a45ea1e>:0

Dec 18, 2017 6:26 AM: Message

removing remote file listed as Deleting: duplicati-bccd1ada17f784554a46321916f22ebb9.dblock.zip.aes

Dec 18, 2017 6:26 AM: Message

keeping protected incomplete remote file listed as Temporary: duplicati-20171216T070727Z.dlist.zip.aes

JonMikelV · December 19, 2017, 6:23am

Hmmm…strange indeed! Something seems to have the file Duplicati wants to delete open (or at least locked) so the question is what and how. I doubt this is the case but theoretically it’s possible Duplicati somehow has it open AND is trying to delete it, @kenkendk might have a better idea on how to figure out what actually has the lock on the archive file.

kenkendk · January 9, 2018, 7:23am

I agree with @JonMikelV’s diagnosis: something is locking the files.

You can try with lsof to see if you can figure out what that “something” is:
https://www.thegeekstuff.com/2012/08/lsof-command-examples/

It could be a number of things, such as a disk snapshot tool, disk maintenance tool, antivirus scanner etc.

skoch · January 9, 2018, 7:39am

I changed it to use WebDav and changed the scheduler to not backup every 15 minutes and now this and some other errors (and warnings) are gone.

Thanks for the support.

JonMikelV · January 10, 2018, 3:18pm

Glad to hear the you managed to take care of those errors!

May I ask what frequency you moved to when shifting away from 15 minutes? I’m just curious in case other users report similar issues.

skoch · January 10, 2018, 5:22pm

I changed to 30 minutes and this error was gone. Also the hash mismatch error was gone after that. Now I increased it to 1 hour to be sure

JonMikelV · January 12, 2018, 11:46pm

Cool, thanks!

I flagged your post as the solution even though it’s unclear whether the WebDAV, timing, or both resolved it - let me know if you disagree.

Oh, and I had a thought on the potential cause. I forgot you were using the 2.0.2.1 beta version which had a process that ran AFTER the “I’m done” message was logged. I haven’t checked the code, but maybe the scheduler decided it was free to start another job even though the previous one was still doing some maintenance work (which might explain why the files were locked).

It’s a pretty weak theory (especially considering the files being reported as locked) but I thought I’d toss it out there in case others run into the issue even with longer frequencies.