Error starting master database on storagenode: database: file is not a database

Due to the exceptional fast help NOT I just played around a big and restarted the server and it seems to be working now. Since 1.17.4 I have some outages which I never hat before. Minutes at a time the webUI is not reachable from UpTimer…nice!

Still having this problem! Node is offline for some minutes at a time. Whats that?
What can I do to solve this? Node is running for over a month and now this…

I’m glad that you have a patience :slight_smile:
Please, show the last 20 lines from the log, when your node would stop the next time.

Or is it always offline? If so - I would recommend to restart the docker either from the Docker desktop (Windows, Mac) or via command line

sudo systemctl restart docker

So I get this:
# docker exec -it storagenode /app/dashboard.sh
2020-12-08T07:26:09.652Z INFO Configuration loaded {“Location”: “/app/config/config.yaml”}
2020-12-08T07:26:09.664Z INFO Identity loaded. {“Node ID”: “1RmW67mfshonihxAuGtNrRyFBkvtAAuenG4xK4JyHve2trRUgJ”}
Error: rpc: dial tcp 127.0.0.1:7778: connect: connection refused

AND:
docker logs storagenode
2020-12-08T07:25:00.243Z INFO Configuration loaded {“Location”: “/app/config/config.yaml”}
2020-12-08T07:25:00.256Z INFO Operator email {“Address”: ““XXXXXXXXXX””}
2020-12-08T07:25:00.257Z INFO Operator wallet {“Address”: “XXXXXXXXX”}
Error: Error starting master database on storagenode: database: file is not a database
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabase:323
storj.io/storj/storagenode/storagenodedb.(*DB).openExistingDatabase:305
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabases:281
storj.io/storj/storagenode/storagenodedb.OpenExisting:248
main.cmdRun:152
storj.io/private/process.cleanup.func1.4:362
storj.io/private/process.cleanup.func1:380
github.com/spf13/cobra.(*Command).execute:842
github.com/spf13/cobra.(*Command).ExecuteC:950
github.com/spf13/cobra.(*Command).Execute:887
storj.io/private/process.ExecWithCustomConfig:88
storj.io/private/process.ExecCustomDebug:70
main.main:338
runtime.main:204

Thanks!

Your database file is corrupted. Please, use this article to check your databases and figure out which one: https://support.storj.io/hc/en-us/articles/360029309111-How-to-fix-a-database-disk-image-is-malformed- (please, note - the “file is not database” can’t be solved by this article, but we can figure out which database is unrecoverable corrupted)

Well I am not that firm with this. Tried this help like some time ago and got it working but it were just the bandwidth db and I just made a new one.

I think the error in the dashboard is very misleading.
Which is the “master DB”?

To figure that out you need to run the first steps from the article - there is checking of all databases and it will error out on corrupted ones
In case of “file is not database” there is no way to recover such a database, only create that file from scratch. But I need to know the names of those databases

~# docker run --rm -it --mount type=bind,source=/root/Storj/storage,destination=/data sstc/sqlite3 find . -iname “*.db” -maxdepth 1 -print0 -exec sqlite3 ‘{}’ ‘PRAGMA integrity_check;’ ‘;’
./bandwidth.db
Error: file is not a database
./heldamount.dbok
./info.dbok
./notifications.dbok
./orders.dbok
./piece_expiration.dbok
./piece_spaced_used.dbok
./pieceinfo.dbok
./pricing.dbok
./reputation.dbok
./satellites.dbok
./secret.dbok
./storage_usage.dbok
./used_serial.dbok

edit: I just deleted the bandwidth.db and made a new one with this command:

sqlite3 bandwidth.db
CREATE TABLE bandwidth_usage (
satellite_id BLOB NOT NULL,
action INTEGER NOT NULL,
amount BIGINT NOT NULL,
created_at TIMESTAMP NOT NULL
);
CREATE TABLE bandwidth_usage_rollups (
interval_start TIMESTAMP NOT NULL,
satellite_id BLOB NOT NULL,
action INTEGER NOT NULL,
amount BIGINT NOT NULL,
PRIMARY KEY ( interval_start, satellite_id, action )
);
CREATE INDEX idx_bandwidth_usage_satellite ON bandwidth_usage(satellite_id);
CREATE INDEX idx_bandwidth_usage_created ON bandwidth_usage(created_at);
.exit

It is only now.

