First some background… About a month ago, there was a communication issue with one of the USB enclosures containing my Storj node drives. (I bumped the USB cable loose… oops) I resolved the issue, but because the nodes were still running at the time, there was file system corruption on a couple of the drives. I ran fsck on the affected drives and fixed all errors until it came back clean. All nodes started up and appeared to be working correctly at the time, so I assumed all was ok.
Fast forward to a few days ago… I noticed that 2 of the nodes are rebooting every 2 minutes. Yesterday and today I’ve been looking into the logs to find out what’s wrong, and they both show that filewalker is exiting with “filestore error: file is a directory” when the node has been running for about 2 minutes. (I’m running in docker, which restarts the container automatically - this is why I didn’t notice it right away)
So, now to my question: based on the log entries below, is there any way to tell what file/directory is the problem so that I can delete it? Or, is there another way I can find out what file/directory is causing the issue?
{“log”:“2024-07-12T03:37:34Z\u0009ERROR\u0009pieces\u0009used-space-filewalker failed\u0009{"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Lazy File Walker": false, "error": "filewalker: filestore error: file is a directory", "errorVerbose": "filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:7176\n\truntime.doInit:7143\n\truntime.main:253"}\n”,“stream”:“stdout”,“time”:“2024-07-12T03:37:34.724490829Z”}
{“log”:“2024-07-12T03:45:29Z\u0009ERROR\u0009piecestore:cache\u0009error getting current used space: \u0009{"Process": "storagenode", "error": "filewalker: filestore error: file is a directory; filewalker: filestore error: file is a directory", "errorVerbose": "group:\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249"}\n”,“stream”:“stdout”,“time”:“2024-07-12T03:45:29.770321233Z”}
{“log”:“2024-07-12T03:45:29Z\u0009ERROR\u0009services\u0009unexpected shutdown of a runner\u0009{"Process": "storagenode", "name": "piecestore:cache", "error": "filewalker: filestore error: file is a directory; filewalker: filestore error: file is a directory", "errorVerbose": "group:\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249"}\n”,“stream”:“stdout”,“time”:“2024-07-12T03:45:29.770359934Z”}
{“log”:“2024-07-12T03:45:30Z\u0009ERROR\u0009failure during run\u0009{"Process": "storagenode", "error": "filewalker: filestore error: file is a directory; filewalker: filestore error: file is a directory", "errorVerbose": "group:\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249\n— filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:6740\n\truntime.doInit:6707\n\truntime.main:249"}\n”,“stream”:“stdout”,“time”:“2024-07-12T03:45:30.574687547Z”}
{“log”:“Error: filewalker: filestore error: file is a directory; filewalker: filestore error: file is a directory\n”,“stream”:“stdout”,“time”:“2024-07-12T03:45:30.575279325Z”}
{“log”:“2024-07-13T04:28:49Z\u0009INFO\u0009reputation:service\u0009node scores updated\u0009{"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Total Audits": 20790, "Successful Audits": 20699, "Audit Score": 1, "Online Score": 0.9902675408563416, "Suspension Score": 0.9932362022860473, "Audit Score Delta": 0, "Online Score Delta": 0, "Suspension Score Delta": 0}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:49.925270727Z”}
{“log”:“2024-07-13T04:28:50Z\u0009ERROR\u0009pieces\u0009used-space-filewalker failed\u0009{"Process": "storagenode", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Lazy File Walker": false, "error": "filewalker: filestore error: file is a directory", "errorVerbose": "filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:7176\n\truntime.doInit:7143\n\truntime.main:253"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.179431482Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009pieces\u0009used-space-filewalker started\u0009{"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.179474158Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009starting subprocess\u0009{"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.179487106Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess started\u0009{"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.183679134Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker.subprocess\u0009Database started\u0009{"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Process": "storagenode"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.249920763Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009reputation:service\u0009node scores updated\u0009{"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Total Audits": 96421, "Successful Audits": 95693, "Audit Score": 1, "Online Score": 0.9833142164713311, "Suspension Score": 0.9999999644626423, "Audit Score Delta": 0, "Online Score Delta": 0, "Suspension Score Delta": 0.00000002694040601713965}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.595114946Z”}
{“log”:“2024-07-13T04:28:50Z\u0009INFO\u0009reputation:service\u0009node scores updated\u0009{"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Total Audits": 113717, "Successful Audits": 113106, "Audit Score": 1, "Online Score": 0.9839936326502323, "Suspension Score": 1, "Audit Score Delta": 0, "Online Score Delta": 0, "Suspension Score Delta": 0}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:50.682967107Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009reputation:service\u0009node scores updated\u0009{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Total Audits": 200886, "Successful Audits": 199667, "Audit Score": 1, "Online Score": 0.9850211782273095, "Suspension Score": 0.9999999999684631, "Audit Score Delta": 0, "Online Score Delta": 0, "Suspension Score Delta": 0}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.029091017Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess finished successfully\u0009{"Process": "storagenode", "satelliteID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.878657902Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009pieces\u0009used-space-filewalker completed\u0009{"Process": "storagenode", "Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "Lazy File Walker": true, "Total Pieces Size": 27720158976, "Total Pieces Content Size": 27663966464}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.878696754Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009pieces\u0009used-space-filewalker started\u0009{"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.878711234Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009starting subprocess\u0009{"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.878845519Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess started\u0009{"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.87945183Z”}
{“log”:“2024-07-13T04:28:51Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker.subprocess\u0009Database started\u0009{"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Process": "storagenode"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:28:51.91562762Z”}
{“log”:“2024-07-13T04:29:49Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess finished successfully\u0009{"Process": "storagenode", "satelliteID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:49.959100667Z”}
{“log”:“2024-07-13T04:29:49Z\u0009INFO\u0009pieces\u0009used-space-filewalker completed\u0009{"Process": "storagenode", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Lazy File Walker": true, "Total Pieces Size": 686708835330, "Total Pieces Content Size": 684329165314}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:49.959142299Z”}
{“log”:“2024-07-13T04:29:49Z\u0009INFO\u0009pieces\u0009used-space-filewalker started\u0009{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:49.959279324Z”}
{“log”:“2024-07-13T04:29:49Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009starting subprocess\u0009{"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:49.959336176Z”}
{“log”:“2024-07-13T04:29:49Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess started\u0009{"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:49.96000185Z”}
{“log”:“2024-07-13T04:29:50Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker.subprocess\u0009Database started\u0009{"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Process": "storagenode"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:50.003873464Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009lazyfilewalker.used-space-filewalker\u0009subprocess finished successfully\u0009{"Process": "storagenode", "satelliteID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.243669946Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009pieces\u0009used-space-filewalker completed\u0009{"Process": "storagenode", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Lazy File Walker": true, "Total Pieces Size": 308291185664, "Total Pieces Content Size": 308099114496}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.243715929Z”}
{“log”:“2024-07-13T04:29:55Z\u0009ERROR\u0009piecestore:cache\u0009error getting current used space: \u0009{"Process": "storagenode", "error": "filewalker: filestore error: file is a directory", "errorVerbose": "filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:7176\n\truntime.doInit:7143\n\truntime.main:253"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.243911772Z”}
{“log”:“2024-07-13T04:29:55Z\u0009ERROR\u0009services\u0009unexpected shutdown of a runner\u0009{"Process": "storagenode", "name": "piecestore:cache", "error": "filewalker: filestore error: file is a directory", "errorVerbose": "filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:7176\n\truntime.doInit:7143\n\truntime.main:253"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.243957081Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "4KPUFAT2VFYBQN5GB6LVKB3H6M5AFNKIT2TTVT63UT3CCWSIWS2Q", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "PUT", "Remote Address": "79.127.201.210:54080", "Size": 65536}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.245414851Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "GAVJOCOLVSHVUDLPZSGB35MUVPW7DRUU6J7H6K2AT34PCXRVS4UQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Remote Address": "79.127.205.234:43784", "Size": 393216}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.246010227Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "72YPT7C74TB33AI2YL6OJAF6PBXSSGL4G6C35QSXS7LB54PW5YQQ", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Remote Address": "79.127.219.43:37134", "Size": 65536}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.246503251Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "2SULJMYHYS7I62DTGBQ5U2RXZIIH435JJDCCBQO36U4CKBR5XWWA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Remote Address": "79.127.205.236:55966", "Size": 458752}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.24683659Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "LYLDUNN42HVWI4VWQATJDJEEXHAI5GQXDRMETF4FYU2DSS7BPOKA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Remote Address": "79.127.226.100:50880", "Size": 131072}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.247540962Z”}
{“log”:“2024-07-13T04:29:55Z\u0009INFO\u0009piecestore\u0009upload canceled\u0009{"Process": "storagenode", "Piece ID": "ISXZNCKFJPMWUSXWTXX7R2K3Y6KKQMCFJBMF6JBXNZ23NQ26CNHA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Remote Address": "79.127.219.36:38370", "Size": 393216}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:55.247995387Z”}
{“log”:“2024-07-13T04:29:58Z\u0009ERROR\u0009failure during run\u0009{"Process": "storagenode", "error": "filewalker: filestore error: file is a directory", "errorVerbose": "filewalker: filestore error: file is a directory\n\tstorj.io/storj/storagenode/blobstore/filestore.init:27\n\truntime.doInit1:7176\n\truntime.doInit:7143\n\truntime.main:253"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:58.110756024Z”}
{“log”:“Error: filewalker: filestore error: file is a directory\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:58.110806763Z”}
{“log”:“2024-07-13 04:29:58,160 INFO exited: storagenode (exit status 1; not expected)\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:58.160619852Z”}
{“log”:“2024-07-13 04:29:59,165 INFO spawned: ‘storagenode’ with pid 244\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.165686866Z”}
{“log”:“2024-07-13 04:29:59,165 WARN received SIGQUIT indicating exit request\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.166075052Z”}
{“log”:“2024-07-13 04:29:59,166 INFO waiting for storagenode, processes-exit-eventlistener, storagenode-updater to die\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.166683846Z”}
{“log”:“2024-07-13T04:29:59Z\u0009INFO\u0009Got a signal from the OS: "terminated"\u0009{"Process": "storagenode-updater"}\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.171314741Z”}
{“log”:“2024-07-13 04:29:59,173 INFO stopped: storagenode-updater (exit status 0)\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.173951205Z”}
{“log”:“2024-07-13 04:29:59,174 INFO stopped: storagenode (terminated by SIGTERM)\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.174817831Z”}
{“log”:“2024-07-13 04:29:59,175 INFO stopped: processes-exit-eventlistener (terminated by SIGTERM)\n”,“stream”:“stdout”,“time”:“2024-07-13T04:29:59.175698817Z”}
{“log”:“2024-07-13 04:30:01,712 INFO Set uid to user 0 succeeded\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:01.713069605Z”}
{“log”:“2024-07-13 04:30:01,724 INFO RPC interface ‘supervisor’ initialized\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:01.724357337Z”}
{“log”:“2024-07-13 04:30:01,724 INFO supervisord started with pid 1\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:01.724522624Z”}
{“log”:“2024-07-13 04:30:02,727 INFO spawned: ‘processes-exit-eventlistener’ with pid 11\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:02.728072529Z”}
{“log”:“2024-07-13 04:30:02,730 INFO spawned: ‘storagenode’ with pid 12\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:02.731430411Z”}
{“log”:“2024-07-13 04:30:02,733 INFO spawned: ‘storagenode-updater’ with pid 13\n”,“stream”:“stdout”,“time”:“2024-07-13T04:30:02.734391461Z”}