Command `object hash range` returned `object not found`

anikeev-yadro commented

2023-12-28 11:08:58 +00:00

Member

Expected Behavior

Command object hash range should return hash on object range

Current Behavior

Command object hash range returned object not found

Steps to Reproduce (for bugs)

1.Create container

COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml container create --rpc-endpoint '10.78.130.135:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --await --policy 'REP 2 IN X CBF 1 SELECT 4 FROM * AS X'
RETCODE: 0

STDOUT:
container ID: FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj
awaiting...
container has been persisted on sidechain

STDERR:

Start / End / Elapsed	 08:09:56.971663 / 08:10:02.379764 / 0:00:05.408101

2.Put object

COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml object put --rpc-endpoint '10.78.130.144:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --cid 'FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj' --file 'TemporaryDir/e1d981b5-fefc-4145-98f6-627f5b4ffc77' --no-progress
RETCODE: 0

STDOUT:
[TemporaryDir/e1d981b5-fefc-4145-98f6-627f5b4ffc77] Object successfully stored
  OID: 6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM
  CID: FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj

STDERR:

Start / End / Elapsed	 08:10:02.769914 / 08:10:03.209652 / 0:00:00.439738

3.Try to get hash of object range

COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml object hash --rpc-endpoint '10.78.130.135:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --cid 'FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj' --oid '6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM' --range '0:250'
RETCODE: 1

STDOUT:
rpc error: read payload hashes via client: status: code = 2049 message = object not found

STDERR:

Start / End / Elapsed	 08:11:47.917467 / 08:11:48.349309 / 0:00:00.431842

4.In the logs we saw the following messages about this OID.

дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.308Z        debug        get/get.go:88        serving request...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z        debug        get/local.go:33        local get failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z        debug        get/get.go:109        operation finished with error        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z        debug        get/container.go:19        trying to execute in container...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "netmap lookup depth": 0}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z        debug        get/container.go:47        process epoch        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "number": 239}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z        debug        get/remote.go:19        processing node...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.316Z        debug        get/remote.go:37        remote call failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.316Z        debug        get/remote.go:19        processing node...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.324Z        debug        get/remote.go:37        remote call failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.325Z        debug        get/remote.go:19        processing node...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.336Z        debug        get/remote.go:37        remote call failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.336Z        debug        get/remote.go:19        processing node...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z        debug        get/remote.go:37        remote call failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z        debug        get/container.go:64        no more nodes, abort placement iteration        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z        debug        get/get.go:109        operation finished with error        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"}

дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.604Z        debug        get/get.go:88        serving request...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z        debug        get/local.go:33        local get failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z        debug        get/get.go:109        operation finished with error        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z        debug        get/container.go:19        trying to execute in container...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "netmap lookup depth": 0}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z        debug        get/container.go:47        process epoch        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "number": 239}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.607Z        debug        get/remote.go:19        processing node...        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.611Z        debug        get/container.go:88        completing the operation        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}
дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.611Z        debug        get/get.go:100        operation finished successfully        {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false}

Context

Autotest testsuites.object.test_object_api.TestObjectApi#test_object_get_range_hash.
Test was success on 4 nodes systems on cloud and HW.

Regression

No

Version

FrostFS Storage node
Version: v0.37.0-25-ge39db638
GoVersion: go1.20.5

Your Environment

32 nodes
cloud

