bug: Log Index Error in Meta Pod on Restart

inviscid commented 2 weeks ago

Search before asking

[X] I had searched in the issues and found no similar issues.

Version

nightly-630

What's Wrong?

Upon restart of a meta pod, we receive the following error in the meta logs:

Id: 0
Raft Cluster Name: databend
Raft Dir: /data/databend-meta/raft
Raft Status: single
HTTP API
   listening at 0.0.0.0:28002
gRPC API
   listening at 0.0.0.0:9191
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-bug-fixes.svc.cluster.local:9191
Raft API
   listening at 0.0.0.0:28004
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-bug-fixes.svc.cluster.local:28004
Upgrade ondisk data if out of date: version: V003, upgrading: None
    Find and clean previous unfinished upgrading
Upgrade ondisk data finished: version: V003, upgrading: None
Error: when Read LogIndex(141565): log entry not found

The meta cluster is a 3 pod cluster running in kubernetes. We haven't observed this issue until recently.

How to Reproduce?

Restart meta pod after recovering from backup.

Are you willing to submit PR?

[ ] Yes I am willing to submit a PR!

dosubot[bot] commented 2 weeks ago

Hello @inviscid! I'm here to help you with any bugs, questions, or contributions you have for the project. Let's tackle this issue together!

To resolve the "Log Index Error in Meta Pod on Restart" issue in a 3-pod Kubernetes cluster running Databend version nightly-630, follow these steps:

Check the Raft Log Entries: Ensure that the Raft log entries are sequential and there are no missing indices. The log entries should start from index 0 and increment by 1 for each subsequent entry.
Identify Inconsistencies: Look for any inconsistencies or gaps in the log indices. For example, if there is a missing log entry or an entry with a duplicate index, it could cause the "Log Index Error".
Correct the Log Entries: If you find any inconsistencies, you need to correct the log entries. This might involve manually editing the log entries to ensure they are sequential and consistent.

Here is an example of how the log entries should look:

