Backup "stuck" after restore from Sleep


#1

Hi,

Using the 2nd Beta of Duplicati 2.0 on MacOS, I’ve noticed that if a backup was running while the computer goes into hibernation, when the computer is turned on, the UI reports the backup as on-going, but nothing is happening ( no progress, I need nothing in the profiling live logs, etc. ). The pause after hibernation setting is set to 0 seconds.

Cheers,


Duplicati Hangs after Internet Disconnect
#2

Just to clarify, this is happening when the machine goes into full hibernation, not just “sleep mode”, right?

Also, do you know:

  • Does it happen if you manually trigger hibernation? (Perhaps there’s some pre-hibernate cleanup going on that’s causing the issue.)

  • If so, is it still “stuck” even if you bring it out of hibernation right away? (Perhaps there’s a clock issue such that Duplicati gets confused about what time it is after a hibernation wake-up.)

  • Did you use any previous version of Duplicati and, if so, did it happen with that one as well?


#3

Hi Jon,

I updated the title of the thread to be a bit more clear. On forgot to make the distinction between sleep and hibernation. In the case of Mac, sleep is when internal components are shutdown to save energy, as opposed to hibernation when the memory of the Mac is copied to disk.

In my case, the computer is asleep, but not in hibernation. I can tell because it turns back on pretty quickly.

As for the questions:

  1. I’m triggering the sleep manually by closing the lid on the computer. However, I think it doesn’t truly go into hibernation.

  2. The times the computer had gone into sleep itself, If I reopened the computer within a couple of minutes, the backup continued. However, since these are laptops, when it is resumed, sometimes the destination is not available.

  3. Yeah, and same behaviour. I was using the previous beta, and some canary build.

You want me to run any specific tests? I might have some time this weekend.


#4

Hi,

I’m also adding a screenshot of the logs once I reopen the computer. We are April 26th today, but the last live logs are from the 24th. I left the computer on for an hour and no live logs came in.


#5

The next time this happens can you check what’s in the estimatedPauseEnd, programState, and pauseTimeRemain rows in the “Server state properties” at the bottom of the “About” -> “System Info” page?

I suspect it will look something like this, which means we can confirm it’s not stuck in a paused mode for some reason.

Server state properties
lastEventId : 44
lastDataUpdateId : 2
lastNotificationUpdateId : 0
estimatedPauseEnd : 0001-01-01T00:00:00
activeTask :
programState : Running
lastErrorMessage :
connectionState : connected
xsfrerror : false
connectionAttemptTimer : 0
failedConnectionAttempts : 0
lastPgEvent :
updaterState : Waiting
updatedVersion : 2.0.2.19_canary_2018-02-12
updateReady : false
updateDownloadProgress : 0
proposedSchedule : []
schedulerQueueIds : []
pauseTimeRemain : 0


Perhaps you are running into something like what’s discussed here:

In the log image you shared it looks like the last thing what was started was a “Backend event: Put”, which supports the above theory. Are you able to look further back (or check going forward) if the last thing to happen before each stall is a “Backend event: Put”?


#6

Hi Jon,

