Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rclone verbose logs cannot be parsed by NPBackup #132

Closed
GuitarBilly opened this issue Feb 20, 2025 · 15 comments
Closed

rclone verbose logs cannot be parsed by NPBackup #132

GuitarBilly opened this issue Feb 20, 2025 · 15 comments
Labels

Comments

@GuitarBilly
Copy link

GuitarBilly commented Feb 20, 2025

npbackup-cli
W10 enterprise 64bit
confirmed on v3.0.0-rc14 and v3.0.0-rc15
This backup to OneDrive worked fine on rc12 and rc13.

I have set "Environment variables" RCLONE_VERBOSE to 2 to print extra information.
I have set "Additional backup only parameters" to --dry-run -o rclone.args="serve restic --stdio --b2-hard-delete --user-agent ISV|rclone.org|rclone/v1.65.2" in an attempt to get the --user-agent passed onto rclone.

steps to reproduce and terminal log:

C:\Users\guitarbilly\Downloads\npbackup-cli>npbackup-cli.exe -c ..\NPBACKUP_COMMON\npbackup.conf --repo-name OneDrive_via_rclone --backup
2025-02-20 22:14:10,166 :: INFO :: npbackup 3.0.0-rc15-windows-cli-x64-public-3.13-c 2025021701 - Copyright (C) 2022-2025 NetInvent running as AD\guitarbilly
2025-02-20 22:14:10,213 :: INFO :: Loaded config AA29C37A in C:\Users\guitarbilly\Downloads\npbackup-cli\..\NPBACKUP_COMMON\npbackup.conf
2025-02-20 22:14:10,219 :: INFO :: No extra information for repos x300server_laptop found
2025-02-20 22:14:10,332 :: INFO :: Searching for a backup newer than 1 day, 0:00:00 ago
2025-02-20 22:14:36,836 :: INFO :: Snapshots listed successfully
2025-02-20 22:14:36,838 :: ERROR :: Runner: Function has_recent_snapshot failed with: list indices must be integers or slices, not str
2025-02-20 22:14:36,840 :: ERROR :: Trace:
Traceback (most recent call last):
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 669, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 442, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 653, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 591, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 512, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 613, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 1095, in has_recent_snapshot
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\restic_wrapper\__init__.py", line 1407, in has_recent_snapshot
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\restic_wrapper\__init__.py", line 1363, in _has_recent_snapshot
TypeError: list indices must be integers or slices, not str
2025-02-20 22:14:36,843 :: ERROR :: Backend finished with errors.
2025-02-20 22:14:36,843 :: WARNING :: Cannot get exec time from environment
2025-02-20 22:14:36,881 :: INFO :: Metrics pushed successfully.
2025-02-20 22:14:36,884 :: ERROR :: Runner: Function backup failed with: cannot unpack non-iterable bool object
2025-02-20 22:14:36,884 :: ERROR :: Trace:
Traceback (most recent call last):
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 669, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 442, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 645, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 591, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 512, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 613, in wrapper
  File "C:\Users\guitarbilly\DOWNLO~1\NP14FC~1\npbackup\core\runner.py", line 1261, in backup
TypeError: cannot unpack non-iterable bool object
2025-02-20 22:14:36,887 :: ERROR :: Cannot decode JSON from restic data: the JSON object must be str, bytes or bytearray, not bool
2025-02-20 22:14:36,887 :: ERROR :: Cannot find processed bytes: 'total_bytes_processed'
2025-02-20 22:14:36,888 :: ERROR :: Backend finished with errors.
2025-02-20 22:14:36,888 :: WARNING :: Cannot get exec time from environment
2025-02-20 22:14:36,983 :: INFO :: Metrics pushed successfully.
2025-02-20 22:14:36,984 :: ERROR :: Operation finished
2025-02-20 22:14:37,005 :: INFO :: ExecTime = 0:00:26.845940, finished, state is: errors.

C:\Users\guitarbilly\Downloads\npbackup-cli>

expected result:
npbackup should not crash but handle it gracefully with an error or warning to the user.

Note that with RCLONE_VERBOSE set to 2 the npbackup-gui hangs on listing snapshots for this OneDrive repo since rc14, hence my trial with npbackup-cli, here are the npbackup-gui messages in the GUI after loading the snapshots:
Last messages

:"d7b4e620"},{"time":"2025-02-20T11:59:51.622411+01:00","parent":"cc8c5b338923ee2dfadff7a63346d5d450f25db4a5a75952b2c66ab053755b58","tree":"9edaa6874f9dbcf82df0cd0aeb2bfa97925aee8f382ffc4fcde2836535d072c6","paths":["C:\\H"],"hostname":"MYLAPTOP","username":"AD\\guitarbilly","tags":["C_H"],"program_version":"restic 0.16.4","id":"34248f08f2093255a7ede7d8335851d269f9440ead3dad7b98e4b81ce410d516","short_id":"34248f08"},{"time":"2025-02-20T12:00:31.0987431+01:00","parent":"d7b4e6201cd5e34b3eb239050ded086f7a04437bd4a448749723347bccfc27ef","tree":"eadf8dcf458e678886274f9fc61e081a4a643db7dbf278460a6cd256881b466a","paths":["C:\\Program Files\\totalcmd\\Wciconex.dll","C:\\Program Files\\totalcmd\\plugins","C:\\Program Files\\totalcmd\\wciconex.inc","C:\\Users\\guitarbilly\\AppData\\Roaming\\GHISLER"],"hostname":"NLNIJ01NB0507","username":"AD\\guitarbilly","tags":["TC"],"program_version":"restic 0.16.4","id":"999e57510cb48cab1fc83abba1029a8e8c511b0a6609197ddcbe6df8de4fcbfe","short_id":"999e5751"}]
Snapshots listed successfully
Runner took 27.58145 seconds for snapshots

Error messages

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160
rclone: 2025/02/20 22:30:52 DEBUG : locks: list request
rclone: 2025/02/20 22:30:52 DEBUG : snapshots: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160
rclone: 2025/02/20 22:30:52 DEBUG : locks: list request
rclone: 2025/02/20 22:30:52 DEBUG : snapshots: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160
rclone: 2025/02/20 22:30:52 DEBUG : locks: list request
rclone: 2025/02/20 22:30:52 DEBUG : snapshots: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160
rclone: 2025/02/20 22:30:52 DEBUG : locks: list request
rclone: 2025/02/20 22:30:52 DEBUG : snapshots: list request

rclone: 2025/02/20 22:30:46 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MyPreciousData\\abc"]
rclone: 2025/02/20 22:30:46 DEBUG : Creating backend with remote "onedrive:MyPreciousData\\abc"
rclone: 2025/02/20 22:30:46 DEBUG : Using config file from "C:\\Users\\guitarbilly\\AppData\\Roaming\\rclone\\rclone.conf"
rclone: 2025/02/20 22:30:47 DEBUG : fs cache: renaming cache item "onedrive:MyPreciousData\\abc" to be canonical "onedrive:MyPreciousData/abc"
rclone: 2025/02/20 22:30:47 DEBUG : file-15691317375884925585: GET request error: object not found
rclone: 2025/02/20 22:30:47 DEBUG : keys: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks: list request
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Starting multipart upload
rclone: 2025/02/20 22:30:51 DEBUG : locks/55c6681445b7a516ccd2baab769ce2a9b70e5a7524a3e1d6ba23a8463dff66c9: Uploading segment 0/160 size 160
rclone: 2025/02/20 22:30:52 DEBUG : locks: list request
rclone: 2025/02/20 22:30:52 DEBUG : snapshots: list request

EDIT : here is the npbackup-gui termnial log:

