From 6750c8000f8c8fe7cf9f1efd7df869d44bac98ac Mon Sep 17 00:00:00 2001 From: Aleksei Bavshin Date: Thu, 12 Dec 2024 09:45:46 -0800 Subject: [PATCH 1/4] refactor: deduplicate log macro bodies --- examples/upstream.rs | 1 - src/log.rs | 119 +++++++++++++------------------------------ 2 files changed, 35 insertions(+), 85 deletions(-) diff --git a/examples/upstream.rs b/examples/upstream.rs index 7056813e..101aac46 100644 --- a/examples/upstream.rs +++ b/examples/upstream.rs @@ -24,7 +24,6 @@ use ngx::http::{ ngx_http_conf_get_module_srv_conf, ngx_http_conf_upstream_srv_conf_immutable, ngx_http_conf_upstream_srv_conf_mutable, HTTPModule, Merge, MergeConfigError, Request, }; -use ngx::log::DebugMask; use ngx::{http_upstream_init_peer_pt, ngx_log_debug_http, ngx_log_debug_mask, ngx_null_command, ngx_string}; #[derive(Clone, Copy, Debug)] diff --git a/src/log.rs b/src/log.rs index a0f0397e..c779c681 100644 --- a/src/log.rs +++ b/src/log.rs @@ -14,16 +14,19 @@ pub fn check_mask(mask: DebugMask, log_level: usize) -> bool { /// for available log levels. #[macro_export] macro_rules! ngx_log_debug { - ( $log:expr, $($arg:tt)* ) => { - let log_level = unsafe { (*$log).log_level }; - if log_level != 0 { + ( mask: $mask:expr, $log:expr, $($arg:tt)+ ) => { + let log = $log; + if $crate::log::check_mask($mask, unsafe { (*log).log_level }) { let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); + let c_message = ::std::ffi::CString::new(format!($($arg)+)).unwrap(); unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); + $crate::ffi::ngx_log_error_core(level, log, 0, fmt.as_ptr(), c_message.as_ptr()); } } + }; + ( $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::All, $log, $($arg)+); } } @@ -32,9 +35,9 @@ macro_rules! ngx_log_debug { /// [`NGX_LOG_DEBUG_HTTP`]: https://nginx.org/en/docs/dev/development_guide.html#logging #[macro_export] macro_rules! ngx_log_debug_http { - ( $request:expr, $($arg:tt)* ) => { + ( $request:expr, $($arg:tt)+ ) => { let log = unsafe { (*$request.connection()).log }; - $crate::ngx_log_debug!(log, $($arg)*); + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Http, log, $($arg)+); } } @@ -48,83 +51,27 @@ macro_rules! ngx_log_debug_http { /// masks. #[macro_export] macro_rules! ngx_log_debug_mask { - ( DebugMask::Core, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Core, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Alloc, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Alloc, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Mutex, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Mutex, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Event, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Event, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Http, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Http, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Mail, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Mail, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); - ( DebugMask::Stream, $log:expr, $($arg:tt)* ) => ({ - let log_level = unsafe { (*$log).log_level }; - if $crate::log::check_mask(DebugMask::Stream, log_level) { - let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)*)).unwrap(); - unsafe { - $crate::ffi::ngx_log_error_core(level, $log, 0, fmt.as_ptr(), c_message.as_ptr()); - } - } - }); + ( DebugMask::Core, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Core, $log, $($arg)+); + }; + ( DebugMask::Alloc, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Alloc, $log, $($arg)+); + }; + ( DebugMask::Mutex, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Mutex, $log, $($arg)+); + }; + ( DebugMask::Event, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Event, $log, $($arg)+); + }; + ( DebugMask::Http, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Http, $log, $($arg)+); + }; + ( DebugMask::Mail, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Mail, $log, $($arg)+); + }; + ( DebugMask::Stream, $log:expr, $($arg:tt)+ ) => { + $crate::ngx_log_debug!(mask: $crate::log::DebugMask::Stream, $log, $($arg)+); + }; } /// Debug masks for use with [`ngx_log_debug_mask`], these represent the only accepted values for @@ -145,6 +92,8 @@ pub enum DebugMask { Mail, /// Aligns to the NGX_LOG_DEBUG_STREAM mask. Stream, + /// Aligns to the NGX_LOG_DEBUG_ALL mask. + All, } impl TryFrom for DebugMask { @@ -159,6 +108,7 @@ impl TryFrom for DebugMask { crate::ffi::NGX_LOG_DEBUG_HTTP => Ok(DebugMask::Http), crate::ffi::NGX_LOG_DEBUG_MAIL => Ok(DebugMask::Mail), crate::ffi::NGX_LOG_DEBUG_STREAM => Ok(DebugMask::Stream), + crate::ffi::NGX_LOG_DEBUG_ALL => Ok(DebugMask::All), _ => Err(0), } } @@ -174,6 +124,7 @@ impl From for u32 { DebugMask::Http => crate::ffi::NGX_LOG_DEBUG_HTTP, DebugMask::Mail => crate::ffi::NGX_LOG_DEBUG_MAIL, DebugMask::Stream => crate::ffi::NGX_LOG_DEBUG_STREAM, + DebugMask::All => crate::ffi::NGX_LOG_DEBUG_ALL, } } } From 7ee10a01eeda1ac84b6553f0bdfecf10b1a55207 Mon Sep 17 00:00:00 2001 From: Aleksei Bavshin Date: Fri, 13 Dec 2024 22:35:25 -0800 Subject: [PATCH 2/4] fix(log): remove a few allocations --- src/log.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/log.rs b/src/log.rs index c779c681..ec6b10a0 100644 --- a/src/log.rs +++ b/src/log.rs @@ -18,10 +18,10 @@ macro_rules! ngx_log_debug { let log = $log; if $crate::log::check_mask($mask, unsafe { (*log).log_level }) { let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let fmt = ::std::ffi::CString::new("%s").unwrap(); - let c_message = ::std::ffi::CString::new(format!($($arg)+)).unwrap(); + let message = format!($($arg)+); + let message = message.as_bytes(); unsafe { - $crate::ffi::ngx_log_error_core(level, log, 0, fmt.as_ptr(), c_message.as_ptr()); + $crate::ffi::ngx_log_error_core(level, log, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); } } }; From 6b3c6e905a7b586414752557cd6c7a0c75c300e3 Mon Sep 17 00:00:00 2001 From: Aleksei Bavshin Date: Tue, 22 Oct 2024 13:39:08 -0700 Subject: [PATCH 3/4] feat: implement ngx_log_error! macro --- examples/upstream.rs | 37 +++++++++++++------------------------ src/log.rs | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+), 24 deletions(-) diff --git a/examples/upstream.rs b/examples/upstream.rs index 101aac46..e2306a08 100644 --- a/examples/upstream.rs +++ b/examples/upstream.rs @@ -13,7 +13,7 @@ use std::slice; use ngx::core::{Pool, Status}; use ngx::ffi::{ - nginx_version, ngx_atoi, ngx_command_t, ngx_conf_log_error, ngx_conf_t, ngx_connection_t, ngx_event_free_peer_pt, + nginx_version, ngx_atoi, ngx_command_t, ngx_conf_t, ngx_connection_t, ngx_event_free_peer_pt, ngx_event_get_peer_pt, ngx_http_module_t, ngx_http_upstream_init_peer_pt, ngx_http_upstream_init_pt, ngx_http_upstream_init_round_robin, ngx_http_upstream_module, ngx_http_upstream_srv_conf_t, ngx_http_upstream_t, ngx_int_t, ngx_module_t, ngx_peer_connection_t, ngx_str_t, ngx_uint_t, NGX_CONF_NOARGS, NGX_CONF_TAKE1, @@ -24,7 +24,10 @@ use ngx::http::{ ngx_http_conf_get_module_srv_conf, ngx_http_conf_upstream_srv_conf_immutable, ngx_http_conf_upstream_srv_conf_mutable, HTTPModule, Merge, MergeConfigError, Request, }; -use ngx::{http_upstream_init_peer_pt, ngx_log_debug_http, ngx_log_debug_mask, ngx_null_command, ngx_string}; +use ngx::{ + http_upstream_init_peer_pt, ngx_conf_log_error, ngx_log_debug_http, ngx_log_debug_mask, ngx_null_command, + ngx_string, +}; #[derive(Clone, Copy, Debug)] #[repr(C)] @@ -242,12 +245,7 @@ unsafe extern "C" fn ngx_http_upstream_init_custom( let maybe_conf: Option<*mut SrvConfig> = ngx_http_conf_upstream_srv_conf_mutable(us, &*addr_of!(ngx_http_upstream_custom_module)); if maybe_conf.is_none() { - ngx_conf_log_error( - NGX_LOG_EMERG as usize, - cf, - 0, - "CUSTOM UPSTREAM no upstream srv_conf".as_bytes().as_ptr() as *const c_char, - ); + ngx_conf_log_error!(NGX_LOG_EMERG, cf, "CUSTOM UPSTREAM no upstream srv_conf"); return isize::from(Status::NGX_ERROR); } let hccf = maybe_conf.unwrap(); @@ -258,12 +256,7 @@ unsafe extern "C" fn ngx_http_upstream_init_custom( let init_upstream_ptr = (*hccf).original_init_upstream.unwrap(); if init_upstream_ptr(cf, us) != Status::NGX_OK.into() { - ngx_conf_log_error( - NGX_LOG_EMERG as usize, - cf, - 0, - "CUSTOM UPSTREAM failed calling init_upstream".as_bytes().as_ptr() as *const c_char, - ); + ngx_conf_log_error!(NGX_LOG_EMERG, cf, "CUSTOM UPSTREAM failed calling init_upstream"); return isize::from(Status::NGX_ERROR); } @@ -290,13 +283,12 @@ unsafe extern "C" fn ngx_http_upstream_commands_set_custom( let value: &[ngx_str_t] = slice::from_raw_parts((*(*cf).args).elts as *const ngx_str_t, (*(*cf).args).nelts); let n = ngx_atoi(value[1].data, value[1].len); if n == (NGX_ERROR as isize) || n == 0 { - ngx_conf_log_error( - NGX_LOG_EMERG as usize, + ngx_conf_log_error!( + NGX_LOG_EMERG, cf, - 0, - "invalid value \"%V\" in \"%V\" directive".as_bytes().as_ptr() as *const c_char, + "invalid value \"{}\" in \"{}\" directive", value[1], - &(*cmd).name, + &(*cmd).name ); return usize::MAX as *mut c_char; } @@ -334,13 +326,10 @@ impl HTTPModule for Module { let mut pool = Pool::from_ngx_pool((*cf).pool); let conf = pool.alloc_type::(); if conf.is_null() { - ngx_conf_log_error( - NGX_LOG_EMERG as usize, + ngx_conf_log_error!( + NGX_LOG_EMERG, cf, - 0, "CUSTOM UPSTREAM could not allocate memory for config" - .as_bytes() - .as_ptr() as *const c_char, ); return std::ptr::null_mut(); } diff --git a/src/log.rs b/src/log.rs index ec6b10a0..b8b9f43a 100644 --- a/src/log.rs +++ b/src/log.rs @@ -13,6 +13,38 @@ pub fn check_mask(mask: DebugMask, log_level: usize) -> bool { /// See [Logging](https://nginx.org/en/docs/dev/development_guide.html#logging) /// for available log levels. #[macro_export] +macro_rules! ngx_log_error { + ( $level:expr, $log:expr, $($arg:tt)+ ) => { + let log = $log; + let level = $level as $crate::ffi::ngx_uint_t; + if level < unsafe { (*log).log_level } { + let message = ::std::format!($($arg)+); + let message = message.as_bytes(); + unsafe { + $crate::ffi::ngx_log_error_core(level, log, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); + } + } + } +} + +/// Write to logger with the context of currently processed configuration file. +#[macro_export] +macro_rules! ngx_conf_log_error { + ( $level:expr, $cf:expr, $($arg:tt)+ ) => { + let cf: *mut $crate::ffi::ngx_conf_t = $cf; + let level = $level as $crate::ffi::ngx_uint_t; + if level < unsafe { (*(*cf).log).log_level } { + let message = ::std::format!($($arg)+); + let message = message.as_bytes(); + unsafe { + $crate::ffi::ngx_conf_log_error(level, cf, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); + } + } + } +} + +/// Write to logger at debug level. +#[macro_export] macro_rules! ngx_log_debug { ( mask: $mask:expr, $log:expr, $($arg:tt)+ ) => { let log = $log; From d7cd6bad1cf6e9f28af685eec7be8c4327aee168 Mon Sep 17 00:00:00 2001 From: Aleksei Bavshin Date: Fri, 13 Dec 2024 22:51:16 -0800 Subject: [PATCH 4/4] feat: format logs to fixed buffer to remove the last allocation --- src/lib.rs | 3 -- src/log.rs | 106 ++++++++++++++++++++++++++++++++++++++++++++++++++--- 2 files changed, 100 insertions(+), 9 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 52f8e882..906af2a8 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -59,9 +59,6 @@ pub mod http; /// The log module. /// /// This module provides an interface into the NGINX logger framework. -/// -/// This module is temporally available only with `std` feature. -#[cfg(feature = "std")] pub mod log; /// Define modules exported by this library. diff --git a/src/log.rs b/src/log.rs index b8b9f43a..3eb18e4f 100644 --- a/src/log.rs +++ b/src/log.rs @@ -1,3 +1,15 @@ +use core::cmp; +use core::fmt::{self, Write}; +use core::mem::MaybeUninit; + +use crate::ffi::NGX_MAX_ERROR_STR; + +/// Size of the static buffer used to format log messages. +/// +/// Approximates the remaining space in `u_char[NGX_MAX_ERROR_STR]` after writing the standard +/// prefix +pub const LOG_BUFFER_SIZE: usize = NGX_MAX_ERROR_STR as usize - b"1970/01/01 00:00:00 [info] 1#1: ".len(); + /// Utility function to provide typed checking of the mask's field state. #[inline(always)] pub fn check_mask(mask: DebugMask, log_level: usize) -> bool { @@ -8,6 +20,21 @@ pub fn check_mask(mask: DebugMask, log_level: usize) -> bool { true } +/// Format args into a provided buffer +// May produce incomplete UTF-8 sequences. But any writes to `ngx_log_t` already can be truncated, +// so nothing we can do here. +#[inline] +pub fn write_fmt<'a>(buf: &'a mut [MaybeUninit], args: fmt::Arguments<'_>) -> &'a [u8] { + if let Some(str) = args.as_str() { + str.as_bytes() + } else { + let mut buf = LogBuf::from(buf); + // nothing we can or want to do on errors + let _ = buf.write_fmt(args); + buf.filled() + } +} + /// Write to logger at a specified level. /// /// See [Logging](https://nginx.org/en/docs/dev/development_guide.html#logging) @@ -18,8 +45,8 @@ macro_rules! ngx_log_error { let log = $log; let level = $level as $crate::ffi::ngx_uint_t; if level < unsafe { (*log).log_level } { - let message = ::std::format!($($arg)+); - let message = message.as_bytes(); + let mut buf = [const { ::core::mem::MaybeUninit::::uninit() }; $crate::log::LOG_BUFFER_SIZE]; + let message = $crate::log::write_fmt(&mut buf, format_args!($($arg)+)); unsafe { $crate::ffi::ngx_log_error_core(level, log, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); } @@ -34,8 +61,8 @@ macro_rules! ngx_conf_log_error { let cf: *mut $crate::ffi::ngx_conf_t = $cf; let level = $level as $crate::ffi::ngx_uint_t; if level < unsafe { (*(*cf).log).log_level } { - let message = ::std::format!($($arg)+); - let message = message.as_bytes(); + let mut buf = [const { ::core::mem::MaybeUninit::::uninit() }; $crate::log::LOG_BUFFER_SIZE]; + let message = $crate::log::write_fmt(&mut buf, format_args!($($arg)+)); unsafe { $crate::ffi::ngx_conf_log_error(level, cf, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); } @@ -50,8 +77,8 @@ macro_rules! ngx_log_debug { let log = $log; if $crate::log::check_mask($mask, unsafe { (*log).log_level }) { let level = $crate::ffi::NGX_LOG_DEBUG as $crate::ffi::ngx_uint_t; - let message = format!($($arg)+); - let message = message.as_bytes(); + let mut buf = [const { ::core::mem::MaybeUninit::::uninit() }; $crate::log::LOG_BUFFER_SIZE]; + let message = $crate::log::write_fmt(&mut buf, format_args!($($arg)+)); unsafe { $crate::ffi::ngx_log_error_core(level, log, 0, c"%*s".as_ptr(), message.len(), message.as_ptr()); } @@ -161,6 +188,52 @@ impl From for u32 { } } +/// Minimal subset of unstable core::io::{BorrowedBuf,BorrowedCursor} +struct LogBuf<'data> { + buf: &'data mut [MaybeUninit], + filled: usize, +} + +impl<'data> LogBuf<'data> { + pub fn filled(&self) -> &'data [u8] { + // SAFETY: valid bytes have been written to self.buf[..self.filled] + unsafe { + let buf = self.buf.get_unchecked(..self.filled); + // inlined MaybeUninit::slice_assume_init_ref + &*(buf as *const [MaybeUninit] as *const [u8]) + } + } + + pub fn append(&mut self, buf: &[u8]) -> &mut Self { + let n = cmp::min(self.buf.len() - self.filled, buf.len()); + unsafe { + // SAFETY: The source buf has at least n bytes + let src = buf.get_unchecked(..n); + // SAFETY: &[u8] and &[MaybeUninit] have the same layout + let src: &[MaybeUninit] = core::mem::transmute(src); + // SAFETY: self.buf has at least n bytes available after self.filled + self.buf + .get_unchecked_mut(self.filled..self.filled + n) + .copy_from_slice(src); + } + self.filled += n; + self + } +} + +impl<'data> From<&'data mut [MaybeUninit]> for LogBuf<'data> { + fn from(buf: &'data mut [MaybeUninit]) -> Self { + Self { buf, filled: 0 } + } +} + +impl fmt::Write for LogBuf<'_> { + fn write_str(&mut self, s: &str) -> fmt::Result { + self.append(s.as_bytes()); + Ok(()) + } +} + #[cfg(test)] mod tests { @@ -187,4 +260,25 @@ mod tests { r = check_mask(DebugMask::Alloc, mock.log_level); assert!(!r); } + + #[test] + fn log_buffer() { + use core::str; + + let mut buf = [const { MaybeUninit::::uninit() }; 32]; + let mut buf = LogBuf::from(&mut buf[..]); + let words = ["Hello", "World"]; + + // normal write + write!(&mut buf, "{} {}!", words[0], words[1]).unwrap(); + assert_eq!(str::from_utf8(buf.filled()), Ok("Hello World!")); + + // overflow results in truncated output + write!(&mut buf, " This is a test, {}", usize::MAX).unwrap(); + assert_eq!(str::from_utf8(buf.filled()), Ok("Hello World! This is a test, 184")); + + // and any following writes are still safe + write!(&mut buf, "test").unwrap(); + assert_eq!(str::from_utf8(buf.filled()), Ok("Hello World! This is a test, 184")); + } }