I’m starting to be a believer in your theory that it’s really the lost connection that is causing them problem. Here are the logs from my laptop for a morning backup several days ago. That said, I had Internet connection at that time, but no network connectivity to the S3 bucket I’m backuping to.

  • Apr 27, 2018 8:34 AM: Backend event: Put - Started: duplicati-b96e2c9a105fe4a83a9bbdc14f3383c3b.dblock.zip.aes (49.99 MB)
  • Apr 27, 2018 8:34 AM: Starting - RemoteOperationPut
  • Apr 27, 2018 8:33 AM: Renaming “duplicati-b596c18e5450f452ea4f76758ea40d8ff.dblock.zip.aes” to “duplicati-b96e2c9a105fe4a83a9bbdc14f3383c3b.dblock.zip.aes”
  • Apr 27, 2018 8:33 AM: Backend event: Put - Rename: duplicati-b96e2c9a105fe4a83a9bbdc14f3383c3b.dblock.zip.aes (49.99 MB)
  • Apr 27, 2018 8:33 AM: Backend event: Put - Rename: duplicati-b596c18e5450f452ea4f76758ea40d8ff.dblock.zip.aes (49.99 MB)
  • Apr 27, 2018 8:33 AM: Backend event: Put - Retrying: duplicati-b596c18e5450f452ea4f76758ea40d8ff.dblock.zip.aes (49.99 MB)
  • Apr 27, 2018 8:33 AM: Operation Put with file duplicati-b596c18e5450f452ea4f76758ea40d8ff.dblock.zip.aes attempt 1 of 5 failed with message: Cannot access a disposed object. Object name: ‘System.Net.Sockets.NetworkStream’.
  • Apr 27, 2018 8:33 AM: RemoteOperationPut took 00:52:55.598
  • Apr 27, 2018 8:33 AM: CommitAddBlockToOutputFlush took 00:00:00.192
  • Apr 27, 2018 8:33 AM: Starting - CommitAddBlockToOutputFlush
  • Apr 27, 2018 8:33 AM: ExecuteReader: SELECT DISTINCT “Hash”, “Size” FROM “Block” WHERE “VolumeID” = ? took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteReader: SELECT DISTINCT “Hash”, “Size” FROM “Block” WHERE “VolumeID” = ?
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid();
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ? took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ?
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid();
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ? took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ?
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid();
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ? took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ?
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid();
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ? took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: SELECT “ID” FROM “Block” WHERE “Hash” = ? AND “Size” = ?
  • Apr 27, 2018 8:33 AM: ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
  • Apr 27, 2018 8:33 AM: Starting - ExecuteScalarInt64: INSERT INTO “Block” (“Hash”, “VolumeID”, “Size”) VALUES (?, ?, ?); SELECT last_insert_rowid();

Also, here are my system properties:

System properties

  • APIVersion : 1
  • PasswordPlaceholder :
  • ServerVersion : 2.0.3.3
  • ServerVersionName : - 2.0.3.3_beta_2018-04-02
  • ServerVersionType : Beta
  • BaseVersionName : 2.0.3.3_beta_2018-04-02
  • DefaultUpdateChannel : Beta
  • DefaultUsageReportLevel : Information
  • ServerTime : 2018-04-30T07:28:12.61894-04:00
  • OSType : OSX
  • DirectorySeparator : /
  • PathSeparator : :
  • CaseSensitiveFilesystem : false
  • MonoVersion : 5.4.1.6
  • MachineName : AlphaBravo.local
  • NewLine :
  • CLRVersion : 4.0.30319.42000
  • CLROSInfo : {“Platform”:“Unix”,“ServicePack”:"",“Version”:“17.6.0.0”,“VersionString”:“Unix 17.6.0.0”}
  • ServerModules : []
  • UsingAlternateUpdateURLs : false
  • LogLevels : [“Profiling”,“Information”,“Warning”,“Error”]
  • SuppressDonationMessages : false
  • SpecialFolders : [{“ID”:"%MY_DOCUMENTS%",“Path”:"/var/root"},{“ID”:"%MY_MUSIC%",“Path”:"/var/root/Music"},{“ID”:"%MY_PICTURES%",“Path”:"/var/root/Pictures"},{“ID”:"%DESKTOP%",“Path”:"/var/root/Desktop"},{“ID”:"%HOME%",“Path”:"/var/root"}]
  • BrowserLocale : {“Code”:“en-CA”,“EnglishName”:“English (Canada)”,“DisplayName”:“English (Canada)”}
  • SupportedLocales : [{“Code”:“cs”,“EnglishName”:“Czech”,“DisplayName”:“čeština”},{“Code”:“da”,“EnglishName”:“Danish”,“DisplayName”:“dansk”},{“Code”:“de”,“EnglishName”:“German”,“DisplayName”:“Deutsch”},{“Code”:“en”,“EnglishName”:“English”,“DisplayName”:“English”},{“Code”:“es”,“EnglishName”:“Spanish”,“DisplayName”:“español”},{“Code”:“fi”,“EnglishName”:“Finnish”,“DisplayName”:“suomi”},{“Code”:“fr”,“EnglishName”:“French”,“DisplayName”:“français”},{“Code”:“it”,“EnglishName”:“Italian”,“DisplayName”:“italiano”},{“Code”:“lt”,“EnglishName”:“Lithuanian”,“DisplayName”:“lietuvių”},{“Code”:“lv”,“EnglishName”:“Latvian”,“DisplayName”:“latviešu”},{“Code”:“nl-NL”,“EnglishName”:“Dutch (Netherlands)”,“DisplayName”:“Nederlands (Nederland)”},{“Code”:“pl”,“EnglishName”:“Polish”,“DisplayName”:“polski”},{“Code”:“pt”,“EnglishName”:“Portuguese”,“DisplayName”:“português”},{“Code”:“pt-BR”,“EnglishName”:“Portuguese (Brazil)”,“DisplayName”:“português (Brasil)”},{“Code”:“ru”,“EnglishName”:“Russian”,“DisplayName”:“русский”},{“Code”:“sk-SK”,“EnglishName”:“Slovak (Slovakia)”,“DisplayName”:“slovenčina (Slovensko)”},{“Code”:“zh-CN”,“EnglishName”:“Chinese (Simplified)”,“DisplayName”:“中文 (中国)”},{“Code”:“zh-HK”,“EnglishName”:“Chinese (Traditional, Hong Kong SAR China)”,“DisplayName”:“中文 (中国香港特别行政区)”},{“Code”:“zh-TW”,“EnglishName”:“Chinese (Traditional)”,“DisplayName”:“中文 (台湾)”}]
  • BrowserLocaleSupported : true
  • backendgroups : {“std”:{“ftp”:null,“ssh”:null,“webdav”:null,“openstack”:“OpenStack Object Storage / Swift”,“s3”:“S3 Compatible”,“aftp”:“FTP (Alternative)”},“local”:{“file”:null},“prop”:{“s3”:null,“azure”:null,“googledrive”:null,“onedrive”:null,“cloudfiles”:null,“gcs”:null,“openstack”:null,“hubic”:null,“amzcd”:null,“b2”:null,“mega”:null,“box”:null,“od4b”:null,“mssp”:null,“dropbox”:null,“sia”:null,“jottacloud”:null,“rclone”:null}}
  • GroupTypes : [“Local storage”,“Standard protocols”,“Proprietary”,“Others”]
  • Backend modules: aftp amzcd azure b2 box cloudfiles dropbox ftp file googledrive gcs hubic jottacloud mega onedrive openstack rclone s3 ssh od4b mssp sia tahoe webdav
  • Compression modules: zip 7z
  • Encryption modules: aes gpg

