Duplicati temp dup-xxxx files not being deleted

bug

#14

Any updates on this problem yet. downgrading is not a option, and having to manually remove files from the temp dir is unreliable as if it fills up can and will crash and bring down the system.

Thanks
Myk


#15

I believe a new version is “close” but I don’t know exactly it will include and whether it will canary, experimental, or beta.


#16

I am running on unRAID via a docker and it works well, there is a update, but it will downgrade to the beta version and then because db is v5 with canary, beta will not connect because its v4 :frowning:


#17

Release: 2.0.3.7 (canary) 2018-06-17

still leaving temp files behind


#18

Yes, I can confirm that the temp files are still being left behind in 2.0.3.7. Backup speeds to Google Drive appears to be fixed. However, that also means the Temp folder fills up a LOT faster now !

I upgraded over the 2.0.3.6 installation and now in addition to the temp file issue, the backup will no longer run if I set snapshot-policy to require. Logs says Duplicati cannot access the drives (eg. E:\ and F:) which are selected for backups. Removing snapshot policy allows the backup to run but then obviously no VSS.


#19

@kenkendk or @Pectojin, do you know if this has been looked into at all yet?

@PhoenixAlpha, I have broken your VSS issue out into it’s own topic (hope you don’t mind).


#20

This issue had slipped off my list. Looking at it now.


#21

Fixed:

It was the files prior to encryption that were not correctly removed.


Very slow to backup
#22

Version 2.0.3.8 canary has been release which includes the fix mentioned above.

If you currently have this issue and are interested in testing, please update to 2.0.3.8 and let us know if it solves the problem. Thanks!

Note that I believe this fix will correctly clean up temp files moving forward, I don’t think it will clean up old ones…


TMP folder grown to 76GB
#23

Hello,

Because my system cannot use the precompiled assemblies, I’m using a self compiled version of Duplicati from vanillas 2.0.3.6 sources.
I had the same issue where the /tmp folder would get filled up, and so I applied that patch to my sources.
I can say that this fixes the issue nicely, the temp files are now cleared properly.


#24


Not fixed for me :frowning:
Temp folder full of temp files and consuming large portion of that drive.
There should be some cleaning routing at end of job.
Running 2.0.3.10_canary_2018-08-30


#25

For those affected, add after backup batch file with this content:
del %tmp%\dup-???-???-???-???-???

It cleans leftovers.


#26

Not fixed for me on 2.0.3.11_canary_2018-09-05 on Windows 10, although possibly it’s better now (can’t say).
Here, the leftovers from the daily backup (based on timestamp of leftover tmp files) have only appeared today which happens to be when Duplicati decided to compact. Maybe backup is fixed, but compact still has issues?

Job log has FilesUploaded: 7

Server log backend events:

2018-09-19 13:01:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bfbacccc9339e41b6b9cb2e7e5dea56a3.dblock.zip.aes (1.38 MB)
2018-09-19 13:01:11 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i898454fc9fbc4bb0b717416f841c44a8.dindex.zip.aes (3.45 KB)
2018-09-19 13:01:11 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20180919T170000Z.dlist.zip.aes (31.65 KB)
2018-09-19 13:03:01 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bae59c06d1c28406182de0ca9070a22ba.dblock.zip.aes (50.04 MB)
2018-09-19 13:03:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i0c586925541a4f4d804f8d74f1fd0083.dindex.zip.aes (51.28 KB)
2018-09-19 13:03:52 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b429246f467134958a7d89ea2caafce11.dblock.zip.aes (14.92 MB)
2018-09-19 13:03:53 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i3e51ef5336d34671834d19ffe6be6e81.dindex.zip.aes (10.47 KB)

2018-09-19 13:03:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-bfbacccc9339e41b6b9cb2e7e5dea56a3.dblock.zip.aes (1.38 MB)
2018-09-19 13:03:57 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i898454fc9fbc4bb0b717416f841c44a8.dindex.zip.aes (3.45 KB)
2018-09-19 13:03:57 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-bfbacccc9339e41b6b9cb2e7e5dea56a3.dblock.zip.aes (1.38 MB)
2018-09-19 13:04:01 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20180919T170000Z.dlist.zip.aes (31.65 KB)

Bucket listing confirming:

