TrueCloudLab/frostfs-node

Fork 28

Flaky test: engine_test.go (TestLockExpiration, TestLockUserScenario, ...) #1700

New issue

Closed

opened 2025-03-31 16:18:11 +00:00 by potyarkin · 3 comments

potyarkin commented

2025-03-31 16:18:11 +00:00

Member

I've noticed that one of our tests is flaky: example A, example B. Crash happens here, this method is being called from several test cases: TestLockExpiration, TestLockUserScenario, probably others.

 func (t *testQoSLimiter) Close() {
 	require.Equal(t.t, int64(0), t.read.Load(), "read requests count after limiter close must be 0")
 	require.Equal(t.t, int64(0), t.write.Load(), "write requests count after limiter close must be 0")
 }

Test failure looks like this:

engine_test.go:169: 
      Error Trace:  ./pkg/local_object_storage/engine/engine_test.go:169
                          ./pkg/local_object_storage/shard/control.go:399
                          ./pkg/local_object_storage/engine/control.go:161
                          ./pkg/local_object_storage/engine/control.go:210
                          ./pkg/local_object_storage/engine/control.go:152
                          ./pkg/local_object_storage/engine/lock_test.go:166
                          ./pkg/local_object_storage/engine/lock_test.go:218
      Error:        Not equal: 
                    expected: 0
                    actual  : 1
      Test:         TestLockExpiration
      Messages:     write requests count after limiter close must be 0

This is probably related to (or is a regression of) #788.

My intuition says that the flakiness might be caused by running tests in parallel:

	`func TestLockExpiration(t *testing.T) {`
	`t.Parallel()`

	`func TestLockUserScenario(t *testing.T) {`
	`t.Parallel()`

To confirm my intuition I've ran a 1000 repetitions of TestLockExpiration and a 1000 repetitions of the full test suite. Without parallel tests TestLockExpiration didn't fail and with parallel tests the expected error occured long before 1000 iterations (same error although in another test case, TestLockUserScenario). Here are both runs (beware that second log is 600MB+, don't click "View full" in Firefox - download to a local file). This is by no means an exhaustive evidence, but I think this hunch warrants further investigation.

I'm not sure if the particular test cases just should not be parallelized or it's a sign of some deeper underlying problem, so I'm bringing it here.

I've noticed that one of our tests is flaky: [example A](https://ci.frostfs.info/job/gerrit/job/frostfs-node/163/pipeline-console/?start-byte=0&selected-node=124#log-215), [example B](https://ci.frostfs.info/job/gerrit/job/frostfs-node/189/pipeline-console/?selected-node=18). Crash happens [here](https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/12a0537a7a9f5af0b4c2bd20f1d5b9f1891897d4/pkg/local_object_storage/engine/engine_test.go#L167-L170), this method is being called from several test cases: `TestLockExpiration`, `TestLockUserScenario`, probably others. https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/12a0537a7a9f5af0b4c2bd20f1d5b9f1891897d4/pkg/local_object_storage/engine/engine_test.go#L167-L170 Test failure looks like this: ``` engine_test.go:169: Error Trace: ./pkg/local_object_storage/engine/engine_test.go:169 ./pkg/local_object_storage/shard/control.go:399 ./pkg/local_object_storage/engine/control.go:161 ./pkg/local_object_storage/engine/control.go:210 ./pkg/local_object_storage/engine/control.go:152 ./pkg/local_object_storage/engine/lock_test.go:166 ./pkg/local_object_storage/engine/lock_test.go:218 Error: Not equal: expected: 0 actual : 1 Test: TestLockExpiration Messages: write requests count after limiter close must be 0 ``` This is probably related to (or is a regression of) #788. My intuition says that the flakiness might be caused by running tests in parallel: https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/12a0537a7a9f5af0b4c2bd20f1d5b9f1891897d4/pkg/local_object_storage/engine/lock_test.go#L144-L145 https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/12a0537a7a9f5af0b4c2bd20f1d5b9f1891897d4/pkg/local_object_storage/engine/lock_test.go#L32-L33 To confirm my intuition I've ran a 1000 repetitions of `TestLockExpiration` and a 1000 repetitions of the full test suite. Without parallel tests `TestLockExpiration` didn't fail and with parallel tests the expected error occured long before 1000 iterations (same error although in another test case, `TestLockUserScenario`). [Here are both runs](https://ci.frostfs.info/job/gerrit/job/frostfs-node/198/) (beware that second log is 600MB+, don't click "View full" in Firefox - download to a local file). This is by no means an exhaustive evidence, but I think this hunch warrants further investigation. I'm not sure if the particular test cases just should not be parallelized or it's a sign of some deeper underlying problem, so I'm bringing it here.

