Ordersdb error: database is locked

[swed1983]

hi team,
node showing online, but values are not increasing, while checking logs, did discovered the error message as “ordersdb error: database is locked”?
Any advice?

[kevink]

Wait 2 hours after starting a node. Problems should go away and you should see a little traffic.

[swed1983]

thanks,
problem exist since yesterday

[kevink]

Have you tried restarting the node since then?

[swed1983]

yes, did tried already several times.

[kevink]

ok then I can’t help. Will have to wait for an answer from the STORJ team.
(Unless you are not using the latest Storagenode version)

[swed1983]

thanks for your assistance. using 0.23.5. have auto-update enabled

[dven]

I have the same error. Please help to get back to full capacity.

server gRPC stream error response {“error”: “piecestore: serial number is already used: usedserialsdb error: database disk image is malformed\n\tstorj.io/storj/s toragenode/storagenodedb.(*usedSerialsDB).Add:35\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:77\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:431\n\tstorj.io/storj /storagenode/piecestore.(*Endpoint).Download:378\n\tstorj.io/storj/pkg/pb._Piecestore_Download_Handler:1096\n\tstorj.io/storj/pkg/server.(*Server).logOnErrorStreamInterceptor:23\n\tgoogle.golang.org/grpc.(*S erver).processStreamingRPC:1127\n\tgoogle.golang.org/grpc.(*Server).handleStream:1178\n\tgoogle.golang.org/grpc.(*Server).serveStreams.func1.1:696”, “errorVerbose”: “piecestore: serial number is already used : usedserialsdb error: database disk image is malformed\n\tstorj.io/storj/storagenode/storagenodedb.(*usedSerialsDB).Add:35\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:77\n\tstorj.i o/storj/storagenode/piecestore.(*Endpoint).doDownload:431\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:378\n\tstorj.io/storj/pkg/pb._Piecestore_Download_Handler:1096\n\tstorj.io/storj/pkg/se rver.(*Server).logOnErrorStreamInterceptor:23\n\tgoogle.golang.org/grpc.(*Server).processStreamingRPC:1127\n\tgoogle.golang.org/grpc.(*Server).handleStream:1178\n\tgoogle.golang.org/grpc.(*Server).serveStrea ms.func1.1:696\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:432\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:378\n\tstorj.io/storj/pkg/pb._Piecestore_Download_Handler:1096 \n\tstorj.io/storj/pkg/server.(*Server).logOnErrorStreamInterceptor:23\n\tgoogle.golang.org/grpc.(*Server).processStreamingRPC:1127\n\tgoogle.golang.org/grpc.(*Server).handleStream:1178\n\tgoogle.golang.org/ grpc.(*Server).serveStreams.func1.1:696”}

[dven]

I found this in the forum https://forum.storj.io/t/usedserialsdb-error-database-disk-image-is-malformed/2335

[Alexey]

How is your disk connected to your host?

[max232]

Version 26.2.
The drive is connected directly to the server.
How to fix?

2019-11-22T06:59:31.500Z ERROR orders archiving orders {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).archiveOne:238\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Archive:202\n\tstorj.io/storj/storagenode/orders.(*Service).handleBatches.func2:213\n\tstorj.io/storj/storagenode/orders.(*Service).handleBatches:230\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func1:164\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"} 2019-11-22T06:59:33.291Z ERROR piecestore failed to add order {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Enqueue:52\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).saveOrder:625\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doUpload:379\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Upload:176\n\tstorj.io/storj/pkg/pb.DRPCPiecestoreDescription.Method.func1:830\n\tstorj.io/drpc/drpcserver.(*Server).doHandle:175\n\tstorj.io/drpc/drpcserver.(*Server).HandleRPC:153\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:114\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:147\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"} 2019-11-22T06:59:35.940Z ERROR piecestore failed to add order {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Enqueue:52\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).saveOrder:625\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload.func4:584\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:609\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Download:396\n\tstorj.io/storj/pkg/pb.DRPCPiecestoreDescription.Method.func2:838\n\tstorj.io/drpc/drpcserver.(*Server).doHandle:175\n\tstorj.io/drpc/drpcserver.(*Server).HandleRPC:153\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:114\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:147\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"} 2019-11-22T06:59:36.545Z ERROR piecestore failed to add order {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Enqueue:52\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).saveOrder:625\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doUpload:379\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Upload:176\n\tstorj.io/storj/pkg/pb.DRPCPiecestoreDescription.Method.func1:830\n\tstorj.io/drpc/drpcserver.(*Server).doHandle:175\n\tstorj.io/drpc/drpcserver.(*Server).HandleRPC:153\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:114\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:147\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"} 2019-11-22T06:59:38.656Z ERROR piecestore failed to add order {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Enqueue:52\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).saveOrder:625\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload.func4:584\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:609\n\tstorj.io/storj/storagenode/piecestore.(*drpcEndpoint).Download:396\n\tstorj.io/storj/pkg/pb.DRPCPiecestoreDescription.Method.func2:838\n\tstorj.io/drpc/drpcserver.(*Server).doHandle:175\n\tstorj.io/drpc/drpcserver.(*Server).HandleRPC:153\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:114\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:147\n\tstorj.io/drpc/drpcctx.(*Tracker).track:51"}