duplicati-20180919T170000Z.dlist.zip.aes 32.4 KB 09/19/2018 13:01
duplicati-bae59c06d1c28406182de0ca9070a22ba.dblock.zip.aes 52.5 MB 09/19/2018 13:01
duplicati-i0c586925541a4f4d804f8d74f1fd0083.dindex.zip.aes 52.5 KB 09/19/2018 13:03
duplicati-b429246f467134958a7d89ea2caafce11.dblock.zip.aes 15.6 MB 09/19/2018 13:03
duplicati-i3e51ef5336d34671834d19ffe6be6e81.dindex.zip.aes 10.7 KB 09/19/2018 13:03

C:\Windows\Temp leftovers:

09/19/2018  01:01 PM        52,472,021 dup-3c7c2f2a-95fc-43de-b6db-8cb83f339b33
09/19/2018  01:01 PM            52,201 dup-70f899d8-79af-4221-b85c-6c722650436c
09/19/2018  01:03 PM        15,641,138 dup-95504a79-97be-49b7-a02a-4f1321ecdc3c
09/19/2018  01:03 PM            10,405 dup-5d004d59-a2ad-4b70-99f5-fb2eed477a8f

Selected time information:

2018-09-19 13:01:12 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 21 small volumes and the maximum is 20
2018-09-19 13:03:56 -04 - [Information-Duplicati.Library.Main.Operation.CompactHandler-CompactResults]: Downloaded 22 file(s) with a total size of 89.78 MB, deleted 44 file(s) with a total size of 89.91 MB, and compacted to 4 file(s) with a size of 65.00 MB, which reduced storage by 40 file(s) and 24.91 MB

2018-09-19 13:01:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-PreBackupVerify]: PreBackupVerify took 0:00:00:02.416
2018-09-19 13:01:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: BackupMainOperation took 0:00:00:01.081
2018-09-19 13:01:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: VerifyConsistency took 0:00:00:00.119
2018-09-19 13:01:05 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.Backup.UploadRealFilelist-UpdateChangeStatistics]: UpdateChangeStatistics took 0:00:00:00.010
2018-09-19 13:01:07 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.Backup.UploadRealFilelist-UploadNewFileset]: Uploading a new fileset took 0:00:00:01.911
2018-09-19 13:03:57 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-CommitFinalizingBackup]: CommitFinalizingBackup took 0:00:00:00.200
2018-09-19 13:04:00 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-AfterBackupVerify]: AfterBackupVerify took 0:00:00:02.523
2018-09-19 13:04:18 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:04:17.683

Getting a bit rougher, here are earlier compact times. They mostly line up with the sorted leftovers list.

2018-09-15 18:47:01 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 1 fully deletable volume(s)
2018-09-16 08:21:57 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 8 fully deletable volume(s)

09/15/2018  06:44 PM               339 dup-edf67c5c-2d98-462f-bcf1-5bd7a6e159e6
09/15/2018  06:45 PM               339 dup-48789543-07c2-4181-9d41-096a8f88a02a
09/15/2018  06:47 PM               339 dup-27a0fe3c-542f-4585-8b1f-ecb9f3d4681d
09/15/2018  06:48 PM               245 dup-056642d1-b23b-4ee7-bd24-c720af4a6d4d
09/15/2018  07:25 PM               157 dup-ab61e2be-841a-48a3-ba5c-394a1697d81a
09/16/2018  08:24 AM               245 dup-d44a04a1-5e9a-49b1-ac5f-8a0f64396d24
09/16/2018  08:24 AM               157 dup-7b10399a-a909-44c5-824b-7e02195fce96
09/16/2018  08:36 AM               245 dup-cd89f06b-b4b7-4739-bb10-29e14dbc2b88
09/16/2018  08:36 AM               157 dup-dc4d1ba2-3183-43c7-9b66-f7a704f85273

#27

I’ll see if I can remember to test a 2.0.3.11 ok Windows compact with before/after temp file count checks.


#28

2.0.3.11_canary_2018-09-05 is probably fixed on Linux. I’m not using /tmp/ but alternate path, which only used by Duplicati. I’ve got dup-* files in the path for several months, but not any recent files since I’ve upgraded the version.


#29

For me it seems to be still an issue on 2.0.3.11 under linux.


#30

@ts678’s left over files on Windows seem to have been generated as part of the compact process (at least based on timestamps).

Can you tell if your temp file times align with the compacting step in your logs?

