Better debug logs

Michael Stone, February 13, 2022, , (src), (all posts)

The standard interfaces in rust for “printf debugging” are traits called Debug and Display, each with a method named fmt() that look like

pub trait Debug {
    fn fmt(&self, f: &mut Formatter<'_>) -> Result<(), Error>;

While a good choice for a general-purpose, portable, standard library, individual programs may benefit from a logging interface that is more tailored to their user interface:

Hierarchical logging with search-based highlighting

In the case of my recent work on depict, I wanted to experiment with arranging my logs hierarchically (based on the structure of the computation generating them) and with making them searchable in my program’s user interface.

Ultimately, I wound up deciding to store my logs in records that look like:

#[derive(Clone, Debug, PartialEq, PartialOrd)]
pub enum Record {
    String { name: Option<String>, ty: Option<String>, names: Vec<String>, val: String, },
    Group { name: Option<String>, ty: Option<String>, names: Vec<String>, val: Vec<Record>, },
    Svg { name: Option<String>, ty: Option<String>, names: Vec<String>, val: String, }

The idea here is that anything that I would normally have logged on a single line with printf() or a Display or Debug method call will be recorded as a Record::String, along with metadata about the computation or event whose value is being recorded and about what search terms the value in question should be indexed under: i.e., what names the value being logged is responsive for.

My logging interface parallels the design of the Debug and Display traits, with two modifications:

pub trait Log<Cx = ()> {
    fn log(&self, cx: Cx, l: &mut Logger) -> Result<(), Error>;
  1. My trait is generic over a type parameter Cx of “context” which can be used by by trait implementors to make extra information – such as a closure – available at value logging time, e.g., in order to give meaning to otherwise opaque integers or other primary keys that may exist in a complex value being logged as stand-ins or indices for data that live elsewhere by calculating all the “names” that the value being logged should be indexed by.

  2. Analogous to the std::fmt::Formatter helper, implementations of my trait delegate the actual mechanics of logging data structured according to their expectations to a &mut Logger object, here with methods for logging sets, sequences, maps, their associated elements and pairs, as well as strings, images, and (nested) groups of the above.

Next, by defining a trait like this one yourself, you can:

  1. implement it on whatever types you like, including standard library container types like HashMaps and BTreeMaps without requiring newtype/“Printer” logging wrappers,

  2. customize the kinds of information to be logged to fit your UI: for example, logging hierarchical arrangements of text and images if those are easy to display because you’re working in a GUI and so have access to an HTML renderer, or to nestable widgets, etc.

Finally, to round out the discussion, here’s a fairly representative example of what the trait impl code looks like for a decently complicated data structure, in this case, a mapping from original to solved box positions implemented via some nested BTreeMaps in which a “context” closure is used to give meaning to the otherwise meaningless integers stored in the BTrees by logging the names of the objects that the integers are indices for:

/// Marker trait for closures mapping LocIx to names
pub(crate) trait L2n : Fn(VerticalRank, OriginalHorizontalRank) -> Vec<Box<dyn Name>> {}
impl<CX: Fn(VerticalRank, OriginalHorizontalRank) -> Vec<Box<dyn Name>>> L2n for CX {}

impl<CX: L2n> log::Log<CX> for BTreeMap<VerticalRank, BTreeMap<OriginalHorizontalRank, SolvedHorizontalRank>> {
    fn log(&self, cx: CX, l: &mut log::Logger) -> Result<(), log::Error> {
       l.with_map("solved_locs", "SolvedLocs", self.iter(), |lvl, row, l| {
           l.with_map(format!("solved_locs[{lvl}]"), "SolvedLocs[i]", row.iter(), |ohr, shr, l| {
               let mut src_names = names![lvl, ohr];
               src_names.append(&mut cx(*lvl, *ohr));
                   format!("{lvl}v, {ohr}h"),
                   format!("{lvl}v, {shr}s")