potyarkin added the

bug

help wanted

labels 2025-03-31 16:18:11 +00:00

a-savchuk commented

2025-03-31 17:09:26 +00:00

Member

My intuition says that the flakiness might be caused by running tests in parallel:

To confirm my intuition I've ran a 1000 repetitions of TestLockExpiration and a 1000 repetitions of the full test suite. Without parallel tests TestLockExpiration didn't fail and with parallel tests the expected error occured long before 1000 iterations (same error although in another test case, TestLockUserScenario)

That's interesting. Each test uses its own engine instance, so they shouldn't affect each other, but your experiment says otherwise.

> My intuition says that the flakiness might be caused by running tests in parallel: > To confirm my intuition I've ran a 1000 repetitions of TestLockExpiration and a 1000 repetitions of the full test suite. Without parallel tests TestLockExpiration didn't fail and with parallel tests the expected error occured long before 1000 iterations (same error although in another test case, TestLockUserScenario) That's interesting. Each test uses its own engine instance, so they shouldn't affect each other, but your experiment says otherwise.

fyrchik added the

label 2025-03-31 17:43:30 +00:00

dstepanov-yadro was assigned by fyrchik

2025-03-31 17:43:38 +00:00

fyrchik added this to the v0.45.0 milestone 2025-03-31 17:43:40 +00:00

potyarkin commented

2025-04-01 07:22:00 +00:00

Author

Member

My experiment is circumstantial evidence at best. There is a non-negligible possibility that my intuition is wrong.

snegurochka referenced this issue from a commit

2025-04-01 11:37:38 +00:00