Server state properties

  • lastEventId : 1298
  • lastDataUpdateId : 24
  • lastNotificationUpdateId : 6
  • estimatedPauseEnd : 0001-01-01T00:00:00
  • activeTask : {“Item1”:7,“Item2”:“2”}
  • programState : Running
  • lastErrorMessage :
  • connectionState : connected
  • xsfrerror : false
  • connectionAttemptTimer : 0
  • failedConnectionAttempts : 0
  • lastPgEvent : {“BackupID”:“2”,“TaskID”:7,“BackendAction”:“Put”,“BackendPath”:“duplicati-b96e2c9a105fe4a83a9bbdc14f3383c3b.dblock.zip.aes”,“BackendFileSize”:52415213,“BackendFileProgress”:0,“BackendSpeed”:-1,“BackendIsBlocking”:true,“CurrentFilename”:"/Users/adenau/Documents/Personel/Condo Honore-Beaugrand/2008-Condo Maintenance/DSC05428.JPG",“CurrentFilesize”:3130031,“CurrentFileoffset”:1024000,“Phase”:“Backup_ProcessingFiles”,“OverallProgress”:0,“ProcessedFileCount”:384693,“ProcessedFileSize”:37897287441,“TotalFileCount”:428181,“TotalFileSize”:47749337761,“StillCounting”:false}
  • updaterState : Waiting
  • updatedVersion :
  • updateReady : false
  • updateDownloadProgress : 0
  • proposedSchedule : [{“Item1”:“1”,“Item2”:“2018-04-30T13:00:00Z”},{“Item1”:“2”,“Item2”:“2018-05-01T04:59:00Z”}]
  • schedulerQueueIds : [{“Item1”:8,“Item2”:“1”},{“Item1”:9,“Item2”:“2”}]
  • pauseTimeRemain : 0

#7

Thanks for the detail!

I’ll try looking into the BackendIsBlocked stuff to see if it can help narrow things down a bit.


#8

Any update on this? I seem to be having a similar problem.
I am backing up to an SSH destination. I set up a new backup yesterday (after I couldn’t get the previous one to complete), and after sending 1.7G of data (out of about 10G), It hasn’t done anything for over 12 hours.

System properties

