Skip to content

Commit 1b89caf

Browse files
committed
Fix logging bugs and improve error handling
- Convert parse functions to return Result instead of panicking - Fix `LOGGING_PYO3` lifecycle by resetting flag when switching modes - Seed `FileWriter` rotation counter from existing file size - Add tests for logging error cases and string stripping - Update docs to correct component_levels type from LogLevel to str
1 parent 6288f0e commit 1b89caf

File tree

9 files changed

+307
-46
lines changed

9 files changed

+307
-46
lines changed

crates/common/src/ffi/logging.rs

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -30,8 +30,9 @@ use nautilus_model::identifiers::TraderId;
3030
use crate::{
3131
enums::{LogColor, LogLevel},
3232
logging::{
33-
headers,
33+
headers, init_logging,
3434
logger::{self, LogGuard, LoggerConfig},
35+
map_log_level_to_filter, parse_component_levels,
3536
writer::FileWriterConfig,
3637
},
3738
};
@@ -101,11 +102,12 @@ pub unsafe extern "C" fn logging_init(
101102
max_file_size: u64,
102103
max_backup_count: u32,
103104
) -> LogGuard_API {
104-
let level_stdout = crate::logging::map_log_level_to_filter(level_stdout);
105-
let level_file = crate::logging::map_log_level_to_filter(level_file);
105+
let level_stdout = map_log_level_to_filter(level_stdout);
106+
let level_file = map_log_level_to_filter(level_file);
106107

107108
let component_levels_json = unsafe { optional_bytes_to_json(component_levels_ptr) };
108-
let component_levels = crate::logging::parse_component_levels(component_levels_json);
109+
let component_levels = parse_component_levels(component_levels_json)
110+
.expect("Failed to parse component log levels");
109111

110112
let config = LoggerConfig::new(
111113
level_stdout,
@@ -130,11 +132,12 @@ pub unsafe extern "C" fn logging_init(
130132
let file_config = FileWriterConfig::new(directory, file_name, file_format, file_rotate);
131133

132134
if u8_as_bool(is_bypassed) {
133-
crate::logging::logging_set_bypass();
135+
logging_set_bypass();
134136
}
135137

136138
LogGuard_API(Box::new(
137-
crate::logging::init_logging(trader_id, instance_id, config, file_config).unwrap(),
139+
init_logging(trader_id, instance_id, config, file_config)
140+
.expect("Failed to initialize logging"),
138141
))
139142
}
140143

crates/common/src/logging/mod.rs

Lines changed: 123 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -189,43 +189,42 @@ pub const fn map_log_level_to_filter(log_level: LogLevel) -> LevelFilter {
189189

190190
/// Parses a string into a [`LevelFilter`].
191191
///
192-
/// # Panics
192+
/// # Errors
193193
///
194-
/// Panics if the provided string is not a valid `LevelFilter`.
195-
#[must_use]
196-
pub fn parse_level_filter_str(s: &str) -> LevelFilter {
194+
/// Returns an error if the provided string is not a valid `LevelFilter`.
195+
pub fn parse_level_filter_str(s: &str) -> anyhow::Result<LevelFilter> {
197196
let mut log_level_str = s.to_string().to_uppercase();
198197
if log_level_str == "WARNING" {
199198
log_level_str = "WARN".to_string();
200199
}
201200
LevelFilter::from_str(&log_level_str)
202-
.unwrap_or_else(|_| panic!("Invalid `LevelFilter` string, was {log_level_str}"))
201+
.map_err(|_| anyhow::anyhow!("Invalid log level string: '{s}'"))
203202
}
204203

205-
#[must_use]
206204
/// Parses component-specific log levels from a JSON value map.
207205
///
208-
/// # Panics
206+
/// # Errors
209207
///
210-
/// Panics if a JSON value in the map is not a string representing a log level.
208+
/// Returns an error if a JSON value in the map is not a string or is not a valid log level.
211209
pub fn parse_component_levels(
212210
original_map: Option<HashMap<String, serde_json::Value>>,
213-
) -> HashMap<Ustr, LevelFilter> {
211+
) -> anyhow::Result<HashMap<Ustr, LevelFilter>> {
214212
match original_map {
215213
Some(map) => {
216214
let mut new_map = HashMap::new();
217215
for (key, value) in map {
218216
let ustr_key = Ustr::from(&key);
219-
// Expect the JSON value to be a string representing a log level
220-
let s = value
221-
.as_str()
222-
.expect("Invalid component log level: expected string");
223-
let lvl = parse_level_filter_str(s);
217+
let s = value.as_str().ok_or_else(|| {
218+
anyhow::anyhow!(
219+
"Component log level for '{key}' must be a string, got: {value}"
220+
)
221+
})?;
222+
let lvl = parse_level_filter_str(s)?;
224223
new_map.insert(ustr_key, lvl);
225224
}
226-
new_map
225+
Ok(new_map)
227226
}
228-
None => HashMap::new(),
227+
None => Ok(HashMap::new()),
229228
}
230229
}
231230

@@ -253,3 +252,111 @@ pub fn log_task_aborted(task_name: &str) {
253252
pub fn log_task_error(task_name: &str, e: &anyhow::Error) {
254253
tracing::error!("Error in task '{task_name}': {e}");
255254
}
255+
256+
#[cfg(test)]
257+
mod tests {
258+
use rstest::rstest;
259+
260+
use super::*;
261+
262+
#[rstest]
263+
#[case("DEBUG", LevelFilter::Debug)]
264+
#[case("debug", LevelFilter::Debug)]
265+
#[case("Debug", LevelFilter::Debug)]
266+
#[case("DeBuG", LevelFilter::Debug)]
267+
#[case("INFO", LevelFilter::Info)]
268+
#[case("info", LevelFilter::Info)]
269+
#[case("WARNING", LevelFilter::Warn)]
270+
#[case("warning", LevelFilter::Warn)]
271+
#[case("WARN", LevelFilter::Warn)]
272+
#[case("warn", LevelFilter::Warn)]
273+
#[case("ERROR", LevelFilter::Error)]
274+
#[case("error", LevelFilter::Error)]
275+
#[case("OFF", LevelFilter::Off)]
276+
#[case("off", LevelFilter::Off)]
277+
#[case("TRACE", LevelFilter::Trace)]
278+
#[case("trace", LevelFilter::Trace)]
279+
fn test_parse_level_filter_str_case_insensitive(
280+
#[case] input: &str,
281+
#[case] expected: LevelFilter,
282+
) {
283+
let result = parse_level_filter_str(input).unwrap();
284+
assert_eq!(result, expected);
285+
}
286+
287+
#[rstest]
288+
#[case("INVALID")]
289+
#[case("DEBG")]
290+
#[case("WARNINGG")]
291+
#[case("")]
292+
#[case("INFO123")]
293+
fn test_parse_level_filter_str_invalid_returns_error(#[case] invalid_input: &str) {
294+
let result = parse_level_filter_str(invalid_input);
295+
296+
assert!(result.is_err());
297+
assert!(
298+
result
299+
.unwrap_err()
300+
.to_string()
301+
.contains("Invalid log level")
302+
);
303+
}
304+
305+
#[rstest]
306+
fn test_parse_component_levels_valid() {
307+
let mut map = HashMap::new();
308+
map.insert(
309+
"Strategy1".to_string(),
310+
serde_json::Value::String("DEBUG".to_string()),
311+
);
312+
map.insert(
313+
"Strategy2".to_string(),
314+
serde_json::Value::String("info".to_string()),
315+
);
316+
317+
let result = parse_component_levels(Some(map)).unwrap();
318+
319+
assert_eq!(result.len(), 2);
320+
assert_eq!(result[&Ustr::from("Strategy1")], LevelFilter::Debug);
321+
assert_eq!(result[&Ustr::from("Strategy2")], LevelFilter::Info);
322+
}
323+
324+
#[rstest]
325+
fn test_parse_component_levels_non_string_value_returns_error() {
326+
let mut map = HashMap::new();
327+
map.insert(
328+
"Strategy1".to_string(),
329+
serde_json::Value::Number(123.into()),
330+
);
331+
332+
let result = parse_component_levels(Some(map));
333+
334+
assert!(result.is_err());
335+
assert!(result.unwrap_err().to_string().contains("must be a string"));
336+
}
337+
338+
#[rstest]
339+
fn test_parse_component_levels_invalid_level_returns_error() {
340+
let mut map = HashMap::new();
341+
map.insert(
342+
"Strategy1".to_string(),
343+
serde_json::Value::String("INVALID_LEVEL".to_string()),
344+
);
345+
346+
let result = parse_component_levels(Some(map));
347+
348+
assert!(result.is_err());
349+
assert!(
350+
result
351+
.unwrap_err()
352+
.to_string()
353+
.contains("Invalid log level")
354+
);
355+
}
356+
357+
#[rstest]
358+
fn test_parse_component_levels_none_returns_empty() {
359+
let result = parse_component_levels(None).unwrap();
360+
assert_eq!(result.len(), 0);
361+
}
362+
}

crates/common/src/logging/writer.rs

Lines changed: 89 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -226,16 +226,26 @@ impl FileWriter {
226226
.append(true)
227227
.open(file_path.clone())
228228
{
229-
Ok(file) => Some(Self {
230-
json_format,
231-
buf: BufWriter::new(file),
232-
path: file_path,
233-
file_config,
234-
trader_id,
235-
instance_id,
236-
level: fileout_level,
237-
cur_file_date: Utc::now().date_naive(),
238-
}),
229+
Ok(file) => {
230+
// Seed cur_file_size from existing file length if rotation is enabled
231+
let mut file_config = file_config;
232+
if let Some(ref mut rotate_config) = file_config.file_rotate
233+
&& let Ok(metadata) = file.metadata()
234+
{
235+
rotate_config.cur_file_size = metadata.len();
236+
}
237+
238+
Some(Self {
239+
json_format,
240+
buf: BufWriter::new(file),
241+
path: file_path,
242+
file_config,
243+
trader_id,
244+
instance_id,
245+
level: fileout_level,
246+
cur_file_date: Utc::now().date_naive(),
247+
})
248+
}
239249
Err(e) => {
240250
tracing::error!("Error creating log file: {e}");
241251
None
@@ -410,3 +420,72 @@ fn strip_ansi_codes(s: &str) -> String {
410420
let no_controls = strip_nonprinting_except_newline(s);
411421
re.replace_all(&no_controls, "").to_string()
412422
}
423+
424+
////////////////////////////////////////////////////////////////////////////////
425+
// Tests
426+
////////////////////////////////////////////////////////////////////////////////
427+
428+
#[cfg(test)]
429+
mod tests {
430+
use log::LevelFilter;
431+
use rstest::rstest;
432+
use tempfile::tempdir;
433+
434+
use super::*;
435+
436+
#[rstest]
437+
fn test_file_writer_with_rotation_creates_new_timestamped_file() {
438+
let temp_dir = tempdir().unwrap();
439+
440+
let config = FileWriterConfig {
441+
directory: Some(temp_dir.path().to_str().unwrap().to_string()),
442+
file_name: Some("test".to_string()),
443+
file_format: None,
444+
file_rotate: Some(FileRotateConfig::from((2000, 5))),
445+
};
446+
447+
let writer = FileWriter::new(
448+
"TRADER-001".to_string(),
449+
"instance-123".to_string(),
450+
config,
451+
LevelFilter::Info,
452+
)
453+
.unwrap();
454+
455+
assert_eq!(
456+
writer
457+
.file_config
458+
.file_rotate
459+
.as_ref()
460+
.unwrap()
461+
.cur_file_size,
462+
0
463+
);
464+
assert!(writer.path.to_str().unwrap().contains("test_"));
465+
}
466+
467+
#[rstest]
468+
#[case("Hello, World!", "Hello, World!")]
469+
#[case("Line1\nLine2", "Line1\nLine2")]
470+
#[case("Tab\there", "Tabhere")]
471+
#[case("Null\0char", "Nullchar")]
472+
#[case("DEL\u{7F}char", "DELchar")]
473+
#[case("Bell\u{07}sound", "Bellsound")]
474+
#[case("Mix\t\0\u{7F}ed", "Mixed")]
475+
fn test_strip_nonprinting_except_newline(#[case] input: &str, #[case] expected: &str) {
476+
let result = strip_nonprinting_except_newline(input);
477+
assert_eq!(result, expected);
478+
}
479+
480+
#[rstest]
481+
#[case("Plain text", "Plain text")]
482+
#[case("\x1B[31mRed\x1B[0m", "[31mRed[0m")]
483+
#[case("\x1B[1;32mBold Green\x1B[0m", "[1;32mBold Green[0m")]
484+
#[case("Before\x1B[0mAfter", "Before[0mAfter")]
485+
#[case("\x1B]0;Title\x07Content", "]0;TitleContent")]
486+
#[case("Text\t\x1B[31mRed\x1B[0m", "Text[31mRed[0m")]
487+
fn test_strip_ansi_codes(#[case] input: &str, #[case] expected: &str) {
488+
let result = strip_ansi_codes(input);
489+
assert_eq!(result, expected);
490+
}
491+
}

crates/common/src/python/logging.rs

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -119,10 +119,12 @@ pub fn py_init_logging(
119119
) -> PyResult<LogGuard> {
120120
let level_file = level_file.map_or(LevelFilter::Off, map_log_level_to_filter);
121121

122+
let component_levels = parse_component_levels(component_levels).map_err(to_pyvalue_err)?;
123+
122124
let config = LoggerConfig::new(
123125
map_log_level_to_filter(level_stdout),
124126
level_file,
125-
parse_component_levels(component_levels),
127+
component_levels,
126128
log_components_only.unwrap_or(false),
127129
is_colored.unwrap_or(true),
128130
print_config.unwrap_or(false),
@@ -145,18 +147,18 @@ pub fn py_logger_flush() {
145147

146148
fn parse_component_levels(
147149
original_map: Option<HashMap<String, String>>,
148-
) -> HashMap<Ustr, LevelFilter> {
150+
) -> anyhow::Result<HashMap<Ustr, LevelFilter>> {
149151
match original_map {
150152
Some(map) => {
151153
let mut new_map = HashMap::new();
152154
for (key, value) in map {
153155
let ustr_key = Ustr::from(&key);
154-
let value = parse_level_filter_str(&value);
155-
new_map.insert(ustr_key, value);
156+
let level = parse_level_filter_str(&value)?;
157+
new_map.insert(ustr_key, level);
156158
}
157-
new_map
159+
Ok(new_map)
158160
}
159-
None => HashMap::new(),
161+
None => Ok(HashMap::new()),
160162
}
161163
}
162164

nautilus_trader/common/component.pyx

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1214,7 +1214,7 @@ cpdef LogGuard init_logging(
12141214
str directory = None,
12151215
str file_name = None,
12161216
str file_format = None,
1217-
dict component_levels: dict[ComponentId, LogLevel] = None,
1217+
dict component_levels = None,
12181218
bint log_components_only = False,
12191219
bint colors = True,
12201220
bint bypass = False,
@@ -1248,17 +1248,17 @@ cpdef LogGuard init_logging(
12481248
If ``None`` then will write to the current working directory.
12491249
file_name : str, optional
12501250
The custom log file name (will use a '.log' suffix for plain text or '.json' for JSON).
1251-
If ``None`` will not log to a file (unless `file_auto` is True).
1251+
If ``None`` will not log to a file.
12521252
file_format : str { 'JSON' }, optional
12531253
The log file format. If ``None`` (default) then will log in plain text.
12541254
If set to 'JSON' then logs will be in JSON format.
1255-
component_levels : dict[ComponentId, LogLevel]
1255+
component_levels : dict[str, str], optional
12561256
The additional per component log level filters, where keys are component
1257-
IDs (e.g. actor/strategy IDs) and values are log levels.
1257+
IDs as strings (e.g. actor/strategy IDs) and values are log level strings (case-insensitive).
12581258
log_components_only : bool, default False
12591259
If only components with explicit component-level filters should be logged.
12601260
When enabled, only log messages from components that have been explicitly
1261-
configured in `log_component_levels` will be output.
1261+
configured in `component_levels` will be output.
12621262
colors : bool, default True
12631263
If ANSI codes should be used to produce colored log lines.
12641264
bypass : bool, default False

0 commit comments

Comments
 (0)