Failed to load the snapshot error (problem with CLI 3.0.1)

Flibble · 17 November 2022 16:12

EDIT:
This issue is probably related to problem with Duplicacy CLI 3.0.1 and backups created in 2.7.2 - see reply Failed to load the snapshot error (problem with CLI 3.0.1) - #3 by Flibble below

Original: post:

Hello, I have interesting problem. When listing restore in GUI all revisions all empty:

and in duplicacy_web.log is this error:
Failed to load the snapshot Snapshot_name at revision 5: msgpack: invalid code=5b decoding bytes length
full log from when restoring from duplicacy_web.log:

2022/11/17 16:37:50 Created listing session 58njn
2022/11/17 16:37:50 Running C:\Users\User/.duplicacy-web/bin/duplicacy_win_x64_3.0.1.exe [-log list -id Snapshot_name -r 5 -storage Storage_name -files]
2022/11/17 16:37:50 Set current working directory to C:\TEMP\Duplicacy\repositories/localhost/all
2022/11/17 16:37:50 INFO STORAGE_SET Storage set to sftp://username@server/folder/Storage_name
2022/11/17 16:37:50 INFO SNAPSHOT_INFO Snapshot Snapshot_name revision 5 created at 2021-07-21 11:00 
2022/11/17 16:37:51 Total files: 2873
2022/11/17 16:37:52 ERROR SNAPSHOT_PARSE Failed to load the snapshot Snapshot_name at revision 5: msgpack: invalid code=5b decoding bytes length
2022/11/17 16:37:52 ERROR SNAPSHOT_PARSE Failed to load the snapshot Snapshot_name at revision 5: msgpack: invalid code=5b decoding bytes length
2022/11/17 16:37:52 Failed to list files for backup Snapshot_name revision 5 in the storage Storage_name: Failed to load the snapshot Snapshot_name at revision 5: msgpack: invalid code=5b decoding bytes length
2022/11/17 16:37:54 127.0.0.1:55619 POST /list_restore_directory

How I got to this problem:

I have old big backup on SFTP where everything’s works fine
I created new storage on other SFTP server in GUI with those settings:

different password
check compy-compatible with old backup storage
enabled Erasure Codding 5:2

After that i copy two snapshots with gui and this Options to new SFTP server

-id Snapshot_name -r 1 -upload-limit-rate 10000000 -threads 2
-id Snapshot_name -r 5 -upload-limit-rate 10000000 -threads 2

check command reporting everything ok:

Running check command from /cache/localhost/all
Options: [-log check -storage Storage_name -a -tabular]
2022-11-17 16:29:45.200 INFO STORAGE_SET Storage set to sftp://username@server/folder/Storage_name
2022-11-17 16:29:46.039 INFO SNAPSHOT_CHECK Listing all chunks
2022-11-17 16:31:07.208 INFO SNAPSHOT_CHECK 1 snapshots and 2 revisions
2022-11-17 16:31:07.208 INFO SNAPSHOT_CHECK Total chunk size is 11,979M in 1854 chunks
2022-11-17 16:31:07.213 INFO SNAPSHOT_CHECK All chunks referenced by snapshot Snapshot_name at revision 1 exist
2022-11-17 16:31:07.216 INFO SNAPSHOT_CHECK All chunks referenced by snapshot Snapshot_name at revision 5 exist
2022-11-17 16:31:07.229 INFO SNAPSHOT_CHECK 
        snap   | rev |                          | files |  bytes | chunks |  bytes | uniq |  bytes | new |  bytes |
 Snapshot_name |   1 | @ 2021-07-18 01:16 -hash |  2887 | 3,544M |    622 | 4,165M |    3 |   466K | 622 | 4,165M |
 Snapshot_name |   5 | @ 2021-07-21 11:00       |  2873 | 3,544M |    624 | 4,165M |    5 |   470K |   5 |   470K |
 Snapshot_name | all |                          |       |        |    627 | 4,165M |  627 | 4,165M |     |        |

restoring via gui show empty snapshots and that strange error

EDIT:
Restoring old backup works ok, but I noticed this info in duplicacy_web.log
"revision 1 is encoded in an old version format"

2022/11/17 17:24:52 INFO STORAGE_SET Storage set to sftp://username@OLDserver/OLDfolder/Storage_name
2022/11/17 17:24:53 INFO SNAPSHOT_INFO Snapshot Snapshot_name revision 1 created at 2021-07-18 01:16 -hash (0)
2022/11/17 17:24:53 Total files: 2887
2022/11/17 17:24:53 INFO SNAPSHOT_VERSION snapshot Snapshot_name at revision 1 is encoded in an old version format
2022/11/17 17:24:53 INFO SNAPSHOT_VERSION snapshot Snapshot_name at revision 1 is encoded in an old version format
2022/11/17 17:24:53 Listed 2887 files for backup Snapshot_name revision 1 in the storage Storage_name
2022/11/17 17:24:56 172.17.0.1:46874 POST /list_restore_directory

My environment Duplicacy 3.0.1 and Duplicacy web 1.5.0 and 1.6.3 (same behaviour)

