Node starting process stuck on flush cache step after failover test. #974

New issue

Closed

opened 2025-12-28 17:21:21 +00:00 by sami · 1 comment

sami commented

2025-12-28 17:21:21 +00:00

Owner

Originally created by @anikeev-yadro on GitHub (Feb 7, 2023).

Originally assigned to: @carpawell on GitHub.

Steps to Reproduce (for bugs)

0.Prefill cluster on ~7Tb (half objects with size 64Kb and half 150Mb)
1.Preset and start k6 load

date;./scenarios/preset/preset_grpc.py --size 150000 --containers 40 --out /var/data/tmp/grpc_060223-150000.json --endpoint 10.78.70.118:8080 --preload_obj 20  --wallet scenarios/files/wallet.json --config scenarios/files/empty_pass.yaml

date;./k6 run -e DURATION=2400 -e WRITERS=10 -e READERS=10 -e DELETERS=0 -e DELETE_AGE=10 -e REGISTRY_FILE=/var/data/tmp/grpc_reg_060223-150000-1.json -e WRITE_OBJ_SIZE=150000  -e GRPC_ENDPOINTS=10.78.70.118:8080,10.78.70.119:8080,10.78.70.121:8080 -e PREGEN_JSON=/var/data/tmp/grpc_060223-150000.json -e STREAM_TIMEOUT=30  -e SLEEP_READ=0.2  -e SLEEP_WRITE=0.2 scenarios/grpc.js

2.Power off node VEDI

anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power reset
Mon Feb  6 16:52:52 MSK 2023
Chassis Power Control: Reset
anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power off
Mon Feb  6 16:53:46 MSK 2023
Chassis Power Control: Down/Off
anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power status
Mon Feb  6 16:53:48 MSK 2023
Chassis Power is off

3.Wait for node VEDI not shown in map
4.Power on VEDI
5.On node BUKI log is cycling on the following errors

Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.166Z        debug        writecache/flush.go:135        tried to flush items from write-cache        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"}
Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.207Z        info        log/log.go:13        local object storage operation        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"}
Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.228Z        warn        engine/engine.go:124        can't update object storage ID        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"}
Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.325Z        debug        writecache/flush.go:135        tried to flush items from write-cache        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"}
Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.360Z        info        log/log.go:13        local object storage operation        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"}
Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.380Z        warn        engine/engine.go:124        can't update object storage ID        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"}
Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.465Z        debug        writecache/flush.go:135        tried to flush items from write-cache        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"}
Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.501Z        info        log/log.go:13        local object storage operation        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"}
Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.522Z        warn        engine/engine.go:124        can't update object storage ID        {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"}

Version

NeoFS Storage node
Version: v0.35.0-28-gb6c63173-dirty
GoVersion: go1.18.4

Your Environment

Server setup and configuration:
HW, 4 servers, 4 SN, 4 http qw, 4 s3 gw

Operating System and version (uname -a):
linux vedi 5.10.0-16-amd64 https://github.com/nspcc-dev/neofs-node/issues/1 SMP Debian 5.10.127-1 (2022-06-30) x86_64 GNU/Linux

Originally created by @anikeev-yadro on GitHub (Feb 7, 2023). Originally assigned to: @carpawell on GitHub. ## Steps to Reproduce (for bugs) 0.Prefill cluster on ~7Tb (half objects with size 64Kb and half 150Mb) 1.Preset and start k6 load ``` date;./scenarios/preset/preset_grpc.py --size 150000 --containers 40 --out /var/data/tmp/grpc_060223-150000.json --endpoint 10.78.70.118:8080 --preload_obj 20 --wallet scenarios/files/wallet.json --config scenarios/files/empty_pass.yaml date;./k6 run -e DURATION=2400 -e WRITERS=10 -e READERS=10 -e DELETERS=0 -e DELETE_AGE=10 -e REGISTRY_FILE=/var/data/tmp/grpc_reg_060223-150000-1.json -e WRITE_OBJ_SIZE=150000 -e GRPC_ENDPOINTS=10.78.70.118:8080,10.78.70.119:8080,10.78.70.121:8080 -e PREGEN_JSON=/var/data/tmp/grpc_060223-150000.json -e STREAM_TIMEOUT=30 -e SLEEP_READ=0.2 -e SLEEP_WRITE=0.2 scenarios/grpc.js ``` 2.Power off node VEDI ``` anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power reset Mon Feb 6 16:52:52 MSK 2023 Chassis Power Control: Reset anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power off Mon Feb 6 16:53:46 MSK 2023 Chassis Power Control: Down/Off anikeev@NB-1670:~/neofs/neofs-testcases$ date;ipmitool -I lanplus -H 10.78.68.120 -U admin -P admin power status Mon Feb 6 16:53:48 MSK 2023 Chassis Power is off ``` 3.Wait for node VEDI not shown in map 4.Power on VEDI 5.On node BUKI log is cycling on the following errors ``` Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.166Z debug writecache/flush.go:135 tried to flush items from write-cache {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"} Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.207Z info log/log.go:13 local object storage operation {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"} Feb 07 08:59:36 buky neofs-node[1629261]: 2023-02-07T08:59:36.228Z warn engine/engine.go:124 can't update object storage ID {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"} Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.325Z debug writecache/flush.go:135 tried to flush items from write-cache {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"} Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.360Z info log/log.go:13 local object storage operation {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"} Feb 07 08:59:37 buky neofs-node[1629261]: 2023-02-07T08:59:37.380Z warn engine/engine.go:124 can't update object storage ID {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"} Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.465Z debug writecache/flush.go:135 tried to flush items from write-cache {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "count": 1, "start": "DvGFSeNyxPduBWJqf3oKaUykZFAdat2Pi8i9qurPLGWQwAavt2gjNjSFRDUhDroyqnq99hJTDhSV6pm3Gt7Q5BUFqRW4ob7c3UUxPWLEsVmPgkutCV1z9MK"} Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.501Z info log/log.go:13 local object storage operation {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "address": "DWwQSxmW48sFGp3QG7SRfdoFpeLJ5S6qFXmnGQEo64rZ/HFHxdmoQ1vYpSwgN5b1nsuihqeNNQS7SFBiiwHwMpZ29", "op": "PUT", "type": "blobovnicza", "storage_id": "9/2/1"} Feb 07 08:59:38 buky neofs-node[1629261]: 2023-02-07T08:59:38.522Z warn engine/engine.go:124 can't update object storage ID {"shard_id": "PYQ2rDBZc6tpf5uT3YReN1", "error": "object is expired"} ``` ## Version ``` NeoFS Storage node Version: v0.35.0-28-gb6c63173-dirty GoVersion: go1.18.4 ``` ## Your Environment Server setup and configuration: HW, 4 servers, 4 SN, 4 http qw, 4 s3 gw Operating System and version (uname -a): linux vedi 5.10.0-16-amd64 https://github.com/nspcc-dev/neofs-node/issues/1 SMP Debian 5.10.127-1 (2022-06-30) x86_64 GNU/Linux