["header",{"DataHeader":{"key":"header","value":{"version":"V003","upgrading":null}}}]
["raft_state",{"RaftStateKV":{"key":"Id","value":{"NodeId":1}}}]
["raft_state",{"RaftStateKV":{"key":"HardState","value":{"HardState":{"leader_id":{"term":1,"node_id":1},"committed":false}}}}]
["raft_log",{"Logs":{"key":0,"value":{"log_id":{"leader_id":{"term":0,"node_id":0},"index":0},"payload":{"Membership":{"configs":[[1]],"nodes":{"1":{}}}}}}}]
["raft_log",{"Logs":{"key":1,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":1},"payload":"Blank"}}}]
["raft_log",{"Logs":{"key":2,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":2},"payload":{"Normal":{"txid":null,"time_ms":1667290820099,"cmd":{"AddNode":{"node_id":1,"node":{"name":"1","endpoint":{"addr":"localhost","port":28103},"grpc_api_advertise_address":"0.0.0.0:9191"},"overriding":false}}}}}}}]
["raft_log",{"Logs":{"key":3,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":3},"payload":{"Normal":{"txid":null,"time_ms":1667290820429,"cmd":{"AddNode":{"node_id":2,"node":{"name":"2","endpoint":{"addr":"localhost","port":28203},"grpc_api_advertise_address":"0.0.0.0:28202"},"overriding":false}}}}}}}]
["raft_log",{"Logs":{"key":4,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":4},"payload":{"Membership":{"configs":[[1],[1,2]],"nodes":{"1":{},"2":{}}}}}}}]
["raft_log",{"Logs":{"key":5,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":5},"payload":{"Membership":{"configs":[[1,2]],"nodes":{"1":{},"2":{}}}}}}}]
["raft_log",{"Logs":{"key":6,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":6},"payload":{"Normal":{"txid":null,"time_ms":1667290821018,"cmd":{"AddNode":{"node_id":3,"node":{"name":"3","endpoint":{"addr":"localhost","port":28303},"grpc_api_advertise_address":"0.0.0.0:28302"},"overriding":false}}}}}}}]
["raft_log",{"Logs":{"key":7,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":7},"payload":{"Membership":{"configs":[[1,2],[1,2,3]],"nodes":{"1":{},"2":{},"3":{}}}}}}}]
["raft_log",{"Logs":{"key":8,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":8},"payload":{"Membership":{"configs":[[1,2,3]],"nodes":{"1":{},"2":{},"3":{}}}}}}}]
["raft_log",{"Logs":{"key":9,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":9},"payload":{"Normal":{"txid":null,"time_ms":1667290824580,"cmd":{"UpsertKV":{"key":"__fd_id_gen/database_id","seq":"Any","value":{"Update":[]},"value_meta":null}}}}}}}]
["raft_log",{"Logs":{"key":10,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":10},"payload":{"Normal":{"txid":null,"time_ms":1667290824586,"cmd":{"Transaction":{"condition":[{"key":"__fd_database/test_tenant/default","expected":0,"target":{"Seq":0}},{"key":"__fd_database_id_to_name/1","expected":0,"target":{"Seq":0}},{"key":"__fd_db_id_list/test_tenant/default","expected":0,"target":{"Seq":0}}],"if_then":[{"request":{"Put":{"key":"__fd_database/test_tenant/default","value":[49],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_database_by_id/1","value":[162,1,30,50,48,50,50,45,49,49,45,48,49,32,48,56,58,50,48,58,50,52,46,53,55,48,53,56,54,32,85,84,67,170,1,30,50,48,50,50,45,49,49,45,48,49,32,48,56,58,50,48,58,50,52,46,53,55,48,53,56,54,32,85,84,67,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_db_id_list/test_tenant/default","value":[10,1,1,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_database_id_to_name/1","value":[10,11,116,101,115,116,95,116,101,110,97,110,116,18,7,100,101,102,97,117,108,116,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}}],"else_then":[]}}}}}}}]
["raft_log",{"Logs":{"key":11,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":11},"payload":{"Normal":{"txid":null,"time_ms":1667290824603,"cmd":{"UpsertKV":{"key":"__fd_clusters/test_tenant/test_cluster/databend_query/RpuWndTf5JlgyJCpAAtQX6","seq":{"Exact":0},"value":{"Update":[123,34,105,100,34,58,34,82,112,117,87,110,100,84,102,53,74,108,103,121,74,67,112,65,65,116,81,88,54,34,44,34,99,112,117,95,110,117,109,115,34,58,48,44,34,118,101,114,115,105,111,110,34,58,48,44,34,102,108,105,103,104,116,95,97,100,100,114,101,115,115,34,58,34,49,50,55,46,48,46,48,46,49,58,57,48,57,48,34,44,34,98,105,110,97,114,121,95,118,101,114,115,105,111,110,34,58,34,118,48,46,56,46,57,53,45,110,105,103,104,116,108,121,45,97,52,49,56,55,100,51,40,114,117,115,116,45,49,46,54,54,46,48,45,110,105,103,104,116,108,121,45,50,48,50,50,45,49,49,45,48,49,84,48,56,58,49,55,58,51,54,46,55,48,49,55,54,53,90,41,34,125]},"value_meta":{"expire_at":1667290884}}}}}}}}]
["raft_log",{"Logs":{"key":12,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":12},"payload":{"Normal":{"txid":null,"time_ms":1667290826333,"cmd":{"UpsertKV":{"key":"__fd_clusters/test_tenant/test_cluster/databend_query/KMZ4VvqDFVExlZFThKDzZ1","seq":{"Exact":0},"value":{"Update":[123,34,105,100,34,58,34,75,77,90,52,86,118,113,68,70,86,69,120,108,90,70,84,104,75,68,122,90,49,34,44,34,99,112,117,95,110,117,109,115,34,58,48,44,34,118,101,114,115,105,111,110,34,58,48,44,34,102,108,105,103,104,116,95,97,100,100,114,101,115,115,34,58,34,49,50,55,46,48,46,48,46,49,58,57,48,57,50,34,44,34,98,105,110,97,114,121,95,118,101,114,115,105,111,110,34,58,34,118,48,46,56,46,57,53,45,110,105,103,104,116,108,121,45,97,52,49,56,55,100,51,40,114,117,115,116,45,49,46,54,54,46,48,45,110,105,103,104,116,108,121,45,50,48,50,50,45,49,49,45,48,49,84,48,56,58,49,55,58,51,54,46,55,48,49,55,54,53,90,41,34,125]},"value_meta":{"expire_at":1667290886}}}}}}}}]
["raft_log",{"Logs":{"key":13,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":13},"payload":{"Normal":{"txid":null,"time_ms":1667290826867,"cmd":{"UpsertKV":{"key":"__fd_clusters/test_tenant/test_cluster/databend_query/7GVP1GsQ2jpDMu1ti8UnF1","seq":{"Exact":0},"value":{"Update":[123,34,105,100,34,58,34,55,71,86,80,49,71,115,81,50,106,112,68,77,117,49,116,105,56,85,110,70,49,34,44,34,99,112,117,95,110,117,109,115,34,58,48,44,34,118,101,114,115,105,111,110,34,58,48,44,34,102,108,105,103,104,116,95,97,100,100,114,101,115,115,34,58,34,49,50,55,46,48,46,48,46,49,58,57,48,57,51,34,44,34,98,105,110,97,114,121,95,118,101,114,115,105,111,110,34,58,34,118,48,46,56,46,57,53,45,110,105,103,104,116,108,121,45,97,52,49,56,55,100,51,40,114,117,115,116,45,49,46,54,54,46,48,45,110,105,103,104,116,108,121,45,50,48,50,50,45,49,49,45,48,49,84,48,56,58,49,55,58,51,54,46,55,48,49,55,54,53,90,41,34,125]},"value_meta":{"expire_at":1667290886}}}}}}}}]
["raft_log",{"Logs":{"key":14,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":14},"payload":{"Normal":{"txid":null,"time_ms":1667290836132,"cmd":{"UpsertKV":{"key":"__fd_id_gen/database_id","seq":"Any","value":{"Update":[]},"value_meta":null}}}}}}}]
["raft_log",{"Logs":{"key":15,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":15},"payload":{"Normal":{"txid":null,"time_ms":1667290836137,"cmd":{"Transaction":{"condition":[{"key":"__fd_database/test_tenant/db1","expected":0,"target":{"Seq":0}},{"key":"__fd_database_id_to_name/9","expected":0,"target":{"Seq":0}},{"key":"__fd_db_id_list/test_tenant/db1","expected":0,"target":{"Seq":0}}],"if_then":[{"request":{"Put":{"key":"__fd_database/test_tenant/db1","value":[57],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_database_by_id/9","value":[42,7,100,101,102,97,117,108,116,162,1,30,50,48,50,50,45,49,49,45,48,49,32,48,56,58,50,48,58,51,53,46,54,51,52,49,50,51,32,85,84,67,170,1,30,50,48,50,50,45,49,49,45,48,49,32,48,56,58,50,48,58,51,53,46,54,51,52,49,50,54,32,85,84,67,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_db_id_list/test_tenant/db1","value":[10,1,9,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}},{"request":{"Put":{"key":"__fd_database_id_to_name/9","value":[10,11,116,101,115,116,95,116,101,110,97,110,116,18,3,100,98,49,160,6,19,168,6,1],"prev_value":true,"expire_at":null}}}],"else_then":[]}}}}}}}]
["raft_log",{"Logs":{"key":16,"value":{"log_id":{"leader_id":{"term":1,"node_id":0},"index":16},"payload":{"Normal":{"txid":null,"time_ms":1667290838209,"cmd":{"UpsertKV":{"key":"__fd_id_gen/table_id","seq":"Any","value":{"Update":[]},"value_meta":null}}}}}}}]

Update the Meta Pod Configuration: Ensure that the Meta Pod configuration is set correctly. Based on the meta-ha.yaml configuration, make sure the bootstrap is set to true, replicaCount is 3, and the persistence size is sufficient (e.g., 8Gi). Also, ensure the logging configuration is set to capture detailed logs for debugging:

bootstrap: true
replicaCount: 3
persistence:
  size: 8Gi

config:
  logDir: /.databend/logs
  logPrefixFilter: ""
  logLevel: "DEBUG"

Restart the Meta Pod: After ensuring the log entries are correct and the configuration is updated, restart the Meta Pod to see if the issue is resolved.

If the issue persists, you may need to investigate further into the specific log entries causing the error and ensure that the Raft state is correctly maintained across all nodes in the cluster ^[1]^[2]^[3].

To continue talking to Dosu, mention @dosu.

drmingdrmer commented 2 weeks ago

Do you have a DEBUG level log so that I can see what's going on.

And if possible, please provide the backup file you were using to restore and the command to restore and the config file that is used when bringing up the meta node.

kkapper commented 2 weeks ago

I'm assembling an active case of this with debug logs.

The startup looks like this:

Databend Metasrv
Version: v1.2.632-nightly-125cb429a5-simd(1.81.0-nightly-2024-09-06T04:33:23.592487613Z)
Working DataVersion: V003(2024-05-31: Store snapshot in rotbl)
Raft Feature set:
    Server Provide: { append:v0, install_snapshot:v1, install_snapshot:v3, vote:v0 }
    Client Require: { append:v0, install_snapshot:v3, vote:v0 }
On Disk Data:
    Dir: /data/databend-meta/raft
    DataVersion: V003(2024-05-31: Store snapshot in rotbl)
    In-Upgrading: None
Log:
    File: enabled=true, level=INFO, dir=/data/databend-meta/log, format=json
    Stderr: enabled=true, level=WARN, format=text
Id: 0
Raft Cluster Name: databend
Raft Dir: /data/databend-meta/raft
Raft Status: single
HTTP API
   listening at 0.0.0.0:28002
gRPC API
   listening at 0.0.0.0:9191
Upgrade ondisk data if out of date: version: V003, upgrading: None
    Find and clean previous unfinished upgrading
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local:9191
Raft API
   listening at 0.0.0.0:28004
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local:28004
Upgrade ondisk data finished: version: V003, upgrading: None
Error: when Read LogIndex(0): log entry not found

kkapper commented 2 weeks ago

This is not currently taking place after a restore. A restore was performed some time in the past. The cluster runs for a few days, then eventually, we will end up in this state.

kkapper commented 2 weeks ago

Here is a small chunk of log data that may be relevant:

2024-09-09T17:09:09.846196Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-09T13:07:35.229000Z+0000
2024-09-09T17:09:09.846214Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T209-N2.11326:normal, log_time_ms: 1725887255229
2024-09-09T17:09:09.846242Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1725887255229
2024-09-09T17:09:09.846260Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T209-N2.11326 time: 1725887255229 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-09T17:09:09.846323Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-09T17:09:09.846379Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-09T17:09:09.846445Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-09T17:09:09.846518Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-09T17:09:09.846583Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/H8pNEAEK6CvwQgnEbNTDc7(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-09T17:09:09.846655Z DEBUG databend_meta::store::raft_state_machine_impl: raft_state_machine_impl.rs:51 applied_state: applied: Some(LogId { leader_id: LeaderId { term: 209, node_id: 2 }, index: 11326 }), membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }
2024-09-09T17:09:09.846752Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:187 get_log_state: (None,Some(LogId { leader_id: LeaderId { term: 209, node_id: 2 }, index: 11326 })]
2024-09-09T17:09:09.846799Z  INFO openraft::storage::helper: helper.rs:231 load membership from log: [11327..11327)
2024-09-09T17:09:09.846829Z DEBUG openraft::storage::helper: helper.rs:193 openraft::storage::helper::StorageHelper<_, _, _>::get_membership membership_in_sm=StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } } membership_in_log=[]
2024-09-09T17:09:09.846881Z  INFO openraft::storage::helper: helper.rs:120 load key log ids from (None,T209-N2.11326]
2024-09-09T17:09:09.846924Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:105 RaftStore::try_get_log_entries: self.id=0, range: 0..=0
2024-09-09T17:09:09.846955Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:117 RaftStore::try_get_log_entries: done: self.id=0, range: 0..=0
2024-09-09T17:09:09.847015Z  INFO openraft::core::tick: tick.rs:145 Timer shutdown signal sent: Ok(())
2024-09-09T17:09:09.847762Z  INFO openraft::core::tick: tick.rs:101 TickLoop received cancel signal, quit
Error: when Read LogIndex(0): log entry not found

kkapper commented 2 weeks ago

2024-09-12T17:07:34.438163Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_table_by_id/48488 == seq(48490)
2024-09-12T17:07:34.438194Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_table_by_id/48488 curr: seq:0 value:None
2024-09-12T17:07:34.438218Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Get(Get key=__fd_table_by_id/48488)
2024-09-12T17:07:34.438248Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_table_by_id/48488 == seq(48490)] then:[Put(Put key=__fd_table_by_id/48488)] else:[Get(Get key=__fd_table_by_id/48488)] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [TxnOpResponse: Get: Get-resp: key=__fd_table_by_id/48488, prev_seq=None], error: }
2024-09-12T17:07:34.438329Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:59.185000Z+0000
2024-09-12T17:07:34.438347Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48018:normal, log_time_ms: 1726075619185
2024-09-12T17:07:34.438376Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075619185
2024-09-12T17:07:34.438397Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48018 time: 1726075619185 ms cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-12T17:07:34.438524Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-12T17:07:34.438600Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-12T17:07:34.438687Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_database_by_id/6073 == seq(48497)
2024-09-12T17:07:34.438722Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_database_by_id/6073 == seq(48497)
2024-09-12T17:07:34.438756Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_database_by_id/6073 curr: seq:0 value:None
2024-09-12T17:07:34.438780Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [], error: }
2024-09-12T17:07:34.438890Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:59.228000Z+0000
2024-09-12T17:07:34.438910Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48019:normal, log_time_ms: 1726075619228
2024-09-12T17:07:34.438947Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075619228
2024-09-12T17:07:34.438966Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48019 time: 1726075619228 ms cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-12T17:07:34.439019Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-12T17:07:34.439057Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-12T17:07:34.439099Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)
2024-09-12T17:07:34.439131Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }
2024-09-12T17:07:34.439184Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }; prev: Normal { internal_seq: 4, value: [10, 6, 112, 117, 98, 108, 105, 99, 18, 24, 18, 16, 10, 7, 100, 101, 102, 97, 117, 108, 116, 16, 185, 47, 24, 240, 250, 2, 160, 6, 108, 168, 6, 24, 160, 6, 108, 168, 6, 24], meta: Some(KVMeta { expire_at: None }) }; res: TombStone { internal_seq: 4 }
2024-09-12T17:07:34.439366Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }; prev: Some(SeqV { seq: 4, meta: Some(KVMeta { expire_at: None }), data: "[binary]" }); result: None
2024-09-12T17:07:34.439462Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }; res: AppliedState: Txn: TxnReply{ success: true, responses: [TxnOpResponse: Delete: Delete-resp: success: true, key=__fd_object_owners/plaid/table-by-id/48496, prev_seq=Some(4)], error: }
2024-09-12T17:07:34.439524Z DEBUG databend_meta::store::raft_state_machine_impl: raft_state_machine_impl.rs:51 applied_state: applied: Some(LogId { leader_id: LeaderId { term: 2234, node_id: 1 }, index: 48019 }), membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }
2024-09-12T17:07:34.439636Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:187 get_log_state: (None,Some(LogId { leader_id: LeaderId { term: 2234, node_id: 1 }, index: 48019 })]
2024-09-12T17:07:34.439689Z  INFO openraft::storage::helper: helper.rs:231 load membership from log: [48020..48020)
2024-09-12T17:07:34.439724Z DEBUG openraft::storage::helper: helper.rs:193 openraft::storage::helper::StorageHelper<_, _, _>::get_membership membership_in_sm=StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } } membership_in_log=[]
2024-09-12T17:07:34.439785Z  INFO openraft::storage::helper: helper.rs:120 load key log ids from (None,T2234-N1.48019]
2024-09-12T17:07:34.439822Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:105 RaftStore::try_get_log_entries: self.id=0, range: 0..=0
2024-09-12T17:07:34.439854Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:117 RaftStore::try_get_log_entries: done: self.id=0, range: 0..=0
2024-09-12T17:07:34.439934Z  INFO openraft::core::tick: tick.rs:145 Timer shutdown signal sent: Ok(())
2024-09-12T17:07:34.440294Z  INFO openraft::core::tick: tick.rs:101 TickLoop received cancel signal, quit
Error: when Read LogIndex(0): log entry not found

drmingdrmer commented 2 weeks ago

The state machine seems incomplete from the log. There are at least one membership log in it. But it is empty from these two logs: 2024-09-12T17:07:34.439724Z DEBUG openraft::storage::helper: helper.rs:193 openraft::storage::helper::StorageHelper<_, _, _>::get_membership membership_in_sm=StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } } membership_in_log=[]

Can you provide the full debug log since the server starts? There should be some log about the initial state machine state just when meta-service started.

kkapper commented 1 week ago

check if my service is running and run commands
ID: 0 NAME : plaid-databend-meta
initialize leader node
Database state already matches or exceeds bootstrap timestamp...initializing normally...
2024-09-13T13:45:29.370981Z  INFO databend_meta::entry: entry.rs:76 Databend Meta version: v1.2.632-nightly-125cb429a5-simd(1.81.0-nightly-2024-09-06T04:33:23.592487613Z)
2024-09-13T13:45:29.371083Z  INFO databend_meta::entry: entry.rs:77 Databend Meta start with config: "{\n  \"cmd\": \"\",\n  \"key\": [\n    \"\"\n  ],\n  \"value\": \"\",\n  \"expire_after\": null,\n  \"prefix\": \"\",\n  \"username\": \"root\",\n  \"password\": \"\",\n  \"config_file\": \"/etc/databend/meta.yaml\",\n  \"log\": {\n    \"file\": {\n      \"on\": true,\n      \"level\": \"DEBUG\",\n      \"dir\": \"/data/databend-meta/log\",\n      \"format\": \"json\",\n      \"limit\": 48,\n      \"prefix_filter\": \"\"\n    },\n    \"stderr\": {\n      \"on\": true,\n      \"level\": \"DEBUG\",\n      \"format\": \"text\"\n    },\n    \"otlp\": {\n      \"on\": false,\n      \"level\": \"INFO\",\n      \"endpoint\": {\n        \"endpoint\": \"http://127.0.0.1:4317\",\n        \"protocol\": \"grpc\",\n        \"labels\": {}\n      }\n    },\n    \"query\": {\n      \"on\": false,\n      \"dir\": \"\",\n      \"otlp\": null\n    },\n    \"profile\": {\n      \"on\": false,\n      \"dir\": \"\",\n      \"otlp\": null\n    },\n    \"structlog\": {\n      \"on\": false,\n      \"dir\": \"\"\n    },\n    \"tracing\": {\n      \"on\": false,\n      \"capture_log_level\": \"INFO\",\n      \"otlp\": {\n        \"endpoint\": \"http://127.0.0.1:4317\",\n        \"protocol\": \"grpc\",\n        \"labels\": {}\n      }\n    }\n  },\n  \"admin_api_address\": \"0.0.0.0:28002\",\n  \"admin_tls_server_cert\": \"\",\n  \"admin_tls_server_key\": \"\",\n  \"grpc_api_address\": \"0.0.0.0:9191\",\n  \"grpc_api_advertise_host\": \"plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local\",\n  \"grpc_tls_server_cert\": \"\",\n  \"grpc_tls_server_key\": \"\",\n  \"raft_config\": {\n    \"config_id\": \"0\",\n    \"raft_listen_host\": \"0.0.0.0\",\n    \"raft_advertise_host\": \"plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local\",\n    \"raft_api_port\": 28004,\n    \"raft_dir\": \"/data/databend-meta/raft\",\n    \"no_sync\": false,\n    \"snapshot_logs_since_last\": 1024,\n    \"heartbeat_interval\": 500,\n    \"install_snapshot_timeout\": 60000,\n    \"max_applied_log_to_keep\": 102400,\n    \"snapshot_chunk_size\": 4194304,\n    \"snapshot_db_debug_check\": true,\n    \"snapshot_db_block_keys\": 8000,\n    \"snapshot_db_block_cache_item\": 1024,\n    \"snapshot_db_block_cache_size\": 1073741824,\n    \"single\": true,\n    \"join\": [],\n    \"leave_via\": [],\n    \"leave_id\": null,\n    \"id\": 0,\n    \"sled_tree_prefix\": \"\",\n    \"sled_max_cache_size_mb\": 10240,\n    \"cluster_name\": \"databend\",\n    \"wait_leader_timeout\": 180000\n  }\n}"
2024-09-13T13:45:29.371719Z  INFO databend_meta::meta_service::meta_node: meta_node.rs:482 '--leave-via' is empty, do not need to leave cluster
2024-09-13T13:45:29.376119Z DEBUG sled::pagecache::logger: logger.rs:623 segment with lsn 9223372036854775807 had computed crc 3971697493, but stored crc 4294967295
2024-09-13T13:45:29.376161Z DEBUG sled::pagecache::logger: logger.rs:623 segment with lsn 9223372036854775807 had computed crc 3971697493, but stored crc 4294967295
2024-09-13T13:45:29.376187Z DEBUG sled::pagecache::logger: logger.rs:623 segment with lsn 9223372036854775807 had computed crc 3971697493, but stored crc 4294967295
2024-09-13T13:45:29.376210Z DEBUG sled::pagecache::logger: logger.rs:623 segment with lsn 9223372036854775807 had computed crc 3971697493, but stored crc 4294967295
2024-09-13T13:45:29.376270Z DEBUG sled::pagecache::logger: logger.rs:623 segment with lsn 9223372036854775807 had computed crc 3971697493, but stored crc 4294967295
2024-09-13T13:45:29.376349Z DEBUG sled::pagecache::iterator: iterator.rs:378 ordering before clearing tears: {164348035072: 524288}, max_header_stable_lsn: 164348035072
2024-09-13T13:45:29.376386Z DEBUG sled::pagecache::iterator: iterator.rs:434 in clean_tail_tears, found missing item in tail: None and we'll scan segments {164348035072: 524288} above lowest lsn 164348035072
2024-09-13T13:45:29.376890Z DEBUG sled::pagecache::iterator: iterator.rs:456 filtering out segments after detected tear at (lsn, lid) 164348043603
2024-09-13T13:45:29.377400Z DEBUG sled::pagecache::iterator: iterator.rs:61 hit max_lsn 164348043603 in iterator, stopping
2024-09-13T13:45:29.377429Z DEBUG sled::pagecache::snapshot: snapshot.rs:367 zeroing the end of the recovered segment at lsn 164348035072 between lids 532820 and 1048575
2024-09-13T13:45:29.384874Z DEBUG sled::pagecache::snapshot: snapshot.rs:615 removing old snapshot file "/data/databend-meta/raft/snap.0000002643E82144"
2024-09-13T13:45:29.385794Z DEBUG sled::pagecache::segment: segment.rs:678 freeing segment 1572864
2024-09-13T13:45:29.386184Z DEBUG sled::pagecache::segment: segment.rs:678 freeing segment 2097152
2024-09-13T13:45:29.386502Z DEBUG sled::pagecache::segment: segment.rs:678 freeing segment 2621440
2024-09-13T13:45:29.386805Z DEBUG sled::pagecache::segment: segment.rs:678 freeing segment 3145728
2024-09-13T13:45:29.387127Z DEBUG sled::pagecache::segment: segment.rs:678 freeing segment 3670016
2024-09-13T13:45:29.387443Z DEBUG sled::pagecache::segment: segment.rs:486 SA starting with tip 4718592 stable -1 free {1572864, 2097152, 2621440, 3145728, 3670016}
2024-09-13T13:45:29.387487Z DEBUG sled::pagecache::iobuf: iobuf.rs:343 starting log at recovered active offset 532820, recovered lsn 164348043604
2024-09-13T13:45:29.387509Z DEBUG sled::pagecache::iobuf: iobuf.rs:371 starting IoBufs with next_lsn: 164348043604 next_lid: 532820
2024-09-13T13:45:29.387537Z DEBUG sled::pagecache: mod.rs:2102 load_snapshot loading pages from 0..4804
Databend Metasrv

Version: v1.2.632-nightly-125cb429a5-simd(1.81.0-nightly-2024-09-06T04:33:23.592487613Z)
Working DataVersion: V003(2024-05-31: Store snapshot in rotbl)

Raft Feature set:
    Server Provide: { append:v0, install_snapshot:v1, install_snapshot:v3, vote:v0 }
    Client Require: { append:v0, install_snapshot:v3, vote:v0 }

2024-09-13T13:45:29.389158Z  INFO databend_meta::entry: entry.rs:124 Initialize on-disk data at /data/databend-meta/raft
2024-09-13T13:45:29.389209Z  INFO databend_common_meta_raft_store::ondisk: mod.rs:79 open and initialize data-version config=RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 }
2024-09-13T13:45:29.389369Z DEBUG databend_common_meta_sled_store::sled_tree: sled_tree.rs:137 SledTree opened tree: header
2024-09-13T13:45:29.389444Z  INFO databend_common_meta_raft_store::ondisk: mod.rs:86 Loaded header: Some(Header { version: V003(2024-05-31: Store snapshot in rotbl), upgrading: None })
On Disk Data:
    Dir: /data/databend-meta/raft
    DataVersion: V003(2024-05-31: Store snapshot in rotbl)
    In-Upgrading: None

Log:
    File: enabled=true, level=DEBUG, dir=/data/databend-meta/log, format=json
    Stderr: enabled=true, level=DEBUG, format=text
Id: 0
Raft Cluster Name: databend
Raft Dir: /data/databend-meta/raft
Raft Status: single

HTTP API
   listening at 0.0.0.0:28002
gRPC API
   listening at 0.0.0.0:9191
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local:9191
Raft API
   listening at 0.0.0.0:28004
   advertise:  plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local:28004

Upgrade ondisk data if out of date: version: V003, upgrading: None
2024-09-13T13:45:29.389545Z  INFO databend_common_meta_raft_store::ondisk: mod.rs:330 Upgrade ondisk data if out of date: version: V003, upgrading: None
    Find and clean previous unfinished upgrading
2024-09-13T13:45:29.389578Z  INFO databend_common_meta_raft_store::ondisk: mod.rs:330     Find and clean previous unfinished upgrading
Upgrade ondisk data finished: version: V003, upgrading: None
2024-09-13T13:45:29.389605Z  INFO databend_common_meta_raft_store::ondisk: mod.rs:330 Upgrade ondisk data finished: version: V003, upgrading: None
2024-09-13T13:45:29.389665Z  INFO databend_meta::entry: entry.rs:161 Starting MetaNode, is-single: true with config: Config { cmd: "", key: [""], value: "", expire_after: None, prefix: "", username: "root", password: "", config_file: "/etc/databend/meta.yaml", log: Config { file: FileConfig { on: true, level: "DEBUG", dir: "/data/databend-meta/log", format: "json", limit: 48, prefix_filter: "" }, stderr: StderrConfig { on: true, level: "DEBUG", format: "text" }, otlp: OTLPConfig { on: false, level: "INFO", endpoint: OTLPEndpointConfig { endpoint: "http://127.0.0.1:4317", protocol: Grpc, labels: {} } }, query: QueryLogConfig { on: false, dir: "", otlp: None }, profile: ProfileLogConfig { on: false, dir: "", otlp: None }, structlog: StructLogConfig { on: false, dir: "" }, tracing: TracingConfig { on: false, capture_log_level: "INFO", otlp: OTLPEndpointConfig { endpoint: "http://127.0.0.1:4317", protocol: Grpc, labels: {} } } }, admin_api_address: "0.0.0.0:28002", admin_tls_server_cert: "", admin_tls_server_key: "", grpc_api_address: "0.0.0.0:9191", grpc_api_advertise_host: Some("plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local"), grpc_tls_server_cert: "", grpc_tls_server_key: "", raft_config: RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 } }
2024-09-13T13:45:29.389672Z DEBUG sled::pagecache::iobuf: iobuf.rs:1208 advancing offset within the current segment from 532820 to 532836
2024-09-13T13:45:29.390169Z  INFO databend_meta::meta_service::meta_node: meta_node.rs:470 start() config=Config { cmd: "", key: [""], value: "", expire_after: None, prefix: "", username: "root", password: "", config_file: "/etc/databend/meta.yaml", log: Config { file: FileConfig { on: true, level: "DEBUG", dir: "/data/databend-meta/log", format: "json", limit: 48, prefix_filter: "" }, stderr: StderrConfig { on: true, level: "DEBUG", format: "text" }, otlp: OTLPConfig { on: false, level: "INFO", endpoint: OTLPEndpointConfig { endpoint: "http://127.0.0.1:4317", protocol: Grpc, labels: {} } }, query: QueryLogConfig { on: false, dir: "", otlp: None }, profile: ProfileLogConfig { on: false, dir: "", otlp: None }, structlog: StructLogConfig { on: false, dir: "" }, tracing: TracingConfig { on: false, capture_log_level: "INFO", otlp: OTLPEndpointConfig { endpoint: "http://127.0.0.1:4317", protocol: Grpc, labels: {} } } }, admin_api_address: "0.0.0.0:28002", admin_tls_server_cert: "", admin_tls_server_key: "", grpc_api_address: "0.0.0.0:9191", grpc_api_advertise_host: Some("plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local"), grpc_tls_server_cert: "", grpc_tls_server_key: "", raft_config: RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 } }
2024-09-13T13:45:29.390800Z  INFO databend_meta::meta_service::meta_node: meta_node.rs:316 open_create_boot, config: RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 }, open: Some(()), create: Some(())
2024-09-13T13:45:29.390997Z  INFO databend_meta::store::store_inner: store_inner.rs:119 open: Some(()), create: Some(()) config_id=0
2024-09-13T13:45:29.391046Z  INFO databend_common_meta_raft_store::state::raft_state: raft_state.rs:69 open: Some(()), create: Some(()) config=RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 }
2024-09-13T13:45:29.391219Z DEBUG databend_common_meta_sled_store::sled_tree: sled_tree.rs:137 SledTree opened tree: raft_state
2024-09-13T13:45:29.391259Z DEBUG databend_common_meta_raft_store::state::raft_state: raft_state.rs:77 get curr_id: Some(0)
2024-09-13T13:45:29.391290Z  INFO databend_meta::store::store_inner: store_inner.rs:125 RaftState opened is_open: true
2024-09-13T13:45:29.391317Z  INFO databend_common_meta_raft_store::log::raft_log: raft_log.rs:45 open RaftLog config=RaftConfig { config_id: "0", raft_listen_host: "0.0.0.0", raft_advertise_host: "plaid-databend-meta-0.plaid-databend-meta.pw-gt.svc.cluster.local", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 500, install_snapshot_timeout: 60000, max_applied_log_to_keep: 102400, snapshot_chunk_size: 4194304, snapshot_db_debug_check: true, snapshot_db_block_keys: 8000, snapshot_db_block_cache_item: 1024, snapshot_db_block_cache_size: 1073741824, single: true, join: [], leave_via: [], leave_id: None, id: 0, sled_tree_prefix: "", sled_max_cache_size_mb: 10240, cluster_name: "databend", wait_leader_timeout: 180000 }
2024-09-13T13:45:29.391481Z DEBUG databend_common_meta_sled_store::sled_tree: sled_tree.rs:137 SledTree opened tree: raft_log
2024-09-13T13:45:29.391505Z  INFO databend_meta::store::store_inner: store_inner.rs:128 RaftLog opened
2024-09-13T13:45:29.391818Z  INFO databend_common_meta_raft_store::sm_v003::snapshot_loader: snapshot_loader.rs:134 dir: /data/databend-meta/raft/df_meta/V003/snapshot; loaded snapshots: []
2024-09-13T13:45:29.391851Z  INFO databend_common_meta_raft_store::sm_v003::snapshot_loader: snapshot_loader.rs:135 dir: /data/databend-meta/raft/df_meta/V003/snapshot; invalid files: []
2024-09-13T13:45:29.391910Z  INFO databend_common_meta_raft_store::sm_v003::snapshot_loader: snapshot_loader.rs:55 choose the latest from found snapshots: []
2024-09-13T13:45:29.391934Z  INFO databend_meta::store::store_inner: store_inner.rs:155 No snapshot, skip rebuilding state machine
2024-09-13T13:45:29.392054Z DEBUG openraft::raft: mod.rs:233 new; cluster=databend
2024-09-13T13:45:29.392090Z DEBUG openraft::core::tick: tick.rs:75 tick;
2024-09-13T13:45:29.392147Z DEBUG openraft::raft: mod.rs:261 RaftCore; id=0 cluster=databend
2024-09-13T13:45:29.392529Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:187 get_log_state: (None,Some(LogId { leader_id: LeaderId { term: 2234, node_id: 1 }, index: 48019 })]
2024-09-13T13:45:29.392585Z DEBUG databend_meta::store::raft_state_machine_impl: raft_state_machine_impl.rs:51 applied_state: applied: None, membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }
2024-09-13T13:45:29.392639Z  INFO openraft::storage::helper: helper.rs:76 get_initial_state vote=<T2234-N1:Q> last_purged_log_id=None last_applied=None committed=T2234-N1.48019 last_log_id=T2234-N1.48019
2024-09-13T13:45:29.392724Z  INFO openraft::storage::helper: helper.rs:96 re-apply log 0..48020 to state machine
2024-09-13T13:45:29.392752Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:105 RaftStore::try_get_log_entries: self.id=0, range: 0..48020
2024-09-13T13:45:29.394599Z DEBUG sled::pagecache::iobuf: iobuf.rs:853 wrote lsns 164348043604-164348043619 to disk at offsets 532820-532835, maxed false complete_len 16
2024-09-13T13:45:29.394641Z DEBUG sled::pagecache::iobuf: iobuf.rs:895 mark_interval(164348043604, 16)
2024-09-13T13:45:29.394666Z DEBUG sled::pagecache::iobuf: iobuf.rs:220 new highest interval: 164348043604 - 164348043619
2024-09-13T13:45:29.402208Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:117 RaftStore::try_get_log_entries: done: self.id=0, range: 0..48020
2024-09-13T13:45:29.402254Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:22:31.856000Z+0000
2024-09-13T13:45:29.402274Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.47998:normal, log_time_ms: 1726075351856
2024-09-13T13:45:29.402307Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075351856
2024-09-13T13:45:29.402360Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.47998 time: 1726075351856 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.402432Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.402504Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.402592Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.402690Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.402774Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.402873Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:23:09.117000Z+0000
2024-09-13T13:45:29.402895Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.47999:normal, log_time_ms: 1726075389117
2024-09-13T13:45:29.402934Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075389117
2024-09-13T13:45:29.402957Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.47999 time: 1726075389117 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.403042Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.403100Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.403179Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.403258Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.403335Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.403417Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:23:38.740000Z+0000
2024-09-13T13:45:29.403437Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48000:normal, log_time_ms: 1726075418740
2024-09-13T13:45:29.403473Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075418740
2024-09-13T13:45:29.403494Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48000 time: 1726075418740 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.403568Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.403629Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.403706Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.403783Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.403878Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.403946Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:24:03.121000Z+0000
2024-09-13T13:45:29.403966Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48001:normal, log_time_ms: 1726075443121
2024-09-13T13:45:29.404005Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075443121
2024-09-13T13:45:29.404028Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48001 time: 1726075443121 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.404103Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.404156Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.404233Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.404312Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.404394Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.404465Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:24:25.755000Z+0000
2024-09-13T13:45:29.404485Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48002:normal, log_time_ms: 1726075465755
2024-09-13T13:45:29.404518Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075465755
2024-09-13T13:45:29.404537Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48002 time: 1726075465755 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.404612Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.404678Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.404758Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.404837Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.404935Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.405010Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:24:55.422000Z+0000
2024-09-13T13:45:29.405031Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48003:normal, log_time_ms: 1726075495422
2024-09-13T13:45:29.405068Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075495422
2024-09-13T13:45:29.405090Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48003 time: 1726075495422 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.405163Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.405227Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.405307Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.405394Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.405474Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.405549Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:25:20.084000Z+0000
2024-09-13T13:45:29.405570Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48004:normal, log_time_ms: 1726075520084
2024-09-13T13:45:29.405603Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075520084
2024-09-13T13:45:29.405624Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48004 time: 1726075520084 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.405697Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.405759Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.405836Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.405927Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.406008Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.406079Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:25:53.714000Z+0000
2024-09-13T13:45:29.406097Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48005:normal, log_time_ms: 1726075553714
2024-09-13T13:45:29.406121Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075553714
2024-09-13T13:45:29.406137Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48005 time: 1726075553714 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.406201Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.406268Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.406349Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.406427Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.406504Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.406578Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:21.575000Z+0000
2024-09-13T13:45:29.406598Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48006:normal, log_time_ms: 1726075581575
2024-09-13T13:45:29.406631Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075581575
2024-09-13T13:45:29.406651Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48006 time: 1726075581575 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.406729Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.406793Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.406883Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.406960Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.407038Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.407113Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:49.123000Z+0000
2024-09-13T13:45:29.407135Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48007:normal, log_time_ms: 1726075609123
2024-09-13T13:45:29.407171Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075609123
2024-09-13T13:45:29.407197Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48007 time: 1726075609123 ms cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48471),__fd_table_by_id/48303 == seq(48319),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48308)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48303),Delete(Delete key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.407293Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48471),__fd_table_by_id/48303 == seq(48319),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48308)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48303),Delete(Delete key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.407399Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_database_by_id/6073 == seq(48471),__fd_table_by_id/48303 == seq(48319),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48308)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48303),Delete(Delete key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.407473Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_database_by_id/6073 == seq(48471)
2024-09-13T13:45:29.407510Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_database_by_id/6073 == seq(48471)
2024-09-13T13:45:29.407545Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_database_by_id/6073 curr: seq:0 value:None
2024-09-13T13:45:29.407576Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48471),__fd_table_by_id/48303 == seq(48319),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48308)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48303),Delete(Delete key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [], error: }
2024-09-13T13:45:29.407670Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:49.155000Z+0000
2024-09-13T13:45:29.407688Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48008:normal, log_time_ms: 1726075609155
2024-09-13T13:45:29.407720Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075609155
2024-09-13T13:45:29.407742Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48008 time: 1726075609155 ms cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48303)] else:[] }
2024-09-13T13:45:29.407800Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48303)] else:[] }
2024-09-13T13:45:29.407838Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48303)] else:[] }
2024-09-13T13:45:29.407890Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Delete(Delete key=__fd_object_owners/plaid/table-by-id/48303)
2024-09-13T13:45:29.407918Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48303", seq: GE(1), value: Delete, value_meta: None }
2024-09-13T13:45:29.407978Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48303", seq: GE(1), value: Delete, value_meta: None }; prev: None; result: None
2024-09-13T13:45:29.408039Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48303)] else:[] }; res: AppliedState: Txn: TxnReply{ success: true, responses: [TxnOpResponse: Delete: Delete-resp: success: false, key=__fd_object_owners/plaid/table-by-id/48303, prev_seq=None], error: }
2024-09-13T13:45:29.408097Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:49.220000Z+0000
2024-09-13T13:45:29.408119Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48009:normal, log_time_ms: 1726075609220
2024-09-13T13:45:29.408150Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075609220
2024-09-13T13:45:29.408173Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48009 time: 1726075609220 ms cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None)
2024-09-13T13:45:29.408228Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None)
2024-09-13T13:45:29.408271Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }
2024-09-13T13:45:29.408335Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }
2024-09-13T13:45:29.408406Z DEBUG databend_common_meta_types::sys_data: sys_data.rs:56 next_seq: 1
2024-09-13T13:45:29.408440Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }; prev: TombStone { internal_seq: 0 }; res: Normal { internal_seq: 1, value: [], meta: None }
2024-09-13T13:45:29.408524Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }; prev: None; result: Some(SeqV { seq: 1, meta: None, data: "[binary]" })
2024-09-13T13:45:29.408608Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None); res: AppliedState: KV: id: Noneprev: Noneresult: Some(SeqV { seq: 1, meta: None, data: "[binary]" })
2024-09-13T13:45:29.408686Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:49.248000Z+0000
2024-09-13T13:45:29.408707Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48010:normal, log_time_ms: 1726075609248
2024-09-13T13:45:29.408743Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075609248
2024-09-13T13:45:29.408766Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48010 time: 1726075609248 ms cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48486),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(0),__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48306)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48488),Put(Put key=__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0),Put(Put key=__fd_table_id_to_name/48488),Put(Put key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.408889Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48486),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(0),__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48306)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48488),Put(Put key=__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0),Put(Put key=__fd_table_id_to_name/48488),Put(Put key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.408988Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_database_by_id/6073 == seq(48486),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(0),__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48306)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48488),Put(Put key=__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0),Put(Put key=__fd_table_id_to_name/48488),Put(Put key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }
2024-09-13T13:45:29.409085Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_database_by_id/6073 == seq(48486)
2024-09-13T13:45:29.409127Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_database_by_id/6073 == seq(48486)
2024-09-13T13:45:29.409165Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_database_by_id/6073 curr: seq:0 value:None
2024-09-13T13:45:29.409198Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48486),__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(0),__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0 == seq(48306)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48488),Put(Put key=__fd_table_id_list/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0),Put(Put key=__fd_table_id_to_name/48488),Put(Put key=__fd_table/6073/analyzetable_8034d191%2d29c0%2d4105%2d968d%2d95cc047d31a0)] else:[] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [], error: }
2024-09-13T13:45:29.409303Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:49.280000Z+0000
2024-09-13T13:45:29.409325Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48011:normal, log_time_ms: 1726075609280
2024-09-13T13:45:29.409367Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075609280
2024-09-13T13:45:29.409395Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48011 time: 1726075609280 ms cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48488)] else:[] }
2024-09-13T13:45:29.409452Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48488)] else:[] }
2024-09-13T13:45:29.409496Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48488)] else:[] }
2024-09-13T13:45:29.409542Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Put(Put key=__fd_object_owners/plaid/table-by-id/48488)
2024-09-13T13:45:29.409573Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48488", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }
2024-09-13T13:45:29.409645Z DEBUG databend_common_meta_types::sys_data: sys_data.rs:56 next_seq: 2
2024-09-13T13:45:29.409674Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48488", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }; prev: TombStone { internal_seq: 0 }; res: Normal { internal_seq: 2, value: [10, 6, 112, 117, 98, 108, 105, 99, 18, 24, 18, 16, 10, 7, 100, 101, 102, 97, 117, 108, 116, 16, 185, 47, 24, 232, 250, 2, 160, 6, 108, 168, 6, 24, 160, 6, 108, 168, 6, 24], meta: Some(KVMeta { expire_at: None }) }
2024-09-13T13:45:29.409888Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48488", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }; prev: None; result: Some(SeqV { seq: 2, meta: Some(KVMeta { expire_at: None }), data: "[binary]" })
2024-09-13T13:45:29.410002Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48488)] else:[] }; res: AppliedState: Txn: TxnReply{ success: true, responses: [TxnOpResponse: Put: Put-resp: key=__fd_object_owners/plaid/table-by-id/48488, prev_seq=None], error: }
2024-09-13T13:45:29.410066Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:51.094000Z+0000
2024-09-13T13:45:29.410087Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48012:normal, log_time_ms: 1726075611094
2024-09-13T13:45:29.410123Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075611094
2024-09-13T13:45:29.410145Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48012 time: 1726075611094 ms cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.410221Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }))
2024-09-13T13:45:29.410283Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.410367Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }
2024-09-13T13:45:29.410446Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13", seq: GE(1), value: AsIs, value_meta: Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) }) }; prev: None; result: None
2024-09-13T13:45:29.410526Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_clusters_v3/plaid/default/databend_query/IOAGwIDNurpfq2cQJD4X13(GE(1)) = AsIs (Some(MetaSpec { expire_at: None, ttl: Some(Interval { millis: 60000 }) })); res: AppliedState: KV: id: Noneprev: Noneresult: None
2024-09-13T13:45:29.410596Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:57.857000Z+0000
2024-09-13T13:45:29.410616Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48013:normal, log_time_ms: 1726075617857
2024-09-13T13:45:29.410651Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075617857
2024-09-13T13:45:29.410674Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48013 time: 1726075617857 ms cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None)
2024-09-13T13:45:29.410730Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None)
2024-09-13T13:45:29.410775Z DEBUG databend_common_meta_raft_store::applier: applier.rs:198 apply_update_kv_cmd upsert_kv=UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }
2024-09-13T13:45:29.410839Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }
2024-09-13T13:45:29.410918Z DEBUG databend_common_meta_types::sys_data: sys_data.rs:56 next_seq: 3
2024-09-13T13:45:29.410940Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }; prev: Normal { internal_seq: 1, value: [], meta: None }; res: Normal { internal_seq: 3, value: [], meta: None }
2024-09-13T13:45:29.411049Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_id_gen/table_id", seq: GE(0), value: Update("[binary]"), value_meta: None }; prev: Some(SeqV { seq: 1, meta: None, data: "[binary]" }); result: Some(SeqV { seq: 3, meta: None, data: "[binary]" })
2024-09-13T13:45:29.411153Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: upsert_kv:__fd_id_gen/table_id(GE(0)) = Update("[binary]") (None); res: AppliedState: KV: id: Noneprev: Some(SeqV { seq: 1, meta: None, data: "[binary]" })result: Some(SeqV { seq: 3, meta: None, data: "[binary]" })
2024-09-13T13:45:29.411250Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:57.890000Z+0000
2024-09-13T13:45:29.411271Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48014:normal, log_time_ms: 1726075617890
2024-09-13T13:45:29.411302Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075617890
2024-09-13T13:45:29.411327Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48014 time: 1726075617890 ms cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48489),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0),__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437),Put(Put key=__fd_table_id_to_name/48496),Put(Put key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.411451Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48489),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0),__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437),Put(Put key=__fd_table_id_to_name/48496),Put(Put key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.411545Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_database_by_id/6073 == seq(48489),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0),__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437),Put(Put key=__fd_table_id_to_name/48496),Put(Put key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.411637Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_database_by_id/6073 == seq(48489)
2024-09-13T13:45:29.411671Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_database_by_id/6073 == seq(48489)
2024-09-13T13:45:29.411700Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_database_by_id/6073 curr: seq:0 value:None
2024-09-13T13:45:29.411731Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48489),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0),__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(0)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_id_list/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437),Put(Put key=__fd_table_id_to_name/48496),Put(Put key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [], error: }
2024-09-13T13:45:29.411840Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:57.925000Z+0000
2024-09-13T13:45:29.411874Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48015:normal, log_time_ms: 1726075617925
2024-09-13T13:45:29.411908Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075617925
2024-09-13T13:45:29.411930Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48015 time: 1726075617925 ms cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.411992Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.412030Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.412072Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Put(Put key=__fd_object_owners/plaid/table-by-id/48496)
2024-09-13T13:45:29.412104Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }
2024-09-13T13:45:29.412182Z DEBUG databend_common_meta_types::sys_data: sys_data.rs:56 next_seq: 4
2024-09-13T13:45:29.412210Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }; prev: TombStone { internal_seq: 0 }; res: Normal { internal_seq: 4, value: [10, 6, 112, 117, 98, 108, 105, 99, 18, 24, 18, 16, 10, 7, 100, 101, 102, 97, 117, 108, 116, 16, 185, 47, 24, 240, 250, 2, 160, 6, 108, 168, 6, 24, 160, 6, 108, 168, 6, 24], meta: Some(KVMeta { expire_at: None }) }
2024-09-13T13:45:29.412422Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(0), value: Update("[binary]"), value_meta: Some(MetaSpec { expire_at: None, ttl: None }) }; prev: None; result: Some(SeqV { seq: 4, meta: Some(KVMeta { expire_at: None }), data: "[binary]" })
2024-09-13T13:45:29.412549Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[] then:[Put(Put key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }; res: AppliedState: Txn: TxnReply{ success: true, responses: [TxnOpResponse: Put: Put-resp: key=__fd_object_owners/plaid/table-by-id/48496, prev_seq=None], error: }
2024-09-13T13:45:29.412611Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:58.666000Z+0000
2024-09-13T13:45:29.412633Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48016:normal, log_time_ms: 1726075618666
2024-09-13T13:45:29.412665Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075618666
2024-09-13T13:45:29.412693Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48016 time: 1726075618666 ms cmd: txn:TxnRequest{ if:[__fd_table_by_id/48496 == seq(48498),__fd_table_by_id/48496 == seq(48498)] then:[Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_copied_files/48496/data_0.csv  ttl: 86400s)] else:[Get(Get key=__fd_table_by_id/48496)] }
2024-09-13T13:45:29.412784Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_table_by_id/48496 == seq(48498),__fd_table_by_id/48496 == seq(48498)] then:[Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_copied_files/48496/data_0.csv  ttl: 86400s)] else:[Get(Get key=__fd_table_by_id/48496)] }
2024-09-13T13:45:29.412873Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_table_by_id/48496 == seq(48498),__fd_table_by_id/48496 == seq(48498)] then:[Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_copied_files/48496/data_0.csv  ttl: 86400s)] else:[Get(Get key=__fd_table_by_id/48496)] }
2024-09-13T13:45:29.412949Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_table_by_id/48496 == seq(48498)
2024-09-13T13:45:29.412987Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_table_by_id/48496 == seq(48498)
2024-09-13T13:45:29.413019Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_table_by_id/48496 curr: seq:0 value:None
2024-09-13T13:45:29.413041Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Get(Get key=__fd_table_by_id/48496)
2024-09-13T13:45:29.413085Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_table_by_id/48496 == seq(48498),__fd_table_by_id/48496 == seq(48498)] then:[Put(Put key=__fd_table_by_id/48496),Put(Put key=__fd_table_copied_files/48496/data_0.csv  ttl: 86400s)] else:[Get(Get key=__fd_table_by_id/48496)] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [TxnOpResponse: Get: Get-resp: key=__fd_table_by_id/48496, prev_seq=None], error: }
2024-09-13T13:45:29.413180Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:59.099000Z+0000
2024-09-13T13:45:29.413202Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48017:normal, log_time_ms: 1726075619099
2024-09-13T13:45:29.413237Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075619099
2024-09-13T13:45:29.413259Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48017 time: 1726075619099 ms cmd: txn:TxnRequest{ if:[__fd_table_by_id/48488 == seq(48490)] then:[Put(Put key=__fd_table_by_id/48488)] else:[Get(Get key=__fd_table_by_id/48488)] }
2024-09-13T13:45:29.413360Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_table_by_id/48488 == seq(48490)] then:[Put(Put key=__fd_table_by_id/48488)] else:[Get(Get key=__fd_table_by_id/48488)] }
2024-09-13T13:45:29.413411Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_table_by_id/48488 == seq(48490)] then:[Put(Put key=__fd_table_by_id/48488)] else:[Get(Get key=__fd_table_by_id/48488)] }
2024-09-13T13:45:29.413467Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_table_by_id/48488 == seq(48490)
2024-09-13T13:45:29.413497Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_table_by_id/48488 == seq(48490)
2024-09-13T13:45:29.413533Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_table_by_id/48488 curr: seq:0 value:None
2024-09-13T13:45:29.413562Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Get(Get key=__fd_table_by_id/48488)
2024-09-13T13:45:29.413593Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_table_by_id/48488 == seq(48490)] then:[Put(Put key=__fd_table_by_id/48488)] else:[Get(Get key=__fd_table_by_id/48488)] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [TxnOpResponse: Get: Get-resp: key=__fd_table_by_id/48488, prev_seq=None], error: }
2024-09-13T13:45:29.413668Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:59.185000Z+0000
2024-09-13T13:45:29.413688Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48018:normal, log_time_ms: 1726075619185
2024-09-13T13:45:29.413722Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075619185
2024-09-13T13:45:29.413745Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48018 time: 1726075619185 ms cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.413841Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.413942Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }
2024-09-13T13:45:29.414032Z DEBUG databend_common_meta_raft_store::applier: applier.rs:269 txn_execute_condition condition=__fd_database_by_id/6073 == seq(48497)
2024-09-13T13:45:29.414069Z DEBUG databend_common_meta_raft_store::applier: applier.rs:281 txn_execute_one_condition cond=__fd_database_by_id/6073 == seq(48497)
2024-09-13T13:45:29.414104Z DEBUG databend_common_meta_raft_store::applier: applier.rs:290 txn_execute_one_condition: key: __fd_database_by_id/6073 curr: seq:0 value:None
2024-09-13T13:45:29.414134Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[__fd_database_by_id/6073 == seq(48497),__fd_table_by_id/48496 == seq(48503),__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437 == seq(48501)] then:[Put(Put key=__fd_database_by_id/6073),Put(Put key=__fd_table_by_id/48496),Delete(Delete key=__fd_table/6073/temp_9a027f38%2d67f7%2d42f9%2dbdf1%2dfc751ba9d437)] else:[] }; res: AppliedState: Txn: TxnReply{ success: false, responses: [], error: }
2024-09-13T13:45:29.414232Z DEBUG databend_common_meta_raft_store::applier: applier.rs:532 apply: raft-log time: 2024-09-11T17:26:59.228000Z+0000
2024-09-13T13:45:29.414252Z DEBUG databend_common_meta_raft_store::applier: applier.rs:87 apply: entry: T2234-N1.48019:normal, log_time_ms: 1726075619228
2024-09-13T13:45:29.414285Z DEBUG databend_common_meta_raft_store::applier: applier.rs:469 to clean expired kvs, log_time_ts: 1726075619228
2024-09-13T13:45:29.414306Z  INFO databend_common_meta_raft_store::applier: applier.rs:102 apply: normal: T2234-N1.48019 time: 1726075619228 ms cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.414372Z DEBUG databend_common_meta_raft_store::applier: applier.rs:133 apply_cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.414415Z DEBUG databend_common_meta_raft_store::applier: applier.rs:240 apply txn cmd txn=TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }
2024-09-13T13:45:29.414457Z DEBUG databend_common_meta_raft_store::applier: applier.rs:348 txn execute TxnOp op=Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)
2024-09-13T13:45:29.414490Z DEBUG databend_common_meta_raft_store::applier: applier.rs:214 upsert_kv upsert_kv=UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }
2024-09-13T13:45:29.414553Z DEBUG databend_common_meta_raft_store::sm_v003::sm_v003: sm_v003.rs:372 applied upsert: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }; prev: Normal { internal_seq: 4, value: [10, 6, 112, 117, 98, 108, 105, 99, 18, 24, 18, 16, 10, 7, 100, 101, 102, 97, 117, 108, 116, 16, 185, 47, 24, 240, 250, 2, 160, 6, 108, 168, 6, 24, 160, 6, 108, 168, 6, 24], meta: Some(KVMeta { expire_at: None }) }; res: TombStone { internal_seq: 4 }
2024-09-13T13:45:29.414746Z DEBUG databend_common_meta_raft_store::applier: applier.rs:228 applied UpsertKV: UpsertKV { key: "__fd_object_owners/plaid/table-by-id/48496", seq: GE(1), value: Delete, value_meta: None }; prev: Some(SeqV { seq: 4, meta: Some(KVMeta { expire_at: None }), data: "[binary]" }); result: None
2024-09-13T13:45:29.414837Z DEBUG databend_common_meta_raft_store::applier: applier.rs:149 apply_result: cmd: txn:TxnRequest{ if:[] then:[Delete(Delete key=__fd_object_owners/plaid/table-by-id/48496)] else:[] }; res: AppliedState: Txn: TxnReply{ success: true, responses: [TxnOpResponse: Delete: Delete-resp: success: true, key=__fd_object_owners/plaid/table-by-id/48496, prev_seq=Some(4)], error: }
2024-09-13T13:45:29.414924Z DEBUG databend_meta::store::raft_state_machine_impl: raft_state_machine_impl.rs:51 applied_state: applied: Some(LogId { leader_id: LeaderId { term: 2234, node_id: 1 }, index: 48019 }), membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }
2024-09-13T13:45:29.415052Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:187 get_log_state: (None,Some(LogId { leader_id: LeaderId { term: 2234, node_id: 1 }, index: 48019 })]
2024-09-13T13:45:29.415105Z  INFO openraft::storage::helper: helper.rs:231 load membership from log: [48020..48020)
2024-09-13T13:45:29.415141Z DEBUG openraft::storage::helper: helper.rs:193 openraft::storage::helper::StorageHelper<_, _, _>::get_membership membership_in_sm=StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } } membership_in_log=[]
2024-09-13T13:45:29.415195Z  INFO openraft::storage::helper: helper.rs:120 load key log ids from (None,T2234-N1.48019]
2024-09-13T13:45:29.415235Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:105 RaftStore::try_get_log_entries: self.id=0, range: 0..=0
2024-09-13T13:45:29.415271Z DEBUG databend_meta::store::raft_log_storage_impl: raft_log_storage_impl.rs:117 RaftStore::try_get_log_entries: done: self.id=0, range: 0..=0
2024-09-13T13:45:29.415335Z  INFO openraft::core::tick: tick.rs:145 Timer shutdown signal sent: Ok(())
2024-09-13T13:45:29.415882Z  INFO openraft::core::tick: tick.rs:101 TickLoop received cancel signal, quit
Error: when Read LogIndex(0): log entry not found