Just curious how did this happen again? And maybe the cli dashboard should show the right error ;D

It can be corrupted if you didn’t update the docker run command with a option --stop-timeout 300 or have had an abruptly killing of the service (for example, it was killed because of too slow responding or by OOM), or power loss.

Well in my command there is the stop-timeout part:
sudo docker run -d --restart unless-stopped --stop-timeout 300

Yeah maybe it was killed then restarted and had a corrupted db then.
Thanks for the help. Next time I will check the DBs first and the report ;D

-> Post in new thread.

1 Like

It is down again…
LOG:

2020-12-08T08:52:54.250Z INFO piecestore uploaded {“Piece ID”: “OIHS5KF4VRDDVHW2J2643M6ASQMZH6DG3XKCHPO3M3CKZXY6EIRQ”, “Satellite ID”: “12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S”, “Action”: “PUT”}
2020-12-08T08:53:29.973Z ERROR pieces:trash emptying trash failed {“error”: “pieces error: filestore error: readdirent: input/output error”, “errorVerbose”: “pieces error: filestore error: readdirent: input/output error\n\tstorj.io/storj/storage/filestore.(*blobStore).EmptyTrash:150\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).EmptyTrash:309\n\tstorj.io/storj/storagenode/pieces.(*Store).EmptyTrash:359\n\tstorj.io/storj/storagenode/pieces.(*TrashChore).Run.func1:51\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/common/sync2.(*Cycle).Start.func1:71\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57”}
2020-12-08T08:55:11.928Z INFO piecestore upload started {“Piece ID”: “5G76AMWSVAS7AYAI2IGU3ZAAGTUF6MSERZ2WFEKMYS7SLLIFRIOA”, “Satellite ID”: “12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S”, “Action”: “PUT”, “Available Space”: 3873336387072}
2020-12-08T08:55:13.445Z INFO piecestore uploaded {“Piece ID”: “5G76AMWSVAS7AYAI2IGU3ZAAGTUF6MSERZ2WFEKMYS7SLLIFRIOA”, “Satellite ID”: “12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S”, “Action”: “PUT”}
2020-12-08T08:55:45.511Z INFO piecestore upload started {“Piece ID”: “LBOQQ7Z57TEXQRAF3H2O7REDLBARHCNJ67X5UMVNJPPOGBMSDR6A”, “Satellite ID”: “1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE”, “Action”: “PUT”, “Available Space”: 3873336130304}
2020-12-08T08:55:48.598Z INFO piecestore uploaded {“Piece ID”: “LBOQQ7Z57TEXQRAF3H2O7REDLBARHCNJ67X5UMVNJPPOGBMSDR6A”, “Satellite ID”: “1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE”, “Action”: “PUT”}
2020-12-08T08:56:03.001Z INFO piecedeleter deleted {“Satellite ID”: “1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE”, “Piece ID”: “LBOQQ7Z57TEXQRAF3H2O7REDLBARHCNJ67X5UMVNJPPOGBMSDR6A”}
2020-12-08T08:56:23.042Z ERROR piecestore:cache error getting current used space: {“error”: “readdirent: input/output error; readdirent: input/output error; readdirent: input/output error; readdirent: input/output error; readdirent: input/output error”, “errorVerbose”: “group:\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error”}
2020-12-08T08:56:23.044Z ERROR services unexpected shutdown of a runner {“name”: “piecestore:cache”, “error”: “readdirent: input/output error; readdirent: input/output error; readdirent: input/output error; readdirent: input/output error; readdirent: input/output error”, “errorVerbose”: “group:\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error\n— readdirent: input/output error”}
2020-12-08T08:56:23.546Z ERROR servers unexpected shutdown of a runner {“name”: “debug”, “error”: “debug: http: Server closed”, “errorVerbose”: “debug: http: Server closed\n\tstorj.io/private/debug.(*Server).Run.func2:108\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57”}

And even more errors, after shutting down the docker and restarting it:

2020-12-08T09:13:52.879Z INFO Operator wallet {“Address”: “XXXXXXXX”}
fatal error: unexpected signal during runtime execution
[signal SIGBUS: bus error code=0x2 addr=0x7f3fcf021000 pc=0xd4b959]

runtime stack:
runtime.throw(0x10119c4, 0x2a)
/usr/local/go/src/runtime/panic.go:1116 +0x72
runtime.sigpanic()
/usr/local/go/src/runtime/signal_unix.go:726 +0x4ac