Did I do something wrong? Thank you

Droolio · 18 November 2022 18:00

I’d run check with the -chunks flag on the new sftp just to make sure everything was copied alright.

Flibble · 18 November 2022 19:49

I did, chunks test is ok:

Running check command from /cache/localhost/all
Options: [-log check -storage Storage_name -chunks -threads 4 -a -tabular]
2022-11-18 19:24:15.322 INFO SNAPSHOT_VERIFY Verifying 1155 chunks
2022-11-18 19:24:15.324 INFO SNAPSHOT_VERIFY Skipped 13 chunks that have already been verified before
2022-11-18 19:24:18.909 INFO VERIFY_PROGRESS Verified chunk 29a524dd6634d29e3545251de563703fca173e45edab20161e922e1450ea4815 (2/1142), 476KB/s 00:34:04 0.2%
...
2022-11-18 20:24:54.433 INFO VERIFY_PROGRESS Verified chunk eee548119bad3ec9246c0d704c5b59680fbc0bd6ae82bf89a7d8fa8eb609302e (1142/1142), 997KB/s 00:00:00 100.0%
2022-11-18 20:24:54.433 INFO SNAPSHOT_VERIFY All 1155 chunks have been successfully verified
2022-11-18 20:24:54.567 INFO SNAPSHOT_VERIFY Added 1142 chunks to the list of verified chunks

But - I found that some revisions are empty and some revisions are fine (can be restored)
I have 464 revisions from 18.7.2021 to 17.11.2022

These revisions are blank:

revision 0 - 18.7.2021
...
revision 433 from 22.10.2022 11:56

These revisions will display the file list and restore works

revision 434 - 23.10.2022 11:56
...
revision 464 (latest 17.11.2022)

And now the most interesting thing - the file duplicacy_linux_x64_3.0.1 in bin folder have created date 22.10.2022 13:38

So the only explanation I can think of is that revisions created with “duplicacy_linux_x64_2.7.2” cannot be restored after copy. But revisions that were already created with version 3.0.1 (after 22.10.2022) can be restored after copy.

Does this make sense? The only explanation I can think of is a bug in duplicacy 3.0.1 and some backward compatibility problem?

Thanks

Droolio · 19 November 2022 17:00

Very interesting!

Seems you may be right in that it’s to do with the new v3.0.1 format. I have a slightly different error:

2022/11/19 16:05:30 Running C:\ProgramData/.duplicacy-web/bin/duplicacy_win_x64_2.7.2.exe [-log list -id my_snapshot -r 16217 -storage GCD -files]
2022/11/19 16:05:30 Set current working directory to C:\ProgramData/.duplicacy-web/repositories/localhost/all
2022/11/19 16:05:30 INFO STORAGE_SET Storage set to gcd://duplicacy_backups
2022/11/19 16:05:33 INFO SNAPSHOT_INFO Snapshot my_snapshot revision 16217 created at 2022-11-19 08:15 -vss
2022/11/19 16:05:37 ERROR SNAPSHOT_PARSE Failed to load files specified in the snapshot my_snapshot at revision 16217: not a list of entries
2022/11/19 16:05:37 ERROR SNAPSHOT_PARSE Failed to load files specified in the snapshot my_snapshot at revision 16217: not a list of entries
2022/11/19 16:05:37 Failed to list files for backup my_snapshot revision 16217 in the storage GCD: Failed to load files specified in the snapshot my_snapshot at revision 16217: not a list of entries

As you can see, I hadn’t yet updated to the latest GUI + v3.0.1 CLI on my server. These snapshots are created on my main PC (which is update to v3.0.1) and stored on the server via network share. Server then copies to GCD daily.

Just updated GUI and CLI v3.0.1 on server and getting slightly different, but basically similar error:

2022/11/19 16:16:10 Running C:\ProgramData/.duplicacy-web/bin/duplicacy_win_x64_3.0.1.exe [-log list -id my_snapshot -r 16217 -storage GCD -files]
2022/11/19 16:16:10 Set current working directory to C:\ProgramData/.duplicacy-web/repositories/localhost/all
2022/11/19 16:16:10 INFO STORAGE_SET Storage set to gcd://duplicacy_backups
2022/11/19 16:16:13 INFO SNAPSHOT_INFO Snapshot my_snapshot revision 16217 created at 2022-11-19 08:15 -vss (0)
2022/11/19 16:16:36 Total files: 401936
2022/11/19 16:16:36 INFO SNAPSHOT_VERSION snapshot my_snapshot at revision 16217 is encoded in an old version format
2022/11/19 16:16:36 ERROR SNAPSHOT_PARSE Failed to open the snapshot my_snapshot at revision 16217: not a list of entries
2022/11/19 16:16:36 ERROR SNAPSHOT_PARSE Failed to open the snapshot my_snapshot at revision 16217: not a list of entries
2022/11/19 16:16:36 Failed to list files for backup my_snapshot revision 16217 in the storage GCD: Failed to open the snapshot my_snapshot at revision 16217: not a list of entries