## Expected Behavior Command `object hash range` should return hash on object range ## Current Behavior Command `object hash range` returned `object not found` ## Steps to Reproduce (for bugs) 1.Create container ``` COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml container create --rpc-endpoint '10.78.130.135:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --await --policy 'REP 2 IN X CBF 1 SELECT 4 FROM * AS X' RETCODE: 0 STDOUT: container ID: FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj awaiting... container has been persisted on sidechain STDERR: Start / End / Elapsed 08:09:56.971663 / 08:10:02.379764 / 0:00:05.408101 ``` 2.Put object ``` COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml object put --rpc-endpoint '10.78.130.144:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --cid 'FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj' --file 'TemporaryDir/e1d981b5-fefc-4145-98f6-627f5b4ffc77' --no-progress RETCODE: 0 STDOUT: [TemporaryDir/e1d981b5-fefc-4145-98f6-627f5b4ffc77] Object successfully stored OID: 6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM CID: FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj STDERR: Start / End / Elapsed 08:10:02.769914 / 08:10:03.209652 / 0:00:00.439738 ``` 3.Try to get hash of object range ``` COMMAND: frostfs-cli --config /jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/wallet_config.yml object hash --rpc-endpoint '10.78.130.135:8080' --wallet '/jenkins/workspace/release_v1.5_sbercloud_tatlin_object_test/tmp.IwNaHU1OOz/frostfs-testcases/TemporaryDir/f2ac42ff-9940-438f-a5d1-2d19b0b95e75.json' --cid 'FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj' --oid '6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM' --range '0:250' RETCODE: 1 STDOUT: rpc error: read payload hashes via client: status: code = 2049 message = object not found STDERR: Start / End / Elapsed 08:11:47.917467 / 08:11:48.349309 / 0:00:00.431842 ``` 4.In the logs we saw the following messages about this OID. ``` дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.308Z debug get/get.go:88 serving request... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z debug get/local.go:33 local get failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z debug get/get.go:109 operation finished with error {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z debug get/container.go:19 trying to execute in container... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "netmap lookup depth": 0} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z debug get/container.go:47 process epoch {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "number": 239} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.309Z debug get/remote.go:19 processing node... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.316Z debug get/remote.go:37 remote call failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.316Z debug get/remote.go:19 processing node... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.324Z debug get/remote.go:37 remote call failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.325Z debug get/remote.go:19 processing node... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.336Z debug get/remote.go:37 remote call failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.336Z debug get/remote.go:19 processing node... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z debug get/remote.go:37 remote call failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z debug get/container.go:64 no more nodes, abort placement iteration {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:11:48 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:11:48.345Z debug get/get.go:109 operation finished with error {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"} ``` ``` дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.604Z debug get/get.go:88 serving request... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z debug get/local.go:33 local get failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z debug get/get.go:109 operation finished with error {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "status: code = 2049 message = object not found"} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z debug get/container.go:19 trying to execute in container... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "netmap lookup depth": 0} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.606Z debug get/container.go:47 process epoch {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false, "number": 239} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.607Z debug get/remote.go:19 processing node... {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.611Z debug get/container.go:88 completing the operation {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 08:12:01 dkarmanov-node1 frostfs-node[954155]: 2023-12-28T08:12:01.611Z debug get/get.go:100 operation finished successfully {"component": "Object.Get service", "request": "GET_RANGE", "address": "FyvrBG7dXrLQvpxoR3umQvSsp1SnDFXXSJgCxTPTrqEj/6aFyDygLvsC4ZpKHJN54Xc9ZRv2gDCTR3SSH1crRjuBM", "raw": false, "local": false, "with session": false, "with bearer": false} ``` ## Context Autotest `testsuites.object.test_object_api.TestObjectApi#test_object_get_range_hash`. Test was success on 4 nodes systems on cloud and HW. ## Regression No ## Version ``` FrostFS Storage node Version: v0.37.0-25-ge39db638 GoVersion: go1.20.5 ``` ## Your Environment 32 nodes cloud

anikeev-yadro added the

bug

triage

labels 2023-12-28 11:08:58 +00:00

dstepanov-yadro commented

2023-12-28 12:50:51 +00:00

Member

Reproduced on 32 node cluster:

#!/bin/bash

set -euxo pipefail

cid=$(frostfs-cli container create -r localhost:8080 --wallet ./wallet.json --policy "REP 2 IN X CBF 1 SELECT 4 FROM * AS X" --config empty_pass.yml --await | grep 'container ID:' | awk '{ print $3 }')

oid=$(frostfs-cli object put -r localhost:8080 --wallet ./wallet.json --file ./8KB.bin --config empty_pass.yml --cid $cid --no-progress | grep 'OID:' | awk '{ print $2 }')

frostfs-cli object head -r localhost:8080 --wallet ./wallet.json --config empty_pass.yml --cid $cid --oid $oid --raw

frostfs-cli object hash -r localhost:8080 --wallet ./wallet.json --config empty_pass.yml --cid $cid --oid $oid --range '0:250

