Could not find file

[kmand]

I know there are older posting on this, but I don’t see an applicable resolution. I’m running against google drive, the only thing unusual might be the very large size of the what I’m backing up. For example last night it took 6 hours on

Examined 1393027 (4.67 TB)
Opened 534 (58.90 GB)
Added 81 (8.80 GB)
Modified 453 (50.08 GB)
Deleted 11

I’m running Duplicati - 2.0.5.1_beta_2020-01-18 on Ubuntu 16.04. I have not changed defaults.

I can get this a couple of times a week, but then sometimes not at all for a couple of weeks. I have a Comcast Gig in, 40Mb out.

This is the typical error, followed by the warning on the next run.

7-14
One or more errors occurred. (Could not find file “/tmp/dup-91fabe15-f0ca-425b-9453-e8b4abe23320” (Could not find file “/tmp/dup-91fabe15-f0ca-425b-9453-e8b4abe23320”) (One or more errors occurred. (The remote server returned an error: (403) Forbidden.)))#

The the next time always has a warning

2020-07-14 12:45:54 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.UploadSyntheticFilelist-MissingTemporaryFilelist]: Expected there to be a temporary fileset for synthetic filelist (258, duplicati-ba90337b599424e1dae9ed5b6b5a1d6c7.dblock.zip.aes), but none was found?

[ts678]

@kmand

I know there are older posting on this, but I don’t see an applicable resolution.

An impediment to resolution has been lack of user detail on how this happens, after they solve their issue.

Problem Backing up in w7 is only waiting two days, so might still have some hope of getting further details.

FileNotFoundException (temp file not found during backup) is at 17 days, and there are lots of older cases.

I would suggest a retry-level log, and in order to make it easier to gather, I will suggest doing it to a file, like:

–log-file and log-file-log-level in Advanced options. There’s increasing evidence (see earlier cases) that an earlier problem causes this one. Note that there are several paths to “Could not find file”, so if you can find some existing error with a multi-line stack trace, please post. Possibly About --> Show log --> Stored has your previous ones. Click on them to see the detailed stack trace, then run a log to see where it had failed.

@kmand

Expected there to be a temporary fileset for synthetic filelist

This indicates that the previous backup was interrupted, which fits in well with its failing due to some error.
This probably happened near start of the run. Duplicati tries to upload a synthetic backup version showing backup progress before interruption (based on backup files before that, plus progress before interruption).

Fix synthetic filelist not being uploaded #4114 fixed bug causing the error, but fix is not yet in Beta release.

EDIT:

@kmand

I can get this a couple of times a week, but then sometimes not at all for a couple of weeks.

Aside from being a more permanent collector, this is the other reason a file will work better than “live log”.
You might also have a look at your past job logs to look for non-zero RetryAttempts stat in the Full log.

What Storage Type is the Destination? My Google Drive seems especially likely to do random Forbidden

[kmand]

Thanks for the reply! I have some questions. First, just to be clear I’m
backing up to Google Drive, and thats my only option.

I see where –log-file and log-file-log-level is set in the GUI, but its
not clear to me what backup run it applies to. Right now I start up
duplicati with

/usr/lib/duplicati/Duplicati.GUI.TrayIcon.exe

Is there are different command line so the extra logging will apply on
all backups?

I’m also not clear where the extra logging goes, is it just in the
regular log that the GUI provides?

Is this supposed to get me a log of the failed backup to the point of
interruption? Would this be in the same place with the successful logs?

Can I get the logs independently of the GUI?

I don’t know if this is helpful or not, but looking at the last
successful log (this morning) I see 6 retryings.

2 of them are Lists

“2020-07-17 03:25:00 -04 -
[Information-Duplicati.Library.Main.Controller-StartingOperation]: The
operation Backup has started”, “2020-07-17 04:27:45 -04 -
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend
event: List - Started: ()”, “2020-07-17 05:00:58 -04 -
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend
event: List - Retrying: ()”, “2020-07-17 05:01:08 -04 -
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend
event: List - Started: ()”, “2020-07-17 05:01:19 -04 -
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend
event: List - Retrying: ()”,

4 of them are puts (all have the same timestamp)

