Wasabi backup won't complete with 2.0.4.4

#1

Tried to make a new job in Duplicti since upgrading to 2.0.4.4 but it never runs to completion. The reports 'One or more errors occured. In the per job log, it show this:

  • Nov 24, 2018 12:13 PM: put duplicati-b7c07e0105ab0420591005f7192acffd6.dblock.zip.aes

{“Size”:52332669,“Hash”:“royLQcfdlJjZiwhh3QlM2uyFTvX7VZtxTn/fyp3zHcM=”}

  • Nov 24, 2018 12:12 PM: put duplicati-b8b295add586e4852b4185d650ad90309.dblock.zip.aes

{“Size”:52372733,“Hash”:“hqDrTbsh225KbK4RYDqFMUtWiaJrn4ZL4ZyI1fYJN0w=”}

  • Nov 24, 2018 12:11 PM: put duplicati-b0aeaa521a2dc4372a4db09e2cb0d619a.dblock.zip.aes

{“Size”:52372733,“Hash”:“hqDrTbsh225KbK4RYDqFMUtWiaJrn4ZL4ZyI1fYJN0w=”}

  • Nov 24, 2018 12:10 PM: put duplicati-b90343cfcf7254dc6bda5639b995ec0fa.dblock.zip.aes

{“Size”:52372733,“Hash”:“hqDrTbsh225KbK4RYDqFMUtWiaJrn4ZL4ZyI1fYJN0w=”}

  • Nov 24, 2018 12:09 PM: put duplicati-b46f8095f1ef9478b87061b09c33b83f1.dblock.zip.aes

{“Size”:52372733,“Hash”:“hqDrTbsh225KbK4RYDqFMUtWiaJrn4ZL4ZyI1fYJN0w=”}

  • Nov 24, 2018 12:08 PM: put duplicati-b5ddd08f4ec914ca2a2bbfd74d8112785.dblock.zip.aes

{“Size”:52372733,“Hash”:“hqDrTbsh225KbK4RYDqFMUtWiaJrn4ZL4ZyI1fYJN0w=”}

  • Nov 24, 2018 12:08 PM: put duplicati-i642495e8654d48daa51833c95abdc144.dindex.zip.aes

{“Size”:51741,“Hash”:“csKlKhozyrQQTVQThRKq1JXcIP5heGUTaigH0wvrfmg=”}

  • Nov 24, 2018 12:07 PM: put duplicati-be1fbf1d5f9784d3d993f7b602133e0ff.dblock.zip.aes

{“Size”:52425421,“Hash”:“IB+t3TU1YUbgl3uo36UFF+Cir+Up4Yi65HhKCte4IC8=”}

  • Nov 24, 2018 12:07 PM: put duplicati-i1a691d4f7c144d1f8be57196dc3d38c7.dindex.zip.aes

{“Size”:40077,“Hash”:“abgppuwDsZSWl+31v4StXfKnS2RFk+O03FgeKvRMMnc=”}

  • Nov 24, 2018 12:06 PM: put duplicati-bc0480f5d2dd74bab88f732783181d3a4.dblock.zip.aes

{“Size”:52393917,“Hash”:“9lNQ9h9Ksk01LOfiXhqu5hE685c+KL1ZCM0aMDYTdHo=”}

  • Nov 24, 2018 12:06 PM: put duplicati-ia6b368a0cbd94ff1be456c7fcf00d8db.dindex.zip.aes

{“Size”:44221,“Hash”:“O/gdYc6BNR1jDEKPgTpjZHBhIMYPrC+ahl2wz3S/NBA=”}

  • Nov 24, 2018 12:05 PM: put duplicati-bc2df736982824142998ddfcad71499d0.dblock.zip.aes

{“Size”:52372205,“Hash”:“rr4y+7ZLnIetDunUmF3KFNbYmzgBqLn4vI9XuzANX9s=”}

  • Nov 24, 2018 12:04 PM: put duplicati-b36d7f3886a644d1e977986663c31b750.dblock.zip.aes