kkapper commented 1 week ago

This is complete startup logs. Until we have an error.

kkapper commented 1 week ago

I have some suspicion that the issue here might be related to the way the bootstrap process works.

This is the initialization script that is included with all databend meta pods from the helm chart:

              echo "check if my service is running and run commands ";
              if [[ $POD_NAME =~ (.*)-([0-9]+)$ ]]
              then
                ID=${BASH_REMATCH[2]}
                NAME=${BASH_REMATCH[1]}
                echo "ID: $ID" "NAME : $NAME"
              {{- if $bootstrap }}
                case ${BASH_REMATCH[2]} in
                0)
                  echo "initialize leader node";
                  exec /databend-meta --id ${ID} --config-id ${ID} \
                      --single \
                      --raft-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                      --grpc-api-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                      --config-file /etc/databend/meta.yaml
                  ;;
                *)
                  echo "initialize follower node";
                  exec /databend-meta --id ${ID} --config-id ${ID} \
                      --join "${NAME}-0.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local:28004" \
                      --raft-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                      --grpc-api-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                      --config-file /etc/databend/meta.yaml
                  ;;
                esac
              {{- else }}
                exec /databend-meta --id ${ID} --config-id ${ID} \
                  {{- range $i := until $replicaCount }}
                  --join "${NAME}-{{ $i }}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local:28004" \
                  {{- end }}
                  --raft-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                  --grpc-api-advertise-host "${POD_NAME}.{{ $fullName }}.${POD_NAMESPACE}.svc.cluster.local" \
                  --config-file /etc/databend/meta.yaml
              {{- end }}
              else
                echo pod name $POD_NAME is not valid && exit 1
              fi