C:\Users\guitarbilly>Downloads\npbackup-gui\npbackup-gui.exe -c Downloads\NPBACKUP_COMMON\npbackup.conf --repo-name OneDrive_via_rclone
2025-02-20 22:29:48,671 :: INFO :: GUI: npbackup 3.0.0-rc15-windows-gui-x64-public-3.13-c 2025021701 - Copyright (C) 2022-2025 NetInvent running as AD\guitarbilly
2025-02-20 22:29:48,728 :: INFO :: Loaded config AA29C37A in C:\Users\guitarbilly\Downloads\NPBACKUP_COMMON\npbackup.conf
2025-02-20 22:29:48,734 :: INFO :: No extra information for repos x300server_MYLAPTOP found
2025-02-20 22:29:49,677 :: INFO :: Listing snapshots of repo OneDrive_via_rclone
2025-02-20 22:30:15,125 :: INFO :: Snapshots listed successfully
2025-02-20 22:30:15,125 :: INFO :: Runner took 25.448921 seconds for snapshots
2025-02-20 22:30:28,720 :: INFO :: Listing snapshots of repo OneDrive_via_rclone
2025-02-20 22:30:56,298 :: INFO :: Snapshots listed successfully
2025-02-20 22:30:56,300 :: INFO :: Runner took 27.58145 seconds for snapshots
2025-02-20 22:30:56,343 :: INFO :: Metrics pushed successfully.
2025-02-20 22:41:21,488 :: CRITICAL :: GUI Execution error list indices must be integers or slices, not str
2025-02-20 22:41:21,490 :: INFO :: Trace:
Traceback (most recent call last):
  File "C:\Users\guitarbilly\DOWNLO~1\NPAA0E~1\npbackup\gui\__main__.py", line 1238, in main_gui
  File "C:\Users\guitarbilly\DOWNLO~1\NPAA0E~1\npbackup\gui\__main__.py", line 1107, in _main_gui
  File "C:\Users\guitarbilly\DOWNLO~1\NPAA0E~1\npbackup\gui\__main__.py", line 659, in get_gui_data
  File "C:\Users\guitarbilly\DOWNLO~1\NPAA0E~1\npbackup\restic_wrapper\__init__.py", line 1363, in _has_recent_snapshot
TypeError: list indices must be integers or slices, not str
2025-02-20 22:41:21,538 :: INFO :: ExecTime = 0:11:32.869565, finished, state is: critical.
@GuitarBilly
Copy link
Author

GuitarBilly commented Feb 21, 2025

removing the RCLONE_VERBOSE = 2 variable makes the snapshot and backup work:

Image

@deajan
Copy link
Contributor

deajan commented Feb 21, 2025

Happy to know that things work ;)

I'm pretty sure that rclone verbose just gives too much information which NPBackup cannot parse, although it does not crash, but just notices the error and still sends metrics.

I'd definitly need to have an output of this with --debug for better comprehension.
Also, would you mind sharing your anonymous yaml config ?

@deajan deajan added the next label Feb 23, 2025
@deajan
Copy link
Contributor

deajan commented Feb 23, 2025

Since rclone works, this can wait until after a v3 release, but still I'd like to be able to filter rclone verbose output to parse only necessary data.

I've managed to update RC15 everywhere, and it seems to work well.
Probably going to release RTM soon unless a major block is found.

@GuitarBilly
Copy link
Author

@deajan agree this is not a show stopper for RTM.
I will still create an anonymized config wtih --debug info for you.

p.s. Upon doing it I found a bug that deserves fixing. Will log an issue for that.

@deajan deajan changed the title rc14/rc15 OneDrive regression rclone verbose logs cannot be parsed by NPBackup Feb 23, 2025
@GuitarBilly
Copy link
Author

@deajan In my opinion this issue boils down to wanting to deal with RCLONE_VERBOSE=2 enabled which is fantastic for debugging but normally not required for regular backup situations.

Enough said; here my anonymized npbackup config file:
github.upload.npbackup.OneDrive_via_rclone.anon.conf.txt

Results from a fresh run with --debug output:

npbackup 3.0.0-linux-gui-x64-legacy-public-3.10-i 2025022301 - Copyright (C) 2022-2025 NetInvent running as linux
2025-02-23 19:06:51,141 :: INFO :: GUI: npbackup 3.0.0-linux-gui-x64-legacy-public-3.10-i 2025022301 - Copyright (C) 2022-2025 NetInvent running as linux
2025-02-23 19:06:51,156 :: INFO :: Loaded config BA602950 in /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf
2025-02-23 19:06:51,158 :: INFO :: No extra information for groups default_group found
2025-02-23 19:06:51,768 :: DEBUG :: gui_thread_runner runs snapshots without threads
2025-02-23 19:06:51,914 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-02-23 19:06:51,914 :: DEBUG :: STDOUT: restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-02-23 19:06:51,915 :: INFO :: Using binary restic 0.17.3 compiled with go1.23.3 on linux/amd64
2025-02-23 19:06:51,915 :: INFO :: Listing snapshots of repo default
2025-02-23 19:06:51,915 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-02-23 19:06:51,915 :: DEBUG :: Setting GOMAXPROCS to 10
2025-02-23 19:06:56,311 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/02/23 19:06:51 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:06:51 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:06:51 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:06:52 DEBUG : file-8063075765049147397: GET request error: object not found
rclone: 2025/02/23 19:06:52 DEBUG : keys: list request
rclone: 2025/02/23 19:06:54 DEBUG : locks: list request
rclone: 2025/02/23 19:06:54 DEBUG : locks/51b078f641f4c082f682613e1a67d73b10a73a5d235819b5620f7aa019a50262: Starting multipart upload
rclone: 2025/02/23 19:06:54 DEBUG : locks/51b078f641f4c082f682613e1a67d73b10a73a5d235819b5620f7aa019a50262: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:06:55 DEBUG : locks: list request
rclone: 2025/02/23 19:06:55 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:06:56,311 :: DEBUG :: STDOUT: rclone: 2025/02/23 19:06:51 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:06:51 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:06:51 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:06:52 DEBUG : file-8063075765049147397: GET request error: object not found
rclone: 2025/02/23 19:06:52 DEBUG : keys: list request
rclone: 2025/02/23 19:06:54 DEBUG : locks: list request
rclone: 2025/02/23 19:06:54 DEBUG : locks/51b078f641f4c082f682613e1a67d73b10a73a5d235819b5620f7aa019a50262: Starting multipart upload
rclone: 2025/02/23 19:06:54 DEBUG : locks/51b078f641f4c082f682613e1a67d73b10a73a5d235819b5620f7aa019a50262: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:06:55 DEBUG : locks: list request
rclone: 2025/02/23 19:06:55 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:06:56,311 :: DEBUG :: Running on_exit callable.
2025-02-23 19:06:56,311 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-02-23 19:06:56,312 :: DEBUG :: Setting GOMAXPROCS to 10
2025-02-23 19:07:00,589 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/02/23 19:06:56 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:06:56 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:06:56 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:06:56 DEBUG : file-9920421487873340252: GET request error: object not found
rclone: 2025/02/23 19:06:57 DEBUG : keys: list request
rclone: 2025/02/23 19:06:58 DEBUG : locks: list request
rclone: 2025/02/23 19:06:58 DEBUG : locks/0cf4574f55be0c864c0a355a7a36d959e6ea06308f39bfd483095709a9b17f0b: Starting multipart upload
rclone: 2025/02/23 19:06:58 DEBUG : locks/0cf4574f55be0c864c0a355a7a36d959e6ea06308f39bfd483095709a9b17f0b: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:06:59 DEBUG : locks: list request
rclone: 2025/02/23 19:06:59 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:07:00,589 :: DEBUG :: STDOUT: rclone: 2025/02/23 19:06:56 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:06:56 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:06:56 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:06:56 DEBUG : file-9920421487873340252: GET request error: object not found
rclone: 2025/02/23 19:06:57 DEBUG : keys: list request
rclone: 2025/02/23 19:06:58 DEBUG : locks: list request
rclone: 2025/02/23 19:06:58 DEBUG : locks/0cf4574f55be0c864c0a355a7a36d959e6ea06308f39bfd483095709a9b17f0b: Starting multipart upload
rclone: 2025/02/23 19:06:58 DEBUG : locks/0cf4574f55be0c864c0a355a7a36d959e6ea06308f39bfd483095709a9b17f0b: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:06:59 DEBUG : locks: list request
rclone: 2025/02/23 19:06:59 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:07:00,589 :: DEBUG :: Running on_exit callable.
2025-02-23 19:07:00,589 :: INFO :: Snapshots listed successfully
2025-02-23 19:07:00,590 :: INFO :: Runner took 8.734447 seconds for snapshots
2025-02-23 19:07:00,590 :: DEBUG :: Metrics disabled for call snapshots
2025-02-23 19:07:00,597 :: DEBUG :: gui_thread_runner got stdout queue close signal
2025-02-23 19:07:00,598 :: DEBUG :: gui_thread_runner got stderr queue close signal


