Have an odd case here, I’ve done probably 6-7 largeish >1TB backups as I’ve played with things and haven’t ran into this issue.
~1TB of data, full backup was going to take a long while so I haven’t been watching it very close. Checked it a bit ago and see it got down to about 250GB left and hung. Backup shows it’s still running, still connected to SFTP server, but nothing is happening. No errors in the logs. This is the last couple of entries in the logs from several hours ago.
Oct 15, 2017 12:19 AM: CommitAddBlockToOutputFlush took 00:00:00.006
Oct 15, 2017 12:19 AM: Starting - CommitAddBlockToOutputFlush
Oct 15, 2017 12:19 AM: ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ? took 00:00:00.000
Oct 15, 2017 12:19 AM: Starting - ExecuteReader: SELECT DISTINCT "Hash", "Size" FROM "Block" WHERE "VolumeID" = ?
Oct 15, 2017 12:19 AM: ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid(); took 00:00:00.000
Oct 15, 2017 12:19 AM: Starting - ExecuteScalarInt64: INSERT INTO "Block" ("Hash", "VolumeID", "Size") VALUES (?, ?, ?); SELECT last_insert_rowid();
I’m going to leave it in a broken state in case @kenkendk or anyone wants me to try any troubleshooting.
Digging a bit more, looks like my external drive on the back end system hiccuped for a moment. Here is the SFTP log for when things quit:
<event seq="8160" time="2017-10-15 00:19:55.381484" app="BvSshServer 7.34" name="I_SFS_TRANSFER_FILE" desc="Virtual filesystem: transfer file.">
<session id="1017" service="SSH" remoteAddress="172.0.0.21:51412" virtualAccount="sftpuser" windowsAccount="Server\BvSsh_VirtualUsers"/>
<channel type="session" id="1"/>
<sfs moduleName="FlowSfsWin" mountPath="/" code="90000" desc="Transferring file ended.">
<parameters path="D:\Backups\Duplicati\F\duplicati-b254f4fa14f6e4db8b0dedffc538751f6.dblock.zip.aes" timeMs="29930" bytesRead="0" bytesWritten="251701117" readRangeOffset="0" readRangeLength="0" writeRangeOffset="0" writeRangeLength="251701117" createdNewFile="true" resizedFile="false" endedBy="Client"/>
<help message="File transfer ended by client."/>
</sfs>
</event>
<event seq="8161" time="2017-10-15 00:19:55.404325" app="BvSshServer 7.34" name="I_SFS_TRANSFER_FILE" desc="Virtual filesystem: transfer file.">
<session id="1017" service="SSH" remoteAddress="172.0.0.21:51412" virtualAccount="sftpuser" windowsAccount="Server\BvSsh_VirtualUsers"/>
<channel type="session" id="1"/>
<sfs moduleName="FlowSfsWin" mountPath="/" code="90000" desc="Transferring file ended.">
<parameters path="D:\Backups\Duplicati\F\duplicati-i276ec606dd134135ad46ce39df19610a.dindex.zip.aes" timeMs="47" bytesRead="0" bytesWritten="1709" readRangeOffset="0" readRangeLength="0" writeRangeOffset="0" writeRangeLength="1709" createdNewFile="true" resizedFile="false" endedBy="Client"/>
<help message="File transfer ended by client."/>
</sfs>
</event>
<event seq="8162" time="2017-10-15 00:20:17.524323" app="BvSshServer 7.34" name="I_SFS_WRITE_FILE" desc="Virtual filesystem: write file.">
<session id="1017" service="SSH" remoteAddress="172.0.0.21:51412" virtualAccount="sftpuser" windowsAccount="Server\BvSsh_VirtualUsers"/>
<channel type="session" id="1"/>
<sfs moduleName="FlowSfsWin" mountPath="/" code="23200" desc="Writing file failed.">
<parameters path="D:\Backups\Duplicati\F\duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes" offset="160818880" length="32740" statusCode="NoSuchFile"/>
<error type="WinApi" operation="GetOverlappedResult()" code="2" message="The system cannot find the file specified."/>
</sfs>
</event>
<event seq="8163" time="2017-10-15 00:20:17.685886" app="BvSshServer 7.34" name="I_SFS_WRITE_FILE" desc="Virtual filesystem: write file.">
<session id="1017" service="SSH" remoteAddress="172.0.0.21:51412" virtualAccount="sftpuser" windowsAccount="Server\BvSsh_VirtualUsers"/>
<channel type="session" id="1"/>
<sfs moduleName="FlowSfsWin" mountPath="/" code="23200" desc="Writing file failed.">
<parameters path="D:\Backups\Duplicati\F\duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes" offset="160851620" length="32740" statusCode="NoMedia"/>
<error type="WinApi" operation="GetOverlappedResult()" code="21" message="The device is not ready."/>
</sfs>
</event>
Here are the last actions from the backup log:
Oct 15, 2017 12:19 AM: put duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes
Oct 15, 2017 12:19 AM: put duplicati-i276ec606dd134135ad46ce39df19610a.dindex.zip.aes
Oct 15, 2017 12:19 AM: put duplicati-b254f4fa14f6e4db8b0dedffc538751f6.dblock.zip.aes
I don’t follow the USB error messages, did it come back online but Duplicati didn’t realize it so stayed “stuck”?
Yeah, the error messages are what was logged by the SFTP service on the destination computer. Must have just been a short blip as everything is fine when I look at it now.
About half a dblock was transferred before the blip, but for whatever reason Duplicati didn’t catch the error message returned from the SFTP server so I guess it still thinks it’s transferring?
Not a big deal, as it was a problem on the destination ultimately not Duplicati, just a weird edge case that seems to have thrown Duplicati into an inconsistent state.
Yep - but I was curious anyway. If the message is being provided back to Duplicati then we should make sure it’s handled, and if the message doesn’t get back then I would expect Duplicati to eventually time out and (hopefully) check the destination, see the too-small file, and re-send. In theory, the timeout duration could even be set based on how long it’s taking to upload similarly size dblocks.
The SFTP library should timeout at some point (especially once the network connection times out). Not sure why this has not happened.
The SFTP session is still established, just the transfer itself failed.
Going to disconnect the session to see what happens.
FYI, figured out why my USB drive went offline for a minute or so, was a short power blip 
Ok, that is a weird issue with the SFTP library then, but I understand how it works.
Edit: yes, try to disconnect the connection, that should start a retry.
Duplicati properly detected the session dying and it picked up and carried on.
Oct 16, 2017 2:34 PM: Backend event: Put - Started: duplicati-i2441372c769643c79d35c6d07faefeed.dindex.zip.aes (1.65 KB)
Oct 16, 2017 2:34 PM: CommitAddBlockToOutputFlush took 00:00:00.000
Oct 16, 2017 2:34 PM: Starting - CommitAddBlockToOutputFlush
Oct 16, 2017 2:34 PM: Starting - RemoteOperationPut
Oct 16, 2017 2:34 PM: RemoteOperationPut took 00:00:40.175
Oct 16, 2017 2:34 PM: Backend event: Put - Completed: duplicati-b25f0bb7674784b5e9609cf24ffdea525.dblock.zip.aes (240.04 MB)
Oct 16, 2017 2:34 PM: Uploaded 240.04 MB in 00:00:40.1600720, 5.98 MB/s
Oct 16, 2017 2:33 PM: Backend event: Put - Started: duplicati-b25f0bb7674784b5e9609cf24ffdea525.dblock.zip.aes (240.04 MB)
Oct 16, 2017 2:33 PM: Starting - RemoteOperationPut
Oct 16, 2017 2:30 PM: Renaming "duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes" to "duplicati-b25f0bb7674784b5e9609cf24ffdea525.dblock.zip.aes"
Oct 16, 2017 2:30 PM: Backend event: Put - Rename: duplicati-b25f0bb7674784b5e9609cf24ffdea525.dblock.zip.aes (240.04 MB)
Oct 16, 2017 2:30 PM: Backend event: Put - Rename: duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes (240.04 MB)
Oct 16, 2017 2:30 PM: Backend event: Put - Retrying: duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes (240.04 MB)
Oct 16, 2017 2:30 PM: Operation Put with file duplicati-b705e9cbef3e2404891c2d78c1296282e.dblock.zip.aes attempt 1 of 10 failed with message: Connection was closed by the server.
Oct 16, 2017 2:30 PM: RemoteOperationPut took 14:10:38.772
Oct 15, 2017 12:19 AM: CommitAddBlockToOutputFlush took 00:00:00.006
Oct 15, 2017 12:19 AM: Starting - CommitAddBlockToOutputFlush
The half uploaded “b705e9cbef3e2404891c2d78c1296282e” dblock still exists on the back end. I expect it’ll get cleaned up in subsequent runs.
Let me know if there is anything else you’d like for me to do/collect, but unless I notice anything else that seems helpful I’ll consider this one done. Thanks!
Yes, do leave it, and Duplicati will say something like “removing partially uploaded file” when it finishes the backup.
Confirmed the partially uploaded file was cleaned up correctly.
2 Likes