kkapper commented 1 week ago

If the nodes have done a failover, node 0 would not be the master node anymore. But we are bootstrapping it as if it was.

kkapper commented 1 week ago

This script might need changed to solve which node is the master and initialize it with variables instead of using the node indices.

kkapper commented 1 week ago

I'm testing if this is true at the moment, will report findings.

inviscid commented 1 week ago

For some context here, hopefully to explain why it might run fine for a few days and then enter into an unhealthy state, we are currently testing using SPOT instances to simulate pod failures over time. It may be that the pod is being restarted after a delay and is no longer in-sync with the rest of the meta pods in the cluster.

I don't know if this is helpful information or irrelevant but just thought I'd let you know.

Our expectation was that meta pod loss and recovery should be transparent to the overall Databend process and that a meta pod rejoining the meta cluster would rejoin and sync up as quickly as it could and then remain a follower until elected leader in the future. We may be misinterpreting the logic but it seems like node 0 will try to become the leader even if another leader is present in the meta cluster already.

drmingdrmer commented 1 week ago

It looks like the snapshot once was removed from this node, which leads to the following error:

2024-09-13T13:45:29.391818Z  INFO databend_common_meta_raft_store::sm_v003::snapshot_loader: snapshot_loader.rs:134 dir: /data/databend-meta/raft/df_meta/V003/snapshot; loaded snapshots: []

