Deduplicate metadata for structured logging

.github/workflows/CI.yml

@@ -23,7 +23,7 @@ jobs:
           - { name: "cairo", features: "png,pdf,svg,ps,use_glib,v1_18,freetype,script,xcb,xlib,win32-surface", nightly: "--features 'png,pdf,svg,ps,use_glib,v1_18,freetype,script,xcb,xlib,win32-surface'", test_sys: true }
           - { name: "gdk-pixbuf", features: "v2_42", nightly: "--all-features", test_sys: true }
           - { name: "gio", features: "v2_80", nightly: "--all-features", test_sys: true }
-          - { name: "glib", features: "v2_80", nightly: "--all-features", test_sys: true }
+          - { name: "glib", features: "v2_80,log", nightly: "--all-features", test_sys: true }
           - { name: "graphene", features: "", nightly: "", test_sys: true }
           - { name: "pango", features: "v1_54", nightly: "--all-features", test_sys: true }
           - { name: "pangocairo", features: "", nightly: "--all-features", test_sys: true }

glib/src/bridged_logging.rs

@@ -1,6 +1,6 @@
 // Take a look at the license at the top of the repository in the LICENSE file.
 
-use crate::{log as glib_log, translate::*};
+use crate::{gstr, log as glib_log, log_structured_array, translate::*, LogField};
 
 // rustdoc-stripper-ignore-next
 /// Enumeration of the possible formatting behaviours for a
@@ -141,19 +141,36 @@ impl GlibLogger {
         func: Option<&str>,
         message: &str,
     ) {
-        let line = line.map(|l| l.to_string());
-        let line = line.as_deref();
-
-        crate::log_structured!(
-            domain.unwrap_or("default"),
-            GlibLogger::level_to_glib(level),
-            {
-                "CODE_FILE" => file.unwrap_or("<unknown file>");
-                "CODE_LINE" => line.unwrap_or("<unknown line>");
-                "CODE_FUNC" => func.unwrap_or("<unknown module path>");
-                "MESSAGE" => message;
-            }
-        );
+        // Write line number into a static array to avoid allocating its string
+        // representation. 16 bytes allow 10^15 lines, which should be more than
+        // sufficient.
+        let mut line_buffer = [0u8; 16];
+        let line = {
+            use std::io::{Cursor, Write};
+            let mut c = Cursor::new(line_buffer.as_mut_slice());
+            match line {
+                Some(lineno) => write!(&mut c, "{lineno}").ok(),
+                None => write!(&mut c, "<unknown line>").ok(),
+            };
+            let pos = c.position() as usize;
+            &line_buffer[..pos]
+        };
+        let glib_level = GlibLogger::level_to_glib(level);
+        let fields = [
+            LogField::new(gstr!("PRIORITY"), glib_level.priority().as_bytes()),
+            LogField::new(
+                gstr!("CODE_FILE"),
+                file.unwrap_or("<unknown file>").as_bytes(),
+            ),
+            LogField::new(gstr!("CODE_LINE"), line),
+            LogField::new(
+                gstr!("CODE_FUNC"),
+                func.unwrap_or("<unknown module path>").as_bytes(),
+            ),
+            LogField::new(gstr!("MESSAGE"), message.as_bytes()),
+            LogField::new(gstr!("GLIB_DOMAIN"), domain.unwrap_or("default").as_bytes()),
+        ];
+        log_structured_array(glib_level, &fields);
     }
 }
 
@@ -200,25 +217,19 @@ impl rs_log::Log for GlibLogger {
             }
             GlibLoggerFormat::Structured => {
                 let args = record.args();
-                if let Some(s) = args.as_str() {
-                    GlibLogger::write_log_structured(
-                        domain,
-                        record.level(),
-                        record.file(),
-                        record.line(),
-                        record.module_path(),
-                        s,
-                    );
+                let message = if let Some(s) = args.as_str() {
+                    s
                 } else {
-                    GlibLogger::write_log_structured(
-                        domain,
-                        record.level(),
-                        record.file(),
-                        record.line(),
-                        record.module_path(),
-                        &args.to_string(),
-                    );
-                }
+                    &args.to_string()
+                };
+                GlibLogger::write_log_structured(
+                    domain,
+                    record.level(),
+                    record.file(),
+                    record.line(),
+                    record.module_path(),
+                    message,
+                );
             }
         };
     }

glib/tests/bridged_logging.rs

