"Waiting for upload to finish"

SlippinJimmy · July 21, 2021, 8:27am

Hi,
My backup into onedrive has recently stopped completing, it now always ends up getting stuck on ‘Waiting for upload to finish’ with no network activity.
Looking in the onedrive folder it’s going into, there are files modified in there from 4am (when the schedule starts) all the way until 9am with files in between with 2minute increments, when this usually only takes about 2 hours max. I’ve tried to grab some logs but I can’t find a way to do so.
I’m running duplicati beta in a docker container on Unraid.

Here’s the current server state under ‘About’;
The only number that keeps updating on this screen is “BackendSpeed” and it just seems to be slowly dropping.

Server state properties
lastEventId : 306
lastDataUpdateId : 16
lastNotificationUpdateId : 2
estimatedPauseEnd : 0001-01-01T00:00:00
activeTask : {"Item1":4,"Item2":"1"}
programState : Running
lastErrorMessage :
connectionState : connected
xsfrerror : false
connectionAttemptTimer : 0
failedConnectionAttempts : 0
lastPgEvent : {"BackupID":"1","TaskID":4,"BackendAction":"Put","BackendPath":"ParallelUpload","BackendFileSize":121235040900,"BackendFileProgress":118183792568,"BackendSpeed":5946469,"BackendIsBlocking":false,"CurrentFilename":null,"CurrentFilesize":0,"CurrentFileoffset":0,"CurrentFilecomplete":false,"Phase":"Backup_WaitForUpload","OverallProgress":0,"ProcessedFileCount":4654,"ProcessedFileSize":116277705825,"TotalFileCount":4654,"TotalFileSize":116277705825,"StillCounting":false}
updaterState : Waiting
updatedVersion :
updateReady : false
updateDownloadProgress : 0
proposedSchedule : [{"Item1":"1","Item2":"2021-07-22T03:00:00Z"},{"Item1":"2","Item2":"2021-07-22T03:00:00Z"}]
schedulerQueueIds : [{"Item1":5,"Item2":"2"}]
pauseTimeRemain : 0

ts678 · July 28, 2021, 5:37pm

Welcome to the forum @SlippinJimmy

For short runs at low detail, server live log at About → Show log → Live → Retry is a good start.
log-file=<path> at log-file-log-level=<level> is better, and (if one has space) can use higher level.
Retry is still a good start. Maximum is Profiling whose logs can be huge but still might not be
enough.to actually debug the whole issue, as @Xavron has noted in some hang-hunting work.

My thought is logs are still useful to understand the general neighborhood, e.g. did Duplicati start
an upload that hung and didn’t complete? That may become easier to see with Advanced option:

C:\ProgramData\Duplicati\duplicati-2.0.5.114_canary_2021-03-10>Duplicati.CommandLine.exe help asynchronous-concurrent-upload-limit
  --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

So if you set that to 1, your uploads will probably be slower (fewer parallel uploads to fill up the network), however you won’t have to manually track concurrent uploads to see if one got stuck. It will be obvious…
Additionally, it might be useful to see if an upload started but didn’t complete, or if nothing was even tried.

I’m not expert in upload code, but I think the speed is computed in progress per time (bytes per second).
This means that if progress stops, time keeps moving and the computed bytes per second slowly sags:

github.com

duplicati/duplicati/blob/265d202a1f99f12f7c5bcf8b9e0deac50ac799c3/Duplicati/Library/Main/ProgressClasses.cs#L250-L268


      
          public void Update(out BackendActionType action, out string path, out long size, out long progress, out long bytes_pr_second, out bool isBlocking)

          {

              lock(m_lock)

              {

                  action = m_action;

                  path = m_path;

                  size = m_size;

                  progress = m_progress;

                  isBlocking = m_blockingSince.Ticks > 0 && (DateTime.Now - m_blockingSince).TotalSeconds > 1;

                      

                  //TODO: The speed should be more dynamic,

                  // so we need a sample window instead of always 

                  // calculating from the beginning

                  if (m_progress <= 0 || m_size <= 0 || m_actionStart.Ticks == 0)

                      bytes_pr_second = -1;

                  else

                      bytes_pr_second = (long)(m_progress / (DateTime.Now - m_actionStart).TotalSeconds);

              }

          }

Your BackendFileSize and BackendFileProgress are higher than I’m used to seeing, almost like the complete backup size. I’m used to it looking like Remote volume size on Options. What is yours?

ts678 · July 28, 2021, 11:02pm

Another method that isn’t logs is to look at the Duplicati database, which I guess on Docker would be to look at it from Unraid where presumably you are storing it (you don’t want persistent data in the Docker).

DB Browser for SQLite (often sqlitebrowser in distro package terms) can probably open the DB read-only (alternatively, make a copy to look at). In the Remotevolume table you can sort on the State column and scroll around. Anything not Verified is a possible concern. You can also filter by typing Uploading into the Filter box. These might be stuck. I think ones that made it are Uploaded. They go to Verified when listed at the end of the backup, but you never made it that far this time, but you likely have old ones.