[BUG] Can't modify account metadata even if there is a role with corresponding permission

[Arjentix]

GIT commit hash

7e0ab9f

Minimum working example

The bug was originally found by @arndey in iroha-java using lts docker image.

This is the edited version of our already existed test:

#[test]
fn register_and_grant_role_for_metadata_access() -> Result<()> {
    let (_rt, _peer, test_client) = <PeerBuilder>::new().start_with_runtime();
    wait_for_genesis_committed(&vec![test_client.clone()], 0);

    let alice_id = <Account as Identifiable>::Id::from_str("alice@wonderland")?;
    let mouse_id = <Account as Identifiable>::Id::from_str("mouse@wonderland")?;

    let register_mouse = RegisterBox::new(Account::new(mouse_id.clone(), []));
    test_client.submit_blocking(register_mouse)?;

    let role_id = <Role as Identifiable>::Id::from_str("USER_METADATA_ACCESS")?;
    let role = iroha_data_model::role::Role::new(role_id.clone())
        .add_permission(CanSetKeyValueInUserMetadata::new(alice_id.clone()))
        .add_permission(CanRemoveKeyValueInUserMetadata::new(alice_id));
    let register_role = RegisterBox::new(role);
    test_client.submit_blocking(register_role)?;

    let grant_role = GrantBox::new(role_id.clone(), mouse_id.clone());
    test_client.submit_blocking(grant_role)?;

    // NEW ===
    let set_key_value = SetKeyValueBox::new(
        mouse_id.clone(),
        Name::from_str("key").expect("Valid"),
        Value::String("value".to_owned()),
    );
    test_client.submit_blocking(set_key_value)?;
    // ===

    let found_role_ids = test_client.request(client::role::by_account_id(mouse_id))?;
    assert!(found_role_ids.contains(&role_id));

    Ok(())
}

Expected behaviour

alice can modify mouse metadata

Actual behaviour

alice cannot modify mouse metadata. The error

Operating system

MacOs on M1 mac

LibC type and version

No response

Current environment

Source code build

Logs in JSON format

Not a JSON, but that's enough to show the problem.
Sorry for a wrong format, but I'm going to fix this bug by my own hands, so I can't see a reason to provide meaningless logs

cargo test --package iroha_client --test mod -- integration::roles::register_and_grant_role_for_metadata_access --exact --nocapture 

    Blocking waiting for file lock on build directory
   Compiling iroha_client v2.0.0-pre-rc.5 (/Volumes/Development/Projects/Soramitsu/iroha/client)
   Compiling test_network v2.0.0-pre-rc.5 (/Volumes/Development/Projects/Soramitsu/iroha/core/test_network)
    Finished test [unoptimized + debuginfo] target(s) in 8.43s
     Running tests/mod.rs (target/debug/deps/mod-3da4e71ac8599d6d)