It’s possible there were multiple temp cleanup bugs and only the main one was addressed…


#31

here is my log

2018-09-30 01:21:03 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: 
2018-09-30 01:21:03 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 27/09/2018 01:16:00
2018-09-30 01:21:03 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...
2018-09-30 01:21:17 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20180926T231600Z.dlist.zip.aes (8.15 MB)
2018-09-30 01:21:19 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20180926T231600Z.dlist.zip.aes (8.15 MB)
2018-09-30 01:21:19 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 1 remote fileset(s)
2018-09-30 01:21:43 +02 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required
2018-09-30 01:21:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2018-09-30 01:21:45 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (3.93 KB)
2018-09-30 01:21:47 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180921T205023Z.dlist.zip.aes (8.05 MB)
2018-09-30 01:21:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20180921T205023Z.dlist.zip.aes (8.05 MB)
2018-09-30 01:21:49 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i691d7e93598240c287d4b34b48faa12f.dindex.zip.aes (13.79 KB)
2018-09-30 01:21:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i691d7e93598240c287d4b34b48faa12f.dindex.zip.aes (13.79 KB)
2018-09-30 01:21:50 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b364e3a8c256c42079543cee574a50d19.dblock.zip.aes (199.91 MB)
2018-09-30 01:22:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b364e3a8c256c42079543cee574a50d19.dblock.zip.aes (199.91 MB)
2018-09-30 01:24:42 +02 - [Information-Duplicati.Library.Modules.Builtin.SendMail-SendMailComplete]: Email sent successfully using server: smtp://gamliel.lan:25/?starttls=never

the dup file time is 01:24:41


#32

Compact process indeed seems not to remove the newly created dblock/dindex files. My /tmp folder has filled up completely (21G) as part of a (big) compact operation.

extract:

251M    /tmp/dup-d78111d1-dacc-4fee-9e79-c9a94cb41391
251M    /tmp/dup-d7b11f65-5f58-49ae-991c-d06d9cf78287
96K     /tmp/dup-d9569068-7135-4023-9906-62d201755013
251M    /tmp/dup-d96b990a-b7bb-4917-8029-030300db7f2e
251M    /tmp/dup-db1918da-a1d4-41ca-ae10-dacf70729d1f
251M    /tmp/dup-dbb2bad1-967c-4db7-a2e0-e3cab150c30e
104K    /tmp/dup-dc995795-531f-4803-b9f4-e5e8204ed46a
251M    /tmp/dup-e01ad7e7-d0c6-451d-8386-9784f4d45159
96K     /tmp/dup-e13f6404-9cb0-4ed4-b80f-da1b94a8d638
296K    /tmp/dup-e2021c0c-5665-492f-a7b9-c70bf44e8a66
251M    /tmp/dup-e23a5481-d76a-41cc-a6f3-7d8547151e3b
96K     /tmp/dup-e2738ed2-3b18-44fc-8a28-73e997c9a5d0
92K     /tmp/dup-e30d9adc-16b7-4c80-8b05-e4bdec5f574c
251M    /tmp/dup-e8ac8898-9be3-426e-bcb4-81a8dafee714
251M    /tmp/dup-ea5e9ec1-582c-4a2b-b7c4-f9e0ea4e7741
251M    /tmp/dup-ea894338-7c54-46d0-8988-569dd0d2bc6e
251M    /tmp/dup-ed20371d-52a6-4a9c-a776-bb9b9f883812
251M    /tmp/dup-f44e78bc-2a9c-4f47-9da3-23f5b3d4bf80
100K    /tmp/dup-f7ea5f33-7687-4e92-b2c8-116204f7232a
251M    /tmp/dup-f8210760-0ef5-4ee7-84e1-739347daf6bd
96K     /tmp/dup-f8dfdac2-b048-423b-936f-92f0df0f3e64
251M    /tmp/dup-fa373cb8-5365-4506-b8b0-da38c29f2ce1
104K    /tmp/dup-fb8258ff-a791-4250-825d-90f29b5d7cc5
104K    /tmp/dup-fd84abc5-dafd-4b76-b5f9-cee44c1aca93
251M    /tmp/dup-fdf43dc5-5296-439b-9a19-1836ee323d8b
100K    /tmp/dup-ff5a7e74-2bcf-4e18-ad97-a2f91c63ffe2

#33

What version were you using and was it native or in Docker container?