Database migration failed malformed, but integrity check is OK

Node Operators troubleshooting
1

One of my nodes updated and the docker container got stuck, checked it to find this error.

2024-05-20T23:57:59.360945473+01:00 2024-05-20T23:57:59+01:00	INFO	Anonymized tracing enabled	{"Process": "storagenode-updater"}
2024-05-20T23:57:59.361790432+01:00 2024-05-20T23:57:59+01:00	INFO	Running on version	{"Process": "storagenode-updater", "Service": "storagenode-updater", "Version": "v1.104.5"}
2024-05-20T23:57:59.362423267+01:00 2024-05-20T23:57:59+01:00	INFO	Downloading versions.	{"Process": "storagenode-updater", "Server Address": "https://version.storj.io"}
2024-05-20T23:57:59.395383020+01:00 2024-05-20T23:57:59+01:00	INFO	Configuration loaded	{"Process": "storagenode", "Location": "/app/config/config.yaml"}
2024-05-20T23:57:59.396209183+01:00 2024-05-20T23:57:59+01:00	INFO	Anonymized tracing enabled	{"Process": "storagenode"}
2024-05-20T23:57:59.409338136+01:00 2024-05-20T23:57:59+01:00	INFO	Operator email	{"Process": "storagenode", "Address": "euan.mutch@gmail.com"}
2024-05-20T23:57:59.409374243+01:00 2024-05-20T23:57:59+01:00	INFO	Operator wallet	{"Process": "storagenode", "Address": "0xc33d367C41ab65acb5034301E9ED7BE34De23691"}
2024-05-20T23:57:59.460505250+01:00 2024-05-20T23:57:59+01:00	INFO	server	kernel support for server-side tcp fast open remains disabled.	{"Process": "storagenode"}
2024-05-20T23:57:59.460630943+01:00 2024-05-20T23:57:59+01:00	INFO	server	enable with: sysctl -w net.ipv4.tcp_fastopen=3	{"Process": "storagenode"}
2024-05-20T23:57:59.729086159+01:00 2024-05-20T23:57:59+01:00	INFO	Current binary version	{"Process": "storagenode-updater", "Service": "storagenode", "Version": "v1.104.5"}
2024-05-20T23:57:59.729126295+01:00 2024-05-20T23:57:59+01:00	INFO	Version is up to date	{"Process": "storagenode-updater", "Service": "storagenode"}
2024-05-20T23:57:59.738001537+01:00 2024-05-20T23:57:59+01:00	INFO	Current binary version	{"Process": "storagenode-updater", "Service": "storagenode-updater", "Version": "v1.104.5"}
2024-05-20T23:57:59.738084545+01:00 2024-05-20T23:57:59+01:00	INFO	Version is up to date	{"Process": "storagenode-updater", "Service": "storagenode-updater"}
2024-05-20T23:57:59.814788233+01:00 2024-05-20T23:57:59+01:00	INFO	Telemetry enabled	{"Process": "storagenode", "instance ID": "12GPnL3Dj6uHpjtyHpNyTScHuhcJk2cEqA889UXuXqUWL15Pu6j"}
2024-05-20T23:57:59.814932588+01:00 2024-05-20T23:57:59+01:00	INFO	Event collection enabled	{"Process": "storagenode", "instance ID": "12GPnL3Dj6uHpjtyHpNyTScHuhcJk2cEqA889UXuXqUWL15Pu6j"}
2024-05-20T23:57:59.852197785+01:00 2024-05-20T23:57:59+01:00	INFO	db.migration.57	Create new bandwidth_usage table, backfilling data from bandwidth_usage_rollups and bandwidth_usage tables, and dropping the old tables.	{"Process": "storagenode"}
2024-05-20T23:58:00.727514581+01:00 2024-05-20T23:58:00+01:00	ERROR	failure during run	{"Process": "storagenode", "error": "Error migrating tables for database on storagenode: migrate: v57: database disk image is malformed\n\tstorj.io/storj/private/migrate.(*Migration).Run:212\n\tstorj.io/storj/storagenode/storagenodedb.(*DB).MigrateToLatest:387\n\tmain.cmdRun:98\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:393\n\tstorj.io/common/process.cleanup.func1:411\n\tgithub.com/spf13/cobra.(*Command).execute:983\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1115\n\tgithub.com/spf13/cobra.(*Command).Execute:1039\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:267", "errorVerbose": "Error migrating tables for database on storagenode: migrate: v57: database disk image is malformed\n\tstorj.io/storj/private/migrate.(*Migration).Run:212\n\tstorj.io/storj/storagenode/storagenodedb.(*DB).MigrateToLatest:387\n\tmain.cmdRun:98\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:393\n\tstorj.io/common/process.cleanup.func1:411\n\tgithub.com/spf13/cobra.(*Command).execute:983\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1115\n\tgithub.com/spf13/cobra.(*Command).Execute:1039\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:267\n\tmain.cmdRun:100\n\tmain.newRunCmd.func1:33\n\tstorj.io/common/process.cleanup.func1.4:393\n\tstorj.io/common/process.cleanup.func1:411\n\tgithub.com/spf13/cobra.(*Command).execute:983\n\tgithub.com/spf13/cobra.(*Command).ExecuteC:1115\n\tgithub.com/spf13/cobra.(*Command).Execute:1039\n\tstorj.io/common/process.ExecWithCustomOptions:112\n\tmain.main:34\n\truntime.main:267"}
2024-05-20T23:58:00.727614618+01:00 Error: Error migrating tables for database on storagenode: migrate: v57: database disk image is malformed
2024-05-20T23:58:00.727644546+01:00 	storj.io/storj/private/migrate.(*Migration).Run:212
2024-05-20T23:58:00.727670379+01:00 	storj.io/storj/storagenode/storagenodedb.(*DB).MigrateToLatest:387
2024-05-20T23:58:00.727737070+01:00 	main.cmdRun:98
2024-05-20T23:58:00.727762284+01:00 	main.newRunCmd.func1:33
2024-05-20T23:58:00.727788233+01:00 	storj.io/common/process.cleanup.func1.4:393
2024-05-20T23:58:00.727813681+01:00 	storj.io/common/process.cleanup.func1:411
2024-05-20T23:58:00.727839120+01:00 	github.com/spf13/cobra.(*Command).execute:983
2024-05-20T23:58:00.727863768+01:00 	github.com/spf13/cobra.(*Command).ExecuteC:1115
2024-05-20T23:58:00.727912622+01:00 	github.com/spf13/cobra.(*Command).Execute:1039
2024-05-20T23:58:00.727933819+01:00 	storj.io/common/process.ExecWithCustomOptions:112
2024-05-20T23:58:00.727951781+01:00 	main.main:34
2024-05-20T23:58:00.727969420+01:00 	runtime.main:267
2024-05-20T23:58:00.728005597+01:00 2024-05-20 23:58:00,727 INFO success: processes-exit-eventlistener entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-05-20T23:58:00.728037167+01:00 2024-05-20 23:58:00,727 INFO success: storagenode entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-05-20T23:58:00.728087496+01:00 2024-05-20 23:58:00,727 INFO success: storagenode-updater entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-05-20T23:58:00.732907287+01:00 2024-05-20 23:58:00,731 INFO exited: storagenode (exit status 1; not expected)
2024-05-20T23:58:01.737106667+01:00 2024-05-20 23:58:01,736 INFO spawned: 'storagenode' with pid 107
2024-05-20T23:58:01.737742297+01:00 2024-05-20 23:58:01,737 WARN received SIGQUIT indicating exit request
2024-05-20T23:58:01.738336502+01:00 2024-05-20 23:58:01,738 INFO waiting for storagenode, processes-exit-eventlistener, storagenode-updater to die
2024-05-20T23:58:01.738634230+01:00 2024-05-20T23:58:01+01:00	INFO	Got a signal from the OS: "terminated"	{"Process": "storagenode-updater"}
2024-05-20T23:58:01.741277807+01:00 2024-05-20 23:58:01,741 INFO stopped: storagenode-updater (exit status 0)
2024-05-20T23:58:01.742303310+01:00 2024-05-20 23:58:01,742 INFO stopped: storagenode (terminated by SIGTERM)
2024-05-20T23:58:01.743314577+01:00 2024-05-20 23:58:01,742 INFO stopped: processes-exit-eventlistener (terminated by SIGTERM)

