From 832980d014c9f54c344b8e452f3dde7d36479020 Mon Sep 17 00:00:00 2001 From: Tomasz Klak Date: Tue, 17 Dec 2024 15:35:47 +0100 Subject: [PATCH] Add timestamp in logs (also) on libtelio side By default timestamp are not added, but tests-like environments might want to add timestamps on libtelio side. This is enabeld for nat-lab / libtelio-remote tests --- .unreleased/log_time_in_telio | 0 Cargo.lock | 1 + Cargo.toml | 1 + nat-lab/tests/uniffi/libtelio_remote.py | 1 + src/ffi.rs | 8 +++++++- src/ffi/logging.rs | 25 ++++++++++++++++++++----- src/libtelio.udl | 3 +++ 7 files changed, 33 insertions(+), 6 deletions(-) create mode 100644 .unreleased/log_time_in_telio diff --git a/.unreleased/log_time_in_telio b/.unreleased/log_time_in_telio new file mode 100644 index 000000000..e69de29bb diff --git a/Cargo.lock b/Cargo.lock index f3b4fd61a..9928e27fb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4595,6 +4595,7 @@ dependencies = [ "telio-utils", "telio-wg", "thiserror 1.0.64", + "time", "tokio", "tracing", "tracing-subscriber", diff --git a/Cargo.toml b/Cargo.toml index 447e129b8..309167998 100644 --- a/Cargo.toml +++ b/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" diff --git a/nat-lab/tests/uniffi/libtelio_remote.py b/nat-lab/tests/uniffi/libtelio_remote.py index be4404627..e1f12e879 100644 --- a/nat-lab/tests/uniffi/libtelio_remote.py +++ b/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): diff --git a/src/ffi.rs b/src/ffi.rs index 31fa339ad..4510e0100 100644 --- a/src/ffi.rs +++ b/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() diff --git a/src/ffi/logging.rs b/src/ffi/logging.rs index a499a37ea..53fe1499a 100644 --- a/src/ffi/logging.rs +++ b/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>>, @@ -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 { } enum LogMessage { - Message(TelioLogLevel, String), + Message(TelioLogLevel, String, SystemTime), Quit(Arc), } @@ -258,7 +263,17 @@ fn start_async_logger(cb: Box, 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)) => { diff --git a/src/libtelio.udl b/src/libtelio.udl index 7dcf5a3b9..2da9d351e 100644 --- a/src/libtelio.udl +++ b/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 {