goroutine 1 [syscall]:
runtime.cgocall(0xd3eb90, 0xc00014f810, 0x0)
/usr/local/go/src/runtime/cgocall.go:133 +0x5b fp=0xc00014f7e0 sp=0xc00014f7a8 pc=0x404e3b
github.com/mattn/go-sqlite3._Cfunc_sqlite3_close_v2(0x7f3fcf0c19b8, 0xc000000000)
_cgo_gotypes.go:618 +0x49 fp=0xc00014f810 sp=0xc00014f7e0 pc=0xcb00a9
github.com/mattn/go-sqlite3.(*SQLiteDriver).Open.func12(0xc0001db048, 0x1a)
/go/pkg/mod/github.com/mattn/go-sqlite3@v2.0.3+incompatible/sqlite3.go:1595 +0x59 fp=0xc00014f848 sp=0xc00014f810 pc=0xcc5ab9
github.com/mattn/go-sqlite3.(*SQLiteDriver).Open(0xc0001271a0, 0xc00003d180, 0x43, 0x0, 0x0, 0x0, 0x0)
/go/pkg/mod/github.com/mattn/go-sqlite3@v2.0.3+incompatible/sqlite3.go:1595 +0x1f1e fp=0xc00014fe38 sp=0xc00014f848 pc=0xcbb81e
database/sql.dsnConnector.Connect(…)
/usr/local/go/src/database/sql/sql.go:707
database/sql.(*dsnConnector).Connect(0xc000126e40, 0x11265c0, 0xc000170500, 0x443dae, 0xc00014fea8, 0x469b60, 0xc00014fef0)
:1 +0x53 fp=0xc00014fe80 sp=0xc00014fe38 pc=0xad49d3
database/sql.(*DB).conn(0xc0000321a0, 0x11265c0, 0xc000170500, 0xc000150001, 0x9c58a9, 0x11265c0, 0xc000170500)
/usr/local/go/src/database/sql/sql.go:1294 +0x204 fp=0xc000150018 sp=0xc00014fe80 pc=0xac75c4
database/sql.(*DB).PingContext(0xc0000321a0, 0x11265c0, 0xc000170500, 0x1, 0x1)
/usr/local/go/src/database/sql/sql.go:799 +0x90 fp=0xc0001500a8 sp=0xc000150018 pc=0xac54d0
storj.io/storj/private/tagsql.Open(0x11265c0, 0xc000170500, 0xfed8de, 0x7, 0xc00003d180, 0x43, 0x21, 0xc00003d180, 0x43, 0xc000205f18)
/go/src/storj.io/storj/private/tagsql/db.go:35 +0x1a5 fp=0xc000150158 sp=0xc0001500a8 pc=0xad6145
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabase(0xc000218900, 0x11265c0, 0xc000170500, 0xff12d8, 0xb, 0x0, 0xe)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:321 +0x20e fp=0xc000150228 sp=0xc000150158 pc=0xcddece
storj.io/storj/storagenode/storagenodedb.(*DB).openExistingDatabase(0xc000218900, 0x11265c0, 0xc000170500, 0xff12d8, 0xb, 0x0, 0x0)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:305 +0x36b fp=0xc000150328 sp=0xc000150228 pc=0xcddc8b
storj.io/storj/storagenode/storagenodedb.(*DB).openDatabases(0xc000218900, 0x11265c0, 0xc000170500, 0x6, 0xc000430768)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:281 +0x228 fp=0xc000150490 sp=0xc000150328 pc=0xcdd828
storj.io/storj/storagenode/storagenodedb.OpenExisting(0x11265c0, 0xc000170500, 0xc000386f60, 0xc000147f60, 0xe, 0xc00042fb60, 0x1c, 0xc00042fb80, 0x16, 0x0, …)
/go/src/storj.io/storj/storagenode/storagenodedb/database.go:248 +0x967 fp=0xc000150578 sp=0xc000150490 pc=0xcdd267
main.cmdRun(0x1663c80, 0xc0000b7c30, 0x0, 0xb, 0x0, 0x0)
/go/src/storj.io/storj/cmd/storagenode/main.go:152 +0x6d8 fp=0xc000150e10 sp=0xc000150578 pc=0xd3a7d8
storj.io/private/process.cleanup.func1.4(0x1126880, 0xc0002206e0)
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:362 +0x11a fp=0xc000150e88 sp=0xc000150e10 pc=0xab19fa
storj.io/private/process.cleanup.func1(0x1663c80, 0xc0000b7c30, 0x0, 0xb, 0x0, 0x0)
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:380 +0x1fef fp=0xc000151d60 sp=0xc000150e88 pc=0xab3aaf
github.com/spf13/cobra.(*Command).execute(0x1663c80, 0xc0000b7b80, 0xb, 0xb, 0x1663c80, 0xc0000b7b80)
/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:842 +0x47c fp=0xc000151e38 sp=0xc000151d60 pc=0x5fd33c
github.com/spf13/cobra.(*Command).ExecuteC(0x16639e0, 0xc000072100, 0x1038660, 0x1)
/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950 +0x375 fp=0xc000151f10 sp=0xc000151e38 pc=0x5fdeb5
github.com/spf13/cobra.(*Command).Execute(…)
/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887
storj.io/private/process.ExecWithCustomConfig(0x16639e0, 0x0, 0x1038660)
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:88 +0x178 fp=0xc000151f60 sp=0xc000151f10 pc=0xaabf18
storj.io/private/process.ExecCustomDebug(...)
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:70
main.main()
/go/src/storj.io/storj/cmd/storagenode/main.go:338 +0x3e fp=0xc000151f88 sp=0xc000151f60 pc=0xd3c8be
runtime.main()
/usr/local/go/src/runtime/proc.go:204 +0x209 fp=0xc000151fe0 sp=0xc000151f88 pc=0x43b8a9
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000151fe8 sp=0xc000151fe0 pc=0x471c41