I checked bandwidth.db and it seems fine?

root@truenas[/mnt/Storj-5/storage]# sqlite3 bandwidth.db "PRAGMA integrity_check;"
ok

How do I fix this error?

2

bandwidth db may be migrated without error, you should check all the other dbs, too.

1 Like
3

Also, please check that you didn’t move databases. If you did - you need to check their current location instead.

4

Checked all the databases and no problems…

root@truenas[/mnt/Storj-5/storage]# find -maxdepth 1 -iname "*.db" -print0 -exec sqlite3 '{}' 'PRAGMA integrity_check;' ';'
./info.db
ok
./heldamount.db
ok
./satellites.db
ok
./orders.db
ok
./piece_spaced_used.db
ok
./used_serial.db
ok
./pieceinfo.db
ok
./piece_expiration.db
ok
./pricing.db
ok
./secret.db
ok
./storage_usage.db
ok
./bandwidth.db
ok
./notifications.db
ok
./reputation.db
ok

root@truenas[/mnt/Storj-5]# find -maxdepth 1 -iname "*.db" -print0 -exec sqlite3 '{}' 'PRAGMA integrity_check;' ';'
./revocations.db
Error: in prepare, file is not a database (26)

Folder structure is identical to my other nodes that are working fine…
It would be nice if the error was a bit more specific.

5

Oh I was checking the databases on a different dataset, zfs is a bit confusing sometimes!
Now I am seeing the errors with the databases. Will fix that and hopefully fixes it.

EDIT: Fixed now and running again :sunny: thanks.

1 Like