Reproduced on 32 node cluster: ``` #!/bin/bash set -euxo pipefail cid=$(frostfs-cli container create -r localhost:8080 --wallet ./wallet.json --policy "REP 2 IN X CBF 1 SELECT 4 FROM * AS X" --config empty_pass.yml --await | grep 'container ID:' | awk '{ print $3 }') oid=$(frostfs-cli object put -r localhost:8080 --wallet ./wallet.json --file ./8KB.bin --config empty_pass.yml --cid $cid --no-progress | grep 'OID:' | awk '{ print $2 }') frostfs-cli object head -r localhost:8080 --wallet ./wallet.json --config empty_pass.yml --cid $cid --oid $oid --raw frostfs-cli object hash -r localhost:8080 --wallet ./wallet.json --config empty_pass.yml --cid $cid --oid $oid --range '0:250 ```

dstepanov-yadro commented

2023-12-28 13:15:27 +00:00

Member

I added some extra logs:

func (r *request) getRemote(ctx context.Context, rs remoteStorage, info client.NodeInfo) (*objectSDK.Object, error) {
	key, err := r.key()
	if err != nil {
		return nil, err
	}

	var idOwner user.ID
	user.IDFromKey(&idOwner, key.PublicKey)
	r.log.Logger.Info("user id", zap.Stringer("pk", idOwner))

	if r.isForwardingEnabled() {
		r.log.Logger.Info("forwarding enabled")
		return rs.ForwardRequest(ctx, info, r.prm.forwarder)
	}
	r.log.Logger.Info("forwarding disabled")

Looks like HEAD request executed with owner's signature:

дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.049Z        info        get/remote.go:76        forwarding enabled        {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false}

дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.056Z        debug        get/container.go:88        completing the operation        {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false}

дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.056Z        debug        get/get.go:100        operation finished successfully        {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false}

But GET_RANGE request executed with node's signature:

дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.736Z        info        get/remote.go:79        forwarding disabled        {"component": "Object.Get service", "request": "GET_RANGE", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": false, "local": false, "with session": false, "with bearer": false}

дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.744Z        debug        get/remote.go:38        remote call failed        {"component": "Object.Get service", "request": "GET_RANGE", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"}

I added some extra logs: ``` func (r *request) getRemote(ctx context.Context, rs remoteStorage, info client.NodeInfo) (*objectSDK.Object, error) { key, err := r.key() if err != nil { return nil, err } var idOwner user.ID user.IDFromKey(&idOwner, key.PublicKey) r.log.Logger.Info("user id", zap.Stringer("pk", idOwner)) if r.isForwardingEnabled() { r.log.Logger.Info("forwarding enabled") return rs.ForwardRequest(ctx, info, r.prm.forwarder) } r.log.Logger.Info("forwarding disabled") ``` Looks like HEAD request executed with owner's signature: ``` дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.049Z info get/remote.go:76 forwarding enabled {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false} дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.056Z debug get/container.go:88 completing the operation {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false} дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.056Z debug get/get.go:100 operation finished successfully {"component": "Object.Get service", "request": "HEAD", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": true, "local": false, "with session": false, "with bearer": false} ``` But GET_RANGE request executed with node's signature: ``` дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.736Z info get/remote.go:79 forwarding disabled {"component": "Object.Get service", "request": "GET_RANGE", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": false, "local": false, "with session": false, "with bearer": false} дек 28 13:10:59 dkarmanov-node1 frostfs-node[3635536]: 2023-12-28T13:10:59.744Z debug get/remote.go:38 remote call failed {"component": "Object.Get service", "request": "GET_RANGE", "address": "8AAN38FQfoKQtdsKivZfFF3f8SawCkYg6Dwtpt86muAZ/EJFTRGviSgEfC4XEa1NSc6tJPeJAAZxmQpTGsJbSSLWU", "raw": false, "local": false, "with session": false, "with bearer": false, "error": "read object header: status: code = 2048 message = access to object operation denied"} ```

fyrchik commented

2023-12-29 05:28:32 +00:00

Owner

For get_range it is expected: we create a new request if an object is missing locally, because GetRange request is allowed to contain multiple ranges, each of which may be redirected to a different node.

For `get_range` it is expected: we _create_ a new request if an object is missing locally, because `GetRange` request is allowed to contain multiple ranges, each of which may be redirected to a different node.

dstepanov-yadro commented

2023-12-29 09:32:05 +00:00

Member

But from user's POV it looks strange: user can download object, but can't get range hash