Node disqualified because file does not exists

Krey · October 13, 2021, 9:13pm

My node was disqualified because audits drop with “file does not exist” errors on us1 satellite
But I’m sure these files were never there.
Node on stable host, on raidz1(4+1), no pool errors. Other nodes on this host and other satellites are OK.

Summary

nodeId 1aGsGmNPwGzwQvr2RMGDoeedsdGrC9wKnY1ZqEvxo1s36Lxbd4
last not found pieces:
Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ
BDQWBWLROLFGYS4R52GO34I65T666IPNKJNGLS6J7GPFSWSQTEYQ
YX2BJBDDKS2HUM7XCBX6DSREUU2V5N4QSWVHIY5KIDLOBOLYHR4Q
7KRORRSCJVUFZV5KU5TF7FJFECFCKWA2YHC67WCETS756SKRBPQA
V2GHQEXBI6FISXPYO2KI4YHFXKOEQMYLNNRGJFFFKXJT2TB3MRIA
5IBWYST356NYYTMI7BYR75FPTRRS53YLKSX7QCKNO5FR2CE4YUYA
6JHQ22O2ZCVJS4RPY3CEZLMLHH6NAY4JNTVOHZW37EKDID7NOO5A
JTZX7V7HON6J6FNIRE7IA2U3GDHCJKERRDOQ262YREQ6N4N4NKFA
SRRBN6UFK7UZOL5R4DC7UFPOEWNJ67PABVUGWBQHKMTGZXQA6URA
I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ

I am writing just for the report. It doesn’t matter to me what happens to this node, as well as to everyone else.

littleskunk · October 13, 2021, 11:07pm

Do you have some logfiles that we can use to search for these pieceIDs?

Krey · October 14, 2021, 5:15am

yes i have logs at least previous and current.
it looks like I jumped to conclusions. Pieces really was uploaded to my node

previous log ends with normally
2021-09-03T12:56:59.027+0300 INFO Got a signal from the OS: “terminated”

next log started with a gap of one hour and file not exists errors
most likely this hour I served a host and transferred the logs to the archive

greps