{“Size”:52372205,“Hash”:“rr4y+7ZLnIetDunUmF3KFNbYmzgBqLn4vI9XuzANX9s=”}

  • Nov 24, 2018 12:03 PM: put duplicati-b38478295f51d4d2dbdd4665d07b05e77.dblock.zip.aes

{“Size”:52372205,“Hash”:“rr4y+7ZLnIetDunUmF3KFNbYmzgBqLn4vI9XuzANX9s=”}

  • Nov 24, 2018 12:02 PM: put duplicati-b30072f3daf1444b6959424b0f1fe5f6b.dblock.zip.aes

{“Size”:52372205,“Hash”:“rr4y+7ZLnIetDunUmF3KFNbYmzgBqLn4vI9XuzANX9s=”}

  • Nov 24, 2018 12:01 PM: put duplicati-b266c35417cec4a76a05435003029136c.dblock.zip.aes

{“Size”:52372205,“Hash”:“rr4y+7ZLnIetDunUmF3KFNbYmzgBqLn4vI9XuzANX9s=”}

  • Nov 24, 2018 12:01 PM: put duplicati-i82504d667ee04e569e7b91f2de1aa53c.dindex.zip.aes

{“Size”:57357,“Hash”:“A2RwkbQ5rKEELLEBuzl/dSgxCRd+WtOIiTZHjFZ8KQA=”}

  • Nov 24, 2018 12:00 PM: put duplicati-b548ecea7d3a747b7a3e4d44565fba548.dblock.zip.aes

{“Size”:52383965,“Hash”:“mViOyh6d+osCkqG8bRPreQLgHocoD732US9KQrRrbmw=”}

  • Nov 24, 2018 12:00 PM: put duplicati-i2a8f977419f14b9e87f60e264272d4e3.dindex.zip.aes

{“Size”:18397,“Hash”:“Pz6UrISfYsIdSMCGwWtH4lKV+mltGfRtuKNsID4OHaA=”}

  • Nov 24, 2018 11:59 AM: put duplicati-bfee8825564d1414f92d92c077ae3b1eb.dblock.zip.aes

{“Size”:52418413,“Hash”:“4nAWhKvo7ArWnZaBCoQ3PKx+2IA9e48prr6zb2B4W10=”}

  • Nov 24, 2018 11:59 AM: put duplicati-ib82c4d77bf1d40fb9200fc6408645355.dindex.zip.aes

{“Size”:40797,“Hash”:“M4Rvg+zpnqSnFwFfOi5Vp/aEEXCJN8NGllBLsQIPQwQ=”}

  • Nov 24, 2018 11:58 AM: put duplicati-b9ddfdfb801e14c5c891a71483a6e8113.dblock.zip.aes

{“Size”:52401197,“Hash”:“Jc7r8W2sF6By9DThuX9LrdCrUqUK0irV0w1L92Mc5uk=”}

  • Nov 24, 2018 11:58 AM: put duplicati-i7afa28bae5624e8e9af7ca71575ca125.dindex.zip.aes

{“Size”:32941,“Hash”:“EB17eyNYasq3BuntMC+96wdld96+fm0ssK+taszwuz0=”}

  • Nov 24, 2018 11:57 AM: put duplicati-b360cdd4ed53d4d06a1160585636ae42c.dblock.zip.aes

{“Size”:52367373,“Hash”:“LoRnIKNDeWu0+Lq6P6KIsDk5vC0v9LzPEccZl9ufdoU=”}

  • Nov 24, 2018 11:57 AM: put duplicati-i811970de7a3a40de81d2efd5cb2d9e95.dindex.zip.aes

{“Size”:76989,“Hash”:“JRsWC72w8zi24WyOSiJk8zCoiQgk3iha0N656uvhjFI=”}

  • Nov 24, 2018 11:56 AM: put duplicati-bdb67ae8120d04b51be8858a9540dfc00.dblock.zip.aes