APIVersion : 1
PasswordPlaceholder : **********
ServerVersion : 2.0.3.13
ServerVersionName : - 2.0.3.13_canary_2018-10-31
ServerVersionType : Canary
StartedBy : Tray icon
BaseVersionName : 2.0.2.1_beta_2017-08-01
DefaultUpdateChannel : Canary
DefaultUsageReportLevel : Information
ServerTime : 2018-11-07T08:40:54.9578962-05:00
OSType : Windows
DirectorySeparator : \
PathSeparator : ;
CaseSensitiveFilesystem : false
MonoVersion :
MachineName : ASROCK_H81M-HDS
UserName : Owner
NewLine : 
CLRVersion : 4.0.30319.42000
CLROSInfo : {"Platform":"Win32NT","ServicePack":"","Version":"6.2.9200.0","VersionString":"Microsoft Windows NT 6.2.9200.0"}
ServerModules : []
UsingAlternateUpdateURLs : false
LogLevels : ["ExplicitOnly","Profiling","Verbose","Retry","Information","DryRun","Warning","Error"]
SuppressDonationMessages : false
SpecialFolders : [{"ID":"%MY_DOCUMENTS%","Path":"C:\\Users\\Owner\\Documents"},{"ID":"%MY_MUSIC%","Path":"C:\\Users\\Owner\\Music"},{"ID":"%MY_PICTURES%","Path":"C:\\Users\\Owner\\Pictures"},{"ID":"%MY_VIDEOS%","Path":"C:\\Users\\Owner\\Videos"},{"ID":"%DESKTOP%","Path":"C:\\Users\\Owner\\Desktop"},{"ID":"%APPDATA%","Path":"C:\\Users\\Owner\\AppData\\Roaming"},{"ID":"%HOME%","Path":"C:\\Users\\Owner"}]
BrowserLocale : {"Code":"en-US","EnglishName":"English (United States)","DisplayName":"English (United States)"}
SupportedLocales : [{"Code":"bn","EnglishName":"Bangla","DisplayName":"বাংলা"},{"Code":"ca","EnglishName":"Catalan","DisplayName":"català"},{"Code":"cs","EnglishName":"Czech","DisplayName":"čeština"},{"Code":"da","EnglishName":"Danish","DisplayName":"dansk"},{"Code":"de","EnglishName":"German","DisplayName":"Deutsch"},{"Code":"en","EnglishName":"English","DisplayName":"English"},{"Code":"es","EnglishName":"Spanish","DisplayName":"español"},{"Code":"fi","EnglishName":"Finnish","DisplayName":"suomi"},{"Code":"fr","EnglishName":"French","DisplayName":"français"},{"Code":"hu","EnglishName":"Hungarian","DisplayName":"magyar"},{"Code":"it","EnglishName":"Italian","DisplayName":"italiano"},{"Code":"ja-JP","EnglishName":"Japanese (Japan)","DisplayName":"日本語 (日本)"},{"Code":"ko","EnglishName":"Korean","DisplayName":"한국어"},{"Code":"lt","EnglishName":"Lithuanian","DisplayName":"lietuvių"},{"Code":"lv","EnglishName":"Latvian","DisplayName":"latviešu"},{"Code":"nl-NL","EnglishName":"Dutch (Netherlands)","DisplayName":"Nederlands (Nederland)"},{"Code":"pl","EnglishName":"Polish","DisplayName":"polski"},{"Code":"pt","EnglishName":"Portuguese","DisplayName":"português"},{"Code":"pt-BR","EnglishName":"Portuguese (Brazil)","DisplayName":"português (Brasil)"},{"Code":"ro","EnglishName":"Romanian","DisplayName":"română"},{"Code":"ru","EnglishName":"Russian","DisplayName":"русский"},{"Code":"sk","EnglishName":"Slovak","DisplayName":"slovenčina"},{"Code":"sk-SK","EnglishName":"Slovak (Slovakia)","DisplayName":"slovenčina (Slovensko)"},{"Code":"sr-RS","EnglishName":"Unknown Locale (sr-RS)","DisplayName":"Unknown Locale (sr-RS)"},{"Code":"sv-SE","EnglishName":"Swedish (Sweden)","DisplayName":"svenska (Sverige)"},{"Code":"th","EnglishName":"Thai","DisplayName":"ไทย"},{"Code":"zh-CN","EnglishName":"Chinese (Simplified, China)","DisplayName":"中文(中国)"},{"Code":"zh-HK","EnglishName":"Chinese (Traditional, Hong Kong SAR)","DisplayName":"中文(香港特別行政區)"},{"Code":"zh-TW","EnglishName":"Chinese (Traditional, Taiwan)","DisplayName":"中文(台灣)"}]
BrowserLocaleSupported : true
backendgroups : {"std":{"ftp":null,"ssh":null,"webdav":null,"openstack":"OpenStack Object Storage / Swift","s3":"S3 Compatible","aftp":"FTP (Alternative)"},"local":{"file":null},"prop":{"s3":null,"azure":null,"googledrive":null,"onedrive":null,"cloudfiles":null,"gcs":null,"openstack":null,"hubic":null,"amzcd":null,"b2":null,"mega":null,"box":null,"od4b":null,"mssp":null,"dropbox":null,"sia":null,"jottacloud":null,"rclone":null}}
GroupTypes : ["Local storage","Standard protocols","Proprietary","Others"]
Backend modules: aftp amzcd azure b2 box cloudfiles dropbox file ftp googledrive gcs hubic jottacloud mega msgroup onedrive onedrivev2 sharepoint openstack rclone s3 od4b mssp sia ssh tahoe webdav
Compression modules: zip 7z
Encryption modules: aes gpg
Server state properties
lastEventId : 214
lastDataUpdateId : 5
lastNotificationUpdateId : 0
estimatedPauseEnd : 0001-01-01T00:00:00
activeTask : {"Item1":2,"Item2":"4"}
programState : Running
lastErrorMessage :
connectionState : connected
xsfrerror : false
connectionAttemptTimer : 0
failedConnectionAttempts : 0
lastPgEvent : {"BackupID":"4","TaskID":2,"BackendAction":"Put","BackendPath":"duplicati-b5b5f034049ca47f497c4113a57d85fb9.dblock.zip.aes","BackendFileSize":52360381,"BackendFileProgress":52360381,"BackendSpeed":1158,"BackendIsBlocking":true,"CurrentFilename":"C:\\Users\\Owner\\Downloads\\LifeCam3.60.exe","CurrentFilesize":22660464,"CurrentFileoffset":0,"Phase":"Backup_ProcessingFiles","OverallProgress":0,"ProcessedFileCount":1209,"ProcessedFileSize":1142669189,"TotalFileCount":63143,"TotalFileSize":10885679602,"StillCounting":false}
updaterState : Waiting
updatedVersion :
updateReady : false
updateDownloadProgress : 0
proposedSchedule : [{"Item1":"4","Item2":"2018-11-08T07:00:00Z"}]
schedulerQueueIds : [{"Item1":3,"Item2":"4"}]
pauseTimeRemain : 0

