From f7ce686f8570e660764993a2c0c648e118f7595f Mon Sep 17 00:00:00 2001 From: Yuri Astrakhan Date: Fri, 13 Sep 2024 10:02:49 -0400 Subject: [PATCH] Efficient logging without extra allocations All logging functions now take a new `Loggable` object that contains a `Cow` - making it possible to log without an extra re-allocation. --- src/vcl/backend.rs | 18 ++++++------- src/vcl/ctx.rs | 67 ++++++++++++++++++++++++++++++++++++++-------- src/vmodtool-rs.py | 4 +-- 3 files changed, 67 insertions(+), 22 deletions(-) diff --git a/src/vcl/backend.rs b/src/vcl/backend.rs index 5c2f226..ca07db8 100644 --- a/src/vcl/backend.rs +++ b/src/vcl/backend.rs @@ -80,7 +80,7 @@ use std::time::{SystemTime, UNIX_EPOCH}; use crate::ffi; use crate::vcl::convert::IntoVCL; -use crate::vcl::ctx::{Ctx, Event, LogTag}; +use crate::vcl::ctx::{Ctx, Event, LogTag, Loggable}; use crate::vcl::utils::{ validate_director, validate_vdir, validate_vfp_ctx, validate_vfp_entry, validate_vrt_ctx, }; @@ -305,13 +305,13 @@ unsafe extern "C" fn vfp_pull( let reader = vfe.priv1.cast::().as_mut().unwrap(); match reader.read(buf) { Err(e) => { - let msg = e.to_string(); + let msg = Loggable::from(e.to_string()); // TODO: we should grow a VSL object ffi::VSLbt( ctx.req.as_ref().unwrap().vsl, ffi::VSL_tag_e_SLT_Error, // SAFETY: we assume ffi::VSLbt() will not store the pointer to the string's content - ffi::txt::from_str(msg.as_str()), + ffi::txt::from_cstr(msg.as_cstr()), ); ffi::vfp_status_VFP_ERROR } @@ -385,7 +385,7 @@ unsafe extern "C" fn wrap_gethdrs, T: Transfer>( } if beresp.proto().is_none() { if let Err(e) = beresp.set_proto("HTTP/1.1") { - ctx.fail(&format!("{}: {e}", backend.get_type())); + ctx.fail(format!("{}: {e}", backend.get_type())); return 1; } } @@ -396,7 +396,7 @@ unsafe extern "C" fn wrap_gethdrs, T: Transfer>( ) .cast::(); if htc.is_null() { - ctx.fail(&format!("{}: insufficient workspace", backend.get_type())); + ctx.fail(format!("{}: insufficient workspace", backend.get_type())); return -1; } (*htc).magic = ffi::HTTP_CONN_MAGIC; @@ -429,13 +429,13 @@ unsafe extern "C" fn wrap_gethdrs, T: Transfer>( ) .cast::(); if vfp.is_null() { - ctx.fail(&format!("{}: insufficient workspace", backend.get_type())); + ctx.fail(format!("{}: insufficient workspace", backend.get_type())); return -1; } let Ok(t) = WS::new((*ctx.raw.bo).ws.as_mut_ptr()) .copy_bytes_with_null(&backend.get_type()) else { - ctx.fail(&format!("{}: insufficient workspace", backend.get_type())); + ctx.fail(format!("{}: insufficient workspace", backend.get_type())); return -1; }; (*vfp).name = t.as_ptr(); @@ -445,7 +445,7 @@ unsafe extern "C" fn wrap_gethdrs, T: Transfer>( (*vfp).priv1 = null(); let vfe = ffi::VFP_Push((*ctx.raw.bo).vfc, vfp); if vfe.is_null() { - ctx.fail(&format!("{}: couldn't insert vfp", backend.get_type())); + ctx.fail(format!("{}: couldn't insert vfp", backend.get_type())); return -1; } // we don't need to clean (*vfe).priv1 at the vfp level, the backend will @@ -501,7 +501,7 @@ unsafe extern "C" fn wrap_getip( .get_ip() .and_then(|ip| ip.into_vcl(&mut ctx.ws).map_err(|e| e.into())) .unwrap_or_else(|e| { - ctx.fail(&format!("{e}")); + ctx.fail(format!("{e}")); null() }) } diff --git a/src/vcl/ctx.rs b/src/vcl/ctx.rs index e884091..ff7266e 100644 --- a/src/vcl/ctx.rs +++ b/src/vcl/ctx.rs @@ -1,6 +1,7 @@ //! Expose the Varnish context [`vrt_ctx`] as a Rust object //! -use std::ffi::{c_int, c_uint, c_void, CString}; +use std::borrow::Cow; +use std::ffi::{c_int, c_uint, c_void, CStr, CString}; use crate::ffi; use crate::ffi::{ @@ -73,6 +74,50 @@ pub struct Ctx<'a> { pub ws: WS<'a>, } +/// An instance of a message that can be logged efficiently, possibly avoiding allocations. +pub struct Loggable<'a>(Cow<'a, CStr>); + +impl Loggable<'_> { + pub fn as_cstr(&self) -> &CStr { + self.0.as_ref() + } +} + +/// TODO: Try to show all parts of the message that are not null bytes, i.e. lossy for CString +const NULL_BYTE_ERR_MSG: &CStr = c"Internal Error: message contains null bytes and cannot be shown"; + +impl<'a> From<&'a str> for Loggable<'a> { + fn from(s: &'a str) -> Self { + Self(CString::new(s).map_or(Cow::Borrowed(NULL_BYTE_ERR_MSG), |s| Cow::Owned(s))) + } +} + +impl<'a> From for Loggable<'a> { + fn from(s: String) -> Self { + Self(CString::new(s).map_or(Cow::Borrowed(NULL_BYTE_ERR_MSG), |s| Cow::Owned(s))) + } +} + +/// FIXME: Do not use because it is likely you want to either pass the owned value, +/// or the &str / &CStr. TODO: delete this one? +impl<'a> From<&'a String> for Loggable<'a> { + fn from(s: &'a String) -> Self { + s.as_str().into() + } +} + +impl<'a> From<&'a CStr> for Loggable<'a> { + fn from(s: &'a CStr) -> Self { + Self(Cow::Borrowed(s)) + } +} + +impl<'a> From for Loggable<'a> { + fn from(s: CString) -> Self { + Self(Cow::Owned(s)) + } +} + impl<'a> Ctx<'a> { /// Wrap a raw pointer into an object we can use. /// @@ -105,23 +150,25 @@ impl<'a> Ctx<'a> { /// /// Once the control goes back to Varnish, it will see that the transaction was marked as fail /// and will return a synthetic error to the client. - pub fn fail(&mut self, msg: &str) -> u8 { - // not great, we have to copy the string to add a null character - let c_cstring = CString::new(msg).unwrap(); + pub fn fail<'b, T: Into>>(&mut self, msg: T) -> u8 { unsafe { - VRT_fail(self.raw, c"%s".as_ptr(), c_cstring.as_ptr()); + VRT_fail(self.raw, c"%s".as_ptr(), msg.into().0.as_ptr()); } 0 } /// Log a message, attached to the current context - pub fn log(&mut self, logtag: LogTag, msg: &str) { + pub fn log<'b, T: Into>>(&mut self, logtag: LogTag, msg: T) { unsafe { let vsl = self.raw.vsl; if vsl.is_null() { log(logtag, msg); } else { - ffi::VSLbt(vsl, logtag.into_u32(), ffi::txt::from_str(msg)); + ffi::VSLbt( + vsl, + logtag.into_u32(), + ffi::txt::from_cstr(msg.into().as_cstr()), + ); } } } @@ -220,15 +267,13 @@ impl Event { } } -// TODO: avoid Stringification -pub fn log(logtag: LogTag, msg: &str) { +pub fn log<'b, T: Into>>(logtag: LogTag, msg: T) { unsafe { - let c_cstring = CString::new(msg).unwrap(); ffi::VSL( logtag.into_u32(), ffi::vxids { vxid: 0 }, c"%s".as_ptr(), - c_cstring.as_ptr().cast::(), + msg.into().0.as_ptr(), ); } } diff --git a/src/vmodtool-rs.py b/src/vmodtool-rs.py index 4bbc515..8342394 100644 --- a/src/vmodtool-rs.py +++ b/src/vmodtool-rs.py @@ -86,7 +86,7 @@ def rustfuncBody(self, vcc, t): rustFuncArgs(self, t) print('''\t) { \t\tOk(o) => { *objp = Box::into_raw(Box::new(o)); }, -\t\tErr(e) => { _ctx.fail(&e.to_string()); }, +\t\tErr(e) => { _ctx.fail(e.to_string()); }, \t}''') elif t == "fini": print("\tdrop(Box::from_raw(*objp));") @@ -96,7 +96,7 @@ def rustfuncBody(self, vcc, t): else: print("\tcrate::{name}(".format(name=self.cname())) rustFuncArgs(self, t) - print("\t).into_result().and_then(|v| v.into_vcl(&mut _ctx.ws)).unwrap_or_else(|e| {{ _ctx.fail(&e); <{0}>::vcl_default() }})".format(self.retval.ct if self.retval.vt != "VOID" else "()")) + print("\t).into_result().and_then(|v| v.into_vcl(&mut _ctx.ws)).unwrap_or_else(|e| {{ _ctx.fail(e); <{0}>::vcl_default() }})".format(self.retval.ct if self.retval.vt != "VOID" else "()")) print("}")