[#1700] engine: Print stacks on test request limiter

snegurochka referenced this issue from a commit

2025-04-01 11:40:55 +00:00

[#1700] gc: Drop Event interface

snegurochka referenced this issue from a commit

2025-04-01 11:40:55 +00:00

[#1700] gc: Take mode mutex in locks handlers

snegurochka referenced this issue from a commit

2025-04-01 13:15:14 +00:00

[#1700] gc: Wait for handlers on GC stopping

dstepanov-yadro closed this issue

2025-04-01 13:15:33 +00:00

dstepanov-yadro reopened this issue

2025-04-10 14:59:48 +00:00

dstepanov-yadro commented

2025-04-10 15:01:16 +00:00

Member

It comes again:

[2025-04-10T14:51:12.857Z] --- FAIL: TestLockUserScenario (9.80s)
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:53.079Z	DEBUG	metabase/control.go:60	created directory for Metabase	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "path": "/tmp/TestLockUserScenario207741622/003/metabase"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:53.211Z	DEBUG	metabase/control.go:81	opened boltDB instance for Metabase	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:53.211Z	DEBUG	metabase/control.go:83	checking metabase version	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:54.131Z	DEBUG	metabase/control.go:60	created directory for Metabase	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "path": "/tmp/TestLockUserScenario207741622/006/metabase"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:54.853Z	DEBUG	metabase/control.go:81	opened boltDB instance for Metabase	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:54.853Z	DEBUG	metabase/control.go:83	checking metabase version	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.899Z	DEBUG	blobstor/control.go:15	opening...	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.899Z	DEBUG	metabase/control.go:60	created directory for Metabase	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "path": "/tmp/TestLockUserScenario207741622/006/metabase"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.899Z	DEBUG	metabase/control.go:81	opened boltDB instance for Metabase	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.899Z	DEBUG	metabase/control.go:83	checking metabase version	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.900Z	DEBUG	blobstor/control.go:15	opening...	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.900Z	DEBUG	metabase/control.go:60	created directory for Metabase	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "path": "/tmp/TestLockUserScenario207741622/003/metabase"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.900Z	DEBUG	metabase/control.go:81	opened boltDB instance for Metabase	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.900Z	DEBUG	metabase/control.go:83	checking metabase version	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.976Z	DEBUG	blobstor/control.go:54	initializing...	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.976Z	DEBUG	blobovniczatree/control.go:27	initializing Blobovnicza's
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.977Z	DEBUG	blobstor/control.go:54	initializing...	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:56.977Z	DEBUG	blobovniczatree/control.go:27	initializing Blobovnicza's
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.851Z	DEBUG	blobovnicza/control.go:27	creating directory for BoltDB	{"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/001/blobovnicza/0/0.db", "ro": false}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.851Z	DEBUG	blobovnicza/control.go:41	opening BoltDB	{"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/001/blobovnicza/0/0.db", "permissions": "-rwxrwxrwx"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:67	initializing...	{"component": "Blobovnicza", "object size limit": 1048576, "storage size limit": 1073741824}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[0:32768]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[32769:65536]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[65537:131072]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[131073:262144]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[262145:524288]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:57.920Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[524289:1048576]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:58.193Z	DEBUG	blobovnicza/control.go:135	saving counters to blobovnicza's meta...	{"component": "Blobovnicza", "size": 0, "items": 0}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:58.878Z	DEBUG	blobovnicza/control.go:145	saving counters to blobovnicza's meta completed successfully	{"component": "Blobovnicza", "size": 0, "items": 0}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:58.959Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.008Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "metabase PUT"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.049Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.101Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase PUT"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.890Z	DEBUG	blobovnicza/control.go:27	creating directory for BoltDB	{"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db", "ro": false}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.890Z	DEBUG	blobovnicza/control.go:41	opening BoltDB	{"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db", "permissions": "-rwxrwxrwx"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:67	initializing...	{"component": "Blobovnicza", "object size limit": 1048576, "storage size limit": 1073741824}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[0:32768]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[32769:65536]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[65537:131072]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[131073:262144]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[262145:524288]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:47:59.953Z	DEBUG	blobovnicza/control.go:85	creating bucket for size range	{"component": "Blobovnicza", "range": "[524289:1048576]"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.158Z	DEBUG	blobovnicza/control.go:135	saving counters to blobovnicza's meta...	{"component": "Blobovnicza", "size": 0, "items": 0}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.203Z	DEBUG	blobovnicza/control.go:145	saving counters to blobovnicza's meta completed successfully	{"component": "Blobovnicza", "size": 0, "items": 0}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.906Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/3mDp6z1o1nvrKP3XaqX12sNPa9c4xGiL4ysekz3PUjPU", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.967Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/3mDp6z1o1nvrKP3XaqX12sNPa9c4xGiL4ysekz3PUjPU", "op": "metabase PUT"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:765	collecting expired metrics started	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:770	collecting expired metrics completed	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:765	collecting expired metrics started	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:770	collecting expired metrics completed	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:539	collecting expired locks started	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:582	collecting expired locks completed	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:336	collecting expired objects started	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:378	collecting expired objects completed	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.987Z	DEBUG	shard/gc.go:462	started expired tombstones handling	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:481	iterating tombstones	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:529	finished expired tombstones handling	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:539	collecting expired locks started	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:336	collecting expired objects started	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:378	collecting expired objects completed	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:462	started expired tombstones handling	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:481	iterating tombstones	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:00.988Z	DEBUG	shard/gc.go:529	finished expired tombstones handling	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:01.907Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase INHUME", "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.832Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "metabase INHUME"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.832Z	INFO	shard/rebuild.go:117	blobstore rebuild stopped	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.832Z	DEBUG	blobstor/control.go:71	closing...	{"shard_id": "732pT6fHcACHXJHhkMM9cu"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.832Z	DEBUG	blobovnicza/control.go:166	closing BoltDB	{"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.881Z	INFO	shard/gc.go:228	waiting for GC workers to stop...
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.881Z	DEBUG	shard/gc.go:187	GC is stopped	{"io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.881Z	WARN	shard/gc.go:131	stop event listener by closed `stop` channel	{"io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.881Z	DEBUG	log/log.go:13	local object storage operation	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase INHUME", "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     engine_test.go:186: 
[2025-04-10T14:51:12.857Z]         	Error Trace:	/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/engine_test.go:186
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/control.go:397
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:161
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:210
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:152
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/lock_test.go:63
[2025-04-10T14:51:12.857Z]         	            				/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/lock_test.go:142
[2025-04-10T14:51:12.857Z]         	Error:      	Should be true
[2025-04-10T14:51:12.857Z]         	Test:       	TestLockUserScenario
[2025-04-10T14:51:12.857Z]         	Messages:   	1
[2025-04-10T14:51:12.857Z]         	            	 write request stack after limiter close: goroutine 1859 [running]:
[2025-04-10T14:51:12.857Z]         	            	runtime/debug.Stack()
[2025-04-10T14:51:12.857Z]         	            		/usr/local/go/src/runtime/debug/stack.go:26 +0x5e
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*testQoSLimiter).WriteRequest(0xc0007a4b70, {0xc00051af40?, 0x1?})
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/engine_test.go:215 +0x85
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).HandleExpiredLocks(0xc000032600, {0x10ffef8, 0xc000752870}, 0xe, {0xc00051af40, 0x1, 0x1})
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/gc.go:693 +0x506
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).processExpiredLocks-fm.(*StorageEngine).processExpiredLocks.func1({{0xc00039a588?, 0xc000032600?}, 0xc00064e080?})
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/inhume.go:288 +0x65
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).iterateOverUnsortedShards(0xe?, 0xc00075ded8)
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/shards.go:293 +0x52
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).processExpiredLocks(...)
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/inhume.go:287
[2025-04-10T14:51:12.857Z]         	            	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).collectExpiredLocks.func2.1.1()
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/gc.go:557 +0x44
[2025-04-10T14:51:12.857Z]         	            	golang.org/x/sync/errgroup.(*Group).Go.func1()
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/go/mod/golang.org/x/sync@v0.10.0/errgroup/errgroup.go:78 +0x50
[2025-04-10T14:51:12.857Z]         	            	created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 1858
[2025-04-10T14:51:12.857Z]         	            		/var/cache/jenkins-agent/go/mod/golang.org/x/sync@v0.10.0/errgroup/errgroup.go:75 +0x93
[2025-04-10T14:51:12.857Z]         	            	
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.882Z	WARN	shard/gc.go:723	failure to get expired unlocked objects	{"shard_id": "732pT6fHcACHXJHhkMM9cu", "error": "database not open", "io_tag": "background"}
[2025-04-10T14:51:12.857Z]     logger.go:146: 2025-04-10T14:48:02.882Z	DEBUG	shard/gc.go:582	collecting expired locks completed	{"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"}
[2025-04-10T14:51:12.857Z] FAIL
[2025-04-10T14:51:12.857Z] FAIL	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine	163.000s

