Used disk space resets after node rm/restart

baker · December 11, 2019, 5:18am

Hi All,

I was replacing some network equipment and decided to update the software on the linux machine running my node. I restarted the machine after the updates and noticed my used disk space had been reset from near 1.6 TB to about 500 MB (I did not pull up the dashboard right away, it probably started at 0). Now every time I stop and start the node, or remove and pull and start the node, the used disk space goes back to 0. The only change I made with direct impact to the storage node is that I changed the version tag in my run command from “arm” to “beta”. Any time I take the node down, I check that my run command is up to date, so I made this change to align with the setup instructions. When I updated system software, Docker CE was updated as well.

Background:
-Node was v0.26.2 both before and after the restart/update.
-Running on rock64 4GB. Debian Stretch. Docker CE version 5:19.03.5~3-0~debian-stretch
-Node has been active since alpha launch.
-Node was approximately 50% full.
-Node appears online, and other than the used space resetting appears to be working fine.

Run Command:

 docker run -d --restart unless-stopped -p 28967:28967 -p 14002:14002 \
                        --log-opt max-size=50m --log-opt max-file=10 \
                        -e WALLET="{removed}" \
                        -e EMAIL="{removed}" \
                        -e ADDRESS="{removed}:28967" \
                        -e BANDWIDTH="36.8TB" \
                        -e STORAGE="3.28TB" \
                        --mount type=bind,source="/etc/storj-cert",destination=/app/identity \
                        --mount type=bind,source="/mnt/storj1/v3alpha",destination=/app/config \
                        --name storagenode storjlabs/storagenode:beta;

I checked that the mount location has r/w access, so no problem there. As far as I know the mount type=bind option should prevent the node from running if the mount location isn’t available. I am fearful that something has happened to the DB, although bandwidth usage is consistent with before the restart. I always shut down the node with the stop -t 300 option.

What I did to get here:

Stopped the node: docker stop -t 300 storagenode
Upgraded software with sudo apt update then sudo apt dist-upgrade
Restarted the machine
Ran stop command again in case the node had auto-started on restart (it had not) docker stop -t 300 storagenode
Removed container docker rm storagenode
Pulled image (but using the beta tag instead of the arm tag I was previously using) docker pull storjlabs/storagenode:beta
Started the node with the run command detailed above
Noticed disk space was reduced to around 500 MB from 1.6 TB
Dumped the logs (see below)

Here are the first 50 lines from the log after I noticed the used disk discrepancy:

