VictoriaMetrics: vmbackupmanager: incompatibility issues with local FS on windows

Describe the bug

Can’t create backups using vmbackupmanager. vmbackup works correctly.

vmbackupmanager produces an error the moment a backup is scheduled to run.

To Reproduce

Executing this command: vmbackupmanager-windows-amd64-prod.exe -eula -dst="fs://E:\Backups\victoria-metrics-backups" -storageDataPath=%VICTORIAMETRICS%\victoria-metrics-data -snapshot.createURL=http://localhost:8428/snapshot/create -maxBytesPerSecond=10485760 -keepLastDaily=2 -keepLastWeekly=1 -keepLastMonthly=3

Version

vmbackupmanager-20230602-121930-tags-v1.91.2-enterprise-0-g9c0ee3336

Logs

Copyright 2018-2022 VictoriaMetrics, Inc - All Rights Reserved.
For any questions please contact info@victoriametrics.com
2023-07-24T09:54:04.610-0300    info    VictoriaMetrics/lib/logger/flag.go:12   build version: vmbackupmanager-20230602-121930-tags-v1.91.2-enterprise-0-g9c0ee3336
2023-07-24T09:54:04.615-0300    info    VictoriaMetrics/lib/logger/flag.go:13   command-line flags
2023-07-24T09:54:04.615-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -dst="fs://E:\\Backups\\victoria-metrics-backups"
2023-07-24T09:54:04.615-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -eula="true"
2023-07-24T09:54:04.615-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -keepLastDaily="2"
2023-07-24T09:54:04.617-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -keepLastMonthly="3"
2023-07-24T09:54:04.618-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -keepLastWeekly="1"
2023-07-24T09:54:04.621-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -maxBytesPerSecond="10485760"
2023-07-24T09:54:04.622-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -snapshot.createURL="http://localhost:8428/snapshot/create"
2023-07-24T09:54:04.623-0300    info    VictoriaMetrics/lib/logger/flag.go:20     -storageDataPath="C:\\Monitoring\\victoria-metrics\\victoria-metrics-data"
2023-07-24T09:54:04.634-0300    info    VictoriaMetrics/lib/httpserver/httpserver.go:96 starting http server at http://127.0.0.1:8300/
2023-07-24T09:54:04.639-0300    info    VictoriaMetrics/lib/httpserver/httpserver.go:97 pprof handlers are exposed at http://127.0.0.1:8300/debug/pprof/
2023-07-24T09:54:04.655-0300    info    VictoriaMetrics/app/vmbackupmanager/main.go:363 sleeping for 5m56s before the next backup
2023-07-24T10:00:01.609-0300    info    VictoriaMetrics/lib/backup/actions/backup.go:116        starting backup from fslocal "C:\\Monitoring\\victoria-metrics\\victoria-metrics-data/snapshots/20230724130001-1774CEFA8C6D71E5" to fsremote "E:\\Backups\\victoria-metrics-backups\\latest" using origin fsnil
2023-07-24T10:00:01.634-0300    panic   VictoriaMetrics/lib/backup/fslocal/fslocal.go:74        BUG: unexpected prefix for file "C:\\Monitoring\\victoria-metrics\\victoria-metrics-data\\snapshots\\20230724130001-1774CEFA8C6D71E5\\data\\small\\2023_06\\176ED613C2B5507D\\index.bin"; want "C:\\Monitoring\\victoria-metrics\\victoria-metrics-data/snapshots/20230724130001-1774CEFA8C6D71E5\\"
panic: BUG: unexpected prefix for file "C:\\Monitoring\\victoria-metrics\\victoria-metrics-data\\snapshots\\20230724130001-1774CEFA8C6D71E5\\data\\small\\2023_06\\176ED613C2B5507D\\index.bin"; want "C:\\Monitoring\\victoria-metrics\\victoria-metrics-data/snapshots/20230724130001-1774CEFA8C6D71E5\\"

goroutine 9 [running]:
github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logMessage({0x181362d, 0x5}, {0xc000312780, 0x124}, 0x2?)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/logger/logger.go:281 +0xa96
github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logLevelSkipframes(0x1, {0x181362d, 0x5}, {0x1844a5f?, 0x1628280?}, {0xc000013600?, 0x1628bc0?, 0xc000458220?})
        github.com/VictoriaMetrics/VictoriaMetrics/lib/logger/logger.go:138 +0x1a5
github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.logLevel(...)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/logger/logger.go:130
github.com/VictoriaMetrics/VictoriaMetrics/lib/logger.Panicf(...)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/logger/logger.go:126
github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/fslocal.(*FS).ListParts(0x1?)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/fslocal/fslocal.go:74 +0x2bd
github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/actions.runBackup(0xc000086140, {0x1a17b10?, 0xc000458170}, {0x1a0f890?, 0x214b5e0}, 0xc00052a029?)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/actions/backup.go:118 +0x15e
github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/actions.(*Backup).Run(0xc00052a000?)
        github.com/VictoriaMetrics/VictoriaMetrics/lib/backup/actions/backup.go:76 +0x1b4