It comes again: ``` [2025-04-10T14:51:12.857Z] --- FAIL: TestLockUserScenario (9.80s) [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:53.079Z DEBUG metabase/control.go:60 created directory for Metabase {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "path": "/tmp/TestLockUserScenario207741622/003/metabase"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:53.211Z DEBUG metabase/control.go:81 opened boltDB instance for Metabase {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:53.211Z DEBUG metabase/control.go:83 checking metabase version {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:54.131Z DEBUG metabase/control.go:60 created directory for Metabase {"shard_id": "732pT6fHcACHXJHhkMM9cu", "path": "/tmp/TestLockUserScenario207741622/006/metabase"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:54.853Z DEBUG metabase/control.go:81 opened boltDB instance for Metabase {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:54.853Z DEBUG metabase/control.go:83 checking metabase version {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.899Z DEBUG blobstor/control.go:15 opening... {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.899Z DEBUG metabase/control.go:60 created directory for Metabase {"shard_id": "732pT6fHcACHXJHhkMM9cu", "path": "/tmp/TestLockUserScenario207741622/006/metabase"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.899Z DEBUG metabase/control.go:81 opened boltDB instance for Metabase {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.899Z DEBUG metabase/control.go:83 checking metabase version {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.900Z DEBUG blobstor/control.go:15 opening... {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.900Z DEBUG metabase/control.go:60 created directory for Metabase {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "path": "/tmp/TestLockUserScenario207741622/003/metabase"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.900Z DEBUG metabase/control.go:81 opened boltDB instance for Metabase {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.900Z DEBUG metabase/control.go:83 checking metabase version {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.976Z DEBUG blobstor/control.go:54 initializing... {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.976Z DEBUG blobovniczatree/control.go:27 initializing Blobovnicza's [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.977Z DEBUG blobstor/control.go:54 initializing... {"shard_id": "KQQrW8QjSJfENVhoFV3kYd"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:56.977Z DEBUG blobovniczatree/control.go:27 initializing Blobovnicza's [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.851Z DEBUG blobovnicza/control.go:27 creating directory for BoltDB {"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/001/blobovnicza/0/0.db", "ro": false} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.851Z DEBUG blobovnicza/control.go:41 opening BoltDB {"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/001/blobovnicza/0/0.db", "permissions": "-rwxrwxrwx"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:67 initializing... {"component": "Blobovnicza", "object size limit": 1048576, "storage size limit": 1073741824} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[0:32768]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[32769:65536]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[65537:131072]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[131073:262144]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[262145:524288]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:57.920Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[524289:1048576]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:58.193Z DEBUG blobovnicza/control.go:135 saving counters to blobovnicza's meta... {"component": "Blobovnicza", "size": 0, "items": 0} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:58.878Z DEBUG blobovnicza/control.go:145 saving counters to blobovnicza's meta completed successfully {"component": "Blobovnicza", "size": 0, "items": 0} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:58.959Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.008Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "metabase PUT"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.049Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.101Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase PUT"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.890Z DEBUG blobovnicza/control.go:27 creating directory for BoltDB {"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db", "ro": false} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.890Z DEBUG blobovnicza/control.go:41 opening BoltDB {"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db", "permissions": "-rwxrwxrwx"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:67 initializing... {"component": "Blobovnicza", "object size limit": 1048576, "storage size limit": 1073741824} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[0:32768]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[32769:65536]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[65537:131072]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[131073:262144]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[262145:524288]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:47:59.953Z DEBUG blobovnicza/control.go:85 creating bucket for size range {"component": "Blobovnicza", "range": "[524289:1048576]"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.158Z DEBUG blobovnicza/control.go:135 saving counters to blobovnicza's meta... {"component": "Blobovnicza", "size": 0, "items": 0} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.203Z DEBUG blobovnicza/control.go:145 saving counters to blobovnicza's meta completed successfully {"component": "Blobovnicza", "size": 0, "items": 0} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.906Z DEBUG log/log.go:13 local object storage operation {"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/3mDp6z1o1nvrKP3XaqX12sNPa9c4xGiL4ysekz3PUjPU", "op": "PUT", "type": "blobovnicza", "storage_id": "0/0"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.967Z DEBUG log/log.go:13 local object storage operation {"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/3mDp6z1o1nvrKP3XaqX12sNPa9c4xGiL4ysekz3PUjPU", "op": "metabase PUT"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:765 collecting expired metrics started {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:770 collecting expired metrics completed {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:765 collecting expired metrics started {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:770 collecting expired metrics completed {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:539 collecting expired locks started {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:582 collecting expired locks completed {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:336 collecting expired objects started {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:378 collecting expired objects completed {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.987Z DEBUG shard/gc.go:462 started expired tombstones handling {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:481 iterating tombstones {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:529 finished expired tombstones handling {"shard_id": "732pT6fHcACHXJHhkMM9cu", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:539 collecting expired locks started {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:336 collecting expired objects started {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:378 collecting expired objects completed {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:462 started expired tombstones handling {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:481 iterating tombstones {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:00.988Z DEBUG shard/gc.go:529 finished expired tombstones handling {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:01.907Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase INHUME", "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.832Z DEBUG log/log.go:13 local object storage operation {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/35Nd7cL9u4zeaJCpVBbfW9uNKMTzVcTY7GVgtwGWRMW7", "op": "metabase INHUME"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.832Z INFO shard/rebuild.go:117 blobstore rebuild stopped {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.832Z DEBUG blobstor/control.go:71 closing... {"shard_id": "732pT6fHcACHXJHhkMM9cu"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.832Z DEBUG blobovnicza/control.go:166 closing BoltDB {"component": "Blobovnicza", "path": "/tmp/TestLockUserScenario207741622/004/blobovnicza/0/0.db"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.881Z INFO shard/gc.go:228 waiting for GC workers to stop... [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.881Z DEBUG shard/gc.go:187 GC is stopped {"io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.881Z WARN shard/gc.go:131 stop event listener by closed `stop` channel {"io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.881Z DEBUG log/log.go:13 local object storage operation {"shard_id": "732pT6fHcACHXJHhkMM9cu", "address": "HN4FqmVorLSxoWhJxwDvR33JXBdHLgQZBTFXbqZyS5cW/2c35MSqHQhadeTMUm1Urv6JCinbeQhet99JVPKZktXr4", "op": "metabase INHUME", "io_tag": "background"} [2025-04-10T14:51:12.857Z] engine_test.go:186: [2025-04-10T14:51:12.857Z] Error Trace: /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/engine_test.go:186 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/control.go:397 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:161 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:210 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/control.go:152 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/lock_test.go:63 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/lock_test.go:142 [2025-04-10T14:51:12.857Z] Error: Should be true [2025-04-10T14:51:12.857Z] Test: TestLockUserScenario [2025-04-10T14:51:12.857Z] Messages: 1 [2025-04-10T14:51:12.857Z] write request stack after limiter close: goroutine 1859 [running]: [2025-04-10T14:51:12.857Z] runtime/debug.Stack() [2025-04-10T14:51:12.857Z] /usr/local/go/src/runtime/debug/stack.go:26 +0x5e [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*testQoSLimiter).WriteRequest(0xc0007a4b70, {0xc00051af40?, 0x1?}) [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/engine_test.go:215 +0x85 [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).HandleExpiredLocks(0xc000032600, {0x10ffef8, 0xc000752870}, 0xe, {0xc00051af40, 0x1, 0x1}) [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/gc.go:693 +0x506 [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).processExpiredLocks-fm.(*StorageEngine).processExpiredLocks.func1({{0xc00039a588?, 0xc000032600?}, 0xc00064e080?}) [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/inhume.go:288 +0x65 [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).iterateOverUnsortedShards(0xe?, 0xc00075ded8) [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/shards.go:293 +0x52 [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).processExpiredLocks(...) [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/engine/inhume.go:287 [2025-04-10T14:51:12.857Z] git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).collectExpiredLocks.func2.1.1() [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/workspace/gerrit/frostfs-node#527-5e9734-57435d/pkg/local_object_storage/shard/gc.go:557 +0x44 [2025-04-10T14:51:12.857Z] golang.org/x/sync/errgroup.(*Group).Go.func1() [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/go/mod/golang.org/x/sync@v0.10.0/errgroup/errgroup.go:78 +0x50 [2025-04-10T14:51:12.857Z] created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 1858 [2025-04-10T14:51:12.857Z] /var/cache/jenkins-agent/go/mod/golang.org/x/sync@v0.10.0/errgroup/errgroup.go:75 +0x93 [2025-04-10T14:51:12.857Z] [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.882Z WARN shard/gc.go:723 failure to get expired unlocked objects {"shard_id": "732pT6fHcACHXJHhkMM9cu", "error": "database not open", "io_tag": "background"} [2025-04-10T14:51:12.857Z] logger.go:146: 2025-04-10T14:48:02.882Z DEBUG shard/gc.go:582 collecting expired locks completed {"shard_id": "KQQrW8QjSJfENVhoFV3kYd", "epoch": 14, "io_tag": "background"} [2025-04-10T14:51:12.857Z] FAIL [2025-04-10T14:51:12.857Z] FAIL git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine 163.000s

snegurochka referenced this issue from a commit

2025-04-14 12:03:37 +00:00

[#1700] config: Move config struct to qos package

snegurochka referenced this issue from a commit

2025-04-14 12:03:37 +00:00

[#1700] config: Drop redundant check

snegurochka referenced this issue from a commit

2025-04-14 12:05:16 +00:00

[#1700] engine: Drop unused block execution methods

snegurochka referenced this issue from a commit

2025-04-14 12:06:03 +00:00

[#1700] shard: Lock shard's mode mutex on close