fix: setup core logger as soon as possible

src/cli/run.rs

@@ -11,26 +11,6 @@ use crate::{ipc, tlog, Entrypoint, IpcMessage};
 pub fn main(args: args::Run) -> ! {
     let tt_args = args.tt_args().unwrap();
 
-    let res = PicodataConfig::init(args);
-    let config = crate::unwrap_ok_or!(res,
-        Err(e) => {
-            tlog!(Error, "{e}");
-            std::process::exit(1);
-        }
-    );
-
-    // Set the log level as soon as possible to not miss any messages during
-    // initialization.
-    tlog::set_log_level(config.instance.log_level());
-    config.log_config_params();
-
-    if let Some(filename) = &config.instance.service_password_file {
-        if let Err(e) = crate::pico_service::read_pico_service_password_from_file(filename) {
-            tlog!(Error, "{e}");
-            std::process::exit(1);
-        }
-    }
-
     // Tarantool implicitly parses some environment variables.
     // We don't want them to affect the behavior and thus filter them out.
     for (k, _) in std::env::vars() {
@@ -98,6 +78,20 @@ pub fn main(args: args::Run) -> ! {
                 drop(to_child);
 
                 super::tarantool::main_cb(&tt_args, || {
+                    // Note: this function may log something into the tarantool's logger, which means it must be done within
+                    // the `tarantool::main_cb` otherwise everything will break. The thing is, tarantool's logger needs to know things
+                    // about the current thread and the way it does that is by accessing the `cord_ptr` global variable. For the main
+                    // thread this variable get's initialized in the tarantool's main function. But if we call the logger before this
+                    // point another mechanism called cord_on_demand will activate and initialize the cord in a conflicting way.
+                    // This causes a crash when the cord gets deinitialized during the normal shutdown process, because it leads to double free.
+                    // (This wouldn't be a problem if we just skipped the deinitialization for the main cord, because we don't actually need it
+                    // as the OS will cleanup all the resources anyway, but this is a different story altogether)
+                    let config = PicodataConfig::init(args)?;
+
+                    if let Some(filename) = &config.instance.service_password_file {
+                        crate::pico_service::read_pico_service_password_from_file(filename)?;
+                    }
+
                     // We don't want a child to live without a supervisor.
                     //
                     // Usually, supervisor waits for child forever and retransmits
@@ -126,6 +120,8 @@ pub fn main(args: args::Run) -> ! {
                         std::process::abort();
                     }));
 
+                    config.log_config_params();
+
                     // Note that we don't really need to pass the `config` here,
                     // because it's stored in the global variable which we can
                     // access from anywhere. But we still pass it explicitly just

src/cli/tarantool.rs

@@ -17,6 +17,8 @@ where
         // SAFETY: the caller is responsible for providing correct E & F.
         let closure = unsafe { Box::<F>::from_raw(data as _) };
         if let Err(e) = closure() {
+            // Print the error message to stderr as well to the logging destination for user friendliness
+            eprintln!("\x1b[31mCRITICAL: {e}\x1b[0m");
             tlog!(Critical, "{e}");
             std::process::exit(1);
         }

src/config.rs

@@ -86,33 +86,39 @@ impl PicodataConfig {
             }
         });
 
+        let mut config_path = None;
         let mut config_from_file = None;
-        match (&args_path, file_exists(&default_path)) {
-            (Some(args_path), true) => {
-                if args_path != &default_path {
-                    let cwd = cwd.display();
-                    let args_path = args_path.display();
-                    #[rustfmt::skip]
-                    tlog!(Warning, "A path to configuration file '{args_path}' was provided explicitly,
-but a '{DEFAULT_CONFIG_FILE_NAME}' file in the current working directory '{cwd}' also exists.
-Using configuration file '{args_path}'.");
-                }
+        if let Some(args_path) = &args_path {
+            config_path = Some(args_path);
+            config_from_file = Some(Self::read_yaml_file(args_path)?);
+        } else if file_exists(&default_path) {
+            #[rustfmt::skip]
+            tlog!(Info, "Reading configuration file '{DEFAULT_CONFIG_FILE_NAME}' in the current working directory '{}'.", cwd.display());
+            config_path = Some(&default_path);
+            config_from_file = Some(Self::read_yaml_file(&default_path)?);
+        }
 
-                config_from_file = Some((Self::read_yaml_file(args_path)?, args_path));
-            }
-            (Some(args_path), false) => {
-                config_from_file = Some((Self::read_yaml_file(args_path)?, args_path));
-            }
-            (None, true) => {
+        let mut parameter_sources = ParameterSourcesMap::default();
+        // Initialize the logger as soon as possible so that as many messages as possible
+        // go into the destination expected by user.
+        init_core_logger_from_args_env_or_config(
+            &args,
+            config_from_file.as_deref(),
+            &mut parameter_sources,
+        )?;
+
+        if let Some(args_path) = &args_path {
+            if args_path != &default_path && file_exists(&default_path) {
+                let cwd = cwd.display();
+                let args_path = args_path.display();
                 #[rustfmt::skip]
-                tlog!(Info, "Reading configuration file '{DEFAULT_CONFIG_FILE_NAME}' in the current working directory '{}'.", cwd.display());
-                config_from_file = Some((Self::read_yaml_file(&default_path)?, &default_path));
+                tlog!(Warning, "A path to configuration file '{args_path}' was provided explicitly,
+but a '{DEFAULT_CONFIG_FILE_NAME}' file in the current working directory '{cwd}' also exists.
+Using configuration file '{args_path}'.");
             }
-            (None, false) => {}
         }
 
-        let mut parameter_sources = ParameterSourcesMap::default();
-        let mut config = if let Some((mut config, path)) = config_from_file {
+        let mut config = if let Some(mut config) = config_from_file {
             config.validate_from_file()?;
             #[rustfmt::skip]
             mark_non_none_field_sources(&mut parameter_sources, &config, ParameterSource::ConfigFile);
@@ -122,7 +128,8 @@ Using configuration file '{args_path}'.");
                 parameter_sources.insert("instance.config_file".into(), ParameterSource::CommandlineOrEnvironment);
             }
 
-            config.instance.config_file = Some(path.clone());
+            assert!(config_path.is_some());
+            config.instance.config_file = config_path.cloned();
             config
         } else {
             Default::default()
@@ -225,19 +232,9 @@ Using configuration file '{args_path}'.");
         // var has lower priority then other PICODATA_* env vars, while
         // --config-parameters parameter has higher priority then other cli args.
         if let Ok(env) = std::env::var(CONFIG_PARAMETERS_ENV) {
-            for item in env.split(';') {
-                let item = item.trim();
-                if item.is_empty() {
-                    continue;
-                }
-                let Some((path, yaml)) = item.split_once('=') else {
-                    return Err(Error::InvalidConfiguration(format!(
-                        "error when parsing {CONFIG_PARAMETERS_ENV} environment variable: expected '=' after '{item}'",
-                    )));
-                };
-
+            for (path, yaml) in parse_picodata_config_parameters_env(&env)? {
                 config_from_args
-                    .set_field_from_yaml(path.trim(), yaml.trim())
+                    .set_field_from_yaml(path, yaml)
                     .map_err(Error::invalid_configuration)?;
             }
         }
@@ -676,6 +673,109 @@ Using configuration file '{args_path}'.");
     }
 }
 
+/// Gets the logging configuration from all possible sources and initializes the core logger.
+///
+/// Note that this function is an exception to the rule of how we do parameter
+/// handling. This is needed because we the logger must be set up as soon as
+/// possible so that logging messages during handling of other parameters go
+/// into the destination expected by user. All other parameter handling is done
+/// elsewhere in [`PicodataConfig::set_from_args_and_env`].
+fn init_core_logger_from_args_env_or_config(
+    args: &args::Run,
+    config: Option<&PicodataConfig>,
+    sources: &mut ParameterSourcesMap,
+) -> Result<(), Error> {
+    let mut destination = None;
+    let mut level = DEFAULT_LOG_LEVEL;
+    let mut format = DEFAULT_LOG_FORMAT;
+
+    let mut destination_source = ParameterSource::Default;
+    let mut level_source = ParameterSource::Default;
+    let mut format_source = ParameterSource::Default;
+
+    // Config has the lowest priority
+    if let Some(config) = config {
+        if let Some(config_destination) = &config.instance.log.destination {
+            destination_source = ParameterSource::ConfigFile;
+            destination = Some(&**config_destination);
+        }
+
+        if let Some(config_level) = config.instance.log.level {
+            level_source = ParameterSource::ConfigFile;
+            level = config_level;
+        }
+
+        if let Some(config_format) = config.instance.log.format {
+            format_source = ParameterSource::ConfigFile;
+            format = config_format;
+        }
+    }
+
+    // Env is middle priority
+    let env = std::env::var(CONFIG_PARAMETERS_ENV);
+    if let Ok(env) = &env {
+        for (path, value) in parse_picodata_config_parameters_env(env)? {
+            match path {
+                "instance.log.destination" => {
+                    destination_source = ParameterSource::CommandlineOrEnvironment;
+                    destination =
+                        Some(serde_yaml::from_str(value).map_err(Error::invalid_configuration)?)
+                }
+                "instance.log.level" => {
+                    level_source = ParameterSource::CommandlineOrEnvironment;
+                    level = serde_yaml::from_str(value).map_err(Error::invalid_configuration)?
+                }
+                "instance.log.format" => {
+                    format_source = ParameterSource::CommandlineOrEnvironment;
+                    format = serde_yaml::from_str(value).map_err(Error::invalid_configuration)?
+                }
+                _ => {
+                    // Skip for now, it will be checked in `set_from_args_and_env`
+                    // when everything else other than logger configuration is processed.
+                }
+            }
+        }
+    }
+
+    // Arguments have higher priority than env.
+    if let Some(args_destination) = &args.log {
+        destination_source = ParameterSource::CommandlineOrEnvironment;
+        destination = Some(args_destination);
+    }
+
+    if let Some(args_level) = args.log_level {
+        level_source = ParameterSource::CommandlineOrEnvironment;
+        level = args_level;
+    }
+
+    // Format is not configurable from commandline options
+
+    tlog::init_core_logger(destination, level.into(), format);
+
+    sources.insert("instance.log.destination".into(), destination_source);
+    sources.insert("instance.log.level".into(), level_source);
+    sources.insert("instance.log.format".into(), format_source);
+
+    Ok(())
+}
+
+fn parse_picodata_config_parameters_env(value: &str) -> Result<Vec<(&str, &str)>, Error> {
+    let mut result = Vec::new();
+    for item in value.split(';') {
+        let item = item.trim();
+        if item.is_empty() {
+            continue;
+        }
+        let Some((path, yaml)) = item.split_once('=') else {
+            return Err(Error::InvalidConfiguration(format!(
+                "error when parsing {CONFIG_PARAMETERS_ENV} environment variable: expected '=' after '{item}'",
+            )));
+        };
+        result.push((path.trim(), yaml.trim()));
+    }
+    Ok(result)
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // ParameterSource
 ////////////////////////////////////////////////////////////////////////////////
@@ -1137,10 +1237,13 @@ pub struct IprotoSection {
 // LogSection
 ////////////////////////////////////////////////////////////////////////////////
 
+const DEFAULT_LOG_LEVEL: args::LogLevel = args::LogLevel::Info;
+const DEFAULT_LOG_FORMAT: LogFormat = LogFormat::Plain;
+
 #[derive(PartialEq, Default, Debug, Clone, serde::Deserialize, serde::Serialize, Introspection)]
 #[serde(deny_unknown_fields)]
 pub struct LogSection {
-    #[introspection(config_default = args::LogLevel::Info)]
+    #[introspection(config_default = DEFAULT_LOG_LEVEL)]
     pub level: Option<args::LogLevel>,
 
     /// By default, Picodata sends the log to the standard error stream
@@ -1150,7 +1253,7 @@ pub struct LogSection {
     /// - system logger
     pub destination: Option<String>,
 
-    #[introspection(config_default = LogFormat::Plain)]
+    #[introspection(config_default = DEFAULT_LOG_FORMAT)]
     pub format: Option<LogFormat>,
 }
 

src/tlog.rs

+use crate::config::LogFormat;
 use ::tarantool::log::{say, SayLevel};
 use once_cell::sync::Lazy;
+use std::ffi::CString;
 use tarantool::cbus::unbounded as cbus;
 use tarantool::fiber;
 
 #[inline(always)]
-pub fn set_log_level(lvl: SayLevel) {
-    tarantool::log::set_current_level(lvl)
+pub fn init_core_logger(destination: Option<&str>, level: SayLevel, format: LogFormat) {
+    let mut destination_ptr: *const u8 = std::ptr::null();
+    let destination_cstr;
+    if let Some(destination) = destination {
+        destination_cstr =
+            CString::new(destination).expect("log destination shouldn't contain nul-bytes");
+        destination_ptr = destination_cstr.as_ptr() as _;
+    }
+
+    // SAFETY: `destination_cstr` must outlive this function call.
+    unsafe {
+        say_logger_init(
+            destination_ptr,
+            level as _,
+            // Default behavior of "nonblocking" for corresponding logger type.
+            -1,
+            format.as_cstr().as_ptr() as _,
+        );
+    }
+
+    // TODO: move to tarantool-module
+    extern "C" {
+        /// Initialize the default tarantool logger (accessed via the say_* functions).
+        ///
+        /// Parameters:
+        /// - `init_str`: Destination descriptor. Pass a `null` for default
+        ///    behavior of loggin to stderr.
+        ///    (see also <https://www.tarantool.io/en/doc/latest/reference/configuration/#cfg-logging-log>)
+        ///
+        /// - `level`: Log level
+        ///
+        /// - `nonblock`:
+        ///     - `< 0`: Use default for the corresponding logger type
+        ///     - `0`: Always block until the message is written to the destination
+        ///     - `> 0`: Never block until the message is written to the destination
+        ///
+        /// - `format`: Supported values are: "json", "plain"
+        fn say_logger_init(init_str: *const u8, level: i32, nonblock: i32, format: *const u8);
+    }
 }
 
 /// For user experience reasons we do some log messages enhancements (we add
@@ -39,18 +78,9 @@ pub static mut DONT_LOG_KV_FOR_NEXT_SENDING_FROM: bool = false;
 impl StrSerializer {
     /// Format slog's record as plain string. Most suitable for implementing [`slog::Drain`].
     pub fn format_message(record: &slog::Record, values: &slog::OwnedKVList) -> String {
-        let msg = if unsafe { CORE_LOGGER_IS_INITIALIZED } {
-            format!("{}", record.msg())
-        } else {
-            let level = slog_level_to_say_level(record.level());
-            format!(
-                "{color_code}{prefix}{msg}\x1b[0m",
-                color_code = color_for_log_level(level),
-                prefix = prefix_for_log_level(level),
-                msg = record.msg(),
-            )
+        let mut s = StrSerializer {
+            str: format!("{}", record.msg()),
         };
-        let mut s = StrSerializer { str: msg };
 
         // XXX: this is the ugliest hack I've done so far. Basically raft-rs
         // logs the full message it's sending if log level is Debug. But we're
@@ -144,29 +174,6 @@ fn slog_level_to_say_level(level: slog::Level) -> SayLevel {
     }
 }
 
-#[inline]
-fn prefix_for_log_level(level: SayLevel) -> &'static str {
-    match level {
-        SayLevel::System => "SYSTEM ERROR: ",
-        SayLevel::Fatal => "FATAL: ",
-        SayLevel::Crit => "CRITICAL: ",
-        SayLevel::Error => "ERROR: ",
-        SayLevel::Warn => "WARNING: ",
-        SayLevel::Info => "",
-        SayLevel::Verbose => "V: ",
-        SayLevel::Debug => "DBG: ",
-    }
-}
-
-#[inline]
-fn color_for_log_level(level: SayLevel) -> &'static str {
-    match level {
-        SayLevel::System | SayLevel::Fatal | SayLevel::Crit | SayLevel::Error => "\x1b[31m", // red
-        SayLevel::Warn => "\x1b[33m", // yellow
-        SayLevel::Info | SayLevel::Verbose | SayLevel::Debug => "",
-    }
-}
-
 static THREAD_SAFE_LOGGING: std::sync::Mutex<Option<cbus::Sender<ThreadSafeLogRequest>>> =
     std::sync::Mutex::new(None);
 

test/int/test_config_file.py

 from conftest import Cluster, Instance, PortDistributor, log_crawler, color
 import os
 import subprocess
+import json
 
 
 def test_config_works(cluster: Cluster):
@@ -315,6 +316,9 @@ cluster:
 
     assert box_cfg["net_msg_max"] == 0x300
 
+    i1.terminate()
+    i1.remove_data()
+
     #
     # Check explicitly set values
     #
@@ -350,9 +354,27 @@ instance:
     # even though this will override any value from the config
     i1.env["PICODATA_LOG_LEVEL"] = "debug"
 
-    i1.restart(remove_data=True)
+    # Check that json output format works
+    json_line_count = 0
+    non_json_lines = []
+
+    def check_parses_as_json(line: bytes):
+        nonlocal json_line_count
+        nonlocal non_json_lines
+        try:
+            json.loads(line)
+            json_line_count += 1
+        except json.JSONDecodeError:
+            non_json_lines.append(line)
+
+    i1.on_output_line(check_parses_as_json)
+    i1.start()
     i1.wait_online()
 
+    assert json_line_count != 0
+    for line in non_json_lines:
+        assert line.startswith(b"[supervisor")
+
     box_cfg = i1.eval("return box.cfg")
 
     assert box_cfg["log"] == "file:/proc/self/fd/2"
@@ -476,3 +498,36 @@ def test_output_config_parameters(cluster: Cluster):
     i1.start()
     i1.wait_online()
     assert len(found_params) == len(params_list)
+
+
+def test_logger_configuration(cluster: Cluster):
+    log_file = f"{cluster.data_dir}/i1.log"
+    cluster.set_config_file(
+        yaml=f"""
+cluster:
+    tier:
+        default:
+instance:
+    cluster_id: test
+    log:
+        destination: {log_file}
+"""
+    )
+
+    assert not os.path.exists(log_file)
+
+    i1 = cluster.add_instance(wait_online=True)
+    assert os.path.exists(log_file)
+
+    i1.terminate()
+    os.remove(log_file)
+
+    other_log_file = f"{cluster.data_dir}/other-i1.log"
+    assert not os.path.exists(other_log_file)
+
+    i1.env["PICODATA_LOG"] = other_log_file
+    i1.start()
+    i1.wait_online()
+
+    assert os.path.exists(other_log_file)
+    assert not os.path.exists(log_file)