@@ -0,0 +1,148 @@
+#![cfg(feature = "log")]
+
+use std::sync::{Arc, Mutex};
+
+use glib::LogLevel;
+use rs_log::Log;
+
+#[derive(Debug, PartialEq, Eq)]
+struct LoggedEvent {
+    level: LogLevel,
+    fields: Vec<(String, Option<String>)>,
+}
+
+fn setup_log_collector() -> Arc<Mutex<Vec<LoggedEvent>>> {
+    let events = Arc::new(Mutex::new(Vec::new()));
+    let event_writer = events.clone();
+    glib::log_set_writer_func(move |level, fields| {
+        let fields = fields
+            .iter()
+            .map(|field| {
+                (
+                    field.key().to_string(),
+                    field.value_str().map(|s| s.to_owned()),
+                )
+            })
+            .collect();
+        event_writer
+            .lock()
+            .unwrap()
+            .push(LoggedEvent { level, fields });
+        glib::LogWriterOutput::Handled
+    });
+    events
+}
+
+/// Test the glib Rust logger with different formats.
+///
+/// We put everything into one test because we can only set the log writer func once.
+#[test]
+fn glib_logger_formats() {
+    let events = setup_log_collector();
+
+    let record = rs_log::RecordBuilder::new()
+        .target("test_target")
+        .level(rs_log::Level::Info)
+        .args(format_args!("test message"))
+        .file(Some("/path/to/a/test/file.rs"))
+        .line(Some(42))
+        .module_path(Some("foo::bar"))
+        .build();
+
+    glib::GlibLogger::new(
+        glib::GlibLoggerFormat::Plain,
+        glib::GlibLoggerDomain::CrateTarget,
+    )
+    .log(&record);
+    let event = events.lock().unwrap().pop().unwrap();
+    assert_eq!(
+        event,
+        LoggedEvent {
+            level: glib::LogLevel::Info,
+            fields: vec![
+                ("GLIB_OLD_LOG_API".to_string(), Some("1".to_string())),
+                ("MESSAGE".to_string(), Some("test message".to_string())),
+                ("PRIORITY".to_string(), Some("6".to_string())),
+                ("GLIB_DOMAIN".to_string(), Some("test_target".to_string()))
+            ]
+        }
+    );
+    events.lock().unwrap().clear();
+
+    glib::GlibLogger::new(
+        glib::GlibLoggerFormat::LineAndFile,
+        glib::GlibLoggerDomain::CrateTarget,
+    )
+    .log(&record);
+    let event = events.lock().unwrap().pop().unwrap();
+    assert_eq!(
+        event,
+        LoggedEvent {
+            level: glib::LogLevel::Info,
+            fields: vec![
+                ("GLIB_OLD_LOG_API".to_string(), Some("1".to_string())),
+                (
+                    "MESSAGE".to_string(),
+                    Some("/path/to/a/test/file.rs:42: test message".to_string())
+                ),
+                ("PRIORITY".to_string(), Some("6".to_string())),
+                ("GLIB_DOMAIN".to_string(), Some("test_target".to_string()))
+            ]
+        }
+    );
+
+    glib::GlibLogger::new(
+        glib::GlibLoggerFormat::Structured,
+        glib::GlibLoggerDomain::CrateTarget,
+    )
+    .log(&record);
+    let event = events.lock().unwrap().pop().unwrap();
+    assert_eq!(
+        event,
+        LoggedEvent {
+            level: glib::LogLevel::Info,
+            fields: vec![
+                ("PRIORITY".to_string(), Some("6".to_string())),
+                (
+                    "CODE_FILE".to_string(),
+                    Some("/path/to/a/test/file.rs".to_string())
+                ),
+                ("CODE_LINE".to_string(), Some("42".to_string())),
+                ("CODE_FUNC".to_string(), Some("foo::bar".to_string())),
+                ("MESSAGE".to_string(), Some("test message".to_string())),
+                ("GLIB_DOMAIN".to_string(), Some("test_target".to_string()))
+            ]
+        }
+    );
+
+    // Structured logging without location fields
+    glib::GlibLogger::new(
+        glib::GlibLoggerFormat::Structured,
+        glib::GlibLoggerDomain::CrateTarget,
+    )
+    .log(
+        &rs_log::RecordBuilder::new()
+            .target("test_target")
+            .level(rs_log::Level::Info)
+            .args(format_args!("test message"))
+            .build(),
+    );
+    let event = events.lock().unwrap().pop().unwrap();
+    assert_eq!(
+        event,
+        LoggedEvent {
+            level: glib::LogLevel::Info,
+            fields: vec![
+                ("PRIORITY".to_string(), Some("6".to_string())),
+                ("CODE_FILE".to_string(), Some("<unknown file>".to_string())),
+                ("CODE_LINE".to_string(), Some("<unknown line>".to_string())),
+                (
+                    "CODE_FUNC".to_string(),
+                    Some("<unknown module path>".to_string())
+                ),
+                ("MESSAGE".to_string(), Some("test message".to_string())),
+                ("GLIB_DOMAIN".to_string(), Some("test_target".to_string()))
+            ]
+        }
+    );
+}