feat: tracing of InferType impls & Unifier::unify

Debugging type checking code in VSCode is suboptimal - we really want a
graphical representation of inference at every step (but also a debugger
that doesn't lock up at inconvenient times would be great).

To make instrumentation consistent I implemented a `#[trace_infer]`
attribute macro which can be used on `InferType` impls.

The `Unifier` has a single `#[tracing::instrument!(..)]` call and there
is also code in `EqlMapper` to dump nodes types and type substitutions
at the end of the type checking process which is useful when debugging
failing inference tests.

To get a trace from a test, uncomment the `init_tracing();` line.

The output is *very* verbose but very useful.

Author: freshtonic

Cargo.lock

@@ -0,0 +1,12 @@
+[package]
+name = "eql-mapper-macros"
+version.workspace = true
+edition.workspace = true
+
+[lib]
+proc-macro = true
+
+[dependencies]
+syn = { version = "2.0", features = ["full"] }
+quote = "1.0"
+proc-macro2 = "1.0"

packages/eql-mapper-macros/Cargo.toml

@@ -0,0 +1,115 @@
+use proc_macro::TokenStream;
+use quote::{quote, ToTokens};
+use syn::{
+    parse::Parse, parse_macro_input, parse_quote, Attribute, FnArg, Ident, ImplItem, ImplItemFn,
+    ItemImpl, Pat, PatType, Signature, Type, TypePath, TypeReference,
+};
+
+/// This macro generates consistently defined `#[tracing::instrument]` attributes for `InferType::infer_enter` &
+/// `InferType::infer_enter` implementations on `TypeInferencer`.
+///
+/// This attribute MUST be defined on the trait `impl` itself (not the trait method impls).
+#[proc_macro_attribute]
+pub fn trace_infer(_attr: TokenStream, item: TokenStream) -> TokenStream {
+    let mut input = parse_macro_input!(item as ItemImpl);
+
+    for item in &mut input.items {
+        if let ImplItem::Fn(ImplItemFn {
+            attrs,
+            sig:
+                Signature {
+                    ident: method,
+                    inputs,
+                    ..
+                },
+            ..
+        }) = item
+        {
+            let node_ident_and_type: Option<(&Ident, &Type)> =
+                if let Some(FnArg::Typed(PatType {
+                    ty: node_ty, pat, ..
+                })) = inputs.get(1)
+                {
+                    if let Pat::Ident(pat_ident) = &**pat {
+                        Some((&pat_ident.ident, node_ty))
+                    } else {
+                        None
+                    }
+                } else {
+                    None
+                };
+
+            let vec_ident: Ident = parse_quote!(Vec);
+
+            match node_ident_and_type {
+                Some((node_ident, node_ty)) => {
+                    let (formatter, node_ty_abbrev) = match node_ty {
+                        Type::Reference(TypeReference { elem, .. }) => match &**elem {
+                            Type::Path(TypePath { path, .. }) => {
+                                let last_segment = path.segments.last().unwrap();
+                                let last_segment_ident = &last_segment.ident;
+                                let last_segment_arguments = if last_segment.arguments.is_empty() {
+                                    None
+                                }  else {
+                                    let args = &last_segment.arguments;
+                                    Some(quote!(<#args>))
+                                };
+                                match last_segment_ident {
+                                    ident if vec_ident == *ident => {
+                                        (quote!(crate::FmtAstVec), quote!(#last_segment_ident #last_segment_arguments))
+                                    }
+                                    _ => (quote!(crate::FmtAst), quote!(#last_segment_ident #last_segment_arguments))
+                                }
+                            },
+                            _ => unreachable!("Infer::infer_enter/infer_exit has sig: infer_..(&mut self, delete: &'ast N) -> Result<(), TypeError>")
+                        },
+                            _ => unreachable!("Infer::infer_enter/infer_exit has sig: infer_..(&mut self, delete: &'ast N) -> Result<(), TypeError>")
+                    };
+
+                    let node_ty_abbrev = node_ty_abbrev
+                        .to_token_stream()
+                        .to_string()
+                        .replace(" ", "");
+
+                    let target = format!("eql-mapper::{}", method.to_string().to_uppercase());
+
+                    let attr: TracingInstrumentAttr = syn::parse2(quote! {
+                        #[tracing::instrument(
+                            target = #target,
+                            level = "trace",
+                            skip(self, #node_ident),
+                            fields(
+                                ast_ty = #node_ty_abbrev,
+                                ast = %#formatter(#node_ident),
+                            ),
+                            ret(Debug)
+                        )]
+                    })
+                    .unwrap();
+                    attrs.push(attr.attr);
+                }
+                None => {
+                    return quote!(compile_error!(
+                        "could not determine name of node argumemt in Infer impl"
+                    ))
+                    .to_token_stream()
+                    .into();
+                }
+            }
+        }
+    }
+
+    input.to_token_stream().into()
+}
+
+struct TracingInstrumentAttr {
+    attr: Attribute,
+}
+
+impl Parse for TracingInstrumentAttr {
+    fn parse(input: syn::parse::ParseStream) -> syn::Result<Self> {
+        Ok(Self {
+            attr: Attribute::parse_outer(input)?.first().unwrap().clone(),
+        })
+    }
+}

packages/eql-mapper-macros/src/lib.rs

@@ -11,6 +11,7 @@ authors = [
 ]
 
 [dependencies]
+eql-mapper-macros = { path = "../eql-mapper-macros" }
 derive_more = { version = "^1.0", features = ["display", "constructor"] }
 impl-trait-for-tuples = "0.2.3"
 itertools = "^0.13"

packages/eql-mapper/Cargo.toml

@@ -2,15 +2,15 @@ use super::importer::{ImportError, Importer};
 use crate::{
     inference::{TypeError, TypeInferencer},
     unifier::{EqlValue, Unifier},
-    DepMut, Param, ParamError, ScopeError, ScopeTracker, TableResolver, Type, TypeRegistry,
+    DepMut, Fmt, Param, ParamError, ScopeError, ScopeTracker, TableResolver, Type, TypeRegistry,
     TypedStatement, Value,
 };
 use sqltk::{Break, NodeKey, Visitable, Visitor};
 use sqltk_parser::ast::{self as ast, Statement};
 use std::{
     cell::RefCell, collections::HashMap, marker::PhantomData, ops::ControlFlow, rc::Rc, sync::Arc,
 };
-use tracing::{span, Level};
+use tracing::{event, span, Level};
 
 /// Validates that a SQL statement is well-typed with respect to a database schema that contains zero or more columns with
 /// EQL types.
@@ -158,14 +158,50 @@ impl<'ast> EqlMapper<'ast> {
             || -> Result<_, EqlMapperError> { Ok((projection?, params?, literals?, node_types?)) };
 
         match combine_results() {
-            Ok((projection, params, literals, node_types)) => Ok(TypedStatement {
-                statement,
-                projection,
-                params,
-                literals,
-                node_types: Arc::new(node_types),
-            }),
-            Err(err) => Err(err),
+            Ok((projection, params, literals, node_types)) => {
+                event!(
+                    target: "eql-mapper::EVENT_RESOLVE_OK",
+                    parent: &span_begin,
+                    Level::TRACE,
+                    projection = %&projection,
+                    params = %Fmt(&params),
+                    literals = %Fmt(&literals),
+                    node_types = %Fmt(&node_types)
+                );
+
+                Ok(TypedStatement {
+                    statement,
+                    projection,
+                    params,
+                    literals,
+                    node_types: Arc::new(node_types),
+                })
+            }
+            Err(err) => {
+                {
+                    let unifier = &*self.unifier.borrow();
+                    unifier.dump_all_nodes(statement);
+                    unifier.dump_substitutions();
+                }
+
+                let projection = self.projection_type(statement);
+                let params = self.param_types();
+                let literals = self.literal_types();
+                let node_types = self.node_types();
+
+                event!(
+                    target: "eql-mapper::EVENT_RESOLVE_ERR",
+                    parent: &span_begin,
+                    Level::TRACE,
+                    err = ?err,
+                    projection = ?projection,
+                    params = ?params,
+                    literals = ?literals,
+                    node_types = ?node_types
+                );
+
+                Err(err)
+            }
         }
     }
 

packages/eql-mapper/src/eql_mapper.rs

@@ -1,3 +1,4 @@
+use eql_mapper_macros::trace_infer;
 use sqltk_parser::ast::Delete;
 
 use crate::{
@@ -6,6 +7,7 @@ use crate::{
     TypeInferencer,
 };
 
+#[trace_infer]
 impl<'ast> InferType<'ast, Delete> for TypeInferencer<'ast> {
     fn infer_exit(&mut self, delete: &'ast Delete) -> Result<(), TypeError> {
         let Delete { returning, .. } = delete;

packages/eql-mapper/src/inference/infer_type_impls/delete_statement.rs

@@ -2,9 +2,10 @@ use crate::{
     inference::{unifier::Type, InferType, TypeError},
     SqlIdent, TypeInferencer,
 };
-
+use eql_mapper_macros::trace_infer;
 use sqltk_parser::ast::{Array, BinaryOperator, Expr, Ident};
 
+#[trace_infer]
 impl<'ast> InferType<'ast, Expr> for TypeInferencer<'ast> {
     fn infer_exit(&mut self, this_expr: &'ast Expr) -> Result<(), TypeError> {
         match this_expr {

packages/eql-mapper/src/inference/infer_type_impls/expr.rs

@@ -1,3 +1,4 @@
+use eql_mapper_macros::trace_infer;
 use sqltk_parser::ast::{Function, FunctionArg, FunctionArgExpr, FunctionArguments, Ident};
 
 use crate::{
@@ -6,6 +7,7 @@ use crate::{
     SqlIdent, TypeInferencer,
 };
 
+#[trace_infer]
 impl<'ast> InferType<'ast, Function> for TypeInferencer<'ast> {
     fn infer_exit(&mut self, function: &'ast Function) -> Result<(), TypeError> {
         if !matches!(function.parameters, FunctionArguments::None) {

packages/eql-mapper/src/inference/infer_type_impls/function.rs

@@ -9,9 +9,10 @@ use crate::{
     unifier::{EqlValue, NativeValue, Value},
     ColumnKind, TableColumn, TypeInferencer,
 };
-
+use eql_mapper_macros::trace_infer;
 use sqltk_parser::ast::{Ident, Insert};
 
+#[trace_infer]
 impl<'ast> InferType<'ast, Insert> for TypeInferencer<'ast> {
     fn infer_enter(&mut self, insert: &'ast Insert) -> Result<(), TypeError> {
         let Insert {

packages/eql-mapper/src/inference/infer_type_impls/insert_statement.rs

@@ -1,10 +1,12 @@
+use eql_mapper_macros::trace_infer;
 use sqltk_parser::ast::Query;
 
 use crate::{
     inference::{InferType, TypeError},
     TypeInferencer,
 };
 
+#[trace_infer]
 impl<'ast> InferType<'ast, Query> for TypeInferencer<'ast> {
     fn infer_exit(&mut self, query: &'ast Query) -> Result<(), TypeError> {
         let Query { body, .. } = query;