Ordersdb error: database is locked

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"}

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

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.

2 Likes

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)

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

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

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

1 Like

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

2 Likes

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.

4 Likes

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

2 Likes

The same for me, like on my previous post.

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

4 Likes

What do you propose we do to solve this? If we skipped the lock, nodes could potentially not get paid for a few transfers. Please propose an alternative solution on the github issue.

Thanks for your reply @heunland !

I proposed two solutions on Github, first is easy to implement and save time for DEV team, second is good for SNO that have a plan for long term cooperation (when used space will be more than 10+TB) but waste a lot of DEV team time.

Thanks for pay attention to this issue!

2 Likes

Thanks for helping us find potential issues. We are already following up on GitHub. Despite how it might appear sometimes to users here on the forum, our team is paying attention to all important matters that are brought up here, and issues in the backlog will be added to sprints according to their urgency/impact on the system functioning properly. We appreciate all user input and thank you for your patience.

3 Likes

This is the same kinda usage if you pull a script to see how much your node has made, and also when you read a long list of logs though ssh.

damn I have the same issue after 27.1
node was updated via storagenode properly and works about 20 hours and than it just happened for no reason

+1 on “ordersdb error: database is locked” :smiley:

This 0.27.1 is a “killer” release! :smiley:

I havent had any problems. Running 3 nodes and 1 on windows none of which had any kinda issues.

Well, I have 500MB log of errors after the upgrade couple of days ago… I had to redeploy the container today :frowning:

I’ve had no problems since the update:

$docker ps

...IMAGE                      ...  CREATED             STATUS           
...storjlabs/storagenode:beta ...  43 hours ago        Up 43 hours  

My largest sqlite database is orders.db and that’s just under 200MB.

How much data is on your node?