{“Size”:52392109,“Hash”:“goxNOc05Pl35wpafzwk0/MU01k0F/lpsjk0J2I6lMUs=”}

  • Nov 24, 2018 11:56 AM: put duplicati-i3332baed88c1449a977611169a655a85.dindex.zip.aes

{“Size”:225821,“Hash”:“nQLVDdZ/dpLY1inrH+UOsC5SAE9xz5tQmArMz8lGMtk=”}

  • Nov 24, 2018 11:55 AM: put duplicati-bd335fdf1b14049589c6d63a63834cb17.dblock.zip.aes

{“Size”:52394525,“Hash”:“iHwdlmJQEvpp5rt8oDAmOU4hR6UcJmeiCegyvhHNXk0=”}

Those seem to be just information messages.

The error posted below is from the duplicati.log file.

—> (Inner Exception #0) Amazon.Runtime.AmazonClientException: Expected hash not equal to calculated hash
at Amazon.S3.Internal.AmazonS3ResponseHandler.CompareHashes (System.String etag, System.Byte hash) <0x41e77ee0 + 0x00127> in :0
at Amazon.S3.Internal.AmazonS3ResponseHandler.ProcessResponseHandlers (IExecutionContext executionContext) <0x41d2b7b0 + 0x0070b> in :0
at Amazon.S3.Internal.AmazonS3ResponseHandler.PostInvoke (IExecutionContext executionContext) <0x41d2b780 + 0x00013> in :0
at Amazon.S3.Internal.AmazonS3ResponseHandler.InvokeSync (IExecutionContext executionContext) <0x41d1a1f0 + 0x00026> in :0
at Amazon.Runtime.Internal.PipelineHandler.InvokeSync (IExecutionContext executionContext) <0x41d09340 + 0x00034> in :0
at Amazon.Runtime.Internal.ErrorHandler.InvokeSync (IExecutionContext executionContext) <0x41d1a100 + 0x00027> in :0
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f408af866d0 + 0x00029> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f408af846b0 + 0x000a7> in :0
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f408af84630 + 0x0006b> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f408af845e0 + 0x0003a> in :0
at System.Runtime.CompilerServices.ConfiguredTaskAwaitable1+ConfiguredTaskAwaiter[TResult].GetResult () <0x7f408b25fbb0 + 0x00012> 24776 in <filename unknown>:0 at Duplicati.Library.Main.Operation.Common.BackendHandler+<>c__DisplayClass13_0+<<UploadFileAsync>b__2>d.MoveNext () <0x41e60940 + 0x00790> in <filename unknown>:0 --- End of stack trace from previous location where exception was thrown --- at Duplicati.Library.Main.Operation.Common.BackendHandler+<DoWithRetry>d__211[T].MoveNext () <0x41e5ea70 + 0x01957> in :0
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f408af866d0 + 0x00029> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f408af846b0 + 0x000a7> in :0
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f408af84630 + 0x0006b> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f408af845e0 + 0x0003a> in :0
at System.Runtime.CompilerServices.ConfiguredTaskAwaitable1+ConfiguredTaskAwaiter[TResult].GetResult () <0x7f408b25fbb0 + 0x00012> 24776 in <filename unknown>:0 at Duplicati.Library.Main.Operation.Common.BackendHandler+<>c__DisplayClass13_0+<<UploadFileAsync>b__1>d.MoveNext () <0x41e59160 + 0x00472> in <filename unknown>:0 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f408af866d0 + 0x00029> in <filename unknown>:0 at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f408af846b0 + 0x000a7> in <filename unknown>:0 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f408af84630 + 0x0006b> in <filename unknown>:0 at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f408af845e0 + 0x0003a> in <filename unknown>:0 at System.Runtime.CompilerServices.ConfiguredTaskAwaitable1+ConfiguredTaskAwaiter[TResult].GetResult () <0x7f408b25fbb0 + 0x00012> 24776 in :0
at Duplicati.Library.Main.Operation.Common.BackendHandler+d__13.MoveNext () <0x41e57930 + 0x008ab> in :0
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f408af866d0 + 0x00029> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f408af846b0 + 0x000a7> in :0
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f408af84630 + 0x0006b> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f408af845e0 + 0x0003a> in :0
at System.Runtime.CompilerServices.TaskAwaiter.GetResult () <0x7f408af845c0 + 0x00012> in :0
at Duplicati.Library.Main.Operation.Backup.BackendUploader+<>c__DisplayClass0_0+<b__0>d.MoveNext () <0x41dcf170 + 0x01c74> in :0
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () <0x7f408af866d0 + 0x00029> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) <0x7f408af846b0 + 0x000a7> in :0
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) <0x7f408af84630 + 0x0006b> in :0
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) <0x7f408af845e0 + 0x0003a> in :0
at System.Runtime.CompilerServices.TaskAwaiter.GetResult () <0x7f408af845c0 + 0x00012> in :0
at CoCoL.AutomationExtensions+d__10`1[T].MoveNext () <0x41b93360 + 0x00231> in :0 <—

This is just when I try to upload my owncloud data. My other existing jobs seem to be fine.

Environment:
Ubuntu 16.04
Duplicati version: duplicati_2.0.4.4-1_all.deb
Backend: Wasabi (S3 Compatitlble)

0 Likes

Backups suddenly failing - 4 machines now
#2

If I look at my remote storage, all I have is dblock.zip.aes and dindex.zip.aes files. I do not see any dlist.zip.aes files.

0 Likes

#3

Found some more logs that give us some work info:

  • Nov 24, 2018 4:14 PM: The operation Backup has failed with error: One or more errors occurred.

  • Nov 24, 2018 4:14 PM: Fatal error

  • Nov 24, 2018 4:14 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/03/20170309_212600.jpg

  • Nov 24, 2018 4:14 PM: Adding directory /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/03/

  • Nov 24, 2018 4:14 PM: Failed to process entry, path: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170529_180648.jpg

  • Nov 24, 2018 4:14 PM: Failed to process entry, path: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170529_180642.jpg

  • Nov 24, 2018 4:14 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170529_180648.jpg

  • Nov 24, 2018 4:14 PM: Failed to process entry, path: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162205.jpg

  • Nov 24, 2018 4:14 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170529_180642.jpg

  • Nov 24, 2018 4:14 PM: Failed to process entry, path: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162158.jpg

  • Nov 24, 2018 4:14 PM: Backend event: Put - Started: duplicati-b062f33fba3a84db9a82a8ca2b965c631.dblock.zip.aes (49.91 MB)

  • Nov 24, 2018 4:14 PM: Backend event: Put - Retrying: duplicati-b17765dfa541d4c959ebda362a36cde57.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:14 PM: Operation Put with file duplicati-b17765dfa541d4c959ebda362a36cde57.dblock.zip.aes attempt 5 of 5 failed with message: Expected hash not equal to calculated hash

  • Nov 24, 2018 4:13 PM: Backend event: Put - Started: duplicati-b17765dfa541d4c959ebda362a36cde57.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:13 PM: Renaming “duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes” to “duplicati-b17765dfa541d4c959ebda362a36cde57.dblock.zip.aes”

  • Nov 24, 2018 4:13 PM: Backend event: Put - Rename: duplicati-b17765dfa541d4c959ebda362a36cde57.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:13 PM: Backend event: Put - Rename: duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:13 PM: Backend event: Put - Retrying: duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:13 PM: Operation Put with file duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes attempt 4 of 5 failed with message: Expected hash not equal to calculated hash

  • Nov 24, 2018 4:12 PM: Backend event: Put - Started: duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:12 PM: Renaming “duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes” to “duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes”

  • Nov 24, 2018 4:12 PM: Backend event: Put - Rename: duplicati-b57dd4ae0972244e49e72dd2d4a5398b3.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:12 PM: Backend event: Put - Rename: duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:12 PM: Backend event: Put - Retrying: duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:12 PM: Operation Put with file duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes attempt 3 of 5 failed with message: Expected hash not equal to calculated hash

  • Nov 24, 2018 4:11 PM: Backend event: Put - Started: duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:11 PM: Renaming “duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes” to “duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes”

  • Nov 24, 2018 4:11 PM: Backend event: Put - Rename: duplicati-bf35d80ea7bd94930b7a46389b4f7486d.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:11 PM: Backend event: Put - Rename: duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:11 PM: Backend event: Put - Retrying: duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:11 PM: Operation Put with file duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes attempt 2 of 5 failed with message: Expected hash not equal to calculated hash

  • Nov 24, 2018 4:10 PM: Backend event: Put - Started: duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:10 PM: Renaming “duplicati-b5c336d93a2c349338a37f45dd4af880b.dblock.zip.aes” to “duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes”

  • Nov 24, 2018 4:10 PM: Backend event: Put - Rename: duplicati-b775cd354b5f04d16bd06a0f3bb1220a7.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:10 PM: Backend event: Put - Rename: duplicati-b5c336d93a2c349338a37f45dd4af880b.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:10 PM: Backend event: Put - Retrying: duplicati-b5c336d93a2c349338a37f45dd4af880b.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:10 PM: Operation Put with file duplicati-b5c336d93a2c349338a37f45dd4af880b.dblock.zip.aes attempt 1 of 5 failed with message: Expected hash not equal to calculated hash

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162205.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162146.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 8:22:58 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162141.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162158.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162143.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 8:22:42 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112617.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162146.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162141.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 8:22:13 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112521.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162143.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112617.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 7:12:31 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_162141.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112521.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 7:12:43 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455 (2).jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112617.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 7:12:48 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110256.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112521.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455 (2).jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 3:24:55 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110247.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110256.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 3:02:56 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_102038.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_112455 (2).jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110247.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 3:02:47 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704.jpg

  • Nov 24, 2018 4:09 PM: Backend event: Put - Started: duplicati-b5c336d93a2c349338a37f45dd4af880b.dblock.zip.aes (49.95 MB)

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110256.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_102038.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/19/2017 2:20:38 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704(0).jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_110247.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:28:27 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102700.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170519_102038.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704(0).jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:28:43 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102544.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102700.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:28:15 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102543.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102704(0).jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102544.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:27:42 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102542.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102700.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102543.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:27:29 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102541.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102544.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102542.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:26:51 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102529.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102543.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102541.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:26:31 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120929.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102542.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102529.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/13/2017 2:25:58 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120919.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102541.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120929.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/8/2017 10:11:10 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/06/20170617_164641.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170513_102529.jpg

  • Nov 24, 2018 4:09 PM: Checking file for changes /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120919.jpg, new: True, timestamp changed: True, size changed: True, metadatachanged: True, 5/8/2017 10:11:22 PM vs 1/1/0001 12:00:00 AM

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120929.jpg

  • Nov 24, 2018 4:09 PM: New file /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/06/20170617_164634.jpg

  • Nov 24, 2018 4:09 PM: Including path as no filters matched: /var/lib/owncloud/data/c2d317e2-2918-1029-9113-d163831ef77c/files/photos/camera/2017/05/20170508_120919.jpg

0 Likes

#4

Okay it looks like it may be associated with the dblock file renames. Once it renames the file, the checksums fail.

0 Likes

#5

Was an earlier version doing this OK? If so, what version? If you’re updating with the Duplicati updater, see Downgrading / reverting to a lower version for information on where updates might be kept on your system.

updated AWSSDK to newest version #3472 worries me a bit, but I think this was first introduced in 2.0.3.24.

error “Expected hash not equal to calculated hash” when backing up to Wasabi #2641 is an older report of this sort of error message on Wasabi, which is also your destination. Seeing ownCloud made me think that was your destination (ownCloud is just source data). Unfortunately I don’t have your environment available.

0 Likes

Backups suddenly failing - 4 machines now
#6

I have jobs that were created on 2.0.3.13. Those seem to running fine on 2.0.3.13 and 2.0.4.4 with the same Wasabi backend and bucket.

It is just a new job that is created with an initial upload. The initial job upload keeps failing.

0 Likes

#7

I’m not very familiar with how this works, but I think the renames are part of recovery from a failed transfer, which makes some sense if one wants a clean retry instead of worrying about who-knows-what-got-written.

–debug-retry-errors might show you error messages produced each time, instead of only after retries end. You can also get a slightly better log with the –log-file option. For example, it will show times to the second. Knowing the error forcing a retry may help. Here’s a B2 example. You might need –log-file-log-level=Retry:

2018-11-17 08:05:55 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b26c17dafffe84613ac6d791ea6d598a5.dblock.zip.aes attempt 1 of 5 failed with message: Unable to read data from the transport connection: The connection was closed.
System.IO.IOException: Unable to read data from the transport connection: The connection was closed.
   at System.Net.ConnectStream.IOError(Exception exception, Boolean willThrow)
   at System.Net.ConnectStream.InternalWrite(Boolean async, Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
   at System.Net.ConnectStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at Duplicati.Library.Utility.Utility.CopyStream(Stream source, Stream target, Boolean tryRewindSource, Byte[] buf)
   at Duplicati.Library.Backend.Backblaze.B2.<>c__DisplayClass24_0.<Put>b__1(AsyncHttpRequest req)
   at Duplicati.Library.JSONWebHelper.GetJSONData[T](String url, Action`1 setup, Action`1 setupbodyreq)
   at Duplicati.Library.Backend.Backblaze.B2.Put(String remotename, Stream stream)
   at Duplicati.Library.Main.Operation.Common.BackendHandler.<DoPut>d__23.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Common.BackendHandler.<>c__DisplayClass13_0.<<UploadFileAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Common.BackendHandler.<DoWithRetry>d__21`1.MoveNext()

