understanding the OAuth stuff is in my dreams but not much more at the moment. I can’t give more than token help here.
I’m doing one test run each on releases from 2.0.6.3 onwards. 2.0.6.100 was fine. 2.0.6.101 seems to be ignoring the Retry-After header. Possibly OneDrive wasn’t upset enough on the earlier runs today to complain. This time the profiling log was useful, as console log has no timestamp from Duplicati, and at information level it suppressed the retry details until the final failure after 5, but one can guess at cause.
OneDrive sent out timestamps, so I can go into the profiling log for a closer look at the activity, and find:
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-19 16:01:51 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip (50.00 MB)
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL)
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" ("Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL) took 0:00:00:00.000
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-DBAEC61963D3D146821DB660383DA5D9" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID")
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: CREATE TEMPORARY TABLE "CmpTable-DBAEC61963D3D146821DB660383DA5D9" AS SELECT DISTINCT "Hash" AS "Hash", "Size" AS "Size" FROM (SELECT "Block"."Hash" AS "Hash", "Block"."Size" AS "Size" FROM "Remotevolume", "Block" WHERE "Remotevolume"."Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip" AND "Remotevolume"."ID" = "Block"."VolumeID" UNION SELECT "DeletedBlock"."Hash" AS "Hash", "DeletedBlock"."Size" AS "Size" FROM "DeletedBlock", "RemoteVolume" WHERE "RemoteVolume"."Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip" AND "RemoteVolume"."ID" = "DeletedBlock"."VolumeID") took 0:00:00:00.001
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT 1 AS "Type", "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47"."Hash" AS "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" WHERE "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-DBAEC61963D3D146821DB660383DA5D9" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-DBAEC61963D3D146821DB660383DA5D9" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" E, "CmpTable-DBAEC61963D3D146821DB660383DA5D9" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size"
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT 1 AS "Type", "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47"."Hash" AS "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" WHERE "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47"."Hash" NOT IN ( SELECT "Hash" FROM "CmpTable-DBAEC61963D3D146821DB660383DA5D9" ) UNION SELECT 0 AS "Type", "Hash" AS "Hash" FROM "CmpTable-DBAEC61963D3D146821DB660383DA5D9" WHERE "Hash" NOT IN (SELECT "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47") UNION SELECT 2 AS "Type", "E"."Hash" AS "Hash" FROM "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" E, "CmpTable-DBAEC61963D3D146821DB660383DA5D9" D WHERE "D"."Hash" = "E"."Hash" AND "D"."Size" != "E"."Size" took 0:00:00:00.000
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-DBAEC61963D3D146821DB660383DA5D9"
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "CmpTable-DBAEC61963D3D146821DB660383DA5D9" took 0:00:00:00.000
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47"
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocklist-F9144B0AEE1B4F4B88857ED211EDFC47" took 0:00:00:00.000
2023-08-19 16:01:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip"
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-bb2bb65d983bc47c098f5a8996430d1ec.dblock.zip" took 0:00:00:00.099
2023-08-19 16:01:51 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:00.220
2023-08-19 16:01:51 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip attempt 1 of 5 failed with message: 429: Too Many Requests error from request https://public.dm.files.1drv.com/y4myYFrfXuLYWvNGcsbeA9hiwtt5D4Jx05XjHHXHXgDPVHBlZH_19Uf_yZ_BqfGYNM60YScR3_WMyQ95DnE3LP9UtXGyE690IS9SyYhYNYW7xehvgUFxQQuQZWn7V1bDy1Utg6xnYRpyQZpx4mLEFXMRXpaSfEtBUGTFqZMcwXAYdzPvnTnpP5Q4RUdbp9oNbdmOJ8t5iqfzgKwJEaI_2nB6M1RHrAoz0-eG0t27sqT3gg/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip
Method: GET, RequestUri: 'https://public.dm.files.1drv.com/y4myYFrfXuLYWvNGcsbeA9hiwtt5D4Jx05XjHHXHXgDPVHBlZH_19Uf_yZ_BqfGYNM60YScR3_WMyQ95DnE3LP9UtXGyE690IS9SyYhYNYW7xehvgUFxQQuQZWn7V1bDy1Utg6xnYRpyQZpx4mLEFXMRXpaSfEtBUGTFqZMcwXAYdzPvnTnpP5Q4RUdbp9oNbdmOJ8t5iqfzgKwJEaI_2nB6M1RHrAoz0-eG0t27sqT3gg/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.6.101
Authorization: Bearer ABC...XYZ
}
StatusCode: 429, ReasonPhrase: 'Too Many Requests', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Retry-After: 247
X-MSNSERVER: DS1PPF951CEC80A
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: X2CJz4k9KUiwv2bA9EUxyg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3062.afa1
X-ClientErrorCode: ThrottledRequest
X-ErrorCodeChain: AccessDenied,ThrottledRequest
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: 7698D28EE32345B49E772B1F7E6066C7 Ref B: BL2AA2030108031 Ref C: 2023-08-19T20:01:52Z
Date: Sat, 19 Aug 2023 20:01:52 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 0
}
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: 429: Too Many Requests error from request https://public.dm.files.1drv.com/y4myYFrfXuLYWvNGcsbeA9hiwtt5D4Jx05XjHHXHXgDPVHBlZH_19Uf_yZ_BqfGYNM60YScR3_WMyQ95DnE3LP9UtXGyE690IS9SyYhYNYW7xehvgUFxQQuQZWn7V1bDy1Utg6xnYRpyQZpx4mLEFXMRXpaSfEtBUGTFqZMcwXAYdzPvnTnpP5Q4RUdbp9oNbdmOJ8t5iqfzgKwJEaI_2nB6M1RHrAoz0-eG0t27sqT3gg/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip
Method: GET, RequestUri: 'https://public.dm.files.1drv.com/y4myYFrfXuLYWvNGcsbeA9hiwtt5D4Jx05XjHHXHXgDPVHBlZH_19Uf_yZ_BqfGYNM60YScR3_WMyQ95DnE3LP9UtXGyE690IS9SyYhYNYW7xehvgUFxQQuQZWn7V1bDy1Utg6xnYRpyQZpx4mLEFXMRXpaSfEtBUGTFqZMcwXAYdzPvnTnpP5Q4RUdbp9oNbdmOJ8t5iqfzgKwJEaI_2nB6M1RHrAoz0-eG0t27sqT3gg/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.6.101
Authorization: Bearer ABC...XYZ
}
StatusCode: 429, ReasonPhrase: 'Too Many Requests', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Retry-After: 247
X-MSNSERVER: DS1PPF951CEC80A
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: X2CJz4k9KUiwv2bA9EUxyg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3062.afa1
X-ClientErrorCode: ThrottledRequest
X-ErrorCodeChain: AccessDenied,ThrottledRequest
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: 7698D28EE32345B49E772B1F7E6066C7 Ref B: BL2AA2030108031 Ref C: 2023-08-19T20:01:52Z
Date: Sat, 19 Aug 2023 20:01:52 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 0
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.Get(String remotename, Stream stream)
at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode)
at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)
at Duplicati.Library.Main.BackendManager.ThreadRun()
2023-08-19 16:01:51 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip (50.00 MB)
2023-08-19 16:02:01 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2023-08-19 16:02:01 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip (50.00 MB)
2023-08-19 16:02:02 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:00.606
2023-08-19 16:02:02 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip attempt 2 of 5 failed with message: 429: Too Many Requests error from request https://public.dm.files.1drv.com/y4m0dJ6T36lQMeSciPwO1N-XvzhQzYU_rwMUvzVuYwi734aALbNtub43i57LzaDj-IVYR16Ec4s4b6hrfiUcaCtB8Sw_aS6T4toYPQ6o4RsJMuDOpJ7hFLrCoE8DS86VHLrduZvRQagCYdrjHhdLaKWqDZTla5VfzykIaNLyShJb49-MolN4MgYmZhJ1Ug1SHnJgGYPyeaCzMBF5YdISbiAqEWZitvUnHqlE4VDfcJPSRU/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip
Method: GET, RequestUri: 'https://public.dm.files.1drv.com/y4m0dJ6T36lQMeSciPwO1N-XvzhQzYU_rwMUvzVuYwi734aALbNtub43i57LzaDj-IVYR16Ec4s4b6hrfiUcaCtB8Sw_aS6T4toYPQ6o4RsJMuDOpJ7hFLrCoE8DS86VHLrduZvRQagCYdrjHhdLaKWqDZTla5VfzykIaNLyShJb49-MolN4MgYmZhJ1Ug1SHnJgGYPyeaCzMBF5YdISbiAqEWZitvUnHqlE4VDfcJPSRU/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.6.101
Authorization: Bearer ABC...XYZ
}
StatusCode: 429, ReasonPhrase: 'Too Many Requests', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Retry-After: 237
X-MSNSERVER: DS4PPF628FEECAA
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: Or3dc79GI0G4jqiPg7Cbkg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3062.afa1
X-ClientErrorCode: ThrottledRequest
X-ErrorCodeChain: AccessDenied,ThrottledRequest
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: C989BE1FBCB34038956AE6A48C50355C Ref B: BL2AA2030110045 Ref C: 2023-08-19T20:02:03Z
Date: Sat, 19 Aug 2023 20:02:03 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 0
}
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: 429: Too Many Requests error from request https://public.dm.files.1drv.com/y4m0dJ6T36lQMeSciPwO1N-XvzhQzYU_rwMUvzVuYwi734aALbNtub43i57LzaDj-IVYR16Ec4s4b6hrfiUcaCtB8Sw_aS6T4toYPQ6o4RsJMuDOpJ7hFLrCoE8DS86VHLrduZvRQagCYdrjHhdLaKWqDZTla5VfzykIaNLyShJb49-MolN4MgYmZhJ1Ug1SHnJgGYPyeaCzMBF5YdISbiAqEWZitvUnHqlE4VDfcJPSRU/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip
Method: GET, RequestUri: 'https://public.dm.files.1drv.com/y4m0dJ6T36lQMeSciPwO1N-XvzhQzYU_rwMUvzVuYwi734aALbNtub43i57LzaDj-IVYR16Ec4s4b6hrfiUcaCtB8Sw_aS6T4toYPQ6o4RsJMuDOpJ7hFLrCoE8DS86VHLrduZvRQagCYdrjHhdLaKWqDZTla5VfzykIaNLyShJb49-MolN4MgYmZhJ1Ug1SHnJgGYPyeaCzMBF5YdISbiAqEWZitvUnHqlE4VDfcJPSRU/duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.6.101
Authorization: Bearer ABC...XYZ
}
StatusCode: 429, ReasonPhrase: 'Too Many Requests', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Retry-After: 237
X-MSNSERVER: DS4PPF628FEECAA
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: Or3dc79GI0G4jqiPg7Cbkg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3062.afa1
X-ClientErrorCode: ThrottledRequest
X-ErrorCodeChain: AccessDenied,ThrottledRequest
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: C989BE1FBCB34038956AE6A48C50355C Ref B: BL2AA2030110045 Ref C: 2023-08-19T20:02:03Z
Date: Sat, 19 Aug 2023 20:02:03 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 0
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.Get(String remotename, Stream stream)
at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode)
at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)
at Duplicati.Library.Main.BackendManager.ThreadRun()
2023-08-19 16:02:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b3517c81f684440b395a08ec46a85f29a.dblock.zip (50.00 MB)
2023-08-19 16:02:12 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
where it looks like Retry-After got ignored, and Duplicati just used its 10 second retry-delay thus got slapped again. I had thought I’d seen source indicating it should respect the header. Might be a bug.
Refactor the Retry-After logic. Now it tracks Retry-After headers on all requests, and blocks any future requests until the time from the prior request has passed. suggests it should work. I didn’t read code.
I have lots of Retry-After in this profiling log (which is kind of old, so unsure what is what), but it ends:
Retry-After: 898
Retry-After: 898
Retry-After: 4583
Retry-After: 4583
Retry-After: 22630
Retry-After: 22630
Retry-After: 31500
Retry-After: 31500
That last one is 8.75 hours. I wonder if ignoring it raises its request? If still ignored, might it just stop?
Upload seems to do Retry-After OK, at least at the fragment level. In addition to the reporting above, regular (sometimes not turned on, but is hourly lately) OneDrive profiling log just asked a Retry-After which looks like it will be respected. This is on 2.0.7.2 Canary like the B2 backup that is my main one partly because it has space, but also because I pay by use, so it’s less likely to gripe use is too much.
2023-08-19 16:53:59 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 1/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-19 16:54:20 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 2/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-19 16:54:42 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 3/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-19 16:55:03 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-19 16:55:25 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetry]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes failed and will be retried
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: 429: Too Many Requests error from request https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ
Method: PUT, RequestUri: 'https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
User-Agent: Duplicati/2.0.7.2
Content-Length: 10437213
Content-Range: bytes 41943040-52380252/52380253
}
StatusCode: 429, ReasonPhrase: 'Too Many Requests', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Retry-After: 30645
X-MSNSERVER: DS1PPF115BFC7FF
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: eVEzDxSCcUGzLy0hRjlLWA.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 5127.da16
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: 517FCF9A282B4F4F9C168B8E5F57E71F Ref B: BL2AA2030110009 Ref C: 2023-08-19T20:55:04Z
Date: Sat, 19 Aug 2023 20:55:25 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 269
Content-Type: application/json; charset=utf-8
}
{
"error": {
"code": "accessDenied",
"message": "Too Many Requests",
"localizedMessage": "This item might have been deleted, expired, or you might not have permission to access it. Contact the owner of this item for more information.",
"innererror": {
"code": "throttledRequest"
}
}
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.ParseResponse[T](HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.MoveNext()
2023-08-19 16:55:25 -04 - [Profiling-Duplicati.Library.RetryAfterHelper-RetryAfterWait]: Waiting for 08:30:44.5438455 to respect Retry-After header
Also see:
OneDrive Throttling which had an example of throttling. It’s rather rare that we see the profiling logs.
Microsoft banned me for using Duplicati on Onedrive is worrisome, but might have been from space.
Regardless, I’ll see what happens to my backup that actually paused, and I don’t seem banned - yet.
The delayed fragment retry got rejected on range (and other) error. Fragment retries exhausted.
A retry of entire file took place (under different name, as usual), and file upload then succeeded.
2023-08-19 16:55:25 -04 - [Profiling-Duplicati.Library.RetryAfterHelper-RetryAfterWait]: Waiting for 08:30:44.5438455 to respect Retry-After header
2023-08-20 01:26:12 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-20 01:26:33 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetry]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes failed and will be retried
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable error from request https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ
Method: PUT, RequestUri: 'https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
User-Agent: Duplicati/2.0.7.2
Content-Length: 10437213
Content-Range: bytes 41943040-52380252/52380253
}
StatusCode: 416, ReasonPhrase: 'Requested Range Not Satisfiable', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
X-MSNSERVER: DS1PPF377FDA309
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: kkEUXCByYE6CTg3ahVRzCA.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3847.1964
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: D4DDB588DB77425DA3F24DB49EF57E87 Ref B: BL2AA2030106019 Ref C: 2023-08-20T05:26:13Z
Date: Sun, 20 Aug 2023 05:26:33 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 101
Content-Type: application/json; charset=utf-8
}
{
"error": {
"code": "invalidRange",
"message": "Optimistic concurrency failure during fragmented upload"
}
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.ParseResponse[T](HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.MoveNext()
2023-08-20 01:26:33 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-20 01:26:53 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetry]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes failed and will be retried
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable error from request https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ
Method: PUT, RequestUri: 'https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
User-Agent: Duplicati/2.0.7.2
Content-Length: 10437213
Content-Range: bytes 41943040-52380252/52380253
}
StatusCode: 416, ReasonPhrase: 'Requested Range Not Satisfiable', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
X-MSNSERVER: DS1PPF7CB3E75F5
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: dSB/HV6iT02QUnfS4Z+Pjg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3847.1964
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: 4F0479D3FD3D4A4684F4DC3FE314A0DB Ref B: BL2AA2030106019 Ref C: 2023-08-20T05:26:33Z
Date: Sun, 20 Aug 2023 05:26:53 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 101
Content-Type: application/json; charset=utf-8
}
{
"error": {
"code": "invalidRange",
"message": "Optimistic concurrency failure during fragmented upload"
}
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.ParseResponse[T](HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.MoveNext()
2023-08-20 01:26:53 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-20 01:27:13 -04 - [Retry-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentRetry]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes failed and will be retried
Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable error from request https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ
Method: PUT, RequestUri: 'https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
User-Agent: Duplicati/2.0.7.2
Content-Length: 10437213
Content-Range: bytes 41943040-52380252/52380253
}
StatusCode: 416, ReasonPhrase: 'Requested Range Not Satisfiable', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
X-MSNSERVER: DS1PPF7CB3E75F5
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: NX3M6tetZE+Ufmw43V+B1g.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3847.1964
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: B1EE7A7B8B0F4413BBC5B8FD44765F28 Ref B: BL2AA2030106019 Ref C: 2023-08-20T05:26:53Z
Date: Sun, 20 Aug 2023 05:27:13 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 101
Content-Type: application/json; charset=utf-8
}
{
"error": {
"code": "invalidRange",
"message": "Optimistic concurrency failure during fragmented upload"
}
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.ParseResponse[T](HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.MoveNext()
2023-08-20 01:27:13 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes
2023-08-20 01:27:34 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes attempt 1 of 3 failed with message: Error uploading fragment 4 of 5 for https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/HP4 clone 12 OneDrive/duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes:/createUploadSession
Method: POST, RequestUri: 'https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/HP4 clone 12 OneDrive/duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes:/createUploadSession', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.7.2
Authorization: Bearer ABC...XYZ
}
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Transfer-Encoding: chunked
Strict-Transport-Security: max-age=31536000
request-id: 2c5bb708-c457-4ae3-a85c-cf6800360c77
client-request-id: 2c5bb708-c457-4ae3-a85c-cf6800360c77
x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"South Central US","Slice":"E","Ring":"5","ScaleUnit":"005","RoleInstance":"SN4PEPF00000479"}}
OData-Version: 4.0
Cache-Control: no-store
Date: Sat, 19 Aug 2023 20:53:39 GMT
Location: https://graph.microsoft.com/
Content-Type: application/json; odata.metadata=minimal; odata.streaming=true; IEEE754Compatible=false; charset=utf-8
}
{
"@odata.context": "https://graph.microsoft.com/v1.0/$metadata#microsoft.graph.uploadSession",
"expirationDateTime": "2023-08-24T20:53:39.122Z",
"nextExpectedRanges": [
"0-"
],
"uploadUrl": "https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ"
}
Duplicati.Library.Backend.MicrosoftGraph.UploadSessionException: Error uploading fragment 4 of 5 for https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/HP4 clone 12 OneDrive/duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes:/createUploadSession
Method: POST, RequestUri: 'https://graph.microsoft.com/v1.0/me/drive/root:/Duplicati Backups/HP4 clone 12 OneDrive/duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes:/createUploadSession', Version: 1.1, Content: <null>, Headers:
{
User-Agent: Duplicati/2.0.7.2
Authorization: Bearer ABC...XYZ
}
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Transfer-Encoding: chunked
Strict-Transport-Security: max-age=31536000
request-id: 2c5bb708-c457-4ae3-a85c-cf6800360c77
client-request-id: 2c5bb708-c457-4ae3-a85c-cf6800360c77
x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"South Central US","Slice":"E","Ring":"5","ScaleUnit":"005","RoleInstance":"SN4PEPF00000479"}}
OData-Version: 4.0
Cache-Control: no-store
Date: Sat, 19 Aug 2023 20:53:39 GMT
Location: https://graph.microsoft.com/
Content-Type: application/json; odata.metadata=minimal; odata.streaming=true; IEEE754Compatible=false; charset=utf-8
}
{
"@odata.context": "https://graph.microsoft.com/v1.0/$metadata#microsoft.graph.uploadSession",
"expirationDateTime": "2023-08-24T20:53:39.122Z",
"nextExpectedRanges": [
"0-"
],
"uploadUrl": "https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ"
} ---> Duplicati.Library.Backend.MicrosoftGraph.MicrosoftGraphException: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable error from request https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ
Method: PUT, RequestUri: 'https://api.onedrive.com/rup/7dfee4690d9f4711/eyJSZXNvdXJjZUlEIjoiN0RGRUU0NjkwRDlGNDcxMSEzMDcwNyIsIlJlbGF0aW9uc2hpcE5hbWUiOiJkdXBsaWNhdGktYjYwZjBjMTkzY2RjMTQxNWI5NDdhN2MwZDBhOTEwYzM0LmRibG9jay56aXAuYWVzIn0/4mVlJc9u8E5j9a2UoVUNyPrdeBuGVoaQAfLZPXALG5c_5Mbu4OhMi7grPZsOHxrz05LMbx4yzRceQ1kAODYgBVY7_HgUz0wfDMxfxfCgkuDNc/eyJuYW1lIjoiZHVwbGljYXRpLWI2MGYwYzE5M2NkYzE0MTViOTQ3YTdjMGQwYTkxMGMzNC5kYmxvY2suemlwLmFlcyIsIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wdV1Zz_-wuw5zeD4y3i2dQnl3FqdSR3-dy0V0mTLO5_85qVek2M0xpv5fOV4NxZGn5HBuzHPQdF-tnTbt-Vxj_-3ewAgWXgPdpZrL-uyDnWTmMs1FYxz7L4LCOomZL__l4ylHl-bsL-4_MjGgKfwP9uNEKL5aV9p8w8fYqLoBCFEMeNb9clr5PsOON84MOtEnncZTovcUS8OVQrFEdWspRi78PMOZWajAvBMJ15lEPsB7JgGeaj_lV2IImo2fkvqhDmuX51GmwqzmOGTSe8ORA-GU4Ex0490r5B6OD72Vg3h6WVGNXtahFvEQlDd0lRmTpu3ZnRmZr4YmgAwdKRz7J2a0QERmx5-fcrjX9y7h5SvGzRZoI8InJPuTf6Wrle6L_1F0yqoRfIXkadI3_vnpIkbDwcJdH60iLedLy9RBqB2KJIizfY3I0DoJFIU-h3rZrRL-D4XTS2lXkn989ydmVG7WOKmmYiAG6q7LqwgI3_mxOp0fgbqxlQHlaMv5f-pkB_wtMxkloh6-Gx-2-mj1QAt37Rn36mXaLvh7oqJME5GzuGY8VC_10GECU6-MRlqZ', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
User-Agent: Duplicati/2.0.7.2
Content-Length: 10437213
Content-Range: bytes 41943040-52380252/52380253
}
StatusCode: 416, ReasonPhrase: 'Requested Range Not Satisfiable', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
X-MSNSERVER: DS1PPF6E63024CC
Strict-Transport-Security: max-age=31536000; includeSubDomains
MS-CV: +pmJ+uTI4UiQ1XXOFAS7Cg.0
X-QosStats: {"ApiId":0,"ResultType":2,"SourcePropertyId":0,"TargetPropertyId":42}
X-ThrowSite: 3847.1964
X-AsmVersion: UNKNOWN; 19.1225.808.2003
X-Cache: CONFIG_NOCACHE
X-MSEdge-Ref: Ref A: 9E7C81E0ACCB49D7ADF102F1DEA1F174 Ref B: BL2AA2030106019 Ref C: 2023-08-20T05:27:13Z
Date: Sun, 20 Aug 2023 05:27:32 GMT
P3P: CP="BUS CUR CONo FIN IVDo ONL OUR PHY SAMo TELo"
Content-Length: 101
Content-Type: application/json; charset=utf-8
}
{
"error": {
"code": "invalidRange",
"message": "Optimistic concurrency failure during fragmented upload"
}
}
at Duplicati.Library.Backend.MicrosoftGraphBackend.CheckResponse(HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.ParseResponse[T](HttpResponseMessage response)
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.MoveNext()
--- End of inner exception stack trace ---
at Duplicati.Library.Backend.MicrosoftGraphBackend.<ThrowUploadSessionException>d__76.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at Duplicati.Library.Backend.MicrosoftGraphBackend.<PutAsync>d__60.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.Backup.BackendUploader.<DoPut>d__24.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.Backup.BackendUploader.<>c__DisplayClass20_0.<<UploadFileAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at Duplicati.Library.Main.Operation.Backup.BackendUploader.<DoWithRetry>d__21.MoveNext()
2023-08-20 01:27:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes (49.95 MB)
2023-08-20 01:27:44 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes (49.95 MB)
2023-08-20 01:27:44 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes (49.95 MB)
2023-08-20 01:27:44 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes" to "duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes"
2023-08-20 01:27:44 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "Remotevolume" SET "Name" = "duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes" WHERE "Name" = "duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes"
2023-08-20 01:27:44 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "Remotevolume" SET "Name" = "duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes" WHERE "Name" = "duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes" took 0:00:00:00.092
2023-08-20 01:27:44 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalar]: Starting - ExecuteScalar: SELECT "Type" FROM "Remotevolume" WHERE "Name" = "duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes"
2023-08-20 01:27:44 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalar]: ExecuteScalar: SELECT "Type" FROM "Remotevolume" WHERE "Name" = "duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes" took 0:00:00:00.000
2023-08-20 01:27:44 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (740, "duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes", "Blocks", "Deleting", -1, 0, 0); SELECT last_insert_rowid();
2023-08-20 01:27:44 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (740, "duplicati-b60f0c193cdc1415b947a7c0d0a910c34.dblock.zip.aes", "Blocks", "Deleting", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.016
2023-08-20 01:27:44 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes (49.95 MB)
2023-08-20 01:27:47 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 0/5 of remote file duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes
2023-08-20 01:28:08 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 1/5 of remote file duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes
2023-08-20 01:28:29 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 2/5 of remote file duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes
2023-08-20 01:28:49 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 3/5 of remote file duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes
2023-08-20 01:29:09 -04 - [Verbose-Duplicati.Library.Backend.MicrosoftGraphBackend-MicrosoftGraphFragmentUpload]: Uploading fragment 4/5 of remote file duplicati-bd3bc4842458d4845a622ac87d1a24c82.dblock.zip.aes
2023-08-20 01:29:30 -04 - [Profiling-Duplicati.Library.Main.Operation.Backup.BackendUploader-UploadSpeed]: Uploaded 49.95 MB in 00:01:45.3213119, 485.68 KB/s
After Duplicati schedule got over being tied up by this one, my regular OneDrive backups ran hourly. successfully and seemingly without retry at file or fragment level (based on lack of Retry in the log).
Suggestions welcome on what to run next, and it’d be nice if devs could consider possibility of a bug.
I have to admit having trouble following the events, it all started with a compact, then a test, and now it’s a backup it seems. What is the best (simplest) way to trigger it ? I’m not sure if you have a full blown OneDrive account or (like myself) a tiny test account of 5GB, is there a hope that I can see the problem with this free account ?
Not really. Backup is just production backup that was scheduled hourly in the GUI for the entire time. Implication of the test throttling leaking into the regular backup once is that it’s tied to user account.
Unknown, as I stopped trying to refine it, but current method was a backup of 10 GB of random data, followed by test ... all to refute the idea that compact is needed. Do test until OneDrive squeals which it did disappointing fast, just tens of GB depending on the period over which it’s tracking usage.
My last run (that caught all the mayhem) looked like below, although if one wanted to get fancy, using console-log-filter might be a way to catch exactly what’s being sought. Or run glogg on log for similar.
“C:\ProgramData\Duplicati\duplicati-2.0.6.101_canary_2022-03-13\Duplicati.CommandLine.exe” test “onedrivev2://Duplicati Backups/onedrive_compact?authid=REDACTED” all --no-encryption --console-log-level=information --log-file=“C:\tmp\onedrive_compact\profiling.log” --log-file-log-level=profiling
EDIT 1:
I got OneDrive when the free limit was 15 GB. You might be able to reproduce something with 5 GB:
but I went to test because it was simpler than constantly setting up a backup and then compacting it.
EDIT 2:
Terminal output from the described test is in the attached file. The rhythm is interesting, as downloads worked well for awhile (mostly during dindex files), then lots of throttling, then OK, then more throttling.
onedrive_download_throttling.zip (15.7 KB)
Thanks, I was indeed able to reproduce it with a mere 3 GB backup that I tested repeatedly with --full-remote-verification flag. I don’t know the limit I hit but it triggered growing delays, not sure if it was because Duplicati was ignoring them. While it was ignoring them, the delay did not grow, it was when the cloud allowed again downloading that it grew until hitting almost 3 hours.
I’m the original author of the OneDrive v2 backend, so thanks to @ts678 for mentioning one of the commits to bring my attention in. (I haven’t been able to spend much time on the forum or digging into bugs lately, but tried to follow through this thread.)
Unfortunately, I don’t have anything particularly useful to add. I use the canary version of Duplicati (the Mono version via Docker on a Raspberry Pi), and I’ve noticed periodic hangs happen randomly for a long while but have never been able to figure out exactly what the source was. As others have seen, I’ve always seen them happen after logging that a Get was starting, so my suspicion is that something there is hanging, but I’m not familiar with collecting memory dumps or analyzing them with Mono and haven’t been able to dig in when it’s reproed. (I’ve usually just restarted the Docker container and let things get repaired if needed.) I’ve mostly seen it happen during the verification phase, so I’ve mitigated most of my issues by not using the percentage based verification parameters. But that is more a bandaid than a fix.
One other thing I noticed while looking through this thread was that the RetryAfterHelper I added doesn’t actually pass the cancelation token into the Task.Delay call. I have no idea if that would make a difference (it shouldn’t affect Get, since no token is passed in to the non async methods, but I suppose in hindsight that the CancelationToken.None in the default case might also be a bad pattern here…). I don’t have a repository currently set up to push a PR from though, so if someone else wants to fix that I’d appreciate it.
Does anyone here know how Duplicati’s standard timeouts are supposed to be implemented on Get calls? Without a cancelation token, my assumption has always been that it would do a thread abort or have something in the HTTP call time out and throw the error back, but I’m wondering now if the timeout should be implemented inside the backend somehow (e.g., by passing a cancelation token with a timeout through to the async calls that get invoked by the synchronous methods). I think I had tried making sure the timeout was applied on all HTTP requests through their standard implementations, but I wasn’t ever able to exhaustively test that it worked.
1 Like
hello @tygill
Thanks for following up, on the narrow subject of Duplicati not respecting the delay, what do you think of this change:
diff --git a/Duplicati/Library/Backend/OAuthHelper/RetryAfterHelper.cs b/Duplicati/Library/Backend/OAuthHelper/RetryAfterHelper.cs
index ce1e60f8b..c0269d4ee 100644
--- a/Duplicati/Library/Backend/OAuthHelper/RetryAfterHelper.cs
+++ b/Duplicati/Library/Backend/OAuthHelper/RetryAfterHelper.cs
@@ -34,7 +34,7 @@ namespace Duplicati.Library
// Whenever a response includes a Retry-After header, we'll update this timestamp with when we can next
// send a request. And before sending any requests, we'll make sure to wait until at least this time.
// Since this may be read and written by multiple threads, it is stored as a long and updated using Interlocked.Exchange.
- private long retryAfter = DateTimeOffset.MinValue.UtcTicks;
+ private static long retryAfter = DateTimeOffset.MinValue.UtcTicks;
public void SetRetryAfter(RetryConditionHeaderValue retryAfter)
{
@@ -60,7 +60,7 @@ namespace Duplicati.Library
long currentRetryAfter;
do
{
- currentRetryAfter = Interlocked.Read(ref this.retryAfter);
+ currentRetryAfter = Interlocked.Read(ref RetryAfterHelper.retryAfter);
if (newRetryAfter < currentRetryAfter)
{
@@ -69,7 +69,7 @@ namespace Duplicati.Library
}
else
{
- replacedRetryAfter = Interlocked.CompareExchange(ref this.retryAfter, newRetryAfter, currentRetryAfter);
+ replacedRetryAfter = Interlocked.CompareExchange(ref RetryAfterHelper.retryAfter, newRetryAfter, currentRetryAfter);
}
}
while (replacedRetryAfter != currentRetryAfter);
@@ -102,7 +102,7 @@ namespace Duplicati.Library
{
// Make sure this is thread safe in case multiple calls are made concurrently to this backend
// This is done by reading the value into a local value which is then parsed and operated on locally.
- long retryAfterTicks = Interlocked.Read(ref this.retryAfter);
+ long retryAfterTicks = Interlocked.Read(ref RetryAfterHelper.retryAfter);
DateTimeOffset delayUntil = new DateTimeOffset(retryAfterTicks, TimeSpan.Zero);
TimeSpan delay;
after applying it, I get
Aug 20, 2023 10:45 PM: Waiting for 04:06:21.5374900 to respect Retry-After header
in the Live log (instead of Duplicati retrying again right away without it, of course)
I’m not experienced enough with the driver to evaluate correctness, so your advice would be appreciated.
1 Like
@gpatel-fr - That change seems alright if that is the desired behavior, but I’m a bit surprised if it makes a functional difference. I would only expect it to have an impact if multiple instances of the OneDrive v2 backend object are created and being used simultaneously or if multiple backend instances are created for some reason. I hadn’t expected either of these to be the case though. The original design had been to have each RetryAfterHelper associated with some specific client (which for the OneDrive ones is created in the constructor), so that in the hypothetical case where multiple backends are active at once and are each using it, they wouldn’t have conflicting RetryAfters (for example, if you have a tool opening two separate backend instances to different accounts in order to copy files between them). But if that assumption was wrong this would be a simple fix that is probably the best way to address it.
Well, when the packet is handled down the line after the retryafter delay is set, the packet is not encrypted / zipped so Duplicati crashes, the backend is released (Dispose() is called) and next time a new RetryAfter object is created.
Fixing it this way would be obviously wrong if 2 different servers were using it (say, if Sharepoint and Onedrive were using it or if one could also have a local Onedrive server besides the Ms one, like one can have a local S3 server besides a Cloud S3 server). So yes it’s a hack.
Maybe throwing an exception if the RetryAfter is set would be better. Not sure which exception though for the packet just be dropped without fuss, I don’t see the case being actually planned in coreDoGetPiping routine (in BackendManager.cs).
After a night, things get clearer. The problem is that the delay should be executed right now when the RetryAfter is received, not just stored to be done with next packet. So the backend call should just loop and not return.
Interesting - I had no idea that the backend could be recreated if there was a failure. In that case, the RetryAfterHelper should either be static (as you have it) or should be something the backend manager and other classes pass in when creating new backends with the same settings. Making it static is likely the most simple by far.
The reason I hadn’t done the RetryAfterHelper wait as soon as the response was received was so that other operations (like logging, etc.) that might happen after a failure would execute immediately, rather than seeing a hang (and the caller could have more control over when and how that wait would happen). But in practice, it’s probably enough to log that it was seen and then wait inline, since retry after should only occur on a failed call which would lead to an immediate retry nearly all the time.
So be it, it’s a very hacky PR:
as me trying to fix the backend in a more proper way would come to no good I’m afraid.
I forgot to comment for the OP: this will not magically fix the throttling. Nothing will do, unless paying more Microsoft. Waiting correctly for the retry-after header does not make Onedrive set ulterior delays in a more civilized way, I have not seen a clear pattern for that.
As Duplicati will not fail because the default 5 retries are exhausted, it may let the job succeed. But it may take a day for that. Or not.
Since I have raised the log level to a warning, it will be more obvious for the user to see what happens and understand what is to be done (be patient or cough more money to Microsoft).
So, the suspicion right now is that the hang is caused when the Retry-After header is not followed? I don’t think there is anything a server is supposed to be able to do, that would cause our http requests to ignore the timeout (as in this test).
Did anyone test that the timeouts work under normal circumstances with OneDrive (maybe with a very small value)?
Obviously, the default is no timeout, so in that case I am a bit more willing to accept an indefinite block if the server never responds.
As far as I can tell, when Duplicati was ignoring the time out in my tests, OneDrive was just replying with decreasing delays (since Duplicati waits a bit between each failure), then at some point the delay expired and the block downloading had a small reprieve and failed again this time with a huge delay (8 hours IIRC). So the server responds if the retry-after is not respected, however it does no special good (or bad, except it can lead to failure when the max retry is exceeded).
Is that what you mean ?
Edit: maybe what you mean is that respecting the retry-after is not respecting the values for delay set in the Duplicati parameters. In my opinion, the Duplicati parameters should apply when the reasons for the failures are not known. Throttling is normal behaviour for this particular cloud server, the users know what they are getting with OneDrive, so I think it’s normal that when facing throttling the normal Duplicati parameters don’t apply and Duplicati waits ‘indefinitely’ (actually the time asked for by the server).
That is fine, but not the original problem. It just seems to be stuck in a get request (not returning an error, nor timing out), which is not related to any retry delay (because that would be handled before that http request).
@ts678 managed to get a call stack for the block above (which confirmed it was in HttpClient.GetAsync), but we were not able to find the reason. I could not reproduce it with my smaller free storage space. Do you have any idea why that async call would never return and seems to do nothing?
Users may have to raise http-operation-timeout because the default 100 seconds is too small for the network speed and dblock size. It’s not hugely common. You can find several examples in the forum.
There’s also http-read-write-timeout but I know even less about it. This is a good area for research…
On the surface, http-operation-timeout is claimed by our option definition to cover initial packet to shutdown. I don’t have packet traces to see if shutdown took place, but it looks like request got action.
maybe because it was not related ? I have seen 503 errors during my tests so the service does not seem very reliable. Also, ignoring the retry-after header could be of no help with dealing with the service.
When we are waiting for the service to be available, we do no http at all so the http timeout does not apply.
Our backends (that don’t use 3rd party libraries) explicitly set the timeout to infinite by default. That is why I’m not surprised that very long blocks can happen, but even with a timeout it got locked up.