running 1 test
2022-07-13T13:54:43.830170Z  INFO iroha: Starting peer listen_addr=127.0.0.1:1024
2022-07-13T13:54:43.830257Z  INFO iroha_p2p::network: Binding listener listen_addr=127.0.0.1:1024
2022-07-13T13:54:43.830624Z  INFO iroha_p2p::network: Starting network actor listen_addr=127.0.0.1:1024
2022-07-13T13:54:43.837124Z  INFO iroha_core::kura: Loaded 0 blocks at init.
2022-07-13T13:54:43.837876Z  INFO iroha_core::sumeragi::fault: Starting Sumeragi
2022-07-13T13:54:43.837972Z  INFO iroha: Starting Iroha as task
2022-07-13T13:54:43.838079Z  INFO iroha_core::genesis: Waiting for active peers
2022-07-13T13:54:43.838183Z  INFO iroha_core::genesis: Peers status peer_count=0
2022-07-13T13:54:43.838208Z  INFO iroha_core::genesis: Waiting for active peers finished.
2022-07-13T13:54:43.838218Z  INFO iroha_core::genesis: Got topology
2022-07-13T13:54:44.840370Z  INFO iroha_core::genesis: Initializing iroha using the genesis block.
2022-07-13T13:54:44.840753Z  INFO start_genesis_round: iroha_core::sumeragi::fault: Validating block block_hash=15de38811783d01f85166efede33ebfcf357c2503c9a043b7cb9f621072b7ce4
2022-07-13T13:54:44.841352Z  INFO start_genesis_round: iroha_core::sumeragi::fault: Using network topology from genesis block
2022-07-13T13:54:44.841402Z  INFO start_genesis_round: iroha_core::sumeragi::fault: Created a block peer_role=Leader block_hash=1127181da89920790486bbfe276524cba5f99d639a83f138c587cb06a51129b9
2022-07-13T13:54:44.843740Z  INFO start_genesis_round:commit_block: iroha_core::sumeragi::fault: Committing block prev_peer_role=Leader new_peer_role=Leader new_block_height=1 block_hash=1127181da89920790486bbfe276524cba5f99d639a83f138c587cb06a51129b9
2022-07-13T13:54:47.643418Z  INFO request{method=GET path=/status version=HTTP/1.1 remote.addr=127.0.0.1:60964}: warp::filters::trace: processing request
2022-07-13T13:54:47.643814Z  INFO request{method=GET path=/status version=HTTP/1.1 remote.addr=127.0.0.1:60964}: warp::filters::trace: finished processing with success status=200
2022-07-13T13:54:47.645175Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60965}: warp::filters::trace: processing request
2022-07-13T13:54:47.645464Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60965}: warp::filters::trace: finished processing with success status=101
2022-07-13T13:54:47.646330Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60966}: warp::filters::trace: processing request
2022-07-13T13:54:47.647110Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60966}: warp::filters::trace: finished processing with success status=200
2022-07-13T13:54:47.672647Z  INFO iroha_core::sumeragi::fault: Validating block block_hash=ae8be0d4dee833c0bcccae5e296f52e17bbfe755e4245841c6d4afaa8d7a2013
2022-07-13T13:54:47.673088Z  INFO iroha_core::sumeragi::fault: Created a block peer_role=Leader block_hash=da14f85ebafb994ce1c2a02d74f7c855b602d83dae02bc36adf18ff09df5998f
2022-07-13T13:54:47.674046Z  INFO commit_block: iroha_core::sumeragi::fault: Committing block prev_peer_role=Leader new_peer_role=Leader new_block_height=2 block_hash=da14f85ebafb994ce1c2a02d74f7c855b602d83dae02bc36adf18ff09df5998f
2022-07-13T13:54:47.675017Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60967}: warp::filters::trace: processing request
2022-07-13T13:54:47.675232Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60967}: warp::filters::trace: finished processing with success status=101
2022-07-13T13:54:47.675959Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60968}: warp::filters::trace: processing request
2022-07-13T13:54:47.676753Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60968}: warp::filters::trace: finished processing with success status=200
2022-07-13T13:54:47.874512Z  INFO iroha_core::sumeragi::fault: Validating block block_hash=1074620a5777cb0688aa58c561aac9417894453d853a7f5aee2d8d59e8a4a4c0
2022-07-13T13:54:47.874939Z  INFO iroha_core::sumeragi::fault: Created a block peer_role=Leader block_hash=a829f2a72147b59bc1d3a67bc7935031cdb104eb4b2a845e2dce5cfbedea9120
2022-07-13T13:54:47.875897Z  INFO commit_block: iroha_core::sumeragi::fault: Committing block prev_peer_role=Leader new_peer_role=Leader new_block_height=3 block_hash=a829f2a72147b59bc1d3a67bc7935031cdb104eb4b2a845e2dce5cfbedea9120
2022-07-13T13:54:47.876862Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60969}: warp::filters::trace: processing request
2022-07-13T13:54:47.877073Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60969}: warp::filters::trace: finished processing with success status=101
2022-07-13T13:54:47.877998Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60970}: warp::filters::trace: processing request
2022-07-13T13:54:47.878765Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60970}: warp::filters::trace: finished processing with success status=200
2022-07-13T13:54:48.076090Z  INFO iroha_core::sumeragi::fault: Validating block block_hash=76e9393dcc1c0b05ff35be1c080f1a293deaa9aba53e008d71854a901bdf0aaa
2022-07-13T13:54:48.076788Z  INFO iroha_core::sumeragi::fault: Created a block peer_role=Leader block_hash=2c82bd79c486765036a49d96a892594b86d751e83f39786268cccb292d8c070d
2022-07-13T13:54:48.077687Z  INFO commit_block: iroha_core::sumeragi::fault: Committing block prev_peer_role=Leader new_peer_role=Leader new_block_height=4 block_hash=2c82bd79c486765036a49d96a892594b86d751e83f39786268cccb292d8c070d
2022-07-13T13:54:48.078670Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60971}: warp::filters::trace: processing request
2022-07-13T13:54:48.078914Z  INFO request{method=GET path=/events version=HTTP/1.1 remote.addr=127.0.0.1:60971}: warp::filters::trace: finished processing with success status=101
2022-07-13T13:54:48.079659Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60972}: warp::filters::trace: processing request
2022-07-13T13:54:48.080440Z  INFO request{method=POST path=/transaction version=HTTP/1.1 remote.addr=127.0.0.1:60972}: warp::filters::trace: finished processing with success status=200
2022-07-13T13:54:48.278035Z  INFO iroha_core::sumeragi::fault: Validating block block_hash=a46a305a54048a88e4be7c5bf6b70908ee0fa409a8c6c2ce96930ff647a3d41a
2022-07-13T13:54:48.278366Z  WARN iroha_core::block: Transaction validation failed reason=Transaction rejected due to insufficient authorisation caused_by=Some(NotPermittedFail { reason: "Validator CheckNested { validator: Or { first: AccountSetOnlyForSignerAccount, second: HasTokenAsValidator { has_token: SetGrantedByAccountOwner }, _phantom_operation: PhantomData } } denied operation SetKeyValue(SetKeyValueBox { object_id: EvaluatesTo { expression: Raw(Id(AccountId(Id { name: \"mouse\", domain_id: Id { name: \"wonderland\" } }))), _value_type: PhantomData }, key: EvaluatesTo { expression: Raw(Name(\"key\")), _value_type: PhantomData }, value: EvaluatesTo { expression: Raw(String(\"value\")), _value_type: PhantomData } }): Nor first validator AccountSetOnlyForSignerAccount succeed: Cannot set values to the account store of another account., nor second validator HasTokenAsValidator { has_token: SetGrantedByAccountOwner } succeed: Account does not have the needed permission token: PermissionToken { name: \"can_set_key_value_in_user_metadata\", params: {\"account_id\": Id(AccountId(Id { name: \"mouse\", domain_id: Id { name: \"wonderland\" } }))} }." })
2022-07-13T13:54:48.278562Z  INFO iroha_core::sumeragi::fault: Created a block peer_role=Leader block_hash=9d1f87347cde0501f2064d2c6030eb344dbb4b588121cd2c5c1dc437cdac55d7
2022-07-13T13:54:48.279445Z  INFO commit_block: iroha_core::sumeragi::fault: Committing block prev_peer_role=Leader new_peer_role=Leader new_block_height=5 block_hash=9d1f87347cde0501f2064d2c6030eb344dbb4b588121cd2c5c1dc437cdac55d7
2022-07-13T13:54:48.279652Z  INFO test_network: Stopping peer p2p_addr=127.0.0.1:1024 api_addr=127.0.0.1:1025
2022-07-13T13:54:48.279844Z  INFO test_network: Shutting down peer...
2022-07-13T13:54:48.280177Z  WARN iroha_client::client::events_api: e=Trying to work with closed connection
2022-07-13T13:54:48.280189Z  WARN iroha_client::client::events_api: e=Trying to work with closed connection
2022-07-13T13:54:48.280205Z  WARN iroha_client::client::events_api: e=Trying to work with closed connection
2022-07-13T13:54:48.280191Z  WARN iroha_client::client::events_api: e=Trying to work with closed connection
Error: Transaction was rejected

Caused by:
   0: Transaction rejected due to insufficient authorisation
   1: Action not permitted: Validator CheckNested { validator: Or { first: AccountSetOnlyForSignerAccount, second: HasTokenAsValidator { has_token: SetGrantedByAccountOwner }, _phantom_operation: PhantomData } } denied operation SetKeyValue(SetKeyValueBox { object_id: EvaluatesTo { expression: Raw(Id(AccountId(Id { name: "mouse", domain_id: Id { name: "wonderland" } }))), _value_type: PhantomData }, key: EvaluatesTo { expression: Raw(Name("key")), _value_type: PhantomData }, value: EvaluatesTo { expression: Raw(String("value")), _value_type: PhantomData } }): Nor first validator AccountSetOnlyForSignerAccount succeed: Cannot set values to the account store of another account., nor second validator HasTokenAsValidator { has_token: SetGrantedByAccountOwner } succeed: Account does not have the needed permission token: PermissionToken { name: "can_set_key_value_in_user_metadata", params: {"account_id": Id(AccountId(Id { name: "mouse", domain_id: Id { name: "wonderland" } }))} }.

Location:
    /Volumes/Development/Projects/Soramitsu/iroha/client/src/client.rs:550:29
thread 'integration::roles::register_and_grant_role_for_metadata_access' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:187:5
stack backtrace:
2022-07-13T13:54:48.281471Z  INFO iroha_core::kura: Kura block thread is shutting down
   0: rust_begin_unwind
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
   1: core::panicking::panic_fmt
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
   2: core::panicking::assert_failed_inner
   3: core::panicking::assert_failed
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:182:5
   4: test::assert_test_result
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/test/src/lib.rs:187:5
   5: mod::integration::roles::register_and_grant_role_for_metadata_access::{{closure}}
             at ./tests/integration/roles.rs:132:1
   6: core::ops::function::FnOnce::call_once
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
   7: core::ops::function::FnOnce::call_once
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
test integration::roles::register_and_grant_role_for_metadata_access ... FAILED

failures:

failures:
    integration::roles::register_and_grant_role_for_metadata_access

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 65 filtered out; finished in 4.56s

error: test failed, to rerun pass '-p iroha_client --test mod'

Who can help?

@Arjentix

[Arjentix]

The original test scenario was wrong, here is the updated version:

#[test]
fn register_and_grant_role_for_metadata_access() -> Result<()> {
    let (_rt, _peer, test_client) = <PeerBuilder>::new().start_with_runtime();
    wait_for_genesis_committed(&vec![test_client.clone()], 0);

    let alice_id = <Account as Identifiable>::Id::from_str("alice@wonderland")?;
    let mouse_id = <Account as Identifiable>::Id::from_str("mouse@wonderland")?;

    // Registering Mouse
    let mouse_key_pair = KeyPair::generate()?;
    let register_mouse = RegisterBox::new(Account::new(
        mouse_id.clone(),
        [mouse_key_pair.public_key().clone()],
    ));
    test_client.submit_blocking(register_mouse)?;

    // Registering role
    let role_id = <Role as Identifiable>::Id::from_str("ACCESS_TO_MOUSE_METADATA")?;
    let role = iroha_data_model::role::Role::new(role_id.clone())
        .add_permission(CanSetKeyValueInUserMetadata::new(mouse_id.clone()))
        .add_permission(CanRemoveKeyValueInUserMetadata::new(mouse_id.clone()));
    let register_role = RegisterBox::new(role);
    test_client.submit_blocking(register_role)?;

    // Mouse grants role to Alice
    let grant_role = GrantBox::new(role_id.clone(), alice_id.clone());
    let grant_role_tx = Transaction::new(mouse_id.clone(), vec![grant_role.into()].into(), 100_000)
        .sign(mouse_key_pair)?;
    test_client.submit_transaction_blocking(grant_role_tx)?;

    // Alice modifies Mouse's metadata
    let set_key_value = SetKeyValueBox::new(
        mouse_id,
        Name::from_str("key").expect("Valid"),
        Value::String("value".to_owned()),
    );
    test_client.submit_blocking(set_key_value)?;

    // Making request to find Alice's roles
    let found_role_ids = test_client.request(client::role::by_account_id(alice_id))?;
    assert!(found_role_ids.contains(&role_id));

    Ok(())
}