“2020-07-17 06:00:49 -04 -
[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend
event: Put - Retrying:
duplicati-b8280d971b9a641aa984b361634358b05.dblock.zip.aes (49.91 MB)”,

[ts678]

@kmand

Is there are different command line so the extra logging will apply on
all backups?

You can put the options on the startup shortcut (or whatever you use). Use double dashes and be sure to quote as needed if you have things like spaces in the logfile path. Or you can use Settings on home page, and if you go this way then you don’t need to add your own quoting, and you also get a description shown.

@kmand

I’m also not clear where the extra logging goes, is it just in the
regular log that the GUI provides?

It goes into the file that you specified:

@kmand

Is this supposed to get me a log of the failed backup to the point of
interruption?

It’s a cumulative log of most Duplicati activities. If you want to delete the log, the file will be started again.

@kmand

Would this be in the same place with the successful logs?

If you mean is it with the default job logs (not all logs here are successes), no, its at the path you asked.

@kmand

Can I get the logs independently of the GUI?

Question is not clear. TrayIcon.exe (which you run) allows GUI, but you don’t need to watch it to get logs.
The file method is easier in this way than live log use at About --> Show log --> Live. The log is a text file.

@kmand

I don’t know if this is helpful or not, but looking at the last
successful log (this morning) I see 6 retryings.

It helps slightly, but these one line summaries cut off all details on what happened. You need a better log.
Retries happen because something failed somehow, and the summary does not provide the information.

The whole sense of timing is also missing, though it could be seen in the GUI (it just wasn’t posted here).
List (of remote directory) should be at start or end of the backup, with a lot of Put (file upload) in between. Your backup ran over half an hour before a List. I suppose it’s possible. Real log would show sequencing.

It’s not clear if Put at 06:00:49 is during the backup itself, or from the Compact phase after Delete phase:

[kmand]

I got a couple of failures in a row. On one of them I was running with
the extra logging. I attached a zip that has two files in it.

The file output is what showed up in the GUI after I added the
advanced commands and told it to run

The file big.log is the file I indicated for where the log should
go in the advanced command.

(logs.zip (7.6 KB)

[ts678]

big.log was useful but worrisome because Google Drive errored on you 22 times before Duplicati gave up.
The one thing that got through on its fourth try was the listing of the remote directory. All the uploads failed.
I think that’s enough to kill the backup, so the “Could not find file” might be a badly handled attempt to stop.

2020-07-20 22:02:27 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes attempt 6 of 5 failed with message: The remote server returned an error: (403) Forbidden.

is when the default 5 number-of-retries ran out. You can try raising it, but Google Drive “shouldn’t” 403 you. Sometimes it throws single 403s at me, but yours was quite a prolonged repetitive sequence of rejections.
retry-delay is another adjustable option that you could try raising in addition to (or instead of?) more retries.

[ts678]

Upload files to Google Drive documents the 750 GB daily upload limit for “Individual users”.
Is it possible you’re hitting this? The page doesn’t say exactly which 403 flavor this causes.
They also don’t say exactly what a day is, but another quota uses U.S. Pacific time days…
Your backup job log “BytesUploaded” in “BackendStatistics” in “Complete log” has a count.
Your operating system might too, provided you’re not doing lots of other network uploading.

[kmand]

Its not for exceeding total bytes. My total for all use per month up and down is a bit over 1TB (confirmed by my own router and Comcast’s count). I rarely go over 40GB a day, and have never reached 100GB (its not all duplicati).

My google drive is a Google Suite account with no storage limit.

One thing thats confusing is that the API doc doesn’t have “Forbidden” as one of the messages that goes with 403.

https://developers.google.com/drive/api/v3/handle-errors

The only thing I can think of is bandwidth throttling. My download link is theoretically a gigabit, but the upload is only 40 megabits and its getting errors on puts.

By the way in the big.log I saw a message with retry 6 of 5.

How does the retry limit work? This wasn’t fatal since the log goes on with more transactions. Also is it per transaction, or something more global?

By the way the folder for this backup on Google Drive has 77000 files adding up to 2024.30GB, neither of which is a Google limit.

[ts678]

@kmand

One thing thats confusing is that the API doc doesn’t have “Forbidden” as one of the messages that goes with 403.

Duplicati is on v2, but it’s no better. Forbidden, though, is a standard 403 all the way back to HTTP 1.0:

Hypertext Transfer Protocol – HTTP/1.0

403 Forbidden
The server understood the request, but is refusing to fulfill it.

@kmand

By the way in the big.log I saw a message with retry 6 of 5.

Possibly this is expressed differently in Canary. I think it’s been fiddled with sometimes. The 5 is number-of-retries, but there’s also the first “try” which is not a retry. In your big log, you can see all the failures, but one of the four (can be configured) parallel uploads got there first. Here I label the uploads A, B, C, and D:

A 2020-07-20 21:48:20 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b4bc325b682cf4f3199737dbc95d54d8c.dblock.zip.aes (49.92 MB)
B 2020-07-20 21:48:23 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b2a57907c7e4b4b289cbf6909a884501b.dblock.zip.aes (49.93 MB)
C 2020-07-20 21:48:24 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b83af10d636ae4d5288667f6b6510dc6a.dblock.zip.aes (49.92 MB)
D 2020-07-20 21:48:24 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b011bee3e67964735a9fee983e4df411f.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:00:48 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b4bc325b682cf4f3199737dbc95d54d8c.dblock.zip.aes attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:00:48 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b4bc325b682cf4f3199737dbc95d54d8c.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:00:48 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b83af10d636ae4d5288667f6b6510dc6a.dblock.zip.aes attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
C 2020-07-20 22:00:48 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b83af10d636ae4d5288667f6b6510dc6a.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:00:49 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b011bee3e67964735a9fee983e4df411f.dblock.zip.aes attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
D 2020-07-20 22:00:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b011bee3e67964735a9fee983e4df411f.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b4bc325b682cf4f3199737dbc95d54d8c.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b4bc325b682cf4f3199737dbc95d54d8c.dblock.zip.aes" to "duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes"
A 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b83af10d636ae4d5288667f6b6510dc6a.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b83af10d636ae4d5288667f6b6510dc6a.dblock.zip.aes" to "duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes"
C 2020-07-20 22:00:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:00:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b011bee3e67964735a9fee983e4df411f.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:00:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:00:59 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b011bee3e67964735a9fee983e4df411f.dblock.zip.aes" to "duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes"
D 2020-07-20 22:00:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:01:07 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b2a57907c7e4b4b289cbf6909a884501b.dblock.zip.aes attempt 1 of 5 failed with message: The remote server returned an error: (403) Forbidden.
B 2020-07-20 22:01:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b2a57907c7e4b4b289cbf6909a884501b.dblock.zip.aes (49.93 MB)
C 2020-07-20 22:01:08 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes attempt 2 of 5 failed with message: The remote server returned an error: (403) Forbidden.
D 2020-07-20 22:01:08 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes attempt 2 of 5 failed with message: The remote server returned an error: (403) Forbidden.
C 2020-07-20 22:01:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:01:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:01:09 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes attempt 2 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:01:09 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes (49.92 MB)
B 2020-07-20 22:01:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b2a57907c7e4b4b289cbf6909a884501b.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:01:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:01:17 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b2a57907c7e4b4b289cbf6909a884501b.dblock.zip.aes" to "duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes"
B 2020-07-20 22:01:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes (49.93 MB)
C 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b7fba8ae76f704b0bbf1c3c5dbc8ac08c.dblock.zip.aes" to "duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes"
C 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bf475a34392d34917abb34cdb94e45c72.dblock.zip.aes" to "duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes"
D 2020-07-20 22:01:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:01:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:19 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bd226bff02684451fb1c00d9c31cece18.dblock.zip.aes" to "duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes"
A 2020-07-20 22:01:19 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:01:29 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes attempt 3 of 5 failed with message: The remote server returned an error: (403) Forbidden.
C 2020-07-20 22:01:29 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:29 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes attempt 3 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:01:29 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:01:29 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes attempt 3 of 5 failed with message: The remote server returned an error: (403) Forbidden.
D 2020-07-20 22:01:29 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes (49.93 MB)
C 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-ba01630bf0e664ed49e0e1b028cc974d7.dblock.zip.aes" to "duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes"
C 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bb428fcdb086e413cbef9c261d018c24a.dblock.zip.aes" to "duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes"
A 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-ba2f57a33913f4ef482b437d2f248fc9d.dblock.zip.aes" to "duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes"
D 2020-07-20 22:01:39 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:01:49 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes attempt 4 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:01:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:01:59 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bee1494ca00964aa98c0e56899f747e17.dblock.zip.aes" to "duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes"
A 2020-07-20 22:01:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:02:07 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes attempt 4 of 5 failed with message: The remote server returned an error: (403) Forbidden.
C 2020-07-20 22:02:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:02:07 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes attempt 5 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:02:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:02:08 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes attempt 4 of 5 failed with message: The remote server returned an error: (403) Forbidden.
D 2020-07-20 22:02:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:02:08 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes attempt 2 of 5 failed with message: The remote server returned an error: (403) Forbidden.
B 2020-07-20 22:02:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes (49.93 MB)
C 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b91c3c9c7009c47aba8e066d231ac06ba.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bfbf68b9123e846b8a61571a21913aafd.dblock.zip.aes" to "duplicati-b91c3c9c7009c47aba8e066d231ac06ba.dblock.zip.aes"
C 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b91c3c9c7009c47aba8e066d231ac06ba.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes (49.92 MB)
A 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b1c15e5c9b5de49d7a87c7dbceb7f26c3.dblock.zip.aes" to "duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes"
A 2020-07-20 22:02:17 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes (49.92 MB)
D 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b10ab147b67744876a1e7fa66c46a66aa.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b4f9f213727a8462e8f99dcce672124ac.dblock.zip.aes" to "duplicati-b10ab147b67744876a1e7fa66c46a66aa.dblock.zip.aes"
D 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b10ab147b67744876a1e7fa66c46a66aa.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bc19ecb78b6de4954b824504ef8a5e0b3.dblock.zip.aes (49.93 MB)
B 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bbb951a0093714154b98f2afde8579700.dblock.zip.aes" to "duplicati-bc19ecb78b6de4954b824504ef8a5e0b3.dblock.zip.aes"
B 2020-07-20 22:02:18 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc19ecb78b6de4954b824504ef8a5e0b3.dblock.zip.aes (49.93 MB)
A 2020-07-20 22:02:27 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes attempt 6 of 5 failed with message: The remote server returned an error: (403) Forbidden.
A 2020-07-20 22:02:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Failed: duplicati-b06c9a241d7d748adafaaebb8c5918b4a.dblock.zip.aes (49.92 MB)
C 2020-07-20 22:02:27 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b91c3c9c7009c47aba8e066d231ac06ba.dblock.zip.aes attempt 5 of 5 failed with message: The remote server returned an error: (403) Forbidden.
C 2020-07-20 22:02:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b91c3c9c7009c47aba8e066d231ac06ba.dblock.zip.aes (49.92 MB)
B 2020-07-20 22:02:27 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bc19ecb78b6de4954b824504ef8a5e0b3.dblock.zip.aes attempt 3 of 5 failed with message: The remote server returned an error: (403) Forbidden.
B 2020-07-20 22:02:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bc19ecb78b6de4954b824504ef8a5e0b3.dblock.zip.aes (49.93 MB)
D 2020-07-20 22:02:28 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b10ab147b67744876a1e7fa66c46a66aa.dblock.zip.aes attempt 5 of 5 failed with message: The remote server returned an error: (403) Forbidden.
D 2020-07-20 22:02:28 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b10ab147b67744876a1e7fa66c46a66aa.dblock.zip.aes (49.93 MB)
2020-07-20 22:02:38 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.IO.FileNotFoundException: Could not find file "/tmp/dup-aee9b1e1-0218-45d7-9146-edf43bf9e238"
File name: '/tmp/dup-aee9b1e1-0218-45d7-9146-edf43bf9e238'
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share, System.Int32 bufferSize, System.Boolean anonymous, System.IO.FileOptions options) [0x0019e] in <a17fa1457c5d44f2885ac746c1764ea5>:0 
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share) [0x00000] in <a17fa1457c5d44f2885ac746c1764ea5>:0 
  at (wrapper remoting-invoke-with-check) System.IO.FileStream..ctor(string,System.IO.FileMode,System.IO.FileAccess,System.IO.FileShare)
  at Duplicati.Library.Main.Volumes.VolumeReaderBase.LoadCompressor (System.String compressor, System.String file, Duplicati.Library.Main.Options options, System.IO.Stream& stream) [0x00000] in <8f1de655bd1240739a78684d845cecc8>:0 
  at Duplicati.Library.Main.Volumes.VolumeReaderBase..ctor (System.String compressor, System.String file, Duplicati.Library.Main.Options options) [0x00007] in <8f1de655bd1240739a78684d845cecc8>:0 
  at Duplicati.Library.Main.Volumes.BlockVolumeReader..ctor (System.String compressor, System.String file, Duplicati.Library.Main.Options options) [0x00010] in <8f1de655bd1240739a78684d845cecc8>:0 
  at Duplicati.Library.Main.Operation.Backup.SpillCollectorProcess+<>c__DisplayClass0_0.<Run>b__0 (<>f__AnonymousType11`2[<Input>j__TPar,<Output>j__TPar] self) [0x0023c] in <8f1de655bd1240739a78684d845cecc8>:0 
  at CoCoL.AutomationExtensions.RunTask[T] (T channels, System.Func`2[T,TResult] method, System.Boolean catchRetiredExceptions) [0x000d5] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.RunMainOperation (System.Collections.Generic.IEnumerable`1[T] sources, Duplicati.Library.Snapshots.ISnapshotService snapshot, Duplicati.Library.Snapshots.UsnJournalService journalService, Duplicati.Library.Main.Operation.Backup.BackupDatabase database, Duplicati.Library.Main.Operation.Backup.BackupStatsCollector stats, Duplicati.Library.Main.Options options, Duplicati.Library.Utility.IFilter sourcefilter, Duplicati.Library.Utility.IFilter filter, Duplicati.Library.Main.BackupResults result, Duplicati.Library.Main.Operation.Common.ITaskReader taskreader, System.Int64 filesetid, System.Int64 lastfilesetid, System.Threading.CancellationToken token) [0x0035f] in <8f1de655bd1240739a78684d845cecc8>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00a12] in <8f1de655bd1240739a78684d845cecc8>:0 

I made the above summary yesterday to confirm what I thought it was doing. You can see that after the “6 of 5” there are three that weren’t at 6 yet, and beneath those others (but not the 6) there’s a “Retrying” line.

I’m kind of curious if the 10 second delay before “Could not find file” is related to the default 10 second time between “Retrying” declaration and actually trying to do the upload (see prior examples). Maybe something cleaned up files when it was clear that one uploader exhausted its retries, then a different uploader tripped.

  --asynchronous-concurrent-upload-limit (Integer): The number of concurrent
    uploads allowed
    When performing asynchronous uploads, the maximum number of concurrent
    uploads allowed. Set to zero to disable the limit.
    * default value: 4

could be an experiment to see if it somehow helps either your “Could not find file” (by avoiding the tripping over a deleted file), or by changing upload characteristics if you suspect that’s somehow causing the 403.

@kmand

How does the retry limit work?

Per-transfer. You have 4 going on at once, all started at about the same time (see top of my analysis), but over time one got ahead of the others. You can see an earlier spot where the Google time-until-403 varied.

@kmand

This wasn’t fatal since the log goes on with more transactions.

I’m not seeing that. After the 6 of 5, there is nothing else “Started”. Don’t be confused by “Retrying” intents.

@kmand

My google drive is a Google Suite account with no storage limit.

Sounds like a paid plan. If you’re paying, do you have support to ask Google why they give 403 Forbidden?

EDIT:

@kmand

The only thing I can think of is bandwidth throttling.

If you wish to try that, 2.0.5.1 can throttle upload but mistakenly throttles download too. It’s fixed in Canary.

[kmand]

The google suite account is a free edu account that Google waives space limit, but its not clear that we get any support. I did try posting to google developers at stackoverflow

(403) Forbidden Error on Put but succeeds on retry

The most interesting comment to me so far is "the response also contains a “JSON object in the response body with additional details”

From the API doc, they give examples like

{
“error”: {
“errors”: [
{
“domain”: “usageLimits”,
“reason”: “userRateLimitExceeded”,
“message”: “User Rate Limit Exceeded”
}
],
“code”: 403,
“message”: “User Rate Limit Exceeded”
}
}

Is there any chance we could get the log to output the full domain/reason/message?

[ts678]

@kmand

Is there any chance we could get the log to output the full domain/reason/message?

I have not seen any such log capability, however it would be a valuable enhancement…

If this were on Windows and .NET Framework, you could use Network Tracing like this:

Network Tracing in the .NET Framework

How to enable network tracing in .NET on mono? has a clear reply that mono lacks this.

If you have a mono debugger, you might be able to study the response here (guessing).
HttpWebRequest.GetResponse is the Microsoft documentation. I’m not at all an expert.

There are some exotic methods to capture encrypted traffic, to decrypt, e.g. mitmproxy.

Logging encrypted data in the clear must be done carefully because it may leak secrets.
If you wish, you could file a GitHub issue for experts to consider at least better error logs.

If any experts are on the forum, feel free to chime in on how to log the right amount here.
Ideally it would be somewhat general-purpose. Many things (and much code) use HTTP.