Merge pull request #1035 from NordSecurity/log_time_in_telio

Add timestamp in logs (also) on libtelio side

Cargo.toml

@@ -62,6 +62,7 @@ telio-wg.workspace = true
 once_cell.workspace = true
 nat-detect.workspace = true
 smart-default.workspace = true
+time.workspace = true
 
 [target.'cfg(target_os = "android")'.dependencies]
 jni = "0.19"

nat-lab/tests/uniffi/libtelio_remote.py

@@ -84,6 +84,7 @@ def __init__(self, daemon, logfile):
         self._libtelio = None
         self._event_cb = TelioEventCbImpl()
         self._logger_cb = TelioLoggerCbImpl(logfile)
+        libtelio.add_timestamps_to_logs()
         libtelio.set_global_logger(libtelio.TelioLogLevel.DEBUG, self._logger_cb)
 
     def shutdown(self):

src/ffi.rs

@@ -20,7 +20,7 @@ use std::{
     time::Duration,
 };
 
-use self::{logging::LOGGER_STOPPER, types::*};
+use self::{logging::LOGGER_STOPPER, logging::TIMESTAMPS_IN_LOGS, types::*};
 use crate::device::{Device, DeviceConfig, Result as DevResult};
 use telio_model::{
     config::{Config, ConfigParseError},
@@ -81,6 +81,12 @@ pub fn unset_global_logger() {
     LOGGER_STOPPER.stop();
 }
 
+/// Enable timestamps in logs generated by libtelio.
+/// When enabled host application doesn't need to add timestamps in the logging callback.
+pub fn add_timestamps_to_logs() {
+    TIMESTAMPS_IN_LOGS.store(true, std::sync::atomic::Ordering::Relaxed);
+}
+
 /// Get default recommended adapter type for platform.
 pub fn get_default_adapter() -> TelioAdapterType {
     AdapterType::default().into()

src/ffi/logging.rs

@@ -2,12 +2,12 @@ use std::{
     io::{self, ErrorKind},
     str::from_utf8,
     sync::{
-        atomic::AtomicUsize,
+        atomic::{AtomicBool, AtomicUsize},
         mpsc::{sync_channel, RecvError, SyncSender},
         Arc, Barrier, Mutex,
     },
     thread::Builder,
-    time::Instant,
+    time::{Instant, SystemTime},
 };
 
 use once_cell::sync::Lazy;
@@ -28,6 +28,7 @@ pub const ASYNC_CHANNEL_CLOSED_MSG: &str = "Async channel explicitly closed";
 static DROPPED_LOGS: AtomicUsize = AtomicUsize::new(0);
 static DROPPED_LOGS_LAST_CHECKED_VALUE: AtomicUsize = AtomicUsize::new(0);
 pub static LOGGER_STOPPER: LoggerStopper = LoggerStopper::new();
+pub static TIMESTAMPS_IN_LOGS: AtomicBool = AtomicBool::new(false);
 
 pub struct LoggerStopper {
     sender: parking_lot::Mutex<Option<SyncSender<LogMessage>>>,
@@ -189,7 +190,11 @@ impl io::Write for FfiCallbackWriter {
             // In both cases there is nothing to do when it happens.
             if self
                 .log_sender
-                .try_send(LogMessage::Message(self.level, filtered_msg))
+                .try_send(LogMessage::Message(
+                    self.level,
+                    filtered_msg,
+                    SystemTime::now(),
+                ))
                 .is_err()
             {
                 DROPPED_LOGS.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
@@ -246,7 +251,7 @@ fn filter_log_message(msg: String) -> Option<String> {
 }
 
 enum LogMessage {
-    Message(TelioLogLevel, String),
+    Message(TelioLogLevel, String, SystemTime),
     Quit(Arc<Barrier>),
 }
 
@@ -258,7 +263,17 @@ fn start_async_logger(cb: Box<dyn TelioLoggerCb>, buffer_size: usize) -> SyncSen
             let _ = cb.log(TelioLogLevel::Debug, START_ASYNC_LOGGER_MSG.to_owned());
             loop {
                 match receiver.recv() {
-                    Ok(LogMessage::Message(level, msg)) => {
+                    Ok(LogMessage::Message(level, msg, timestamp)) => {
+                        let msg = if TIMESTAMPS_IN_LOGS.load(std::sync::atomic::Ordering::Relaxed) {
+                            let timestamp: time::OffsetDateTime = timestamp.into();
+                            let timestamp: String = timestamp
+                                .format(&time::format_description::well_known::Rfc3339)
+                                .unwrap_or_else(|_| timestamp.to_string());
+                            format!("{timestamp} {msg}")
+                        } else {
+                            msg
+                        };
+
                         let _ = cb.log(level, msg);
                     }
                     Ok(LogMessage::Quit(barrier)) => {

src/libtelio.udl

@@ -191,6 +191,9 @@ namespace telio {
     /// Utility function to create a `Config` object from a json-string
     [Throws=TelioError]
     Config deserialize_meshnet_config(string cfg_str);
+
+    /// For testing only - embeds timestamps into generated logs
+    void add_timestamps_to_logs();
 };
 
 interface Telio {