root@nas:/mnt/log/storj/v3/20210903/storj# tail node19.log
2021-09-03T12:56:58.587+0300    INFO    piecedeleter    delete piece sent to trash      {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "2VWSZNCZHLRSBY3VVDVVPU6XG2A7RTESJNAQJQ3Z26Q3BJBCRQNA"}
2021-09-03T12:56:58.736+0300    INFO    piecestore      upload started  {"Piece ID": "QMZBADDCZRI5XKCAALBYDLOEUCHH6OBCIZ4LJMIIUVWCBUNTCBGA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Available Space": 1250275885056}
2021-09-03T12:56:58.836+0300    INFO    piecestore      uploaded        {"Piece ID": "QMZBADDCZRI5XKCAALBYDLOEUCHH6OBCIZ4LJMIIUVWCBUNTCBGA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Size": 1280}
2021-09-03T12:56:58.934+0300    INFO    piecestore      uploaded        {"Piece ID": "IJGA2JI55HTABZL3YDJILJAZVK4M6QYCQFHRL6PNJHIEPKQSKETA", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 181504}
2021-09-03T12:56:59.027+0300    INFO    Got a signal from the OS: "terminated"
2021-09-03T12:56:59.028+0300    INFO    piecestore      downloaded      {"Piece ID": "CP7N6W262AHPVOJ6JOAWBS2ADOTJS4LX2LO4W7TGV626EWIK7Q6Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2021-09-03T12:56:59.028+0300    INFO    piecestore      upload canceled {"Piece ID": "H5LRE6JXPKTGCQFWPRCAX7AM4HZ5QKHUDA4J43HH4EA57HJ5GBQA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Size": 0}
2021-09-03T12:56:59.028+0300    INFO    piecestore      upload canceled {"Piece ID": "LRRS7QVE2W4H5TXAQDEH4NCQRTONWDV5KEDXDBVFPPST33OAJJDA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Size": 0}
2021-09-03T12:56:59.028+0300    INFO    piecestore      downloaded      {"Piece ID": "FATFDRA67H2PAKW5UQ5FAGHH5EQ6I24OFUL7ZVNVXXDVVQOZFXAA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET"}
2021-09-03T12:56:59.028+0300    INFO    piecestore      downloaded      {"Piece ID": "GO3VINNXCWBMAFCNRZG6ESZRE4ULUUNMJPF5576NHURHNKVJRKHA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET"}

START OF CURRENT LOG
root@storj:~# head -n 40 /var/log/storj/node19.log
2021-09-03T14:02:32.845+0300    INFO    Configuration loaded    {"Location": "/mnt/storj/node19/config.yaml"}
2021-09-03T14:02:32.859+0300    DEBUG   Anonymized tracing disabled
2021-09-03T14:02:32.872+0300    INFO    Operator email  {"Address": "krey@irinium.ru"}
2021-09-03T14:02:32.872+0300    INFO    Operator wallet {"Address": "0x7b9c2d38dfc07692e955476f907541a7ca186573"}
2021-09-03T14:02:33.118+0300    DEBUG   Version info    {"Version": "1.36.1", "Commit Hash": "e1410f6a55ee452e7b57f37744ea185d1643f4d9", "Build Timestamp": "2021-08-09 16:56:43 +0300 MSK", "Release Build": true}
2021-09-03T14:02:33.739+0300    DEBUG   version Allowed minimum version from control server.    {"Minimum Version": "1.24.0"}
2021-09-03T14:02:33.739+0300    DEBUG   version Running on allowed version.     {"Version": "1.36.1"}
2021-09-03T14:02:33.740+0300    INFO    Telemetry enabled       {"instance ID": "1aGsGmNPwGzwQvr2RMGDoeedsdGrC9wKnY1ZqEvxo1s36Lxbd4"}
2021-09-03T14:02:33.761+0300    INFO    db.migration    Database Version        {"version": 53}
2021-09-03T14:02:33.763+0300    DEBUG   db      Database version is up to date  {"version": 53}
2021-09-03T14:02:33.936+0300    DEBUG   trust   Fetched URLs from source; updating cache        {"source": "https://www.storj.io/dcs-satellites", "count": 6}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2021-09-03T14:02:33.937+0300    DEBUG   trust   Satellite is trusted    {"id": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2021-09-03T14:02:33.937+0300    INFO    preflight:localtime     start checking local system clock with trusted satellites' system clock.
2021-09-03T14:02:34.824+0300    INFO    preflight:localtime     local system clock is in sync with trusted satellites' system clock.
2021-09-03T14:02:34.824+0300    DEBUG   servers started {"items": ["debug", "server"]}
2021-09-03T14:02:34.824+0300    DEBUG   services        started {"items": ["version", "trust", "contact:chore", "PieceDeleter", "pieces:trash", "piecestore:cache", "piecestore:monitor", "retain", "orders", "nodestats:cache", "console:endpoint", "gracefulexit:blobscleaner", "gracefulexit:chore", "collector", "bandwidth"]}
2021-09-03T14:02:34.824+0300    INFO    Node 1aGsGmNPwGzwQvr2RMGDoeedsdGrC9wKnY1ZqEvxo1s36Lxbd4 started
2021-09-03T14:02:34.824+0300    INFO    Public server started on 192.168.156.219:4319
2021-09-03T14:02:34.824+0300    INFO    bandwidth       Performing bandwidth usage rollups
2021-09-03T14:02:34.824+0300    INFO    Private server started on 127.0.0.1:4219
2021-09-03T14:02:34.824+0300    INFO    trust   Scheduling next refresh {"after": "6h5m40.040805768s"}
2021-09-03T14:02:34.824+0300    DEBUG   pieces:trash    starting to empty trash
2021-09-03T14:02:34.824+0300    WARN    piecestore:monitor      Disk space is less than requested. Allocated space is   {"bytes": 12386991667723}
2021-09-03T14:02:34.824+0300    INFO    failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/lucas-clemente/quic-go/wiki/UDP-Receive-Buffer-Size for details.
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo"}
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE"}
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6"}
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S"}
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs"}
2021-09-03T14:02:34.825+0300    DEBUG   contact:chore   Starting cycle  {"Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB"}
2021-09-03T14:02:34.837+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "CI65EGSF3QPRVVL3EKEBZJGZOA5XYN5QJBBYT4235QPGWGUP32ZQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:02:34.837+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "J3J2T45OMGZJFJDTEPKHQPCME2KM6LREPSUBIKK4GDZ2Z6XU6UIA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:02:34.837+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "2MLEFHZXHZEJNCDRWPYP3RX7XL4LSVCXEUSVPW5KV3QUVPZP4AUA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:02:34.837+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "EWUW5M22HHYCFPEARWD4HSMMET6BOM3FBDITQTWKTRJ47WUF2BAA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:02:34.838+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "LR4ALUGVAKA7NJTYKVUJWOQ4ZTKOF6Q2VGTBIKB6O6PSBZ75VSPA", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

ARCHIEVED LOG
root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ
2021-08-19T06:51:54.349+0300    INFO    piecestore      upload started  {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Available Space": 1788539305984}
2021-08-19T06:52:22.915+0300    INFO    piecestore      uploaded        {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 2319360}
2021-08-19T17:18:29.442+0300    INFO    piecestore      download started        {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}
2021-08-19T17:18:35.268+0300    INFO    piecestore      downloaded      {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}
2021-08-20T00:54:30.748+0300    INFO    piecestore      download started        {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}
2021-08-20T00:54:34.787+0300    INFO    piecestore      downloaded      {"Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "GET"}

CURRENT LOG
root@storj:~# cat /var/log/storj/node19.log | grep Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ | head
2021-09-03T14:02:35.117+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:45:11.246+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T15:45:11.214+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T16:45:11.195+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T17:45:11.208+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T18:45:11.199+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T19:45:11.198+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T20:45:11.241+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T21:45:11.206+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T22:45:11.246+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:152\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

ARCHIEVED LOG
root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep -i I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ
2021-08-19T07:30:02.316+0300    INFO    piecestore      upload started  {"Piece ID": "I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Available Space": 1787339735040}
2021-08-19T07:30:08.538+0300    INFO    piecestore      uploaded        {"Piece ID": "I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ", "Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Action": "PUT", "Size": 2319360}

CURRENT LOG
root@storj:~# cat /var/log/storj/node19.log | grep I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ | head
2021-09-03T14:02:35.118+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2021-09-03T14:45:11.248+0300    ERROR   collector       unable to delete piece  {"Satellite ID": "12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs", "Piece ID": "I7S3INA7F3K5NUK5SCCJACLK4AHUDLHBQ5S3WC3DTNL3QMMN27LQ", "error": "pieces error: filestore error: file does not exist", "errorVerbose": "pieces error: filestore error: file does not exist\n\tstorj.io/storj/storage/filestore.(*blobStore).Stat:103\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).pieceSizes:239\n\tstorj.io/storj/storagenode/pieces.(*BlobsUsageCache).Delete:220\n\tstorj.io/storj/storagenode/pieces.(*Store).Delete:299\n\tstorj.io/storj/storagenode/collector.(*Service).Collect:97\n\tstorj.io/storj/storagenode/collector.(*Service).Run.func1:57\n\tstorj.io/common/sync2.(*Cycle).Run:92\n\tstorj.io/storj/storagenode/collector.(*Service).Run:53\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2.1:87\n\truntime/pprof.Do:40\n\tstorj.io/storj/private/lifecycle.(*Group).Run.func2:86\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

Alexey · October 14, 2021, 5:59am

Do you have logs with GET_AUDIT or GET_REPAIR with these missed pieces?

Also side question - do you have logs between 2021-08-20T00:54:34.787+0300 and 2021-09-03T14:02:35.117+0300 for piece Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ?
I’m interesting in - what’s happened with that piece after it was successful downloaded that it become lost 13 days after.

Krey · October 14, 2021, 6:04am

No

root@storj:~# cat /var/log/storj/node19.log | grep Q7ZL3U66CTGO2PMC5KCA56EXZWZMUYL7UFISDTUFFTIW7LH7ZFIQ | grep GET | wc -l
0

Alexey · October 14, 2021, 6:09am

Then unlikely these pieces are the reason for disqualification.
Your node must be online, answer on audit request and:

do not provide a piece within 5 minutes timeout, do the same two more times (time between GET_AUDIT or GET_REPAIR download started and ended more than 5 minutes);
provide a corrupted piece, the audit fail immediately (no failure records in logs after successful download by GET_AUDIT or GET_REPAIR);
return an error “file not found” or equivalent (“disk I/O error” or similar), the audit fail immediately (you should see a record in logs with failure for GET_AUDIT/GET_REPAIR download).

All these cases will end with failed audit. Too many failed audits in row and node will be disqualified.

Krey · October 14, 2021, 6:09am

only to 2021-09-03T12:56:59.028+0300 where node was stopped
between 2021-08-20T00:54:34.787+0300 and 2021-09-03T12:56:59.028+0300 where is no other records for this piece
Next node start was 2021-09-03T14:02:32.845+0300. One hour (13th) was downtime

Krey · October 14, 2021, 6:16am

look other pieces with file not exist error

root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q
2021-06-01T17:57:02.790+0300    DEBUG   retain  About to move piece to trash    {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Status": "enabled"}

root@storj:~# cat /var/log/storj/node19.log | grep CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q
2021-09-12T02:06:55.855+0300    INFO    piecestore      download started        {"Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR"}
2021-09-12T02:06:55.858+0300    ERROR   piecestore      download failed {"Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:534\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:217\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:102\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:95\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}

root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA"
2021-05-25T17:48:50.285+0300    INFO    piecestore      upload started  {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Available Space": 3898520376862}
2021-05-25T17:48:50.417+0300    INFO    piecestore      uploaded        {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Size": 1280}
2021-06-01T17:52:55.771+0300    DEBUG   retain  About to move piece to trash    {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Status": "enabled"}

root@storj:~# cat /var/log/storj/node19.log | grep "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA"
2021-09-03T15:01:35.158+0300    INFO    piecestore      download started        {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR"}
2021-09-03T15:01:35.161+0300    ERROR   piecestore      download failed {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:534\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:217\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:102\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:95\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}

Alexey · October 14, 2021, 6:21am

Could you please create an issue there: Issues · storj/storj · GitHub with that excerpt?

(We do not use internal issues for storagenodes anymore. The development process, include bugs processing, is moved to the public).

Krey · October 14, 2021, 6:49am

github.com/storj/storj

Storj ask GET_REPAIR for piece previously trashed

opened 06:38AM - 14 Oct 21 UTC

Krey81

Bug

My node 1aGsGmNPwGzwQvr2RMGDoeedsdGrC9wKnY1ZqEvxo1s36Lxbd4 was disqualified on u…s1 in logs i see many errors "file does not exist". I inspect logs for some pieces Forum discussion [https://forum.storj.io/t/node-disqualified-because-file-does-not-exists/15681](url) I have full debug logs for several months 1GB in zipped archive ` root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q 2021-06-01T17:57:02.790+0300 DEBUG retain About to move piece to trash {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Status": "enabled"} root@storj:~# cat /var/log/storj/node19.log | grep CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q 2021-09-12T02:06:55.855+0300 INFO piecestore download started {"Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR"} 2021-09-12T02:06:55.858+0300 ERROR piecestore download failed {"Piece ID": "CCRQFQY3TOSRRTHB22GGXEZARO4WVK4E3MW3GEIS2LEOJGEC2S6Q", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:534\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:217\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:102\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:95\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"} root@nas:/mnt/log/storj/v3/20210903/storj# cat node19.log | grep "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA" 2021-05-25T17:48:50.285+0300 INFO piecestore upload started {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Available Space": 3898520376862} 2021-05-25T17:48:50.417+0300 INFO piecestore uploaded {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "PUT", "Size": 1280} 2021-06-01T17:52:55.771+0300 DEBUG retain About to move piece to trash {"Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Status": "enabled"} root@storj:~# cat /var/log/storj/node19.log | grep "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA" 2021-09-03T15:01:35.158+0300 INFO piecestore download started {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR"} 2021-09-03T15:01:35.161+0300 ERROR piecestore download failed {"Piece ID": "VURO7JPIXWRFW5H7R5MLAD2MWU5ITWZCOON2ODPR6VFGXAO365XA", "Satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "Action": "GET_REPAIR", "error": "file does not exist", "errorVerbose": "file does not exist\n\tstorj.io/common/rpc/rpcstatus.Wrap:73\n\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:534\n\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:217\n\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33\n\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58\n\tstorj.io/drpc/drpcserver.(*Server).handleRPC:102\n\tstorj.io/drpc/drpcserver.(*Server).ServeOne:60\n\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:95\n\tstorj.io/drpc/drpcctx.(*Tracker).track:52"} `

BrightSilence · October 14, 2021, 7:44am

It was previously mentioned that as a safeguard for these kinds of issues, audits wouldn’t count against you if fewer than 29 nodes responded with the correct piece. Do we know if this safeguard is also in place for repair now that that impacts the scores as well?

Alexey · October 16, 2021, 12:50pm

I’ve got logs from the satellite, your node have a lot of direct audit errors “file does not exist” with resolution “Verify: piece not found (audit failed)”: audit-logs-nodeID-1aGsGmNPwGzwQvr2RMGDoeedsdGrC9wKnY1ZqEvxo1s36Lxbd4.json | Storj DCS (the link will expire after 2021-10-21T12:25:38Z)

Pieces from these segments are not expired, so your node should not move them to trash and must have them.
Due to the large number of direct audit errors, your node had no chance of surviving the audit…
Please, check why this node could lost these pieces.

The issue with repair workers and moving pieces to trash before an audit is still need investigation though, thanks for creating an issue on GitHub!