A lot of unsent orders

Odmin · October 28, 2020, 4:29pm

I’m during the investigation with database corruption and filesystem corruption found a new issue, inside orders/unsent on one node I have a a lot of unsent orders

Log contain this errors:

2020-10-28T16:18:04.923636856Z 2020-10-28T16:18:04.923Z INFO    piecestore      download started        {"Piece ID": "J6MQYDGF7B5U4LBAEQ3ERQYHHBPVOMPTUZYUH7M3CGKCOY6NYFHA", "Satellite ID": "12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzos
MuawymB", "Action": "GET_REPAIR"}
2020-10-28T16:18:05.220339427Z 2020-10-28T16:18:05.220Z INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      sending {"count": 83}
2020-10-28T16:18:05.220348174Z 2020-10-28T16:18:05.220Z INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      sending {"count": 776}
2020-10-28T16:18:05.220350439Z 2020-10-28T16:18:05.220Z INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       sending {"count": 29}
2020-10-28T16:18:05.220352296Z 2020-10-28T16:18:05.220Z INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      sending {"count": 144}
2020-10-28T16:18:05.220516841Z 2020-10-28T16:18:05.220Z INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      sending {"count": 177}
2020-10-28T16:18:05.330745076Z 2020-10-28T16:18:05.330Z INFO    piecestore      downloaded      {"Piece ID": "D5QTH4PCWQLBAS67K6CMQUQUIZPKT7QFRAWC7SJLXJ3P22JEGWKA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE",
 "Action": "GET_REPAIR"}
2020-10-28T16:18:05.380746879Z 2020-10-28T16:18:05.380Z ERROR   orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      rpc client error when receiving new order settlements   {"error": "order: failed to receive settlement res
ponse: endpoint disabled", "errorVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstor$
.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.399466647Z 2020-10-28T16:18:05.399Z ERROR   orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      rpc client error when receiving new order settlements   {"error": "order: failed to receive settlement re$
ponse: endpoint disabled", "errorVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj
.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.399473924Z 2020-10-28T16:18:05.399Z INFO    orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      finished
2020-10-28T16:18:05.400181246Z 2020-10-28T16:18:05.399Z ERROR   orders.12L9ZFwhzVpuEKMUNUqkaTLGzwY9G24tbiigLiXpmZWKwmcNDDs      failed to settle orders {"error": "order: failed to receive settlement response: endpoint disabled", "erro
rVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj.io/storj/storagenode/orders.(*S
ervice).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.463101750Z 2020-10-28T16:18:05.461Z ERROR   orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      rpc client when sending new orders settlements  {"error": "order: sending settlement agreements returned a
n error: EOF", "errorVerbose": "order: sending settlement agreements returned an error: EOF\n\tstorj.io/storj/storagenode/orders.(*Service).settle.func2:322\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57", "request": {"limit":{"se
rial_number":"AAAAAAC6ZANV6CEBY7YA4RCMXU","satellite_id":"12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB","uplink_public_key":{},"storage_node_id":"12LcaN37vw6V3HSm7c9zrLQEWBgDFTzmm6FFihWQoLrmfNtbygq","piece_id":"ZGSGQZG4CCESJBBC
EUWSIDMT7HRRXISTCPU3ATY3E4MSK3VLJKXQ","limit":2319360,"action":1,"piece_expiration":"0001-01-01T00:00:00Z","order_expiration":"2020-05-22T18:35:11.309476022Z","order_creation":"2020-05-20T18:35:11.321534019Z","satellite_signature":"ME
UCIQCTnKHsoH8nixrX5GjBnMQBXIgbalssOMZgbl5d5QQnyQIgJui39A96vJV5eLl3CdxZ7fA32fMUAZtLerpecGk5yAY=","satellite_address":{}},"order":{"serial_number":"AAAAAAC6ZANV6CEBY7YA4RCMXU","amount":1045248,"uplink_signature":"zchyN4Q1up0O63on7u2C/77
i2oMhGBS+Qebv4A3yFQdZBITeea61SSeG/02H1xmfGAjf6cQDDGc1DfkeBiz7CA=="}}}
2020-10-28T16:18:05.463118435Z 2020-10-28T16:18:05.462Z INFO    orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      finished
2020-10-28T16:18:05.464791759Z 2020-10-28T16:18:05.463Z ERROR   orders.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB      failed to settle orders {"error": "order: failed to receive settlement response: endpoint disabled; order:
 sending settlement agreements returned an error: EOF", "errorVerbose": "group:\n--- order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storage$
ode/orders.(*Service).Settle:241\n\tstorj.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57\n--- order: sending settlement agreements returned an error: EOF\n\tstorj.i
o/storj/storagenode/orders.(*Service).settle.func2:322\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.684887211Z 2020-10-28T16:18:05.684Z ERROR   orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      rpc client error when receiving new order settlements   {"error": "order: failed to receive settlement res
ponse: endpoint disabled", "errorVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj
.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.684892101Z 2020-10-28T16:18:05.684Z INFO    orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      finished
2020-10-28T16:18:05.684895444Z 2020-10-28T16:18:05.684Z ERROR   orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      failed to settle orders {"error": "order: failed to receive settlement response: endpoint disabled", "erro
rVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj.io/storj/storagenode/orders.(*S
ervice).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.819953369Z 2020-10-28T16:18:05.819Z ERROR   orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       rpc client error when receiving new order settlements   {"error": "order: failed to receive settlement res
ponse: endpoint disabled", "errorVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj
.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.820096847Z 2020-10-28T16:18:05.819Z INFO    orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       finished
2020-10-28T16:18:05.820111780Z 2020-10-28T16:18:05.820Z ERROR   orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       failed to settle orders {"error": "order: failed to receive settlement response: endpoint disabled", "erro
rVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj.io/storj/storagenode/orders.(*S
ervice).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:05.824798446Z 2020-10-28T16:18:05.824Z INFO    piecestore      downloaded      {"Piece ID": "X6WV3DP5W2SJHDDERBFV4WQKXIWX4T2IDUQBMG64LZGWSVCXE6DQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE",
 "Action": "GET_REPAIR"}
2020-10-28T16:18:06.124595882Z 2020-10-28T16:18:06.124Z INFO    piecestore      download started        {"Piece ID": "4TNHOSDTHOTMQ44GEQ3KOSKJK3XHDMJARUHJU2A4OXMFXEVOWCYQ", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8Ej
T69tGE", "Action": "GET_AUDIT"}
2020-10-28T16:18:06.154201293Z 2020-10-28T16:18:06.153Z ERROR   orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      rpc client error when receiving new order settlements   {"error": "order: failed to receive settlement res
ponse: endpoint disabled", "errorVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj
.io/storj/storagenode/orders.(*Service).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2020-10-28T16:18:06.154208008Z 2020-10-28T16:18:06.154Z INFO    orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      finished
2020-10-28T16:18:06.154210792Z 2020-10-28T16:18:06.154Z ERROR   orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      failed to settle orders {"error": "order: failed to receive settlement response: endpoint disabled", "erro
rVerbose": "order: failed to receive settlement response: endpoint disabled\n\tstorj.io/storj/storagenode/orders.(*Service).settle:350\n\tstorj.io/storj/storagenode/orders.(*Service).Settle:241\n\tstorj.io/storj/storagenode/orders.(*S
ervice).sendOrdersFromDB.func2:219\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

How I can fix it?

PS. Databases OK, filesystem clean.

anon27637763 · October 28, 2020, 4:46pm

I haven’t seen too many failures this month. The last failure for my node was October 12th.

I’ve enabled external logging and start a new log each month using logrotate. Here are October’s failed orders from my log:

grep ERROR.*orders.*failed node.log | cut -d "." -f1,3 |cut -f1

Result:

2020-10-05T07:01:54.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T18:08:09.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T18:08:52.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:07:14.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:16:14.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:28:56.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:35:01.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:48:16.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:50:54.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T20:58:14.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:08:19.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:12:04.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:25:09.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:33:03.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:41:43.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:53:25.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T21:54:55.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:07:25.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:16:01.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:30:17.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:37:17.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:50:29.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T22:54:31.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:04:46.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:06:14.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:17:00.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:17:58.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:31:59.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:44:13.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-10T23:57:30.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:07:37.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:08:13.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:22:28.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:25:59.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:38:49.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T00:47:04.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:00:22.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:10:31.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:23:18.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:31:40.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:34:27.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-11T01:35:06.12rfG3sh9NCWiX3ivPjq2HtdLmbqCrvHVEzJubnzFzosMuawymB
2020-10-12T15:15:17.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE

nerdatwork · October 28, 2020, 5:39pm

That’s a really old order. Orders expire after 48 hours so any file older than 48 hours is safe to delete. Also note any order lost will affect payment.

You can delete order files while node is running but new orders will only be sent every hour. If you want to force them to be sent asap then you can restart your node.

moby · October 28, 2020, 6:42pm

It looks like you have unsent orders in your orders database still. Those will always fail as the endpoint for submitting those is disabled. As long as your node is sending orders from the filestore with no errors, you should be okay despite those errors.

EDIT: it is not actually an okay error on v1.15 and before. See conversation below

moby · October 28, 2020, 6:46pm

Actually, I am assuming you are on version v1.15. If this is the case, your filestore orders may not be sending. We have a fix in the upcoming release for this. A quick fix would be to drop all orders in your orders.db, then you shouldn’t see this error anymore.

Odmin · October 28, 2020, 6:48pm

Thanks a lot for your reply!
I will just ignore these errors now and will be waiting for the next release. Yes, I have the latest version v1.15

moby · October 28, 2020, 6:49pm

Okay, but if you ignore them, your new orders will not send and you will not get paid. I would advise (if you care about your payout) to remove the orders from your database file, as they cannot be sent anyway.

moby · October 28, 2020, 6:49pm

By the time the new release comes out, many of your filestore orders will likely be expired

Odmin · October 28, 2020, 6:50pm

Got it!
Thanks again! will do it.

moby · October 28, 2020, 6:50pm

Please let us know if this does not resolve the issue

Alexey · October 28, 2020, 6:51pm

@moby Is it true for everyone node on 1.15.*?
If so, should we made an announcements or something?

moby · October 28, 2020, 6:55pm

@Alexey Right now, the satellite will never accept orders submitted from the old endpoint, and database orders can only be submitted to the old endpoint. So now, anyone on any version (including 1.15.*) will not be able to submit orders.db orders.

When we made the change initially, we assumed that by the time we disabled the endpoint, every node would have sent their orders from the DB, but we didn’t account for the case where there are expired orders in the database. I believe that is what is happening with @Odmin’s node. This should all be fixed with 1.16, but yes, an announcement might be a good idea if node operators are running into issues involving orders.db.

Odmin · October 28, 2020, 7:52pm

Successfully fix this issue, thank you @moby again!

The solution is easy:

Stop storage node
Backup orders.db (just copy it)
sqlite3 /storage/orders.db

DELETE FROM unsent_order;
.exit
start storage node
look into logs and check the status of orders
look into the unsent folder and make sure that everything is sent after some time

Sasha · November 1, 2020, 2:03am

@moby, Does this need to be done for SNO’s running 15.3?

moby · November 1, 2020, 3:53am

@Sasha yes, if you are seeing these errors. If not, you don’t need to worry about it.

rafh69 · November 4, 2020, 1:24pm

Hello, I needed help to resolve the unsent orders situation. On windows the only thing I can see is the folder (C: \ Storj \ Storage Node \ orders \ unsent) with 1743 files. This help request comes due to the October payment, where I had a calculation of 18 and received only 13. I would appreciate much help in solving this problem. my node is with version v1.15.3

Alexey · November 4, 2020, 7:09pm

Stop the storagenode
Remove all orders older than 48 hours (they will not be accepted because they expired already)
Move all remaining orders to the other folder
Move orders by batches back to the orders/unsent
Restart the storagenode
If orders are sent, repeat from p.4
if orders are stuck, move half to the other folder and repeat from p.5
Repeat p.7 until you will have a broken order - please remove it.
Repeat from p.4 until all orders are sent or removed.

Then please remove orders from the orders.db

Stop the storagenode
Execute either with a local installed sqlite3 or with a docker version (you can take it from https://support.storj.io/hc/en-us/articles/360029309111), correct the path:

sqlite3 /path/to/orders.db "delete from unsent_order;"

Start the storagenode
Check your logs

Sasha · November 4, 2020, 8:51pm

Hopefully SNO’s would be compensated in some way for this unsent orders issue.

SGC · November 4, 2020, 11:34pm

if it’s storj labs fault i totally agree… tho if it’s due to node’s not running under optimal conditions, then i would think it’s really the SNO’s own issue…