fix(orchestrator): properly log some messages (#5992)

While debugging orchestrator logs I noticed that some logs do not
appear, not only in Kibana but also in systemd journal.

Changes:
1. Pass `ReplicaLogger` instead of `slog::Logger` to some utility
functions. For some reason (I didn't investigate)
`slog::log!(replica_logger.inner.root)` always logs an empty message
while `log!(replica_logger)` properly logs a message (see [Kibana
logs](https://kibana.testnet.dfinity.network/app/discover#/?_g=(filters:!(),refreshInterval:(pause:!t,value:60000),time:(from:now-1w,to:now))&_a=(columns:!(host.name,message,level,crate_,module),filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'535335e8-7195-4af7-95ab-e59ab3bb8056',key:module,negate:!f,params:!(process_manager,ic_http_endpoints_async_utils),type:phrases,value:!(process_manager,ic_http_endpoints_async_utils)),query:(bool:(minimum_should_match:1,should:!((match_phrase:(module:process_manager)),(match_phrase:(module:ic_http_endpoints_async_utils))))))),grid:(columns:(host.name:(width:359))),hideChart:!f,index:'535335e8-7195-4af7-95ab-e59ab3bb8056',interval:auto,query:(language:kuery,query:''),sort:!(!('@timestamp',desc))))
and note that logs from `process_manager` and
`ic_http_endpoints_async_utils` appear in Kibana only for system tests
running on this branch)
2. Move creation of `ReplicaLogger` to the `main` function of
`Orchestrator`. Currently, the messages logged after the `Orchestrator`
struct is dropped might not be printed because the logs are flushed when
the
[_async_drop_guard](https://docs.rs/slog-async/latest/slog_async/struct.AsyncGuard.html)
is dropped, which happens in the `Orchestrator` struct's destructor

Author: kpop-dfinity

Cargo.lock

@@ -50,5 +50,5 @@ pub async fn main() {
         &tokio::runtime::Handle::current(),
         config,
     );
-    shutdown_signal(log.inner_logger.root.clone()).await;
+    shutdown_signal(log.clone()).await;
 }

rs/bitcoin/adapter/bin/ic-btc-adapter/main.rs

@@ -9,6 +9,7 @@ rust_library(
     version = "0.9.0",
     deps = [
         # Keep sorted.
+        "//rs/monitoring/logger",
         "@crate_index//:anyhow",
         "@crate_index//:async-stream",
         "@crate_index//:byte-unit",

rs/http_endpoints/async_utils/BUILD.bazel

@@ -14,6 +14,7 @@ bytes = { workspace = true }
 futures = { workspace = true }
 futures-util = { workspace = true }
 hyper = { workspace = true }
+ic-logger = { path = "../../monitoring/logger" }
 slog = { workspace = true }
 tokio = { workspace = true }
 tonic = { workspace = true }

rs/http_endpoints/async_utils/Cargo.toml

@@ -1,9 +1,9 @@
-use slog::{info, Logger};
-
 mod hyper;
 mod join_map;
 mod unix;
 
+use ic_logger::{info, ReplicaLogger};
+
 pub use self::{
     hyper::ExecuteOnTokioRuntime,
     join_map::JoinMap,
@@ -22,7 +22,7 @@ pub fn abort_on_panic() {
 /// Returns a `Future` that completes when the service should gracefully
 /// shutdown. Completion happens if either of `SIGINT` or `SIGTERM` are
 /// received.
-pub async fn shutdown_signal(log: Logger) {
+pub async fn shutdown_signal(log: ReplicaLogger) {
     use tokio::signal::unix::{signal, SignalKind};
     let mut sig_int =
         signal(SignalKind::interrupt()).expect("failed to install SIGINT signal handler");

rs/http_endpoints/async_utils/src/lib.rs

@@ -52,5 +52,5 @@ pub async fn main() {
         &tokio::runtime::Handle::current(),
         config,
     );
-    shutdown_signal(logger.inner_logger.root.clone()).await;
+    shutdown_signal(logger.clone()).await;
 }

rs/https_outcalls/adapter/src/main.rs

@@ -84,7 +84,7 @@ impl OrchestratorArgs {
 
     /// Parse `self.replica_config_file` and persist in
     /// [`TempDir`][tempfile::TempDir] "ic_config"
-    pub(crate) fn get_ic_config(&self) -> Config {
+    pub fn get_ic_config(&self) -> Config {
         let tmpdir = tempfile::Builder::new()
             .prefix("ic_config")
             .tempdir()

rs/orchestrator/src/args.rs

@@ -67,9 +67,7 @@ impl BoundaryNodeManager {
         Self {
             registry,
             _metrics: metrics,
-            process: Arc::new(Mutex::new(ProcessManager::new(
-                logger.clone().inner_logger.root,
-            ))),
+            process: Arc::new(Mutex::new(ProcessManager::new(logger.clone()))),
             ic_binary_dir,
             crypto_config,
             version,

rs/orchestrator/src/boundary_node.rs

@@ -1,20 +1,21 @@
 use clap::Parser;
 use ic_http_endpoints_async_utils::shutdown_signal;
-use ic_logger::{info, warn};
+use ic_logger::{info, new_replica_logger_from_config, warn};
 use orchestrator::{args::OrchestratorArgs, orchestrator::Orchestrator};
 
 #[tokio::main]
 async fn main() {
     let args = OrchestratorArgs::parse();
+    let config = args.get_ic_config();
+    let (logger, _async_log_guard) = new_replica_logger_from_config(&config.orchestrator_logger);
 
     let (exit_sender, exit_signal) = tokio::sync::watch::channel(false);
 
-    let mut orchestrator = Orchestrator::new(args)
+    let mut orchestrator = Orchestrator::new(args, &config, logger.clone())
         .await
         .expect("Failed to start orchestrator");
-    let logger = orchestrator.logger.clone();
     let join_handle = tokio::spawn(async move { orchestrator.start_tasks(exit_signal).await });
-    shutdown_signal(logger.inner_logger.root.clone()).await;
+    shutdown_signal(logger.clone()).await;
 
     exit_sender.send(true).expect("Failed to send exit signal");
 

rs/orchestrator/src/main.rs

@@ -15,17 +15,19 @@ use crate::{
 };
 use backoff::ExponentialBackoffBuilder;
 use get_if_addrs::get_if_addrs;
-use ic_config::metrics::{Config as MetricsConfig, Exporter};
+use ic_config::{
+    metrics::{Config as MetricsConfig, Exporter},
+    Config,
+};
 use ic_crypto::CryptoComponent;
 use ic_crypto_node_key_generation::{generate_node_keys_once, NodeKeyGenerationError};
 use ic_http_endpoints_metrics::MetricsHttpEndpoint;
 use ic_image_upgrader::ImageUpgrader;
-use ic_logger::{error, info, new_replica_logger_from_config, warn, ReplicaLogger};
+use ic_logger::{error, info, warn, ReplicaLogger};
 use ic_metrics::MetricsRegistry;
 use ic_registry_replicator::RegistryReplicator;
 use ic_sys::utility_command::UtilityCommand;
 use ic_types::{hostos_version::HostosVersion, ReplicaVersion, SubnetId};
-use slog_async::AsyncGuard;
 use std::{
     collections::HashMap,
     convert::TryFrom,
@@ -42,7 +44,6 @@ const CHECK_INTERVAL_SECS: Duration = Duration::from_secs(10);
 
 pub struct Orchestrator {
     pub logger: ReplicaLogger,
-    _async_log_guard: AsyncGuard,
     _metrics_runtime: MetricsHttpEndpoint,
     upgrade: Option<Upgrade>,
     hostos_upgrade: Option<HostosUpgrader>,
@@ -83,10 +84,13 @@ fn load_version_from_file(logger: &ReplicaLogger, path: &Path) -> Result<Replica
 }
 
 impl Orchestrator {
-    pub async fn new(args: OrchestratorArgs) -> Result<Self, OrchestratorInstantiationError> {
+    pub async fn new(
+        args: OrchestratorArgs,
+        config: &Config,
+        logger: ReplicaLogger,
+    ) -> Result<Self, OrchestratorInstantiationError> {
         args.create_dirs();
         let metrics_addr = args.get_metrics_addr();
-        let config = args.get_ic_config();
         let crypto_config = config.crypto.clone();
         let node_id = tokio::task::spawn_blocking(move || {
             generate_node_keys_once(&crypto_config, Some(tokio::runtime::Handle::current()))
@@ -100,8 +104,6 @@ impl Orchestrator {
         .await
         .unwrap()?;
 
-        let (logger, _async_log_guard) =
-            new_replica_logger_from_config(&config.orchestrator_logger);
         let metrics_registry = MetricsRegistry::global();
         let replica_version = load_version_from_file(&logger, &args.version_file)
             .map_err(|()| OrchestratorInstantiationError::VersionFileError)?;
@@ -148,11 +150,11 @@ impl Orchestrator {
         let registry_replicator = Arc::new(RegistryReplicator::new_from_config(
             logger.clone(),
             Some(node_id),
-            &config,
+            config,
         ));
 
         let (nns_urls, nns_pub_key) =
-            registry_replicator.parse_registry_access_info_from_config(&config);
+            registry_replicator.parse_registry_access_info_from_config(config);
 
         match registry_replicator
             .start_polling(nns_urls, nns_pub_key)
@@ -213,7 +215,7 @@ impl Orchestrator {
             registry_local_store.clone(),
         );
 
-        let replica_process = Arc::new(Mutex::new(ProcessManager::new(slog_logger.clone())));
+        let replica_process = Arc::new(Mutex::new(ProcessManager::new(logger.clone())));
         let ic_binary_directory = args
             .ic_binary_directory
             .as_ref()
@@ -330,7 +332,6 @@ impl Orchestrator {
 
         Ok(Self {
             logger,
-            _async_log_guard,
             _metrics_runtime,
             upgrade,
             hostos_upgrade,