goroutine 21 [select]:
database/sql.(*DB).connectionOpener(0xc000204c30, 0x11265c0, 0xc0001707c0)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 20 [chan receive]:
storj.io/private/process.Ctx.func1(0xc000386cc0, 0xc000284af0)
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:115 +0x45
created by storj.io/private/process.Ctx
/go/pkg/mod/storj.io/private@v0.0.0-20201026143115-bc926bfa3bca/process/exec_conf.go:114 +0x2cb

goroutine 19 [syscall]:
os/signal.signal_recv(0x0)
/usr/local/go/src/runtime/sigqueue.go:147 +0x9d
os/signal.loop()
/usr/local/go/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
/usr/local/go/src/os/signal/signal.go:150 +0x45

goroutine 15 [sleep]:
time.Sleep(0x8bb2c97000)
/usr/local/go/src/runtime/time.go:188 +0xbf
github.com/spacemonkeygo/monkit/v3.(*ticker).run(0x1848fc0)
/go/pkg/mod/github.com/spacemonkeygo/monkit/v3@v3.0.7/meter.go:203 +0x7e
created by github.com/spacemonkeygo/monkit/v3.(*ticker).register
/go/pkg/mod/github.com/spacemonkeygo/monkit/v3@v3.0.7/meter.go:195 +0x139

goroutine 23 [select]:
database/sql.(*DB).connectionOpener(0xc000204ea0, 0x11265c0, 0xc000170980)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 25 [select]:
database/sql.(*DB).connectionOpener(0xc000205110, 0x11265c0, 0xc000170b40)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 27 [select]:
database/sql.(*DB).connectionOpener(0xc000205380, 0x11265c0, 0xc000170e80)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 29 [select]:
database/sql.(*DB).connectionOpener(0xc0002055f0, 0x11265c0, 0xc000171040)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 31 [select]:
database/sql.(*DB).connectionOpener(0xc000205860, 0x11265c0, 0xc000171240)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 33 [select]:
database/sql.(*DB).connectionOpener(0xc000205ad0, 0x11265c0, 0xc000171400)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 35 [select]:
database/sql.(*DB).connectionOpener(0xc000205d40, 0x11265c0, 0xc0001715c0)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

goroutine 37 [select]:
database/sql.(*DB).connectionOpener(0xc0000321a0, 0x11265c0, 0xc000171780)
/usr/local/go/src/database/sql/sql.go:1126 +0xf5
created by database/sql.OpenDB
/usr/local/go/src/database/sql/sql.go:740 +0x12a

Looks like you might be having problems with the disk. Have you run fsck on it to check the file system integrity?

You need to check your disk for errors. And system disk too, because seems system files corrupted too.