If there is a Leader in the cluster that contains complete data. This node can be rebuilt with the following steps:

shutdown this node.
remove all data from this node.
restart this node. And the data will be automatically synchronized to this node from the Leader.

kkapper commented 1 week ago

@drmingdrmer this fix does work to fix the error.

There is some more we should discuss though:

What causes this snapshot file to be deleted?
databend-meta will not start at all if this file is corrupted or missing. Should it be able to bootstrap from a running leader?
Should I just be manually making backups of snapshot files in addition to using databendmeta-ctl export db? I am capable of backing up that directory and restoring it before node turning on if needed.

drmingdrmer commented 1 week ago

What causes this snapshot file to be deleted?

I'm not sure about this issue. It hasn't occurred in any of our other deployments. The oldest snapshot will be removed if there are more than 3 snapshot files. This is the only scenario in which meta-service deletes snapshot files.

databend-meta will not start at all if this file is corrupted or missing. Should it be able to bootstrap from a running leader?

What do you mean about bootstrap from a running leader? If this node is a member of a cluster, and it does not contain any data, the leader will replicate all of the data and recover it.

Should I just be manually making backups of snapshot files in addition to using databendmeta-ctl export db? I am capable of backing up that directory and restoring it before node turning on if needed.

databend-metactl --export is used to backup all data, including raft-log and raft-snapshot. A real-world production should always backup.

Backing up the dir does work. You are very likely backing up a inconsistent database, since a running databend-meta may be updating the dir parallelly.

databendlabs / databend