JSON decode errors - Error messages during backup and restore

[Granddave]

trafficstars

Hi!

When using NPbackup v3.0.0-rc6 on Windows 11 I get some errors.

I set up a local backup configuration with a single directory as source, no other configuration is changed.

Both backup and restore functionality are seemingly working, but there are some error messages:

1. "VSS error" during backup
2. Lots of "JSON decode error: Expecting value: line 1 column 1 (char 0) on content"
3. "UtimesNano: Access is denied." during restore

Backup

Last messages:

Running backup of ['C:/Users/david/Documents/Test'] to repo default
Repository is not initialized or accessible
{"message_type":"initialized","id":"46ddc67d9ef1eab3f3cdf09cee1ff5743dff11b589728677a080c35edaa60b04","repository":"C:\\Users\\david\\Desktop"}
Repo initialized successfully
Using VSS snapshot to backup
no parent snapshot found, will read all files
no parent snapshot found, will read all files

Files:          31 new,     0 changed,     0 unmodified
Dirs:           86 new,     0 changed,     0 unmodified
Added to the repository: 2.814 MiB (2.237 MiB stored)

processed 31 files, 3.114 MiB in 0:00
snapshot e82861d5 saved
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'snapshot e82861d5 saved'
Runner took 4.496415 seconds for backup

Error messages:

VSS error: The caller does not have sufficient backup privileges or is not an administrator: E_ACCESSDENIED (0x80070005)
VSS cannot be used. Backup will be done without VSS.
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'no parent snapshot found, will read all files'
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Files:          31 new,     0 changed,     0 unmodified'
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Dirs:           86 new,     0 changed,     0 unmodified'
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Added to the repository: 2.814 MiB (2.237 MiB stored)'
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'processed 31 files, 3.114 MiB in 0:00'
JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'snapshot e82861d5 saved'
Backup is smaller than configured minmium backup size
Operation finished with failure

Restoration of single file

Last messages:

Launching restore to C:/Users/david/Desktop
{"message_type":"status","percent_done":1,"total_files":1,"files_restored":1,"total_bytes":826,"bytes_restored":826}
{"message_type":"summary","total_files":1,"files_restored":5,"total_bytes":826,"bytes_restored":826}
Runner took 1.451094 seconds for restore

Error messages:

{"message_type":"error","error":{"message":"UtimesNano: Access is denied."},"during":"restore","item":"\\C\\Users"}
Fatal: There were 1 errors

Data not restored:
{"message_type":"status","percent_done":1,"total_files":1,"files_restored":1,"total_bytes":826,"bytes_restored":826}
{"message_type":"error","error":{"message":"UtimesNano: Access is denied."},"during":"restore","item":"\\C\\Users"}
{"message_type":"summary","total_files":1,"files_restored":5,"total_bytes":826,"bytes_restored":826}
Fatal: There were 1 errors
JSON decode error: Extra data: line 2 column 1 (char 117) on output '{"message_type":"status","percent_done":1,"total_files":1,"files_restored":1,"total_bytes":826,"bytes_restored":826}
{"message_type":"error","error":{"message":"UtimesNano: Access is denied."},"during":"restore","item":"\\C\\Users"}
{"message_type":"summary","total_files":1,"files_restored":5,"total_bytes":826,"bytes_restored":826}
Fatal: There were 1 errors

'

Anything that has previously been seen? Thanks

[deajan]

So, basically you get a VSS error that says not have sufficient backup privileges or is not an administrator The same applies to restoration, you get Access is denied errors because of insufficient permissions.

Would you mind running NPBackup as administrator and check again ?

It's not a requirement to run NPBackup as admin, at least if you don't want to play with VSS, so I don't enforce it, which allows non-admin users to still be able to backup their data.

[Granddave]

I see, yes running as admin gives another result. I guess that scheduling a task (which my plan is to do) runs the application as admin as well?

Here's the logs from the logfile:

Backup

2024-09-29 15:18:11,499 :: INFO :: Running backup of ['C:/Users/david/Documents/Trackmania2020'] to repo default
2024-09-29 15:18:12,210 :: INFO :: Using VSS snapshot to backup
2024-09-29 15:18:12,975 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'error: failed to create snapshot for [c:\]: VSS error: executables compiled for 386 can't use VSS on other architectures. Please use an executable compiled for your platform.'
2024-09-29 15:18:12,975 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'no parent snapshot found, will read all files'
2024-09-29 15:18:12,975 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'creating VSS snapshot for [c:\]'
2024-09-29 15:18:12,975 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Files:          31 new,     0 changed,     0 unmodified'
2024-09-29 15:18:12,975 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Dirs:           86 new,     0 changed,     0 unmodified'
2024-09-29 15:18:12,976 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'Added to the repository: 0 B   (0 B   stored)'
2024-09-29 15:18:12,976 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'processed 31 files, 3.114 MiB in 0:00'
2024-09-29 15:18:12,976 :: ERROR :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'snapshot 5902d74c saved'
2024-09-29 15:18:12,976 :: INFO :: JSON decode error: Expecting value: line 1 column 1 (char 0) on content 'snapshot 5902d74c saved'
2024-09-29 15:18:12,977 :: INFO :: Processed 3.3 MB of data
2024-09-29 15:18:12,977 :: ERROR :: Backup is smaller than configured minmium backup size
2024-09-29 15:18:12,977 :: ERROR :: Operation finished with failure
2024-09-29 15:18:12,978 :: INFO :: Runner took 1.480584 seconds for backup