2019-12-11T02:36:14.668Z	e[34mINFOe[0m	Configuration loaded from: /app/config/config.yaml
2019-12-11T02:36:14.677Z	e[34mINFOe[0m	Operator email: {removed}
2019-12-11T02:36:14.677Z	e[34mINFOe[0m	operator wallet: {removed}
2019-12-11T02:36:15.734Z	e[34mINFOe[0m	version	running on version v0.26.2
2019-12-11T02:36:16.659Z	e[34mINFOe[0m	db.migration	Database Version	{"version": 25}
2019-12-11T02:36:16.705Z	e[34mINFOe[0m	bandwidth	Performing bandwidth usage rollups
2019-12-11T02:36:16.708Z	e[34mINFOe[0m	Node 12dqTFg2cPRT4fv4nhxjVvwqbwxumMwknLBBn1wVkqCXSG4qC1m started
2019-12-11T02:36:16.709Z	e[34mINFOe[0m	Public server started on [::]:28967
2019-12-11T02:36:16.709Z	e[34mINFOe[0m	Private server started on 127.0.0.1:7778
2019-12-11T02:36:16.709Z	e[34mINFOe[0m	contact:chore	Storagenode contact chore starting up
2019-12-11T02:36:16.741Z	e[34mINFOe[0m	version	running on version v0.26.2
2019-12-11T02:36:25.117Z	e[34mINFOe[0m	orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW	sending	{"count": 418}
2019-12-11T02:36:25.120Z	e[34mINFOe[0m	orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6	sending	{"count": 294}
2019-12-11T02:36:25.120Z	e[34mINFOe[0m	orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs	sending	{"count": 172}
2019-12-11T02:36:25.122Z	e[34mINFOe[0m	orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S	sending	{"count": 205}
2019-12-11T02:36:25.773Z	e[34mINFOe[0m	orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S	finished
2019-12-11T02:36:26.340Z	e[34mINFOe[0m	orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs	finished
2019-12-11T02:36:27.284Z	e[34mINFOe[0m	orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6	finished
2019-12-11T02:36:28.814Z	e[34mINFOe[0m	orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW	finished
2019-12-11T02:36:29.083Z	e[34mINFOe[0m	piecestore:monitor	Remaining Bandwidth	{"bytes": 36295416042240}
2019-12-11T02:36:38.822Z	e[31mERRORe[0m	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-12-11T02:41:03.726Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "D4SNT57PIYRMYASVTQ3NTDTFWAEVVNQZAQXOYH2CWL5WYUXWNDGA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:04.295Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "X24LLYGBIROPEUM7RDCUFBBI56AUI5LIRWEDMLBEQKMTPUB5GLEA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:04.569Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "AX6OEGJB23V3R7Z3PJ6QSP7POSNGXWTYPBUPEBGN7SSR5LFUGYUA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:06.979Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "BAAR4XKJEZQERC2JBPLTZQPHSRPNCDPK3XEEHJTPDWHCCKURZ3AA", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "PUT"}
2019-12-11T02:41:07.290Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "E3H4YCFSE5ATF6HG4QMHAYQ6OTR3RBAOSGZD2UQHMZTKUWXQNLZQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:13.907Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "DPPIY7HCKI43LKP5TXVRCMAHI3YXPIFRKPY33JJLYLDW7USHC7AA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT"}
2019-12-11T02:41:14.236Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "LGK7I6ZXXVELNSU537ER6FDV4ZHJZQSKQT444TMIUC7F7JR4EYGA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:15.775Z	e[31mERRORe[0m	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-12-11T02:41:15.776Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "X24LLYGBIROPEUM7RDCUFBBI56AUI5LIRWEDMLBEQKMTPUB5GLEA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:15.978Z	e[31mERRORe[0m	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-12-11T02:41:15.979Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "D4SNT57PIYRMYASVTQ3NTDTFWAEVVNQZAQXOYH2CWL5WYUXWNDGA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:17.968Z	e[31mERRORe[0m	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-12-11T02:41:17.969Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "E3H4YCFSE5ATF6HG4QMHAYQ6OTR3RBAOSGZD2UQHMZTKUWXQNLZQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:18.068Z	e[31mERRORe[0m	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-12-11T02:41:18.069Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "BAAR4XKJEZQERC2JBPLTZQPHSRPNCDPK3XEEHJTPDWHCCKURZ3AA", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "PUT"}
2019-12-11T02:41:20.313Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "R6PUHX5QAQVBG7S3OJ7GS622MCIBRLZ22SETDPWYQQBNZEASE77A", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:20.882Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "EDA2UVKEFRZEVLG7MMU5RSF7BDA66A3BV6QH4JAT3GZMHZALVNTQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:22.701Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "NR2BLBST3WFF6JSZDNIUTCHRXBP3XNPVNXWMU3LWBXBG3FCWKBLQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "PUT"}
2019-12-11T02:41:23.706Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "SY5LEW5BK5EUCR6F2Q7DOOYTA2LITAG623K54CNHKIUNUXEVDP4Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT"}
2019-12-11T02:41:24.164Z	e[34mINFOe[0m	piecestore	download started	{"Piece ID": "LXLPJAOZE7ZLCCTOBD2S7D5RZ47I2EBRNYUI4QC5BQ4ALNMLQOHA", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2019-12-11T02:41:24.864Z	e[31mERRORe[0m	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-12-11T02:41:24.865Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "LGK7I6ZXXVELNSU537ER6FDV4ZHJZQSKQT444TMIUC7F7JR4EYGA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT"}
2019-12-11T02:41:25.272Z	e[31mERRORe[0m	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-12-11T02:41:25.272Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "AX6OEGJB23V3R7Z3PJ6QSP7POSNGXWTYPBUPEBGN7SSR5LFUGYUA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:26.586Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "ZQPLL4AUZLLZ3ITYDFKYJJVG3BAXFEX3EDPSA3NKXKWP3Q2ZKOOQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-11T02:41:26.748Z	e[31mERRORe[0m	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-12-11T02:41:26.749Z	e[34mINFOe[0m	piecestore	uploaded	{"Piece ID": "DPPIY7HCKI43LKP5TXVRCMAHI3YXPIFRKPY33JJLYLDW7USHC7AA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT"}
2019-12-11T02:41:27.923Z	e[34mINFOe[0m	piecestore	download started	{"Piece ID": "O2YRJLBWK4SZGIFE6QMR34W7IM32MIX3CCKSBBT2RNQECVM4BWZQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2019-12-11T02:41:31.130Z	e[34mINFOe[0m	piecestore	upload started	{"Piece ID": "RKZPRUEABWNBT5W2PX4ROI33FAKRQI6V7NKTUJD2LWTQNOFCY6FA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}

I tried restarting the container with no effect, the used disk space reset. I tried removing and recreating the container, the used disk space reset. When I did this the only thing that changed is now I get this at the beginning of the logs (which was not present after the initial restart):

2019-12-11T04:17:38.642Z        INFO    piecestore:monitor      Remaining Bandwidth     {"bytes": 36293612318976}
2019-12-11T04:17:38.642Z        WARN    piecestore:monitor      Disk space is less than requested. Allocating space     {"bytes": 1868984774656}

I checked, and the space is still being used on the disk. I have currently stopped the node in the hopes that I might be able to fix it without collecting too much other data in the mean time. I’m not a total newbie at this, and I think I ran down all of the usual problems/troubleshooting steps. If you made it this far, thanks for your time with this lengthy post.

(edit: fixed typos)

jocelyn · December 11, 2019, 6:45am

Hi @baker
Sorry you are having this issue. Our engineering team has been notified…it is currently late night in the US however, so they may not see it immediately
Thank you for joining the forum, and for letting us know. Please do check back and Ill be happy to pass along any updates I hear as well
thanks
Jocelyn
Community Manager

deathlessdd · December 11, 2019, 4:49pm

I would make sure your drive is mounted at reboot.

baker · December 11, 2019, 4:57pm

Thank you for the reply. The disk is mounted at boot via an fstab entry. I can read and write to the mount point, so I don’t believe there is an issue there. The node has been online for months and has survived system reboots in the past.

deathlessdd · December 11, 2019, 5:09pm

I know but you said you updated so if you updated it could have screwed alot of things up with linux. Espically since its an arm processor, the new kernal might not support certain things. One of the things I refuse to do is update linux while my node is running on it because im scared in running into these kinda issues. If your using an external hard drive anyways you could just reinstall linux on it pretty easy.

baker · December 11, 2019, 6:36pm

I agree that updating “outside” software and/or the kernel could potentially cause issues. It is still Debian Stretch, so not even the latest kernel (I realize that doesn’t mean much). But I would rather have as up to date and as secure a system as possible. If my node can be recovered, that would be great. But I would settle for something being learned (if anything) so the product can be improved. And if it turns out it was user error, then I will have learned that too.

deathlessdd · December 11, 2019, 6:47pm

Only real thing to do is downgrade the distro to the one you were running before you updated, But ubuntu sometimes is hard to recover once its screwed up, Its like the OS you just reinstall if your just running the OS on a simple sd card cause its easier to deal with then trying to spend hours on which update caused an issue. Its more then likly an issue with docker and the update that installed.

baker · December 11, 2019, 7:11pm

An excellent suggestion. That will be where I go next, but my guess is that rolling back won’t help anything. There is nothing obvious to me that indicates the updates are to blame. Maybe docker (which is why I included the version), but there aren’t any of the typical errors that seem to occur when there is a docker configuration issue. Whether the issue is due to the updates or not, the node seems to have amnesia about pieces it stores, so there is definitely something wrong with the node that I can’t directly attribute to the underlying system. I’ll wait to see if there is any advanced troubleshooting that Storj support can suggest.

deathlessdd · December 11, 2019, 7:16pm

Other thing is you could do is unmount and remount the drive and remove the old container and make sure the locations are updated as well. If its not seeing the right pieces then chances are its not seeing the correct location of the storage anymore.

baker · December 12, 2019, 5:10am

So unmounting, remounting, and rm’ing the container didn’t help. I did verify that the node can access the storage directory. I started the node just now, allowed the node to collect a few MB of pieces, then stopped the node. I was able to find the pieces in the blobs folder with the current time stamp. I restarted the node and the used disk space reset to 0 again.

deathlessdd · December 12, 2019, 1:20pm

So does that mean your still getting data but at the sametime its not saving to the database? Ive seen the database lock before and normally it does just fix itself but it takes time, If your still getting upload and they are completed then I would just let it run, But if your just getting constant Errors I would think theres definitely an issue with docker having permissions to your database.

baker · December 12, 2019, 2:49pm

So when I run the node I get uploads. All successful. And this time I even got a download. So clearly the node is writing to and reading from the piecestore database (I do not actually know if that is in it’s own db). But when the node is shut down and restarted, the used disk space goes back to zero. And the part I really can’t square away is that there are no errors in the logs (see below from a quick run I just did). No db locked messages either. Although I suspect if I run it long enough I will start failing audits.

Maybe the node just isn’t reporting used disk space properly, and everything else is working fine in the background. If it is just a matter of the used disk space being broken, it is beyond my abilities to diagnose that. I am hesitant to run the node for any significant amount of time, because if the node is actually forgetting about the pieces I will end up accumulating a lot of pieces that will fail to be retrieved later.

2019-12-12T13:58:48.228Z        INFO    Configuration loaded from: /app/config/config.yaml
2019-12-12T13:58:48.233Z        INFO    Operator email: {removed}
2019-12-12T13:58:48.234Z        INFO    operator wallet: {removed}
2019-12-12T13:58:48.819Z        INFO    version running on version v0.26.2
2019-12-12T13:58:48.845Z        INFO    db.migration    Database Version        {"version": 25}
2019-12-12T13:58:48.851Z        INFO    bandwidth       Performing bandwidth usage rollups
2019-12-12T13:58:48.852Z        INFO    Node 12dqTFg2cPRT4fv4nhxjVvwqbwxumMwknLBBn1wVkqCXSG4qC1m started
2019-12-12T13:58:48.852Z        INFO    Public server started on [::]:28967
2019-12-12T13:58:48.852Z        INFO    Private server started on 127.0.0.1:7778
2019-12-12T13:58:48.853Z        INFO    contact:chore   Storagenode contact chore starting up
2019-12-12T13:58:48.871Z        INFO    orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW       sending {"count": 1}
2019-12-12T13:58:48.881Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      sending {"count": 3}
2019-12-12T13:58:48.882Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      sending {"count": 3}
2019-12-12T13:58:48.886Z        INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      sending {"count": 1}
2019-12-12T13:58:48.887Z        INFO    version running on version v0.26.2
2019-12-12T13:58:49.117Z        INFO    piecestore:monitor      Remaining Bandwidth     {"bytes": 36293531252480}
2019-12-12T13:58:49.117Z        WARN    piecestore:monitor      Disk space is less than requested. Allocating space     {"bytes": 1872078290944}
2019-12-12T13:58:49.150Z        INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      finished
2019-12-12T13:58:49.326Z        INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      finished
2019-12-12T13:58:49.448Z        INFO    orders.118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW       finished
2019-12-12T13:58:49.720Z        INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      finished
2019-12-12T13:59:07.038Z        INFO    piecestore      upload started  {"Piece ID": "XDZ3VLXPMQOLDLWNMZQBP5ZMI27PGY7YIETVEMJAR7JWXLH3RO2A", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:08.299Z        INFO    piecestore      upload started  {"Piece ID": "ZEDBBDHVKD2IRFUSXGKYATDP6FKV2YIA62XSFXNWTWHDGI6IFWSA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:10.027Z        INFO    piecestore      uploaded        {"Piece ID": "ZEDBBDHVKD2IRFUSXGKYATDP6FKV2YIA62XSFXNWTWHDGI6IFWSA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:12.438Z        INFO    piecestore      upload started  {"Piece ID": "DXCUOEIKC2UGDSHH2W4QY66E6MDDCLGAZO6OLKNQSCAVF3QANVKQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:13.507Z        INFO    piecestore      upload started  {"Piece ID": "V6GQQZABCXBQ6DPXGZV7KAIPTADNJV3XVSACRFHDWJUHIR4FUI2A", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:15.174Z        INFO    piecestore      uploaded        {"Piece ID": "V6GQQZABCXBQ6DPXGZV7KAIPTADNJV3XVSACRFHDWJUHIR4FUI2A", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:18.633Z        INFO    piecestore      uploaded        {"Piece ID": "XDZ3VLXPMQOLDLWNMZQBP5ZMI27PGY7YIETVEMJAR7JWXLH3RO2A", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:18.911Z        INFO    piecestore      upload started  {"Piece ID": "4CCIVKJHWI7PDNZ7LSH2OBIWCNZMYJQMLTY4VE4VI5HP6FPC3JHA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:20.642Z        INFO    piecestore      upload started  {"Piece ID": "UJ43WWSSIKN5E4UE4MBFQ3WI5UZECQTKGOHACS4S37PR4G3P6KWQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:21.177Z        INFO    piecestore      upload started  {"Piece ID": "4TLSDUCDS7XO44S4AEG7NS566ZUOXVHKVEZZKPPNV6KLSH66T4IA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:21.813Z        INFO    piecestore      uploaded        {"Piece ID": "DXCUOEIKC2UGDSHH2W4QY66E6MDDCLGAZO6OLKNQSCAVF3QANVKQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:27.838Z        INFO    piecestore      uploaded        {"Piece ID": "UJ43WWSSIKN5E4UE4MBFQ3WI5UZECQTKGOHACS4S37PR4G3P6KWQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:28.454Z        INFO    piecestore      uploaded        {"Piece ID": "4CCIVKJHWI7PDNZ7LSH2OBIWCNZMYJQMLTY4VE4VI5HP6FPC3JHA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:29.398Z        INFO    piecestore      uploaded        {"Piece ID": "4TLSDUCDS7XO44S4AEG7NS566ZUOXVHKVEZZKPPNV6KLSH66T4IA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:34.016Z        INFO    piecestore      upload started  {"Piece ID": "CGFSBIZICFFDMT6EWQSYT6BPTQMU7CEJTMOP2GH34VJYXJLPGDQQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:35.459Z        INFO    piecestore      upload started  {"Piece ID": "GXVVXL2IGVOJNII2BSLIKJIIZ6UBYLZ2G3GG2XRXQQAVNO6W5GTQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:37.421Z        INFO    piecestore      uploaded        {"Piece ID": "CGFSBIZICFFDMT6EWQSYT6BPTQMU7CEJTMOP2GH34VJYXJLPGDQQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:40.161Z        INFO    piecestore      upload started  {"Piece ID": "K6INPT7PRBA322S3T3XLTZKUQRZCP5KMDZLYM5FEFOH6ZSRGPNBA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:41.161Z        INFO    piecestore      upload started  {"Piece ID": "CTNIAG4ZNJESIUWBFXBY4TRDAS3L5DFLS4YXWMRL7EMU6QPB27HQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:41.855Z        INFO    piecestore      uploaded        {"Piece ID": "GXVVXL2IGVOJNII2BSLIKJIIZ6UBYLZ2G3GG2XRXQQAVNO6W5GTQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:45.343Z        INFO    piecestore      upload started  {"Piece ID": "RMU2VQUX3G474ZUQDBV7HY7Y4OIQ3NWSIUIEYCVL22GAWZVXTYAA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:47.853Z        INFO    piecestore      upload started  {"Piece ID": "G3SZX4763QAVDJV5MH6EANPXQIMRTVLUPDI25XMYAHLAAT6TCCMQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:48.361Z        INFO    piecestore      uploaded        {"Piece ID": "CTNIAG4ZNJESIUWBFXBY4TRDAS3L5DFLS4YXWMRL7EMU6QPB27HQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:48.631Z        INFO    piecestore      upload started  {"Piece ID": "UB5ZK3M3B3DOGRHCH4LF45XAYO6NELWCYGYTCUPHYVRR3VDVNWJQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:49.429Z        INFO    piecestore      uploaded        {"Piece ID": "K6INPT7PRBA322S3T3XLTZKUQRZCP5KMDZLYM5FEFOH6ZSRGPNBA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:50.447Z        INFO    piecestore      uploaded        {"Piece ID": "G3SZX4763QAVDJV5MH6EANPXQIMRTVLUPDI25XMYAHLAAT6TCCMQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:52.376Z        INFO    piecestore      uploaded        {"Piece ID": "UB5ZK3M3B3DOGRHCH4LF45XAYO6NELWCYGYTCUPHYVRR3VDVNWJQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:53.404Z        INFO    piecestore      uploaded        {"Piece ID": "RMU2VQUX3G474ZUQDBV7HY7Y4OIQ3NWSIUIEYCVL22GAWZVXTYAA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:54.537Z        INFO    piecestore      upload started  {"Piece ID": "GWVSOINBOB6CLK4PQ237PLOKFPHBJLCTUENNUQLJEXSXOQBHEYQQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:56.514Z        INFO    piecestore      upload started  {"Piece ID": "D52YF4HSIVWRERTERZCC4RQYIMJPBZ3ZNC5FETBPZJFSKMWTJUZA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T13:59:56.605Z        INFO    piecestore      uploaded        {"Piece ID": "GWVSOINBOB6CLK4PQ237PLOKFPHBJLCTUENNUQLJEXSXOQBHEYQQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T14:00:00.226Z        INFO    piecestore      download started        {"Piece ID": "E6XTCE6PV3VGNJOKOFVHSS7U3FYEYNK3LUYXYYVOP4XSMD7CJDCQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2019-12-12T14:00:01.173Z        INFO    piecestore      downloaded      {"Piece ID": "E6XTCE6PV3VGNJOKOFVHSS7U3FYEYNK3LUYXYYVOP4XSMD7CJDCQ", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Action": "GET"}
2019-12-12T14:00:02.461Z        INFO    piecestore      uploaded        {"Piece ID": "D52YF4HSIVWRERTERZCC4RQYIMJPBZ3ZNC5FETBPZJFSKMWTJUZA", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T14:00:21.232Z        INFO    piecestore      upload started  {"Piece ID": "FMFEXDKDLJKA4IAZALTBXHUNG6ZLAZG4FQZWASEVF7AHIOGMM2RQ", "Satellite ID": "118UWpMCHzs6CvSgWd9BfFVjw5K9pZbJjkfZJexMtSkmKxvvAW", "Action": "PUT"}
2019-12-12T14:00:23.681Z        INFO    Got a signal from the OS: "terminated"

(edit: formatting)

deathlessdd · December 12, 2019, 5:42pm

Ok I think I figured out the issue theres something that isnt able to read disk space

Because I seen this in both problems and im sure your not allowing more space then allowed. So im almost certain now theres an issue somewhere between docker and the kernel that is perventing this

I found this to see if your kernel is missing stuff that helps

Kernel compatibility

Docker cannot run correctly if your kernel is older than version 3.10 or if it is missing some modules. To check kernel compatibility, you can download and run the check-config.sh script.

$ curl https://raw.githubusercontent.com/docker/docker/master/contrib/check-config.sh > check-config.sh

$ bash ./check-config.sh

baker · December 12, 2019, 6:31pm

So since the node isn’t taking into account the fact that it is actually storing pieces on the drive, it appears to the node like I am allocating more space than available. The 1872078290944 bytes is the balance of the free space on the drive. I allocated 3.28 TB out of a total disk size of 3.6 TB (90% allocation as recommended).

So it’s not that the node isn’t able to read disk space, it’s that the node doesn’t realize it is already using disk space.

When I run the script, the only thing I am missing outside of the “Storage Driver” category is “CONFIG_BRIDGE_VLAN_FILTERING”, which I’m sure is completely unrelated. Under the “Storage Driver” category, none of the missing items seem relevant.

deathlessdd · December 12, 2019, 6:32pm

Mine is enabled tho

Gonna test on all my nodes to see.
I tested my pi4 but docker no longer work on it because I updated and I have this too

baker · December 12, 2019, 6:39pm

Based on my wikipedia/google search, AUFS isn’t really used anymore. It is not included by default in Debian Stretch, and apparently although once used by docker as a default, it has since been replaced by OverlayFS and AUFS is only really supported for legacy applications.

Edit: Does the first machine you tested run on Jesse?

deathlessdd · December 12, 2019, 6:40pm

Alright ill keep digging.

deathlessdd · December 12, 2019, 6:41pm

Nah its ubuntu 18.04 But my Pi4 is also running on ubuntu 18.04 as well though

When I use the command

$ grep aufs /proc/filesystems

I get “nodev aufs”

baker · December 12, 2019, 7:14pm

You can check which storage driver docker is using with docker info. Mine outputs overlay2 as the storage driver, so I assume the missing aufs support is not an issue for my setup.

deathlessdd · December 12, 2019, 7:26pm

What about the usb controller does that seem to be running fine after the update?