#9

Unfortunately I don’t think anything has progressed here. Most likely you’re running into the issue where Duplicati doesn’t detect an interruption during an upload and ends up waiting forever for a response from the destination that the upload has completed.

Cancelling and restarting the job should continue where it left off.

I don’t know enough about how uploads happen to know if there’s a way to set a failure timeout or monitor throughout to detect this. :frowning:


#10

Ok that helps.
I do find that cancelling and restarting seems to work, sort of. The issue is that when I restart I get a ‘database is locked’ message. I don’t know how to fix that, so I end up rebooting before restarting the backup.
Is there an easier way to unlock the database?


#11

This is likely due to the database being locked while a backup is running (per The database file is locked database is locked).

However, after restarting Duplicati the lock should be removed - is it possible you’re restarting the GUI but not the server?


#12

probably… how do i restart the server?


#13

When you say “cancelling and restarting” do you mean in the web GUI you hit the Cancel button then when that’s done you click the “Run now” link?

If so, when you hit “Cancel” do you select “right away” or “after next upload”?


#14

I have tried both.
When I use “after…”, it goes on for a long time, as this is a big backup that hasn’t ever finished.
When I use “right away”, I get an error message pop-up about cancellation.
Once I clear the pop-up message, I then select “run now”.


#15

My guess is that the “cancel right away” option is either not closing the database as it should or (more likely) allowing a subsequent cleanup step to occur (thus re-locking the database).

Since you’re running Windows and it appears you’re using the tray icon (not a service) you should be able to use the Task Manager (Ctrl+Shift+Escape) Processes tab to find the Duplicati process then click the “End Process” button in the lower right.

If I’m wrong and you are using the service, in Task Manager use the Services tab to find Duplicati then right click on it and select Restart (or “Stop Service” then “Start Service” if Restart isn’t an option).