main.(*backuper).makeBackup(0xc00006e0f0, 0xc000086140, {0x1816238?, 0xfffffcb9cf476000?})
        github.com/VictoriaMetrics/VictoriaMetrics/app/vmbackupmanager/main.go:496 +0x11e
main.(*backuper).run(0xc00006e0f0, {0x1a11da0, 0xc00006e0a0})
        github.com/VictoriaMetrics/VictoriaMetrics/app/vmbackupmanager/main.go:425 +0x20e
main.(*backuper).scheduleBackups(0xc00006e0f0, {0x1a11da0, 0xc00006e0a0})
        github.com/VictoriaMetrics/VictoriaMetrics/app/vmbackupmanager/main.go:372 +0x3a5
main.runBackupManager.func1()
        github.com/VictoriaMetrics/VictoriaMetrics/app/vmbackupmanager/main.go:150 +0x65
created by main.runBackupManager
        github.com/VictoriaMetrics/VictoriaMetrics/app/vmbackupmanager/main.go:148 +0x3aa

Screenshots

No response

Used command-line flags

-eula -dst="fs://E:\Backups\victoria-metrics-backups" -storageDataPath=%VICTORIAMETRICS%\victoria-metrics-data -snapshot.createURL=http://localhost:8428/snapshot/create -maxBytesPerSecond=10485760 -keepLastDaily=2 -keepLastWeekly=1 -keepLastMonthly=3

Additional information

Windows Server 2019 as Admin.

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 23 (11 by maintainers)

Commits related to this issue

Most upvoted comments

@zekker6 Hi zek, yep, seems everything is working now: Thanks! 😃

Executing same command as before: ✔️

... <long list of files>
...
2023-07-27T15:55:36.138Z        info    VictoriaMetrics/lib/backup/actions/copy.go:120  server-side copied 382 out of 382 parts from src fsremote "E:\\Backups\\victoria-metrics-backups\\latest" to dst fsremote "E:\\Backups\\victoria-metrics-backups\\monthly\\2023-07" in 1.604384s
2023-07-27T15:55:36.138Z        info    VictoriaMetrics/lib/backup/actions/copy.go:127  backup copy from src fsremote "E:\\Backups\\victoria-metrics-backups\\latest" to dst fsremote "E:\\Backups\\victoria-metrics-backups\\monthly\\2023-07" is complete; backed up 310503211 bytes in 1.693 seconds; deleted 0 bytes; server-side copied 310503211 bytes
2023-07-27T15:55:36.140Z        info    VictoriaMetrics/app/vmbackupmanager/main.go:477 backup has been successfully created
2023-07-27T15:55:36.486Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    daily backups to delete []
2023-07-27T15:55:36.768Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    weekly backups to delete []
2023-07-27T15:55:37.045Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    monthly backups to delete []
2023-07-27T15:55:37.581Z        info    VictoriaMetrics/app/vmbackupmanager/main.go:363 sleeping for 4m23s before the next backup

Shutting down the service (Control+C) and restarting it also works correctly. ✔️

...
2023-07-27T15:58:55.182Z        info    VictoriaMetrics/lib/backup/actions/copy.go:120  server-side copied 17 out of 17 parts from src fsremote "E:\\Backups\\victoria-metrics-backups\\latest" to dst fsremote "E:\\Backups\\victoria-metrics-backups\\monthly\\2023-07" in 56.4529ms
2023-07-27T15:58:55.186Z        info    VictoriaMetrics/lib/backup/actions/copy.go:127  backup copy from src fsremote "E:\\Backups\\victoria-metrics-backups\\latest" to dst fsremote "E:\\Backups\\victoria-metrics-backups\\monthly\\2023-07" is complete; backed up 310626495 bytes in 0.287 seconds; deleted 876 bytes; server-side copied 124160 bytes
2023-07-27T15:58:55.189Z        info    VictoriaMetrics/app/vmbackupmanager/main.go:477 backup has been successfully created
2023-07-27T15:58:55.492Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    daily backups to delete []
2023-07-27T15:58:55.779Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    weekly backups to delete []
2023-07-27T15:58:56.065Z        info    VictoriaMetrics/app/vmbackupmanager/retention.go:123    monthly backups to delete []
2023-07-27T15:58:56.670Z        info    VictoriaMetrics/app/vmbackupmanager/main.go:363 sleeping for 1m4s before the next backup

Seems everything is working.

@tekert Thanks, this will not be necessary because we have our benchmark which can generate data for testing. Also, those issues are not related to data itself but to a way we handle file operations in vmbackupmanager when running on Windows.

Apart writing data from memory storage can also perform:

  • background merges
  • reading data for query processing

So the problem with deleting even symlinked files is that this file can be opened for reading at query execution path. This means that in order to be absolutely sure that we will not get file is already used by another process error in windows we need to:

  • stop query processing
  • stop writing new data
  • stop background merges process.

This seems like we need to stop all DB operations anyway, very similar to what happens on graceful shutdown during restart. That’s why we decided not to implement this as a built-in functionality to keep code base simpler.