[Alexey]

I have no solution at the moment and this error is affecting payouts:

Payout feedback

I thought I noticed some differences last month as well, but didn’t have time to really dive in. (And it was pretty close anyway) I do remember there was some weird glitch in the graphs on the web dashboard for the stefan-benten satellite earlier. Could it be related, maybe there is some faulty accounting for transfers on either the node side or satellite side? I’m not at home right now, but I’ll try to do a similar comparison between the numbers this weekend for my own node.

[max232]

@max232

{“error”: “ordersdb error: database is locked”

I also want to note that such an error usually appears on old nodes that store large amounts of data (more than 3 TB)
There is an assumption that when the node starts, it does not have time to process the entire amount of stored data. I know at least 5 other nodes from other users.

[kevink]

I got multiple of those errors too and not only on my big node. It also happened on my node with less than 2 TB but not on my smallest one (<600GB)

[max232]

Probably the main thing is the speed of access to the disk.

[Odmin]

Here is exaple of load during storagenode container restart/upgrade:

So, it very heavy load for cpu and disk system.

[Knowledge]

We believe it’s a bug and the engineers are working towards a solution.

[Odmin]

May be it can be helpful:

I easy reproduce “database is locked”, just start storagenode after regular OS update.

System (docker host):

Inside container from the same period:

CPU: 8 Cores
Disk: ZFS raidz1 8хHDD + SSD LOG + SSD cache (ultra fast storage)

And I got this errors during node start:
docker logs storagenode 2>&1 | grep database

2019-11-26T10:32:15.829Z        ERROR   orders  archiving orders        {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).archiveOne:238\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Archive:202\n\tstorj.io/storj/storagenode/orders.(*Service).handleBatches.func2:213\n\tstorj.io/storj/storagenode/orders.(*Service).handleBatches:237\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrders.func1:164\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2019-11-26T10:32:48.841Z        ERROR   piecestore      failed to add order     {"error": "ordersdb error: database is locked", "errorVerbose": "ordersdb error: database is locked\n\tstorj.io/storj/storagenode/storagenodedb.(*ordersDB).Enqueue:52\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).saveOrder:625\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload.func4:584\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).doDownload:609\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:391\n\tstorj.io/storj/pkg/pb._Piecestore_Download_Handler:1096\n\tstorj.io/storj/pkg/server.(*Server).logOnErrorStreamInterceptor:23\n\tgoogle.golang.org/grpc.(*Server).processStreamingRPC:1127\n\tgoogle.golang.org/grpc.(*Server).handleStream:1178\n\tgoogle.golang.org/grpc.(*Server).serveStreams.func1.1:696"}

As you can see on the screenshot, we have heavy IO wait on a short time period on ultrafast storage (I afraid on single disk we have catastrophic). This node is 6+ month age and slite database files have a big size.

[max232]

In version 0.27.1, the same problem remained.
Nothing has changed

[Odmin]

The same for me, like on my previous post.

We can lose a lot of old good nodes, please pay attention!