Failed to settle orders for satellite "error": "order: sending settlement agreements returned an error: timeout: no recent network activity"

Bivvo · March 23, 2022, 7:02pm


2022-03-23T18:05:10.043Z        ERROR   orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      rpc client when sending new orders settlements  {"error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57", "request": {"limit":{"serial_number":"AAAAAADCHXXNEESKNWNUHB5TMU","satellite_id":"121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6","uplink_public_key":{},"storage_node_id":"1veqEG5xuBNkt6cK1NbmL5fbNxXq6E7JzB7CiiaptoapoWnB1i","piece_id":"KIWVOLO4ZO7TLEUJEVLFMAUPMBIGGWP774WEK2JR3OIZE32GLAUA","limit":2319360,"action":1,"piece_expiration":"0001-01-01T00:00:00Z","order_expiration":"2022-03-25T16:33:22.002663311Z","order_creation":"2022-03-23T16:33:22.002663311Z","encrypted_metadata_key_id":"4VwE2lxbA3w=","encrypted_metadata":"yhM8tiv9R2xW6BwPrIfWAZ8iMjp2/7AmVPL0RH40e/I45PwrGl88lletsqQdb8qQEVQ5+/xiXhzoJlwMZAma3w==","satellite_signature":"MEUCIBMatFEGFt7LpPJAifbAIzCjxboyN31UEjucZkk+rUQDAiEAvK7YjR07RDbZW1zic0HYnnV0eKWj1UHifiqQyGY+Q7Y="},"order":{"serial_number":"AAAAAADCHXXNEESKNWNUHB5TMU","amount":768,"uplink_signature":"LEURmLZurGkbaxCb9xOjZPTwWejX6nFMV0nDvRxJUWaadHhOmm83aHSfYRtu30NLyPF4jAhuViO8JmE1PF9NDQ=="}}}
2022-03-23T18:05:10.044Z        ERROR   orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      failed to settle orders for satellite   {"satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

After the automatic update to 1.50.4.
what is it about?

Alexey · March 23, 2022, 7:14pm

About inability to settle orders for the satellite because of timeout.
If your node would not submit orders within 48 hours, they will expire and your node would not be paid for these orders.

Please, check your network - is there something which could filter outgoing connections?
Specifically to ap1.storj.io:7777

Your firewall should not have any active outbound rules.

Bivvo · March 23, 2022, 7:38pm

Nothing changed since weeks.

nmap says:

Also, cannot find this issue in the forum.
Sure, that it is not related to the latest release?

Node is working well, except that. ins, outs, audits… No other errors.

Alexey · March 24, 2022, 6:20am

It’s not related to the latest release.
At least no issues so far.

You can search for “failed to settle orders”:

Bivvo · March 24, 2022, 7:05am

pi@raspberrypi:~ $ docker logs sn1 2>&1 | grep 'failed to settle orders'
2022-03-23T18:05:10.044Z	ERROR	orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6	failed to settle orders for satellite	{"satellite ID": "121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6", "error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity\n\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264\n\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2022-03-23T19:04:54.144Z	ERROR	orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S	failed to settle orders for satellite	{"satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity\n\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264\n\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2022-03-23T23:04:48.594Z	ERROR	orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S	failed to settle orders for satellite	{"satellite ID": "12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S", "error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity\n\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264\n\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205\n\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

That’s all.

Bivvo · March 24, 2022, 11:51am

Another one, popping up first time:

2022-03-24T11:22:17.272Z        ERROR   piecestore      download failed {"Piece ID": "ZZ35PEYKZK224Q6TAYI4AI7QJZUX54BNUBXIFF6MFEMHEPDQ2MCA", "Satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "Action": "GET_REPAIR", "error": "used serial already exists in store", "errorVerbose": "used serial already exists in store
\tstorj.io/storj/storagenode/piecestore/usedserials.insertSerial:263
\tstorj.io/storj/storagenode/piecestore/usedserials.(*Table).Add:117
\tstorj.io/storj/storagenode/piecestore.(*Endpoint).verifyOrderLimit:76
\tstorj.io/storj/storagenode/piecestore.(*Endpoint).Download:497
\tstorj.io/common/pb.DRPCPiecestoreDescription.Method.func2:228
\tstorj.io/drpc/drpcmux.(*Mux).HandleRPC:33
\tstorj.io/common/rpc/rpctracing.(*Handler).HandleRPC:58
\tstorj.io/drpc/drpcserver.(*Server).handleRPC:122
\tstorj.io/drpc/drpcserver.(*Server).ServeOne:66
\tstorj.io/drpc/drpcserver.(*Server).Serve.func2:112
\tstorj.io/drpc/drpcctx.(*Tracker).track:52"}

What does that mean?

stefanbenten · March 24, 2022, 1:14pm

What OS and hardware are you using?

Bivvo · March 24, 2022, 1:26pm

Debian Bullseye, latest updates, on RPi4B.
@stefanbenten

stefanbenten · March 24, 2022, 1:31pm

Could you post the output of uname -a ?

stefanbenten · March 24, 2022, 1:44pm

BTW, automatic update to v1.50.4 is not possible. Docker images have not been pushed yet

Bivvo · March 24, 2022, 1:47pm

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 5.10.92-v8+ #1514 SMP PREEMPT Mon Jan 17 17:39:38 GMT 2022 aarch64 GNU/Linux

Ok, just wanted to mention, that the dashboard shows version 1.50.4

Alexey · March 24, 2022, 7:40pm

@Bivvo have used a new version with autoupdater

stefanbenten · March 24, 2022, 9:58pm

I have found that the root cause of this error comes from the quic package we are using.
Trying to work my way through where its timing out…

Bivvo · March 24, 2022, 10:03pm

Which one? „used serial“ or „settle orders“?

stefanbenten · March 24, 2022, 10:17pm

The “Order settling” one

Bivvo · March 25, 2022, 7:44pm


2022-03-25T19:04:59.856Z        ERROR   orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       rpc client when sending new orders settlements  {"error": "order: sending settlement agreements returned an error: EOF", "errorVerbose": "order: sending settlement agreements returned an error: EOF
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57", "request": {"limit":{"serial_number":"AAAAAADCICOTJ5WA2KWJO2U5RY","satellite_id":"1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE","uplink_public_key":{},"storage_node_id":"1veqEG5xuBNkt6cK1NbmL5fbNxXq6E7JzB7CiiaptoapoWnB1i","piece_id":"KMWHHFOATLSIW3HFURIHIEL74EXYYA2GPRSUJLXN7JU3A4LT5UJQ","limit":2317056,"action":2,"piece_expiration":"0001-01-01T00:00:00Z","order_expiration":"2022-03-27T17:21:56.060000195Z","order_creation":"2022-03-25T17:21:56.060000195Z","encrypted_metadata_key_id":"QDs91VL1vug=","encrypted_metadata":"uODGH1Cc8qNASu0Enc8oO0HPj44MN9WJOsLqC0IQAr6E9OEc63k=","satellite_signature":"MEQCIFadOCNgDRQ7bRCAldr3B6l8tBrQZ6yVZ4OF45LIGhClAiBs/Nn4e37Jm9d+yb3dKSoUriDnz9Y1NUNt3aD2sgtxYw=="},"order":{"serial_number":"AAAAAADCICOTJ5WA2KWJO2U5RY","amount":2105344,"uplink_signature":"0/c37HCIRn08fif9YRSY5c7amb7aIpHEVKXoH7R5ZHwTB65xIQkII8KKWS9VHMr6mDOJWXMP+vwDic1NPKk3BA=="}}}
2022-03-25T19:04:59.857Z        ERROR   orders.1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE       failed to settle orders for satellite   {"satellite ID": "1wFTAgs9DP5RSnCqKV1eLf6N9wtk4EAtmN5DpSxcs8EjT69tGE", "error": "order: sending settlement agreements returned an error: EOF", "errorVerbose": "order: sending settlement agreements returned an error: EOF
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:264
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

Errors occurring more frequently.

Bivvo · March 27, 2022, 6:03am


2022-03-27T04:05:01.763Z        ERROR   orders.12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo       rpc client error when closing sender    {"error": "order: CloseAndRecv settlement agreements returned an error: context canceled", "errorVerbose": "order: CloseAndRecv settlement agreements returned an error: context canceled
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:275
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}
2022-03-27T04:05:01.763Z        ERROR   orders.12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo       failed to settle orders for satellite   {"satellite ID": "12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo", "error": "order: CloseAndRecv settlement agreements returned an error: context canceled", "errorVerbose": "order: CloseAndRecv settlement agreements returned an error: context canceled
\tstorj.io/storj/storagenode/orders.(*Service).settleWindow:275
\tstorj.io/storj/storagenode/orders.(*Service).SendOrders.func1:205
\tgolang.org/x/sync/errgroup.(*Group).Go.func1:57"}

„order: CloseAndRecv settlement agreements returned an error: context canceled“

thepaul · March 28, 2022, 7:07pm

The “no recent network activity” error message is quic-go’s version of ETIMEDOUT (“connection timed out”). It’s a very confusing message, I agree.

Alexey · March 29, 2022, 7:25am

8 posts were split to a new topic: "GET_REPAIR”, “error”: “used serial already exists in store”

Bivvo · March 28, 2022, 10:17pm

Mainly having those:

2022-03-28T05:31:13.323Z        ERROR   orders.121RTSDpyNZVcEU84Ticf2L1ntiuUimbWgfATz21tuvgk3vzoA6      rpc client when sending new orders settlements  {"error": "order: sending settlement agreements returned an error: timeout: no recent network activity", "errorVerbose": "order: sending settlement agreements returned an error: timeout: no recent network activity

2022-03-28T02:30:48.776Z        ERROR   orders.12EayRS2V1kEsWESU9QMRseFhdxYxKicsiFmxrsLZHeLUtdps3S      rpc client when sending new orders settlements  {"error": "order: sending settlement agreements returned an error: EOF", "errorVerbose": "order: sending settlement agreements returned an error: EOF

And just 1-2 times this one:

2022-03-27T04:05:01.763Z        ERROR   orders.12tRQrMTWUWwzwGh18i7Fqs67kmdhH9t6aToeiwbo5mfS2rUmo       rpc client error when closing sender    {"error": "order: CloseAndRecv settlement agreements returned an error: context canceled", "errorVerbose": "order: CloseAndRecv settlement agreements returned an error: context canceled

But they seem to work on it since 4d.

Should we open a defect on GitHub?