Title
#general
n

Nick Burrett

07/03/2022, 1:25 PM
I've tried to setup the metadata service as 3 replicas on kubernetes, initally using the helm scripts which installs v0.7.85-nightly. I don't get any indication in nodes 2 and 3 that they are making any attempt to collect to the primary raft server (node 1) during bootstrap, similarly there is no indication on node 1 any attempted incoming connection from nodes 2 any 3. I have port-scanned all 3 pods to ensure that all 3 ports 28002, 9191, 28004 are visible and connectable for each pod and have confirmed that join-hostname for node is correct. But it's unclear as to what/why nodes 2 & 3 choose not to talk to node 1 as there's nothing in the logs to indicate a refusal to do any work. Log here is from v0.7.113-nightly node 2:
2022-07-03T12:59:49.610820Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "2", endpoint: Endpoint { addr: "10.240.1.217", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="2"}: databend_meta::meta_service::raftmeta: MetaNode started: RaftConfig { config_id: "2", raft_listen_host: "0.0.0.0", raft_advertise_host: "10.240.1.217", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 1000, install_snapshot_timeout: 4000, max_applied_log_to_keep: 1000, single: false, join: ["metrics-meta-0.metrics-meta.databend:28004"], leave_via: [], leave_id: None, id: 2, sled_tree_prefix: "", cluster_name: "foo_cluster" }
2022-07-03T12:59:49.611332Z  INFO start: databend_meta::meta_service::raftmeta: Done starting MetaNode: Config { cmd: "", config_file: "", log_level: "DEBUG", log_dir: "/data/databend-meta/log", 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_tls_server_cert: "", grpc_tls_server_key: "", raft_config: RaftConfig { config_id: "2", raft_listen_host: "0.0.0.0", raft_advertise_host: "10.240.1.217", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 1000, install_snapshot_timeout: 4000, max_applied_log_to_keep: 1000, single: false, join: ["metrics-meta-0.metrics-meta.databend:28004"], leave_via: [], leave_id: None, id: 2, sled_tree_prefix: "", cluster_name: "foo_cluster" } }
2022-07-03T12:59:49.611483Z  INFO databend_meta: HTTP API server listening on 0.0.0.0:28002
2022-07-03T12:59:49.611541Z  WARN databend_meta::api::http_service: Http API TLS not set
2022-07-03T12:59:49.611772Z  INFO databend_meta: Databend meta server listening on 0.0.0.0:9191
2022-07-03T12:59:49.611792Z  INFO poem::server: listening addr=<socket://0.0.0.0:28002>
2022-07-03T12:59:49.611819Z  INFO databend_meta::api::grpc_server: GrpcServer::start
2022-07-03T12:59:49.611829Z  INFO poem::server: server started
2022-07-03T12:59:49.612510Z  INFO databend_meta::api::grpc_server: gRPC addr: 0.0.0.0:9191
2022-07-03T12:59:49.612674Z  INFO spawn-grpc: databend_meta::api::grpc_server: metasrv starts to wait for stop signal: 0.0.0.0:9191
2022-07-03T12:59:49.612943Z  INFO databend_meta::api::grpc_server: Done GrpcServer::start
2022-07-03T12:59:49.613099Z  INFO join_cluster{grpc_api_addr="0.0.0.0:9191"}: databend_meta::meta_service::raftmeta: meta node is opened
2022-07-03T12:59:49.613121Z DEBUG sled::pagecache::iobuf: wrote lsns 1076-1087 to disk at offsets 1076-1087, maxed false complete_len 12    
2022-07-03T12:59:49.613357Z DEBUG sled::pagecache::iobuf: mark_interval(1076, 12)    
2022-07-03T12:59:49.613423Z DEBUG sled::pagecache::iobuf: new highest interval: 1076 - 1087    
2022-07-03T12:59:49.613641Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "2", endpoint: Endpoint { addr: "10.240.1.217", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="2"}:new{id=2 cluster=foo_cluster}:get_current_snapshot{id=2}: databend_meta::store::meta_raft_store: got snapshot start
2022-07-03T12:59:49.613669Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "2", endpoint: Endpoint { addr: "10.240.1.217", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="2"}:new{id=2 cluster=foo_cluster}:get_current_snapshot{id=2}: databend_meta::store::meta_raft_store: got snapshot complete
2022-07-03T12:59:49.613684Z DEBUG start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "2", endpoint: Endpoint { addr: "10.240.1.217", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="2"}:new{id=2 cluster=foo_cluster}: openraft::core: id=2 target_state: Learner
2022-07-03T12:59:49.613727Z DEBUG start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "2", endpoint: Endpoint { addr: "10.240.1.217", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="2"}:new{id=2 cluster=foo_cluster}:run{id=2 raft_state="learner"}: openraft::core: report_metrics: Metrics{id:2,Learner, term:0, last_log:None, last_applied:None, leader:None, membership:{log_id:0-0 membership:[{2}]}, snapshot:None, replication:
2022-07-03T12:59:54.831697Z DEBUG hyper::proto::h1::io: parsed 4 headers
2022-07-03T12:59:54.831746Z DEBUG hyper::proto::h1::conn: incoming body is empty
2022-07-03T12:59:54.831831Z DEBUG hyper::proto::h1::io: flushed 140 bytes
2022-07-03T12:59:59.832556Z DEBUG hyper::proto::h1::io: parsed 4 headers
1:27 PM
The config for node 1:
2022-07-03T12:54:16.688400Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=true node=Node { name: "1", endpoint: Endpoint { addr: "10.240.1.104", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="1"}:start_grpc{host="0.0.0.0" port=28004}: databend_meta::meta_service::raftmeta: about to start raft grpc on resolved addr 0.0.0.0:28004
2022-07-03T12:54:16.688504Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=true node=Node { name: "1", endpoint: Endpoint { addr: "10.240.1.104", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="1"}: databend_meta::meta_service::raftmeta: MetaNode started: RaftConfig { config_id: "1", raft_listen_host: "0.0.0.0", raft_advertise_host: "10.240.1.104", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 1000, install_snapshot_timeout: 4000, max_applied_log_to_keep: 1000, single: true, join: [], leave_via: [], leave_id: None, id: 1, sled_tree_prefix: "", cluster_name: "foo_cluster" }
2022-07-03T12:54:16.688587Z  INFO start: databend_meta::meta_service::raftmeta: Done starting MetaNode: Config { cmd: "", config_file: "", log_level: "DEBUG", log_dir: "/data/databend-meta/log", 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_tls_server_cert: "", grpc_tls_server_key: "", raft_config: RaftConfig { config_id: "1", raft_listen_host: "0.0.0.0", raft_advertise_host: "10.240.1.104", raft_api_port: 28004, raft_dir: "/data/databend-meta/raft", no_sync: false, snapshot_logs_since_last: 1024, heartbeat_interval: 1000, install_snapshot_timeout: 4000, max_applied_log_to_keep: 1000, single: true, join: [], leave_via: [], leave_id: None, id: 1, sled_tree_prefix: "", cluster_name: "foo_cluster" } }
2022-07-03T12:54:16.688773Z  INFO databend_meta: HTTP API server listening on 0.0.0.0:28002
2022-07-03T12:54:16.688896Z  WARN databend_meta::api::http_service: Http API TLS not set
2022-07-03T12:54:16.691559Z  INFO databend_meta: Databend meta server listening on 0.0.0.0:9191
2022-07-03T12:54:16.691724Z  INFO databend_meta::api::grpc_server: GrpcServer::start
2022-07-03T12:54:16.692403Z  INFO databend_meta::api::grpc_server: gRPC addr: 0.0.0.0:9191
2022-07-03T12:54:16.692703Z  INFO poem::server: listening addr=<socket://0.0.0.0:28002>
2022-07-03T12:54:16.692805Z  INFO poem::server: server started
2022-07-03T12:54:16.692929Z  INFO spawn-grpc: databend_meta::api::grpc_server: metasrv starts to wait for stop signal: 0.0.0.0:9191
2022-07-03T12:54:16.693018Z  INFO databend_meta::api::grpc_server: Done GrpcServer::start
2022-07-03T12:54:16.693063Z  INFO join_cluster{grpc_api_addr="0.0.0.0:9191"}: databend_meta::meta_service::raftmeta: '--join' is empty, do not need joining cluster
2022-07-03T12:54:16.693156Z DEBUG start:open_create_boot{open=Some(()) create=Some(()) is_initialize=true node=Node { name: "1", endpoint: Endpoint { addr: "10.240.1.104", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="1"}:new{id=1 cluster=foo_cluster}: openraft::core: raft node is initializing
2022-07-03T12:54:16.694016Z DEBUG sled::pagecache::iobuf: advancing offset within the current segment from 4716 to 4728    
2022-07-03T12:54:16.701140Z DEBUG sled::pagecache::iobuf: wrote lsns 4716-4727 to disk at offsets 4716-4727, maxed false complete_len 12    
2022-07-03T12:54:16.701306Z DEBUG sled::pagecache::iobuf: mark_interval(4716, 12)    
2022-07-03T12:54:16.701468Z DEBUG sled::pagecache::iobuf: new highest interval: 4716 - 4727    
2022-07-03T12:54:16.701693Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=true node=Node { name: "1", endpoint: Endpoint { addr: "10.240.1.104", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="1"}:new{id=1 cluster=foo_cluster}:get_current_snapshot{id=1}: databend_meta::store::meta_raft_store: got snapshot start
2022-07-03T12:54:16.701820Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=true node=Node { name: "1", endpoint: Endpoint { addr: "10.240.1.104", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="1"}:new{id=1 cluster=foo_cluster}:get_current_snapshot{id=1}: databend_meta::store::meta_raft_store: got snapshot complete
dr-dr xp

dr-dr xp

07/03/2022, 2:02 PM
It looks like there is an already initialized store thus it won't try to join a cluster.:
meta node is opened
You can find such a log in it.
2:03 PM
And looks like we're gonna have to improve the log message to make it more clear.
bohu

bohu

07/03/2022, 2:19 PM
xp has open a PR to address the log message https://github.com/datafuselabs/databend/pull/6415
n

Nick Burrett

07/03/2022, 2:36 PM
Ah ha, thanks. That makes sense. Looks like the way I got into this problem was by having Istio enabled on the namespace, which caused cross-pod connections to fail. Nodes 2 & 3 would fail like per this log, then be restarted. Since there was already something in the store, when I disabled Istio and restarted the statefulset, I still had the lingering raft config to never get the cluster spun up.
2022-07-03T14:26:49.443642Z  INFO spawn-grpc: databend_meta::api::grpc_server: metasrv starts to wait for stop signal: 0.0.0.0:9191
2022-07-03T14:26:49.443674Z  INFO databend_meta::api::grpc_server: Done GrpcServer::start
2022-07-03T14:26:49.443692Z  INFO join_cluster{grpc_api_addr="0.0.0.0:9191"}: databend_meta::meta_service::raftmeta: try to join cluster accross metrics-meta-0.metrics-meta.databend:28004...
2022-07-03T14:26:49.443803Z DEBUG sled::pagecache::iobuf: advancing offset within the current segment from 858 to 920    
2022-07-03T14:26:49.443876Z DEBUG hyper::client::connect::dns: resolving host="metrics-meta-0.metrics-meta.databend"
2022-07-03T14:26:49.448996Z DEBUG sled::pagecache::iobuf: wrote lsns 858-919 to disk at offsets 858-919, maxed false complete_len 62    
2022-07-03T14:26:49.449036Z DEBUG sled::pagecache::iobuf: mark_interval(858, 62)    
2022-07-03T14:26:49.449047Z DEBUG sled::pagecache::iobuf: new highest interval: 858 - 919    
2022-07-03T14:26:49.449202Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "3", endpoint: Endpoint { addr: "10.240.1.113", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="3"}:new{id=3 cluster=foo_cluster}:get_current_snapshot{id=3}: databend_meta::store::meta_raft_store: got snapshot start
2022-07-03T14:26:49.449222Z  INFO start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "3", endpoint: Endpoint { addr: "10.240.1.113", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="3"}:new{id=3 cluster=foo_cluster}:get_current_snapshot{id=3}: databend_meta::store::meta_raft_store: got snapshot complete
2022-07-03T14:26:49.449238Z DEBUG start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "3", endpoint: Endpoint { addr: "10.240.1.113", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="3"}:new{id=3 cluster=foo_cluster}: openraft::core: id=3 target_state: Learner
2022-07-03T14:26:49.449272Z DEBUG start:open_create_boot{open=Some(()) create=Some(()) is_initialize=false node=Node { name: "3", endpoint: Endpoint { addr: "10.240.1.113", port: 28004 }, grpc_api_addr: Some("0.0.0.0:9191") } config_id="3"}:new{id=3 cluster=foo_cluster}:run{id=3 raft_state="learner"}: openraft::core: report_metrics: Metrics{id:3,Learner, term:0, last_log:None, last_applied:None, leader:None, membership:{log_id:0-0 membership:[{3}]}, snapshot:None, replication:
2022-07-03T14:26:49.450179Z DEBUG join_cluster{grpc_api_addr="0.0.0.0:9191"}: hyper::client::connect::http: connecting to 10.240.0.206:28004
2022-07-03T14:26:49.450353Z ERROR join_cluster{grpc_api_addr="0.0.0.0:9191"}: databend_meta::meta_service::raftmeta: connect to metrics-meta-0.metrics-meta.databend:28004 join cluster fail: tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 111, kind: ConnectionRefused, message: "Connection refused" })))
2022-07-03T14:26:49.450426Z  INFO common_base::base::http_shutdown_handlers: http api: graceful stop
2022-07-03T14:26:49.450444Z  INFO common_base::base::http_shutdown_handlers: http api: send signal to abort_handle
2022-07-03T14:26:49.450457Z  INFO common_base::base::http_shutdown_handlers: Done: http api: send signal to abort_handle, res: Ok(())
2022-07-03T14:26:49.450473Z  INFO common_base::base::http_shutdown_handlers: http api: received force shutdown signal
2022-07-03T14:26:49.450482Z  INFO databend_meta::api::grpc_server: GrpcServer::stop
2022-07-03T14:26:49.450489Z  INFO databend_meta::api::grpc_server: received force shutdown signal
2022-07-03T14:26:49.450495Z  INFO databend_meta::api::grpc_server: block waiting for fin_rx
Error: Code: 2001, displayText = join cluster via ["metrics-meta-0.metrics-meta.databend:28004"] fail.

<Backtrace disabled by default. Please use RUST_BACKTRACE=1 to enable>
I now have the raft setup working, so at least I can sort the Istio config as a cluster-config specific issue.