Because you’re on Wasabi, I’d note that there might have been some odd technical issues starting Nov. 23 however it’s not clear whether it could have caused what you’re seeing, but maybe your issue will go away.

0 Likes

Backups suddenly failing - 4 machines now
#8

I found where the symptom is coming from. The backup works find if I disable ‘Use SSL’ for the wasabi backend, in the job.

0 Likes

#9

Isn’t disabling SSL a bad idea? Sorry if that sounds like a noob question, but I’m suffering similar issues with Wasabi as well. It does seem that something happened at Wasabi last week to break the backups to them.

0 Likes

#10

Yes and no. If your data is client-side encrypted as best practices says it should be, there isn’t much risk of data theft. However you are still subject to man in the middle attacks because there is no host identification and verification that SSL/TLS provides.

0 Likes

#11

And api key credentials leakage (possibly) if the initial connection info is intercepted.

0 Likes

#12

Any time a destination file needs to be “replaced” (compact, purge, retention-policy, etc.) Duplicati will upload a newly named file and, if successful, THEN delete the old file. So no actual “file rename” takes place.

For files that have a timestamp in their name (dlist files), the new name is usually the old one with 1 second added to the timestamp portion. In theory it’s EVENTUALLY possible for a file to be updated so often it’s timestamp collides with an already existing file, but even if you’r doing backups every 10 minutes you’d need 600 “updates” to a single dlist file before that collision would happen. :slight_smile:

0 Likes

#13

@JonMikelV This issue was happening during the initial upload with the web GUI. So there was only one job running and there were no existing files to collide outside the inital job upload. Also, this issue only exists when ‘Use SSL’ option is enabled. So this sounds like a fringe case issue.

0 Likes

#14

Thanks for the clarification (reminder?) that the initial backup hadn’t completed yet.

0 Likes

#15

The initial upload did complete once I recreated the job with ‘Use SSL’ disabled with an empty remote storage bucket/path.

0 Likes

#16

Once the job gets into that state, no amount of deleting or repairing the database seems to help.

0 Likes