This 16217 revision is recently created this morning with v3.0.1, and copied to GCD with v2.7.2, and neither version is able to unpack it. I can get a file list from my locally stored 16217 revision, though.

Haven’t yet checked older revisions. I, too, started using v3.0.1 on around 21/10/2022.

I figure it might be possible to fix the most recent revisions on GCD, by deleting them and re-copying, but the issue of older revisions remains(?).

Need to do more experimenting…

@gchen This seems to be a pretty serious issue - what happens when snapshot formats are copied with different versions?

Edit: Don’t seem to have any issues with older format revisions, but then that’s probably because none of my revisions on GCD have been copied with v3.0.1 yet(?) - and likely won’t ever be since, all the older snapshots have already been copied and only new revisions will be the newer format.

OPs issues seems to stem from copying v2 format with v3 client. My issue is copying v3 format with v2 client.

The fix?

In OPs case, either Duplicacy copy needs to be fixed and snapshots re-copied, or you’d have to do an initial copy with v2 client and then you’d be OK using v3 from then on.

In my case, I may need to delete my most recent v3-with-v2-copied snapshots, and re-copy with v3.

gchen · 22 November 2022 04:09

This is a bug. CLI 3.0.1 always set the version bit to 1, even when copying old backups, which is a mistake. Here is the culprit line:

github.com

gilbertchen/duplicacy/blob/0a794e6feae91cf0e6511b77a5bf160999c1838e/src/duplicacy_snapshot.go#L437

    
      
          // LoadLengths construct 'ChunkLengths' from the json description.
          func (snapshot *Snapshot) LoadLengths(description []byte) (err error) {
          	return json.Unmarshal(description, &snapshot.ChunkLengths)
          }
          
          
// MarshalJSON creates a json representation of the snapshot.
          func (snapshot *Snapshot) MarshalJSON() ([]byte, error) {
          
          
	object := make(map[string]interface{})
          
          
	object["version"] = 1
          	object["id"] = snapshot.ID
          	object["revision"] = snapshot.Revision
          	object["options"] = snapshot.Options
          	object["tag"] = snapshot.Tag
          	object["start_time"] = snapshot.StartTime
          	object["end_time"] = snapshot.EndTime
          
          
	if snapshot.FileSize != 0 && snapshot.NumberOfFiles != 0 {
          		object["file_size"] = snapshot.FileSize
          		object["number_of_files"] = snapshot.NumberOfFiles

I don’t think this was caused by CLI 3.0.1. Must be something else.

This is the error you get when you trying to use CLI v2 to parse a backup created by CLI v3. It is expected as CLI v2 knows nothing about the version bit and thus has to blindly parse the backup in old format.

Flibble · 22 November 2022 08:24

Thanks! What will the repair look like? Will the existing copies be readable in the next version, or will I have to delete all the incorrectly copied revisions and re-copy them later

I believe this correlates with the CLI 3.0.1 update

By the way, one more interesting thing:
On 22.10.2022 afternoon the CLI was updated from 2.7 ma 3.01.
Revisions created with CLI 3.01 in old repository don’t have an extra “(0)” after the date

This is screenshot from old backup source where everything is restorable

This is screenshot below is from new the repository where the copy was made using CLI 3.0.1
It doesn’t show “(0)”, but there is a regularity:

Those revisions that have “(0)” in the source are shown empty with the error “invalid code=5b”. (for example revision 90)
Those revisions that don’t have “(0)” in the copy source name can be restored (for example revision 95)

Droolio · 22 November 2022 14:39

Thanks for looking into that.

Could fixing this allow Duplicacy to upgrade the format during copy, or would it keep the old snapshot format without the version bit set?

gchen · 23 November 2022 02:52

The fix is in Fixed a bug that didn't preserve the version bit when copying old sna… · gilbertchen/duplicacy@58f0d2b · GitHub

With this fix, the new CLI should be able to correctly handle old v2 backups even if their version bit is wrong. So there is no need to re-copy them, but you can still do that if you want, in which case you can simply delete those snapshot files in the storage and then re-run the copy command.

“(0)” only indicates that the version bit is “0”. It doesn’t mean the snapshot file is empty.

towerbr · 23 November 2022 10:55

@gchen, a side question: what is the purpose of this “version”? I read the description in github commit and I didn’t understand it well.

gchen · 24 November 2022 04:32

version == 1 means it is the new format, version == 0 means it is the old format. When copying old backups the version bit should be preserved but I forgot about this case and always set it to 1.

pdp8user · 1 December 2022 00:07

So are we likely to see a 3.0.2 shortly? Or do I have to downgrade?
I’m seeing what looks like the issue on copies of backups that were made some months ago and that are being copied to a storage that had been off-line for a while.

I’m running the web gui on linux, so I presume that to downgrade I’d have to turn off auto-update.
Brian

805hp · 5 December 2022 20:36

@gchen - do you have any estimated timeline for the new v3 release that would include this fix and other changes since 3.0.1?

Flibble · 7 January 2023 14:22

Problem solved, since 3.1.0 is “live” on https://duplicacy.com/latest_cli_version

system · 17 January 2023 14:23

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.