...which does not lead to a fatal error or crash, but this GUI state:

Image

npbackup then does crash when you trigger the snapshot reading one more time either via opening/closing the configuration or by pressing the GUi repo 'Backup state' button, here the additional debug log:

2025-02-23 19:10:39,205 :: DEBUG :: gui_thread_runner runs snapshots without threads
2025-02-23 19:10:39,345 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-02-23 19:10:39,345 :: DEBUG :: STDOUT: restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-02-23 19:10:39,345 :: INFO :: Using binary restic 0.17.3 compiled with go1.23.3 on linux/amd64
2025-02-23 19:10:39,345 :: INFO :: Listing snapshots of repo default
2025-02-23 19:10:39,346 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-02-23 19:10:39,346 :: DEBUG :: Setting GOMAXPROCS to 10
2025-02-23 19:10:43,614 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/02/23 19:10:39 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:10:39 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:10:39 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:10:39 DEBUG : file-11839853202405371980: GET request error: object not found
rclone: 2025/02/23 19:10:40 DEBUG : keys: list request
rclone: 2025/02/23 19:10:41 DEBUG : locks: list request
rclone: 2025/02/23 19:10:41 DEBUG : locks/6e23210173fdd007080e3e5ab8a77c687af072513cbca8544e97e83bd19d9c86: Starting multipart upload
rclone: 2025/02/23 19:10:41 DEBUG : locks/6e23210173fdd007080e3e5ab8a77c687af072513cbca8544e97e83bd19d9c86: Uploading segment 0/187 size 187
rclone: 2025/02/23 19:10:42 DEBUG : locks: list request
rclone: 2025/02/23 19:10:42 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:10:43,614 :: DEBUG :: STDOUT: rclone: 2025/02/23 19:10:39 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:10:39 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:10:39 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:10:39 DEBUG : file-11839853202405371980: GET request error: object not found
rclone: 2025/02/23 19:10:40 DEBUG : keys: list request
rclone: 2025/02/23 19:10:41 DEBUG : locks: list request
rclone: 2025/02/23 19:10:41 DEBUG : locks/6e23210173fdd007080e3e5ab8a77c687af072513cbca8544e97e83bd19d9c86: Starting multipart upload
rclone: 2025/02/23 19:10:41 DEBUG : locks/6e23210173fdd007080e3e5ab8a77c687af072513cbca8544e97e83bd19d9c86: Uploading segment 0/187 size 187
rclone: 2025/02/23 19:10:42 DEBUG : locks: list request
rclone: 2025/02/23 19:10:42 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:10:43,615 :: DEBUG :: Running on_exit callable.
2025-02-23 19:10:43,615 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-02-23 19:10:43,615 :: DEBUG :: Setting GOMAXPROCS to 10
2025-02-23 19:10:48,735 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/02/23 19:10:43 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:10:43 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:10:43 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:10:44 DEBUG : file-2335515084405154304: GET request error: object not found
rclone: 2025/02/23 19:10:44 DEBUG : keys: list request
rclone: 2025/02/23 19:10:46 DEBUG : locks: list request
rclone: 2025/02/23 19:10:46 DEBUG : locks/b96968f20e84971c7c1b480681e14a1615b658955bc321f19bb75027191cde1b: Starting multipart upload
rclone: 2025/02/23 19:10:47 DEBUG : locks/b96968f20e84971c7c1b480681e14a1615b658955bc321f19bb75027191cde1b: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:10:48 DEBUG : locks: list request
rclone: 2025/02/23 19:10:48 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:10:48,735 :: DEBUG :: STDOUT: rclone: 2025/02/23 19:10:43 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/02/23 19:10:43 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/02/23 19:10:43 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/02/23 19:10:44 DEBUG : file-2335515084405154304: GET request error: object not found
rclone: 2025/02/23 19:10:44 DEBUG : keys: list request
rclone: 2025/02/23 19:10:46 DEBUG : locks: list request
rclone: 2025/02/23 19:10:46 DEBUG : locks/b96968f20e84971c7c1b480681e14a1615b658955bc321f19bb75027191cde1b: Starting multipart upload
rclone: 2025/02/23 19:10:47 DEBUG : locks/b96968f20e84971c7c1b480681e14a1615b658955bc321f19bb75027191cde1b: Uploading segment 0/188 size 188
rclone: 2025/02/23 19:10:48 DEBUG : locks: list request
rclone: 2025/02/23 19:10:48 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"}]

2025-02-23 19:10:48,735 :: DEBUG :: Running on_exit callable.
2025-02-23 19:10:48,736 :: INFO :: Snapshots listed successfully
2025-02-23 19:10:48,736 :: INFO :: Runner took 9.448468 seconds for snapshots
2025-02-23 19:10:48,736 :: DEBUG :: Metrics computed:
npbackup_exec_state{npversion="npbackup3.0.0-gui",action="snapshots",repo_name="default",timestamp="1740334248"} 0
npbackup_exec_time{npversion="npbackup3.0.0-gui",action="snapshots",repo_name="default",timestamp="1740334248"} 9.448468
2025-02-23 19:10:48,757 :: DEBUG :: gui_thread_runner got stdout queue close signal
2025-02-23 19:10:48,758 :: DEBUG :: gui_thread_runner got stderr queue close signal

and GUI state:

Image

after pressing Close button:

Image

then it crashes wth this final info in the terminal:

2025-02-23 19:17:31,800 :: CRITICAL :: GUI Execution error list indices must be integers or slices, not str
2025-02-23 19:17:31,801 :: INFO :: Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/gui/__main__.py", line 1239, in main_gui
    _main_gui(viewer_mode=viewer_mode)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/gui/__main__.py", line 1218, in _main_gui
    current_state, backup_tz, snapshot_list = get_gui_data(repo_config)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/gui/__main__.py", line 659, in get_gui_data
    current_state, backup_tz = ResticRunner._has_recent_snapshot(
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_wrapper/__init__.py", line 1363, in _has_recent_snapshot
    last_snapshot["time"],
TypeError: list indices must be integers or slices, not str
2025-02-23 19:17:31,808 :: INFO :: ExecTime = 0:10:40.667726, finished, state is: critical.

@deajan deajan added this to the 3.0.1 milestone Mar 5, 2025
@deajan
Copy link
Contributor

deajan commented Mar 6, 2025

@GuitarBilly There's a fix now in master for filtering rclone debug logs.
Would you mind giving it a test ride ?

@deajan
Copy link
Contributor

deajan commented Mar 6, 2025

Released in 3.0.1-rc1 comming out tomorrow morning.

@GuitarBilly
Copy link
Author

@deajan, sure i'll try; realistically it will happen about two weeks from now (occupied with other things atm).

@deajan
Copy link
Contributor

deajan commented Mar 13, 2025

@GuitarBilly No worries, this is "a side quest" fix ;)
I'm just happy for all the feedback / help you provide making NPBackup user worthy.
I'll remove the milestone for now since v3.0.1 should release soonish.

@deajan deajan removed this from the 3.0.1 milestone Mar 13, 2025
@GuitarBilly
Copy link
Author

@deajan, hope this help.
i have run the following command on the latest github development version:

venv/bin/python·bin/npbackup-gui·--dry-run·--config-file=/home/linux/npbackup/npbackup.v3.conf·--run-as-cli·--backup·--repo-name·OneDrive_via_rclone·--repo-group·OneDrive_via_rclone

terminal output (skipped the download part from github):

npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-26 18:47:29,436 :: INFO :: npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-26 18:47:29,461 :: INFO :: Loaded config 9CFC27FE in /home/linux/npbackup/npbackup.v3.conf
2025-03-26 18:47:29,526 :: INFO :: Using binary restic 0.17.3 compiled with go1.23.3 on linux/amd64
2025-03-26 18:47:29,526 :: INFO :: Searching for a backup newer than 1 day, 0:00:00 ago
2025-03-26 18:47:56,515 :: INFO :: Snapshots listed successfully
2025-03-26 18:47:56,515 :: ERROR :: Runner: Function has_recent_snapshot failed with: list indices must be integers or slices, not str
2025-03-26 18:47:56,515 :: ERROR :: Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 698, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 496, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 682, in wrapper
    result = fn(  # pylint: disable=E1102 (not-callable)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 625, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 566, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 647, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 1174, in has_recent_snapshot
    data = self.restic_runner.has_recent_snapshot(self.minimum_backup_age)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_wrapper/__init__.py", line 1455, in has_recent_snapshot
    result, timestamp = self._has_recent_snapshot(snapshots, delta)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_wrapper/__init__.py", line 1411, in _has_recent_snapshot
    last_snapshot["time"],
TypeError: list indices must be integers or slices, not str
2025-03-26 18:47:56,516 :: ERROR :: Backend finished with errors.
2025-03-26 18:47:56,516 :: WARNING :: Cannot get exec time from environment
2025-03-26 18:47:56,516 :: INFO :: Dry run mode. Not sending metrics.
2025-03-26 18:47:56,516 :: ERROR :: Runner: Function backup failed with: cannot unpack non-iterable bool object
2025-03-26 18:47:56,516 :: ERROR :: Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 698, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 496, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 674, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 625, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 566, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 647, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 1340, in backup
    has_recent_snapshots, _ = self.has_recent_snapshot(
TypeError: cannot unpack non-iterable bool object
2025-03-26 18:47:56,516 :: ERROR :: Cannot decode JSON from restic data: the JSON object must be str, bytes or bytearray, not bool
2025-03-26 18:47:56,516 :: ERROR :: Cannot find processed bytes: 'total_bytes_processed'
2025-03-26 18:47:56,516 :: ERROR :: Backend finished with errors.
2025-03-26 18:47:56,517 :: WARNING :: Cannot get exec time from environment
2025-03-26 18:47:56,517 :: INFO :: Dry run mode. Not sending metrics.
2025-03-26 18:47:56,517 :: ERROR :: Operation finished
2025-03-26 18:47:56,524 :: INFO :: ExecTime = 0:00:27.089708, finished, state is: errors.
~/npbackup.latest.github

FYI - in the npbackup-gui then the snapshots command also throws an error (hence my trail to run a backup via --run-as-cli.

@deajan
Copy link
Contributor

deajan commented Mar 26, 2025

Thank you for the report. I guess this is still with RCLONE_VERBOSE set ?
Can you throw in --debug so I know what output I didn't filter properly ?

@GuitarBilly
Copy link
Author

yes that is correct, RCLONE_VERBOSE with value 2 is added to the configuration.

First i have ran again with --debug, then i changed the --backup to --snapshots because that is what was failing in the GUI. Interestingly there are different results. Last i added the GUI for good measure.

here is the output of

venv/bin/python·bin/npbackup-gui·--debug·--dry-run·--config-file=/home/linux/npbackup/npbackup.v3.conf·--run-as-cli·--backup·--repo-name·OneDrive_via_rclone·--repo-group·OneDrive_via_rclone

npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-27 00:35:08,604 :: INFO :: npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-27 00:35:08,630 :: INFO :: Loaded config 9CFC27FE in /home/linux/npbackup/npbackup.v3.conf
2025-03-27 00:35:08,695 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-03-27 00:35:08,696 :: DEBUG :: STDOUT: restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-03-27 00:35:08,696 :: INFO :: Using binary restic 0.17.3 compiled with go1.23.3 on linux/amd64
2025-03-27 00:35:08,696 :: INFO :: Searching for a backup newer than 1 day, 0:00:00 ago
2025-03-27 00:35:08,696 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-27 00:35:08,696 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-27 00:35:14,968 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/27 00:35:08 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:35:08 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:35:08 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:35:08 DEBUG : onedrive: Loaded invalid token from config file - ignoring
rclone: 2025/03/27 00:35:08 DEBUG : Saving config "token" in section "onedrive" of the config file
rclone: 2025/03/27 00:35:08 DEBUG : onedrive: Saved new token in config file
rclone: 2025/03/27 00:35:09 DEBUG : file-7816414304037884050: GET request error: object not found
rclone: 2025/03/27 00:35:10 DEBUG : keys: list request
rclone: 2025/03/27 00:35:11 DEBUG : locks: list request
rclone: 2025/03/27 00:35:12 DEBUG : locks/96b7f86f248884b82edd8d6761765946c8b708cdc55a18dca2658dffb18c5093: Starting multipart upload
rclone: 2025/03/27 00:35:12 DEBUG : locks/96b7f86f248884b82edd8d6761765946c8b708cdc55a18dca2658dffb18c5093: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:35:13 DEBUG : locks: list request
rclone: 2025/03/27 00:35:13 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-27 00:35:14,969 :: DEBUG :: STDOUT: rclone: 2025/03/27 00:35:08 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:35:08 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:35:08 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:35:08 DEBUG : onedrive: Loaded invalid token from config file - ignoring
rclone: 2025/03/27 00:35:08 DEBUG : Saving config "token" in section "onedrive" of the config file
rclone: 2025/03/27 00:35:08 DEBUG : onedrive: Saved new token in config file
rclone: 2025/03/27 00:35:09 DEBUG : file-7816414304037884050: GET request error: object not found
rclone: 2025/03/27 00:35:10 DEBUG : keys: list request
rclone: 2025/03/27 00:35:11 DEBUG : locks: list request
rclone: 2025/03/27 00:35:12 DEBUG : locks/96b7f86f248884b82edd8d6761765946c8b708cdc55a18dca2658dffb18c5093: Starting multipart upload
rclone: 2025/03/27 00:35:12 DEBUG : locks/96b7f86f248884b82edd8d6761765946c8b708cdc55a18dca2658dffb18c5093: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:35:13 DEBUG : locks: list request
rclone: 2025/03/27 00:35:13 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-27 00:35:14,969 :: DEBUG :: Running on_exit callable.
2025-03-27 00:35:14,969 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-27 00:35:14,969 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-27 00:35:20,211 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/27 00:35:15 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:35:15 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:35:15 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:35:15 DEBUG : file-11154754390687793872: GET request error: object not found
rclone: 2025/03/27 00:35:15 DEBUG : keys: list request
rclone: 2025/03/27 00:35:17 DEBUG : locks: list request
rclone: 2025/03/27 00:35:17 DEBUG : locks/6eaa5f10066e0f301aa4d8e06717176f61ad6499e69806693f84684bb87dc602: Starting multipart upload
rclone: 2025/03/27 00:35:17 DEBUG : locks/6eaa5f10066e0f301aa4d8e06717176f61ad6499e69806693f84684bb87dc602: Uploading segment 0/187 size 187
rclone: 2025/03/27 00:35:19 DEBUG : locks: list request
rclone: 2025/03/27 00:35:19 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-27 00:35:20,211 :: DEBUG :: STDOUT: rclone: 2025/03/27 00:35:15 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:35:15 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:35:15 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:35:15 DEBUG : file-11154754390687793872: GET request error: object not found
rclone: 2025/03/27 00:35:15 DEBUG : keys: list request
rclone: 2025/03/27 00:35:17 DEBUG : locks: list request
rclone: 2025/03/27 00:35:17 DEBUG : locks/6eaa5f10066e0f301aa4d8e06717176f61ad6499e69806693f84684bb87dc602: Starting multipart upload
rclone: 2025/03/27 00:35:17 DEBUG : locks/6eaa5f10066e0f301aa4d8e06717176f61ad6499e69806693f84684bb87dc602: Uploading segment 0/187 size 187
rclone: 2025/03/27 00:35:19 DEBUG : locks: list request
rclone: 2025/03/27 00:35:19 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-27 00:35:20,211 :: DEBUG :: Running on_exit callable.
2025-03-27 00:35:20,211 :: INFO :: Snapshots listed successfully
2025-03-27 00:35:20,212 :: ERROR :: Runner: Function has_recent_snapshot failed with: list indices must be integers or slices, not str
2025-03-27 00:35:20,212 :: ERROR :: Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 698, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 496, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 682, in wrapper
    result = fn(  # pylint: disable=E1102 (not-callable)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 625, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 566, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 647, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 1174, in has_recent_snapshot
    data = self.restic_runner.has_recent_snapshot(self.minimum_backup_age)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_wrapper/__init__.py", line 1455, in has_recent_snapshot
    result, timestamp = self._has_recent_snapshot(snapshots, delta)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_wrapper/__init__.py", line 1411, in _has_recent_snapshot
    last_snapshot["time"],
TypeError: list indices must be integers or slices, not str
2025-03-27 00:35:20,212 :: ERROR :: Backend finished with errors.
2025-03-27 00:35:20,212 :: WARNING :: Cannot get exec time from environment
2025-03-27 00:35:20,212 :: DEBUG :: Metrics computed:
npbackup_exec_state{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="has_recent_snapshot",repo_name="OneDrive_via_rclone",timestamp="1743032120"} 2
2025-03-27 00:35:20,212 :: INFO :: Dry run mode. Not sending metrics.
2025-03-27 00:35:20,213 :: ERROR :: Runner: Function backup failed with: cannot unpack non-iterable bool object
2025-03-27 00:35:20,213 :: ERROR :: Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 698, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 496, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 674, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 625, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 566, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 647, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 1340, in backup
    has_recent_snapshots, _ = self.has_recent_snapshot(
TypeError: cannot unpack non-iterable bool object
2025-03-27 00:35:20,213 :: ERROR :: Cannot decode JSON from restic data: the JSON object must be str, bytes or bytearray, not bool
2025-03-27 00:35:20,213 :: DEBUG :: Data is: False, Trace:
Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 698, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 496, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 674, in wrapper
    result = fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 625, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 566, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 647, in wrapper
    return fn(self, *args, **kwargs)
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/core/runner.py", line 1340, in backup
    has_recent_snapshots, _ = self.has_recent_snapshot(
TypeError: cannot unpack non-iterable bool object

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/linux/npbackup.latest.github/npbackup/npbackup/restic_metrics/__init__.py", line 202, in restic_json_to_prometheus
    restic_json = json.loads(restic_json)
  File "/usr/lib/python3.10/json/__init__.py", line 339, in loads
    raise TypeError(f'the JSON object must be str, bytes or bytearray, '
TypeError: the JSON object must be str, bytes or bytearray, not bool
2025-03-27 00:35:20,232 :: ERROR :: Cannot find processed bytes: 'total_bytes_processed'
2025-03-27 00:35:20,232 :: ERROR :: Backend finished with errors.
2025-03-27 00:35:20,232 :: WARNING :: Cannot get exec time from environment
2025-03-27 00:35:20,232 :: DEBUG :: Metrics computed:
restic_backup_failure{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",timestamp="1743032120"} 1
npbackup_exec_state{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup",repo_name="OneDrive_via_rclone",timestamp="1743032120"} 2
2025-03-27 00:35:20,232 :: INFO :: Dry run mode. Not sending metrics.
2025-03-27 00:35:20,232 :: ERROR :: Operation finished
2025-03-27 00:35:20,239 :: INFO :: ExecTime = 0:00:11.636376, finished, state is: errors.
~/npbackup.latest.github

and here the output of the --snapshots:

venv/bin/python·bin/npbackup-gui·--debug·--dry-run·--config-file=/home/linux/npbackup/npbackup.v3.conf·--run-as-cli·--snapshots·--repo-name·OneDrive_via_rclone·--repo-group·OneDrive_via_rclone

npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-27 00:40:14,273 :: INFO :: npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-27 00:40:14,298 :: INFO :: Loaded config 9CFC27FE in /home/linux/npbackup/npbackup.v3.conf
2025-03-27 00:40:14,363 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-03-27 00:40:14,363 :: DEBUG :: STDOUT: restic 0.17.3 compiled with go1.23.3 on linux/amd64

2025-03-27 00:40:14,363 :: INFO :: Using binary restic 0.17.3 compiled with go1.23.3 on linux/amd64
2025-03-27 00:40:14,364 :: INFO :: Listing snapshots of repo OneDrive_via_rclone
2025-03-27 00:40:14,364 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-27 00:40:14,364 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-27 00:40:22,499 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/27 00:40:14 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:40:14 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:40:14 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:40:15 DEBUG : file-9199004314396080971: GET request error: object not found
rclone: 2025/03/27 00:40:15 DEBUG : keys: list request
rclone: 2025/03/27 00:40:17 DEBUG : locks: list request
rclone: 2025/03/27 00:40:17 DEBUG : locks/c33216abd7c6b98d5406833d441ebbbb0d15eb1092d318ffda3cab4904027474: Starting multipart upload
rclone: 2025/03/27 00:40:18 DEBUG : locks/c33216abd7c6b98d5406833d441ebbbb0d15eb1092d318ffda3cab4904027474: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:40:20 DEBUG : locks: list request
rclone: 2025/03/27 00:40:20 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-27 00:40:22,499 :: DEBUG :: STDOUT: rclone: 2025/03/27 00:40:14 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:40:14 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:40:14 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:40:15 DEBUG : file-9199004314396080971: GET request error: object not found
rclone: 2025/03/27 00:40:15 DEBUG : keys: list request
rclone: 2025/03/27 00:40:17 DEBUG : locks: list request
rclone: 2025/03/27 00:40:17 DEBUG : locks/c33216abd7c6b98d5406833d441ebbbb0d15eb1092d318ffda3cab4904027474: Starting multipart upload
rclone: 2025/03/27 00:40:18 DEBUG : locks/c33216abd7c6b98d5406833d441ebbbb0d15eb1092d318ffda3cab4904027474: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:40:20 DEBUG : locks: list request
rclone: 2025/03/27 00:40:20 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-27 00:40:22,499 :: DEBUG :: Running on_exit callable.
2025-03-27 00:40:22,499 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-27 00:40:22,499 :: DEBUG :: Setting GOMAXPROCS to 10
rclone: 2025/03/27 00:40:22 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:40:22 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:40:22 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:40:23 DEBUG : file-4006203844852001755: GET request error: object not found
rclone: 2025/03/27 00:40:23 DEBUG : keys: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Starting multipart upload
rclone: 2025/03/27 00:40:25 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:40:26 DEBUG : locks: list request
rclone: 2025/03/27 00:40:26 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots
2025-03-27 00:40:27,615 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.17.3_linux_amd64', '--limit-upload', '102400', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/27 00:40:22 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:40:22 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:40:22 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:40:23 DEBUG : file-4006203844852001755: GET request error: object not found
rclone: 2025/03/27 00:40:23 DEBUG : keys: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Starting multipart upload
rclone: 2025/03/27 00:40:25 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:40:26 DEBUG : locks: list request
rclone: 2025/03/27 00:40:26 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-27 00:40:27,615 :: DEBUG :: STDOUT: rclone: 2025/03/27 00:40:22 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/27 00:40:22 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/27 00:40:22 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/27 00:40:23 DEBUG : file-4006203844852001755: GET request error: object not found
rclone: 2025/03/27 00:40:23 DEBUG : keys: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks: list request
rclone: 2025/03/27 00:40:24 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Starting multipart upload
rclone: 2025/03/27 00:40:25 DEBUG : locks/7f9ed5456a19408e872d3b504e683a99936a5f808ca1ab4a11ecf643d84d29a0: Uploading segment 0/188 size 188
rclone: 2025/03/27 00:40:26 DEBUG : locks: list request
rclone: 2025/03/27 00:40:26 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-27 00:40:27,615 :: DEBUG :: Running on_exit callable.
2025-03-27 00:40:27,616 :: INFO :: Snapshots listed successfully
2025-03-27 00:40:27,616 :: INFO :: Runner took 13.311052 seconds for snapshots
2025-03-27 00:40:27,616 :: DEBUG :: Metrics computed:
npbackup_exec_state{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="snapshots",repo_name="OneDrive_via_rclone",timestamp="1743032427"} 0
npbackup_exec_time{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="snapshots",repo_name="OneDrive_via_rclone",timestamp="1743032427"} 13.311052
2025-03-27 00:40:27,616 :: INFO :: Dry run mode. Not sending metrics.
2025-03-27 00:40:27,616 :: INFO :: Operation finished
2025-03-27 00:40:27,622 :: INFO :: ExecTime = 0:00:13.350505, finished, state is: success.
~/npbackup.latest.github

here the GUI response when changing the repo which equals the snapshots command afaik:

Image

pressing close displays the error,

Image

after which pressing OK exits npbackup-gui and closes its terminal.

@deajan
Copy link
Contributor

deajan commented Mar 28, 2025

It's not easy trying to debug things without me setting up a full rclone repo.
I've re-read my previous fix and noticed that my regex wasn't filtering properly full line results.
I've fixed the regex and added various debug lines in order to see what actually happens.

Would you mind running the latest git code with the same backup and snapshot debug commands ?
Again (and again and again), thank you for your precious time.

@GuitarBilly
Copy link
Author

sure I can run the latest git code again. It is better.

here is the output of

venv/bin/python·bin/npbackup-gui·--debug·--dry-run·--config-file=/home/linux/npbackup/npbackup.v3.conf·--run-as-cli·--backup·--repo-name·OneDrive_via_rclone·--repo-group·OneDrive_via_rclone

npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-30 18:10:13,015 :: INFO :: npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-30 18:10:13,041 :: INFO :: Loaded config 9CFC27FE in /home/linux/npbackup/npbackup.v3.conf
2025-03-30 18:10:13,105 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.18.0 compiled with go1.24.1 on linux/amd64

2025-03-30 18:10:13,105 :: DEBUG :: STDOUT: restic 0.18.0 compiled with go1.24.1 on linux/amd64

2025-03-30 18:10:13,106 :: INFO :: Using binary restic 0.18.0 compiled with go1.24.1 on linux/amd64
2025-03-30 18:10:13,106 :: INFO :: Searching for a backup newer than 1 day, 0:00:00 ago
2025-03-30 18:10:13,106 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:10:13,106 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-30 18:10:18,673 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:10:13 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:13 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:13 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:13 DEBUG : file-14647437990274065400: GET request error: object not found
rclone: 2025/03/30 18:10:14 DEBUG : keys: list request
rclone: 2025/03/30 18:10:15 DEBUG : locks: list request
rclone: 2025/03/30 18:10:15 DEBUG : locks/25e35a4bcf5e52f0ca901b197314b57e4094163aa6acc749ad6226fec6fdb14a: Starting multipart upload
rclone: 2025/03/30 18:10:16 DEBUG : locks/25e35a4bcf5e52f0ca901b197314b57e4094163aa6acc749ad6226fec6fdb14a: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:17 DEBUG : locks: list request
rclone: 2025/03/30 18:10:17 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-30 18:10:18,673 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:10:13 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:13 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:13 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:13 DEBUG : file-14647437990274065400: GET request error: object not found
rclone: 2025/03/30 18:10:14 DEBUG : keys: list request
rclone: 2025/03/30 18:10:15 DEBUG : locks: list request
rclone: 2025/03/30 18:10:15 DEBUG : locks/25e35a4bcf5e52f0ca901b197314b57e4094163aa6acc749ad6226fec6fdb14a: Starting multipart upload
rclone: 2025/03/30 18:10:16 DEBUG : locks/25e35a4bcf5e52f0ca901b197314b57e4094163aa6acc749ad6226fec6fdb14a: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:17 DEBUG : locks: list request
rclone: 2025/03/30 18:10:17 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-30 18:10:18,673 :: DEBUG :: Running on_exit callable.
2025-03-30 18:10:18,674 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:10:18,674 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-30 18:10:23,793 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', '--json', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:10:18 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:18 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:18 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:19 DEBUG : file-14098935322912295395: GET request error: object not found
rclone: 2025/03/30 18:10:19 DEBUG : keys: list request
rclone: 2025/03/30 18:10:20 DEBUG : locks: list request
rclone: 2025/03/30 18:10:20 DEBUG : locks/fb25ddfb14cf5e770a3a104eabaa7134ec9b4cf570ef9853593aa2b8c4daa945: Starting multipart upload
rclone: 2025/03/30 18:10:21 DEBUG : locks/fb25ddfb14cf5e770a3a104eabaa7134ec9b4cf570ef9853593aa2b8c4daa945: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:22 DEBUG : locks: list request
rclone: 2025/03/30 18:10:22 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-30 18:10:23,793 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:10:18 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:18 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:18 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:19 DEBUG : file-14098935322912295395: GET request error: object not found
rclone: 2025/03/30 18:10:19 DEBUG : keys: list request
rclone: 2025/03/30 18:10:20 DEBUG : locks: list request
rclone: 2025/03/30 18:10:20 DEBUG : locks/fb25ddfb14cf5e770a3a104eabaa7134ec9b4cf570ef9853593aa2b8c4daa945: Starting multipart upload
rclone: 2025/03/30 18:10:21 DEBUG : locks/fb25ddfb14cf5e770a3a104eabaa7134ec9b4cf570ef9853593aa2b8c4daa945: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:22 DEBUG : locks: list request
rclone: 2025/03/30 18:10:22 DEBUG : snapshots: list request
[{"time":"2025-02-23T19:01:47.980798989+01:00","tree":"c68f100920af8ae3b3a976c07e964cb996e4d774c0b7a72ccf214b0adbfa4b2c","paths":["/home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:01:47.980798989+01:00","backup_end":"2025-02-23T19:01:55.839219359+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":4,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":5,"data_added":4892,"data_added_packed":2975,"total_files_processed":1,"total_bytes_processed":2983},"id":"3baa9df07cd543e07b7715c6b0dde26295da989abf2dcc0cf1248850b31b21ef","short_id":"3baa9df0"},{"time":"2025-02-23T19:46:06.08633833+01:00","tree":"ae720781f9a1caa9c7e0cc21668e0d1ba3cf3b01d6db372bc5bcc73ac3704920","paths":["/home/linux/npbackup.latest.github/update.all.and.start.gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-23T19:46:06.08633833+01:00","backup_end":"2025-02-23T19:46:13.536042263+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":1,"tree_blobs":4,"data_added":2461,"data_added_packed":1702,"total_files_processed":1,"total_bytes_processed":941},"id":"716f837213faeca7c9bead65265e31b5b95e297029f9030fe6193e7cb5b0d9d1","short_id":"716f8372"},{"time":"2025-02-26T22:24:07.339859762+01:00","tree":"2563016ec9922b907966f3e50ebe56a4f9da32c80be1cbc63867a6504e4b2f62","paths":["/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh"],"hostname":"x300werkstation","username":"linux","uid":1000,"gid":1000,"tags":["onedrive","rclone"],"program_version":"restic 0.17.3","summary":{"backup_start":"2025-02-26T22:24:07.339859762+01:00","backup_end":"2025-02-26T22:24:14.901924484+01:00","files_new":1,"files_changed":0,"files_unmodified":0,"dirs_new":3,"dirs_changed":0,"dirs_unmodified":0,"data_blobs":0,"tree_blobs":4,"data_added":1529,"data_added_packed":1223,"total_files_processed":1,"total_bytes_processed":941},"id":"7f0eee1d707b2731a43f64fd1865e3cfe65fd3b6bb5f93f6d2cf0ca7f5893c87","short_id":"7f0eee1d"}]

2025-03-30 18:10:23,793 :: DEBUG :: Running on_exit callable.
2025-03-30 18:10:23,794 :: INFO :: Snapshots listed successfully
2025-03-30 18:10:23,794 :: INFO :: No recent backup found in repo OneDrive_via_rclone. Newest is from 2025-02-26 22:24:07.339859+01:00
2025-03-30 18:10:23,794 :: INFO :: Runner took 10.688462 seconds for has_recent_snapshot
2025-03-30 18:10:23,794 :: INFO :: Running backup of ['/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh'] to repo OneDrive_via_rclone
2025-03-30 18:10:23,853 :: DEBUG :: Command "${NPBACKUP_BACKEND_BINARY} cache --cleanup" returned with exit code "0". Command output was:
no old cache dirs found

2025-03-30 18:10:23,853 :: DEBUG :: STDOUT: no old cache dirs found

2025-03-30 18:10:23,853 :: INFO :: Pre-execution of command ${NPBACKUP_BACKEND_BINARY} cache --cleanup succeeded with:
no old cache dirs found

2025-03-30 18:10:23,854 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:10:23,854 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-30 18:10:28,913 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:10:23 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:23 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:23 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:24 DEBUG : file-4972377245661204778: GET request error: object not found
rclone: 2025/03/30 18:10:24 DEBUG : keys: list request
rclone: 2025/03/30 18:10:25 DEBUG : locks: list request
rclone: 2025/03/30 18:10:26 DEBUG : locks/f1c1c674c3e3da892532f8b88cf0d15d3fe47e27c9346d8b1063bc2b4f576ded: Starting multipart upload
rclone: 2025/03/30 18:10:26 DEBUG : locks/f1c1c674c3e3da892532f8b88cf0d15d3fe47e27c9346d8b1063bc2b4f576ded: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:27 DEBUG : locks: list request
rclone: 2025/03/30 18:10:28 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:10:28,913 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:10:23 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:23 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:23 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:24 DEBUG : file-4972377245661204778: GET request error: object not found
rclone: 2025/03/30 18:10:24 DEBUG : keys: list request
rclone: 2025/03/30 18:10:25 DEBUG : locks: list request
rclone: 2025/03/30 18:10:26 DEBUG : locks/f1c1c674c3e3da892532f8b88cf0d15d3fe47e27c9346d8b1063bc2b4f576ded: Starting multipart upload
rclone: 2025/03/30 18:10:26 DEBUG : locks/f1c1c674c3e3da892532f8b88cf0d15d3fe47e27c9346d8b1063bc2b4f576ded: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:10:27 DEBUG : locks: list request
rclone: 2025/03/30 18:10:28 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:10:28,913 :: DEBUG :: Running on_exit callable.
2025-03-30 18:10:28,913 :: INFO :: Running in dry mode. No modifications will be done
2025-03-30 18:10:28,914 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:10:28,914 :: DEBUG :: Setting GOMAXPROCS to 10
rclone: 2025/03/30 18:10:28 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:28 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:28 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:29 DEBUG : file-9941895164188364721: GET request error: object not found
rclone: 2025/03/30 18:10:29 DEBUG : keys: list request
rclone: 2025/03/30 18:10:44 DEBUG : snapshots: list request
using parent snapshot 7f0eee1d
rclone: 2025/03/30 18:10:44 DEBUG : index: list request

Files:           0 new,     0 changed,     1 unmodified
Dirs:            0 new,     3 changed,     0 unmodified
Would add to the repository: 1.096 KiB (886 B stored)

processed 1 files, 941 B in 0:16
2025-03-30 18:10:45,106 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', 'backup', '--dry-run', '--no-scan', '/home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh', '--exclude-file', 'excludes/generic_excluded_extensions', '--exclude-file', 'excludes/generic_excludes', '--exclude-file', 'excludes/linux_excludes', '--exclude-caches', '--tag', 'onedrive', '--tag', 'rclone']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:10:28 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:28 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:28 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:29 DEBUG : file-9941895164188364721: GET request error: object not found
rclone: 2025/03/30 18:10:29 DEBUG : keys: list request
rclone: 2025/03/30 18:10:44 DEBUG : snapshots: list request
using parent snapshot 7f0eee1d
rclone: 2025/03/30 18:10:44 DEBUG : index: list request

Files:           0 new,     0 changed,     1 unmodified
Dirs:            0 new,     3 changed,     0 unmodified
Would add to the repository: 1.096 KiB (886 B stored)

processed 1 files, 941 B in 0:16

2025-03-30 18:10:45,106 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:10:28 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:10:28 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:10:28 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:10:29 DEBUG : file-9941895164188364721: GET request error: object not found
rclone: 2025/03/30 18:10:29 DEBUG : keys: list request
rclone: 2025/03/30 18:10:44 DEBUG : snapshots: list request
using parent snapshot 7f0eee1d
rclone: 2025/03/30 18:10:44 DEBUG : index: list request

Files:           0 new,     0 changed,     1 unmodified
Dirs:            0 new,     3 changed,     0 unmodified
Would add to the repository: 1.096 KiB (886 B stored)

processed 1 files, 941 B in 0:16

2025-03-30 18:10:45,107 :: DEBUG :: Running on_exit callable.
2025-03-30 18:10:45,107 :: INFO :: Backend finished with success
2025-03-30 18:10:45,107 :: DEBUG :: Restic output:
using parent snapshot 7f0eee1d

Files:           0 new,     0 changed,     1 unmodified
Dirs:            0 new,     3 changed,     0 unmodified
Would add to the repository: 1.096 KiB (886 B stored)

processed 1 files, 941 B in 0:16

2025-03-30 18:10:45,108 :: INFO :: Processed 0.9189453125 KiB of data
2025-03-30 18:10:45,108 :: DEBUG :: Metrics computed:
restic_files{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="new",action="backup"} 0
restic_files{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="changed",action="backup"} 0
restic_files{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="unmodified",action="backup"} 1
restic_dirs{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="new",action="backup"} 0
restic_dirs{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="changed",action="backup"} 3
restic_dirs{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="unmodified",action="backup"} 0
restic_files{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",state="total",action="backup"} 1
restic_snasphot_size_bytes{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup",type="processed"} 941
restic_total_duration_seconds{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup"} 16
restic_errors{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup"} 0
restic_backup_failure{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",timestamp="1743351045"} 0
npbackup_exec_state{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup",repo_name="OneDrive_via_rclone",timestamp="1743351045"} 0
npbackup_exec_time{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="backup",repo_name="OneDrive_via_rclone",timestamp="1743351045"} 32.001211
2025-03-30 18:10:45,108 :: INFO :: Dry run mode. Not sending metrics.
2025-03-30 18:10:45,108 :: INFO :: Operation finished with success
2025-03-30 18:10:45,108 :: INFO :: Runner took 32.061485 seconds for backup
2025-03-30 18:10:45,108 :: INFO :: Operation finished
2025-03-30 18:10:45,115 :: INFO :: ExecTime = 0:00:32.100488, finished, state is: success.
~/npbackup.latest.github

and here the output of the --snapshots:

venv/bin/python·bin/npbackup-gui·--debug·--dry-run·--config-file=/home/linux/npbackup/npbackup.v3.conf·--run-as-cli·--snapshots·--repo-name·OneDrive_via_rclone·--repo-group·OneDrive_via_rclone

npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-30 18:08:33,274 :: INFO :: npbackup 3.0.1-linux-gui-x64-legacy-public-3.10-i 2025032101 - Copyright (C) 2022-2025 NetInvent running as linux
2025-03-30 18:08:33,310 :: INFO :: Loaded config 9CFC27FE in /home/linux/npbackup/npbackup.v3.conf
2025-03-30 18:08:33,374 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', 'version']" returned with exit code "0". Command output was:
restic 0.18.0 compiled with go1.24.1 on linux/amd64

2025-03-30 18:08:33,374 :: DEBUG :: STDOUT: restic 0.18.0 compiled with go1.24.1 on linux/amd64

2025-03-30 18:08:33,374 :: INFO :: Using binary restic 0.18.0 compiled with go1.24.1 on linux/amd64
2025-03-30 18:08:33,374 :: INFO :: Listing snapshots of repo OneDrive_via_rclone
2025-03-30 18:08:33,374 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:08:33,375 :: DEBUG :: Setting GOMAXPROCS to 10
2025-03-30 18:08:41,535 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:08:33 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:08:33 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:08:33 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:08:33 DEBUG : onedrive: Loaded invalid token from config file - ignoring
rclone: 2025/03/30 18:08:34 DEBUG : Saving config "token" in section "onedrive" of the config file
rclone: 2025/03/30 18:08:34 DEBUG : onedrive: Saved new token in config file
rclone: 2025/03/30 18:08:35 DEBUG : file-10692630059068034031: GET request error: object not found
rclone: 2025/03/30 18:08:35 DEBUG : keys: list request
rclone: 2025/03/30 18:08:36 DEBUG : locks: list request
rclone: 2025/03/30 18:08:37 DEBUG : locks/767d0b139743c1ea91f3aed457e1c4cd1b46ecddbeeafb3cf6d7fc2c4f60c302: Starting multipart upload
rclone: 2025/03/30 18:08:38 DEBUG : locks/767d0b139743c1ea91f3aed457e1c4cd1b46ecddbeeafb3cf6d7fc2c4f60c302: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:08:40 DEBUG : locks: list request
rclone: 2025/03/30 18:08:40 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:08:41,535 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:08:33 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:08:33 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:08:33 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:08:33 DEBUG : onedrive: Loaded invalid token from config file - ignoring
rclone: 2025/03/30 18:08:34 DEBUG : Saving config "token" in section "onedrive" of the config file
rclone: 2025/03/30 18:08:34 DEBUG : onedrive: Saved new token in config file
rclone: 2025/03/30 18:08:35 DEBUG : file-10692630059068034031: GET request error: object not found
rclone: 2025/03/30 18:08:35 DEBUG : keys: list request
rclone: 2025/03/30 18:08:36 DEBUG : locks: list request
rclone: 2025/03/30 18:08:37 DEBUG : locks/767d0b139743c1ea91f3aed457e1c4cd1b46ecddbeeafb3cf6d7fc2c4f60c302: Starting multipart upload
rclone: 2025/03/30 18:08:38 DEBUG : locks/767d0b139743c1ea91f3aed457e1c4cd1b46ecddbeeafb3cf6d7fc2c4f60c302: Uploading segment 0/187 size 187
rclone: 2025/03/30 18:08:40 DEBUG : locks: list request
rclone: 2025/03/30 18:08:40 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:08:41,535 :: DEBUG :: Running on_exit callable.
2025-03-30 18:08:41,535 :: DEBUG :: Setting environment variable "RCLONE_VERBOSE"
2025-03-30 18:08:41,535 :: DEBUG :: Setting GOMAXPROCS to 10
rclone: 2025/03/30 18:08:41 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:08:41 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:08:41 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:08:42 DEBUG : file-16742447974153703292: GET request error: object not found
rclone: 2025/03/30 18:08:42 DEBUG : keys: list request
rclone: 2025/03/30 18:08:43 DEBUG : locks: list request
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Starting multipart upload
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Uploading segment 0/186 size 186
rclone: 2025/03/30 18:08:46 DEBUG : locks: list request
rclone: 2025/03/30 18:08:46 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots
2025-03-30 18:08:47,129 :: DEBUG :: Command "['/home/linux/npbackup.latest.github/npbackup/npbackup/../RESTIC_SOURCE_FILES/restic_0.18.0_linux_amd64', '--limit-upload', '102400', 'snapshots']" returned with exit code "0". Command output was:
rclone: 2025/03/30 18:08:41 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:08:41 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:08:41 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:08:42 DEBUG : file-16742447974153703292: GET request error: object not found
rclone: 2025/03/30 18:08:42 DEBUG : keys: list request
rclone: 2025/03/30 18:08:43 DEBUG : locks: list request
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Starting multipart upload
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Uploading segment 0/186 size 186
rclone: 2025/03/30 18:08:46 DEBUG : locks: list request
rclone: 2025/03/30 18:08:46 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:08:47,129 :: DEBUG :: STDOUT: rclone: 2025/03/30 18:08:41 DEBUG : rclone: Version "v1.69.1" starting with parameters ["rclone" "serve" "restic" "--stdio" "--b2-hard-delete" "onedrive:MPD/npbackup.repo"]
rclone: 2025/03/30 18:08:41 DEBUG : Creating backend with remote "onedrive:MPD/npbackup.repo"
rclone: 2025/03/30 18:08:41 DEBUG : Using config file from "/home/linux/.config/rclone/rclone.conf"
rclone: 2025/03/30 18:08:42 DEBUG : file-16742447974153703292: GET request error: object not found
rclone: 2025/03/30 18:08:42 DEBUG : keys: list request
rclone: 2025/03/30 18:08:43 DEBUG : locks: list request
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Starting multipart upload
rclone: 2025/03/30 18:08:44 DEBUG : locks/8c08fbdd4dcda422a83f3f6d2ab7d00a36edfe91f84fd5c9633d9dc8bc031221: Uploading segment 0/186 size 186
rclone: 2025/03/30 18:08:46 DEBUG : locks: list request
rclone: 2025/03/30 18:08:46 DEBUG : snapshots: list request
ID        Time                 Host             Tags             Paths                                                                               Size
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3baa9df0  2025-02-23 19:01:47  x300werkstation                   /home/linux/npbackup.latest.github/npbackup/npbackup.OneDrive_via_rclone.anon.conf  2.913 KiB
716f8372  2025-02-23 19:46:06  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.gui.sh                      941 B
7f0eee1d  2025-02-26 22:24:07  x300werkstation  onedrive,rclone  /home/linux/npbackup.latest.github/update.all.and.start.npbackup-gui.sh             941 B
--------------------------------------------------------------------------------------------------------------------------------------------------------------
3 snapshots

2025-03-30 18:08:47,129 :: DEBUG :: Running on_exit callable.
2025-03-30 18:08:47,130 :: INFO :: Snapshots listed successfully
2025-03-30 18:08:47,130 :: INFO :: Runner took 13.814107 seconds for snapshots
2025-03-30 18:08:47,130 :: DEBUG :: Metrics computed:
npbackup_exec_state{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="snapshots",repo_name="OneDrive_via_rclone",timestamp="1743350927"} 0
npbackup_exec_time{npversion="npbackup3.0.1-gui",instance="x300werkstation__nFknv3rc12",backup_job="x300werkstation__nFkn",group="x300werkstation",action="snapshots",repo_name="OneDrive_via_rclone",timestamp="1743350927"} 13.814107
2025-03-30 18:08:47,130 :: INFO :: Dry run mode. Not sending metrics.
2025-03-30 18:08:47,130 :: INFO :: Operation finished
2025-03-30 18:08:47,137 :: INFO :: ExecTime = 0:00:13.864349, finished, state is: success.
~/npbackup.latest.github

So both commands now have the status of success. Then I try with the GUI too. The GUI gives messages in the window but does not crash anymore.

Image

Image

Since my commandline was --dry-run and the GUI does not crash, I dare to launch a manual backup in the GUI:

Image

Image

It seems we have a winner! one more snapshot available !!
Last, I have a look at the Grafana dashboard, currently at NPBackup v3 20250306. this now gives a warning ¨match[] must contain at least one non-empty matcher¨ and no output:

Image

Next try, remove the RCLONE_VERBOSE = 2 from the configuration and run again. This makes the GUI complete the backup without any "DEBUG" messages in the "error messages" part of the window, but brings no change to the Grafana Dashboard.

@deajan
Copy link
Contributor

deajan commented Apr 1, 2025

Thank you for the (re) testing, happy to know it works.
The error messages shown in GUI come from rclone which outputs the errors to stderr instead of stdout, so there's nothing I can really do, since that shouldn't be the case.

I'll close this one and open another issue for the grafana dashboard.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants