bucket creation fails at the backend where-as db has the entry and it shows BucketAlreadyOwnedByYou when issued again

[rkomandu]

Environment info

• NooBaa Version: VERSION ODF 4.11.2
• Platform: Kubernetes 1.14.1 | minikube 1.1.1 | OpenShift 4.1 | other: specify

Actual behavior

1. In Noobaa db once the bucket entry is created, it should do create the directory in the backend as well, which is not the case in the ODF 4.11.2 .

Romy A and I had debugged Live on the system and hence opening this defect.

oc version Client Version: 4.11.0 Kustomize Version: v4.5.4 Server Version: 4.11.7 Kubernetes Version: v1.24.0+3882f8f

Expected behavior

Steps to reproduce

Unable to create users and buckets is the effect as mentioned in the defect. Discussed with Romy today for 2hrs over the webex . Symptom which led to this is as follows

Fyre SC cluster had the master node kernel upgraded over the weekend and GPFS was down, with disks unavailable that are serviced from the master node of SC -- build mmbuildgpl on the master node and started GPFS, got the disks to "up" state and later it mounted on all nodes of remote cluster as well noobaa-db pod restarted 44hrs ago (for whatever reason), this is earlier to the kernel upgrade on the master node of SC Over webex we did the following -- restarted noobaa db pod (no luck) -- restarted noobaa-endpoint (no luck --> as S3 CLI showed read timeout on creating the buckets) -- restarted the metallb speaker pods on the worker nodes only (no luck) -- restarted the noobaa core pod Then it did the trick of able to communicate back to the noobaa-db.. So the bottom line is that the noobaa-db pod and noobaa-core communication is broken due to this behavior. Why does it behave no clue. Shared MG logs with Romy for her understanding as we got duplicate bucket (BucketAlreadyOwnedByYou) an already existing defect due to this noobaa-db non responsiveness. Marking it as noobaa defect for now.. not for HPO.. however we will end up in weird DB entries as observed by earlier steps.

More information - Screenshots / Logs / Other output

Logs are uploaded in the box folder https://app.box.com/file/1054088210623?tc=collab-file-invite-control https://app.box.com/file/1054093717179?tc=collab-file-invite-control

[nimrod-becker]

Quoting from a triage meeting. A potential problem with the DB not responding, or responding slowly + No atomicity between DB entry creation and folder creation on the FS. Entry was created but folder was not.

Need to better handle errors between DB entry creation and folder

[nimrod-becker]

Talking to Danny, he mentioned he saw something similar with account creation where the creation in DB failed but we got an error of account already exists.

This might be an issue with the system store that does not evacuate an entry in some cases where the db update itself failed.... need to be investigated

[aspandey]

I tried reproducing this issue and also tried to come up with some solution -

1 - Started all the pods and then killed noobaa-db-pg-0 by modifying the replica count. 2 - Tried to create account/ buckets. It failed saying that "this.begin() must be called before sending queries on this transaction " 3 - I restarted the DB and tried to create same account/bucket again. It failed but eventually it gets success. It sometimes take lot of time after which we can create same account/bucket.

We had this doubt that the cache in memory is not getting refreshed at the right time so I tried to force this refresh using some variable which did not work.

Next thing I changed is the refresh threshold. from this.START_REFRESH_THRESHOLD = 10 * 60 * 1000; this.FORCE_REFRESH_THRESHOLD = 60 * 60 * 1000;

to this.START_REFRESH_THRESHOLD = 2 * 60 * 1000; this.FORCE_REFRESH_THRESHOLD = 4 * 60 * 1000;

I observed after changing these values, when we bring the DB up account/bucket creation happens very soon as compared to previous values.

This is just one observation. I need to investigate more to come to some conclusive point.

[aspandey]

As per my understanding, our main issue is this - When the postgrace DB is Down and we create a bucket or account, it fails. Once the database is UP and running again and we try to create same bucket/account again, it says “BUCKET_ALREADY_OWNED_BY_YOU” even if the bucket does not show in list bucket. However eventually we could see the bucket in list.

Findings -

With the latest master branch, I could not see the issue. I thought that https://github.com/noobaa/noobaa-core/pull/7167 Could have fixed the issue but removing this also had the same effect and could not reproduce the issue.

So when a database is completely down and we try to create a bucket it fails and when the DB is UP again we could again create the same bucket without failure.

Having said that, we have the following observation which may or may not be problematic, based on what kind of experience we want customers to have.

When we bring the DB down by editing replica count using “kubectl edit statefulset noobaa-db-pg” it starts terminating the DB. This process internally happens in steps which means even when the DB pod is in terminating state, it might be taking some request from core. While DB is in a terminating state and going down and if we try to create buckets/accounts, it may return an error message to the user which could indicate that the bucket creation has failed.

However, if we bring the DB UP, after a few min/sec do the list_bucket, it shows the bucket name. That means the changes (done by system_store.make_changes) had gone to DB; it is just that the info, which we fetch in the bucket creation step, fails. Which gives an impression that the bucket creation failed which actually got passed.

Example: Just after changes the replica count of DB to 0 and saving the file, I tried to create bucket “banana-1”

[host1@host1 noobaa-operator]$ nb api bucket create_bucket '{"name":"banana-1"}' INFO[0000] ✅ Exists: NooBaa "noobaa" INFO[0000] ✅ Exists: Service "noobaa-mgmt" INFO[0000] ✅ Exists: Secret "noobaa-operator" INFO[0000] ✅ Exists: Secret "noobaa-admin" INFO[0000] ✈️ RPC: bucket.create_bucket() Request: map[name:banana-1] WARN[0000] RPC: GetConnection creating connection to wss://localhost:34115/rpc/ 0xc000c49b00 INFO[0000] RPC: Connecting websocket (0xc000c49b00) &{RPC:0xc0005a1040 Address:wss://localhost:34115/rpc/ State:init WS: PendingRequests:map[] NextRequestID:0 Lock:{state:1 sema:0} ReconnectDelay:0s cancelPings:} INFO[0000] RPC: Connected websocket (0xc000c49b00) &{RPC:0xc0005a1040 Address:wss://localhost:34115/rpc/ State:init WS: PendingRequests:map[] NextRequestID:0 Lock:{state:1 sema:0} ReconnectDelay:0s cancelPings:} ERRO[0000] ⚠️ RPC: bucket.create_bucket() Response Error: Code=INTERNAL Message=the database system is shutting down FATA[0000] ❌ the database system is shutting down

Here it looks like the bucket creation has failed.

================================================= When looking at logs, we can see that make_changes to DB was successful.

^[[32mFeb-20 18:22:05.136^[[35m [WebServer/40] ^[[36m [L3]^[[39m core.rpc.rpc:: RPC._on_request: ENTER srv bucket_api.create_bucket reqid wss://localhost:34115/rpc/-0 connid ws://[::ffff:127.0.0.1]:50818/(9qag2ejid)

^[[32mFeb-20 18:22:05.138^[[35m [WebServer/40] ^[[36m [L1]^[[39m core.server.common_services.auth_server:: load_auth: { system: ^[[32m'admin'^[[39m } { account_id: ^[[32m'63f34f9c7cd54d002814d204'^[[39m, system_id: ^[[32m'63f34f8d7cd54d002814d1f4'^[[39m, role: ^[[32m'operator'^[[39m, authorized_by: ^[[32m'noobaa'^[[39m, iat: ^[[33m1676890013^[[39m } ^[[32mFeb-20 18:22:05.138^[[35m [WebServer/40] ^[[36m [L3]^[[39m core.server.common_services.auth_server:: load auth system: 63f34f8d7cd54d002814d1f4 ^[[32mFeb-20 18:22:05.138^[[35m [WebServer/40] ^[[36m [L0]^[[39m core.server.system_services.bucket_server:: validate_non_nsfs_bucket_create_allowed: ^[[90mundefined^[[39m ^[[90mundefined^[[39m ^[[32mFeb-20 18:22:05.139^[[35m [WebServer/40] ^[[36m [L0]^[[39m core.server.notifications.dispatcher:: Adding ActivityLog entry { event: ^[[32m'bucket.create'^[[39m, level: ^[[32m'info'^[[39m, system: 63f34f8d7cd54d002814d1f4, actor: 63f34f9c7cd54d002814d204, bucket: 63f3ba4d7cd54d002814d2f3, desc: SENSITIVE-f4b6955d5488d167 }

^[[32mFeb-20 18:22:05.141^[[35m [WebServer/40] ^[[36m [LOG]^[[39m core.server.system_services.system_store:: SystemStore.make_changes: { insert: { tieringpolicies: [ { _id: 63f3ba4d7cd54d002814d2f2, name: ^[[32m'banana-1#led5a15e'^[[39m, system: 63f34f8d7cd54d002814d1f4, tiers: [ { tier: 63f3ba4d7cd54d002814d2f1, order: ^[[33m0^[[39m, spillover: ^[[33mfalse^[[39m, disabled: ^[[33mfalse^[[39m } ], chunk_split_config: { avg_chunk: ^[[33m4194304^[[39m, delta_chunk: ^[[33m1048576^[[39m } } ], tiers: [ { _id: 63f3ba4d7cd54d002814d2f1, name: ^[[32m'banana-1#led5a15e'^[[39m, system: 63f34f8d7cd54d002814d1f4, chunk_config: 63f34f8d7cd54d002814d1f7, data_placement: ^[[32m'SPREAD'^[[39m, mirrors: [ { _id: 63f3ba4d7cd54d002814d2f0, spread_pools: ^[[36m[Array]^[[39m } ] } ], buckets: [ { _id: 63f3ba4d7cd54d002814d2f3, name: SENSITIVE-e1623878a99dce31, tag: ^[[32m''^[[39m, system: 63f34f8d7cd54d002814d1f4, owner_account: 63f34f9c7cd54d002814d204, tiering: 63f3ba4d7cd54d002814d2f2, storage_stats: { chunks_capacity: ^[[33m0^[[39m, blocks_size: ^[[33m0^[[39m, pools: {}, objects_size: ^[[33m0^[[39m, objects_count: ^[[33m0^[[39m, objects_hist: [], last_update: ^[[33m1676917140000^[[39m }, lambda_triggers: [], versioning: ^[[32m'DISABLED'^[[39m, object_lock_configuration: ^[[90mundefined^[[39m, master_key_id: 63f3ba4d7cd54d002814d2f4 } ], master_keys: [ { _id: 63f3ba4d7cd54d002814d2f4, description: ^[[32m'master key of 63f3ba4d7cd54d002814d2f3 bucket'^[[39m, master_key_id: 63f34f8d7cd54d002814d1f5, cipher_type: ^[[32m'aes-256-gcm'^[[39m, cipher_key: <Buffer a5 27 d4 8a bc 27 d9 c2 ec ec 01 35 29 ab 0e 98 00 66 ed 0d b5 a7 80 26 2a 29 c6 fb ec 9b 8e 94>, cipher_iv: <Buffer 4d d8 94 e6 9b 00 48 f9 9a 26 58 3c 4c 70 93 b7>, disabled: ^[[33mfalse^[[39m } ] }, update: {} }

===================================================== However in the next steps, probably getting info about the bucket, we get the error message.

^[[32mFeb-20 18:22:05.469^[[35m [WebServer/40] ^[[36m [L1]^[[39m core.rpc.rpc:: RPC._on_response: reqid 2@ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm) connid ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm) ^[[32mFeb-20 18:22:05.536^[[35m [WebServer/40] ^[[31m[ERROR]^[[39m core.rpc.rpc:: RPC._request: response ERROR srv server_inter_process_api.load_system_store reqid 2@ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm) connid ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm) params { since: ^[[33m1676917325139^[[39m } took [133.4+225.8=359.2] [RpcError: the database system is shutting down] { rpc_code: ^[[32m'INTERNAL'^[[39m, rpc_data: { retryable: ^[[33mtrue^[[39m } } ^[[32mFeb-20 18:22:05.539^[[35m [WebServer/40] ^[[36m [L0]^[[39m core.rpc.rpc_base_conn:: RPC CONNECTION CLOSED. got event from connection: ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm) Error: publish_to_cluster: disconnect on error the database system is shutting down ws://[::ffff:172.17.0.1]:7244/(9q6or7sjm)

After bringing the DB up, list_bucket shows the list of buckets which we created.

• name: banana-1
• name: banana-2
• name: orange-1
• name: first.bucket

The current functionality will not bring the system in an unstable state but it certainly creates confusion in the mind of the user. In my opinion, we should return the success message for bucket creation if it has succeeded or we should fail it completely and should update the DB..

[romayalon]

Talking to Danny, he mentioned he saw something similar with account creation where the creation in DB failed but we got an error of account already exists.

This might be an issue with the system store that does not evacuate an entry in some cases where the db update itself failed.... need to be investigated

@nimrod-becker are you sure it's not a not updated cache thing?

[romayalon]

@aspandey @rkomandu Have you tried it with NSFS buckets? I think that the symptom we saw was that the DB bucket entry exists but the equivalent folder in the file system was missing

[rkomandu]

@romayalon , our buckets are NSFS only for the SS.

[rkomandu]

@aspandey There is one more scenario here as per my steps mentioned in https://github.com/noobaa/noobaa-core/issues/7103#issue-1447507211 (first comment).

I see if there is a long gap on the DB being in "ContainerCreationError" state due to the backend (FS) is down for whatever reason and once the backend (FS) which we term as Storage Cluster is up, the noobaa-db come back to Running state , however the re-establish of connection between noobaa-core and noobaa-db is not happening as per my observation/post above. So is the hand-shake code in-place between noobaa-core and noobaa-db if the recovery is long in the DB case ?

[romayalon]

@rkomandu Apologies for the confusion, I wanted to ask Ashish regarding the NSFS buckets

[aspandey]

@aspandey @rkomandu Have you tried it with NSFS buckets? I think that the symptom we saw was that the DB bucket entry exists but the equivalent folder in the file system was missing

NO, I have not tried it with NSFS bucket. When I started looking at the bug, I could see some issue without NSFS also so thought it might be enough to debug without NSFS. I will try with NSFS bucket also.

[github-actions[bot]]

This issue had no activity for too long - it will now be labeled stale. Update it to prevent it from getting closed.

[github-actions[bot]]

This issue is stale and had no activity for too long - it will now be closed.