While restoring the file I didn't get any error messages :+1:

Restore

2024-09-29 15:21:06,947 :: INFO :: Listing snapshots of repo default
2024-09-29 15:21:08,384 :: INFO :: Snapshots listed successfully
2024-09-29 15:21:08,385 :: INFO :: Runner took 1.437502 seconds for snapshots
2024-09-29 15:21:08,617 :: INFO :: Recent snapshot 5902d74c of 2024-09-29T15:18:12.2429704+02:00 exists !
2024-09-29 15:21:13,807 :: INFO :: Showing content of snapshot 5902d74c in repo default
2024-09-29 15:21:15,252 :: INFO :: Successfuly listed snapshot 5902d74c content
2024-09-29 15:21:15,253 :: INFO :: Runner took 1.446723 seconds for ls
2024-09-29 15:21:15,469 :: INFO :: Using basic json representation for data which is slow and memory hungry. Consider using a newer OS that supports Python 3.8+
2024-09-29 15:21:15,502 :: INFO :: Finished creating data tree
2024-09-29 15:21:24,405 :: INFO :: Launching restore to C:/Users/david/Desktop
2024-09-29 15:21:25,844 :: INFO :: successfully restored data
2024-09-29 15:21:25,844 :: INFO :: Runner took 1.44066 seconds for restore

Any thoughts on the JSON decode error though?

Thanks for your quick response

[deajan]

Indeed, scheduling a task on a computer requires administrative privileges.

As the first error message suggests, use the windows-x64 compiled version if you run on a x64 platform, or else VSS won't work properly.

I'll have a look about the JSON decode errors.

[DavidSchargel]

I am getting similar VSS kinds of errors here NPBackup v3.0.0-rc6 on Windows 11 backing up manually through the gui exe app running with Admin privileges.

Backup Log

2024-10-12 18:18:47,808 :: INFO :: Listing snapshots of repo default
2024-10-12 18:18:50,198 :: INFO :: Snapshots listed successfully
2024-10-12 18:18:50,198 :: INFO :: Runner took 2.389615 seconds for snapshots
2024-10-12 18:18:50,439 :: INFO :: Recent snapshot 14c07adb of 2024-10-12T18:11:26.018465-07:00 exists !
2024-10-12 18:18:55,131 :: INFO :: Running backup of ['C:/Users/DIRECTORY_NAMES_HIDDEN_FOR_ISSUE_POSTING'] to repo default
2024-10-12 18:18:56,501 :: INFO :: Using VSS snapshot to backup
2024-10-12 18:24:42,548 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'using parent snapshot 14c07adb'
2024-10-12 18:24:42,549 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'creating VSS snapshot for [c:\]'
2024-10-12 18:24:42,549 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'successfully created snapshot for [c:\]'
2024-10-12 18:24:42,550 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'mountpoints in snapshot volume [c:\]:'
2024-10-12 18:24:42,550 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 2) on content ' - c:\users\DIRECTORY_NAMES_HIDDEN_FOR_ISSUE_POSTING\ (not snapshotted)'
2024-10-12 18:24:42,551 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'Files:           0 new,     0 changed, 209211 unmodified'
2024-10-12 18:24:42,552 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'Dirs:            0 new,     0 changed, 36538 unmodified'
2024-10-12 18:24:42,552 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'Added to the repository: 0 B   (0 B   stored)'
2024-10-12 18:24:42,552 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'processed 209211 files, 132.042 GiB in 5:39'
2024-10-12 18:24:42,553 :: ERROR :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'snapshot 600e6a71 saved'
2024-10-12 18:24:42,553 :: INFO :: JSON decode error: JSON is malformed: invalid character (byte 0) on content 'snapshot 600e6a71 saved'
2024-10-12 18:24:42,556 :: INFO :: Processed 141.8 GB of data
2024-10-12 18:24:42,556 :: INFO :: Operation finished with success
2024-10-12 18:24:42,558 :: INFO :: Runner took 347.430544 seconds for backup

[deajan]

Thanks for reporting back. Those errors can be safely ignored, they are only cosmetic. The fix is already in master. I'll just finish some GUI work before letting the next RC out.

[deajan]

New RC released including the fix.