feat(observability): structured logging + VeriSimDB audit-trail wiring (#50)

hyperpolymath · claude · web-flow · commit 95d867b88a0f · 2026-07-11T11:46:49.000+01:00
Replaces the runtime path's ad-hoc println breadcrumb with Logging-based structured records, and wires the previously-dormant VeriSimDB audit path into every tool call. - src/tools/observability.jl (new): correlation-id/tool-call-id minting, order-independent argument hashing (never raw args), shape-only result summaries (never raw values), configure_logging! (stderr ConsoleLogger, level from STATISTIKLES_LOG_LEVEL, default Info), log_tool_call (@info/@warn per tool call), and the audit-record construction + record_audit! persistence wrapper (opt-in via STATISTIKLES_AUDIT_PERSIST, off by default so nothing depends on a live VeriSimDB backend). - src/tools/lmstudio.jl: process_tool_calls now accepts/returns a per-chat-turn correlation_id, times each tool call, and emits a log_tool_call + record_audit! per call instead of the old println("[symbolic] executing: ..."). - src/tools/chat.jl: mints one correlation_id per turn, threads it through process_tool_calls and enforce_numeric_boundary! (including its guardrail retry), and adds @warn/@error structured records alongside the existing user-facing error messages (REPL stdout output is unchanged/unpolluted — logs go to stderr only). - src/tools/executor.jl: adds a @debug breadcrumb (off by default) in the catch-all, carrying an argument hash rather than raw arguments. - src/Statistikles.jl: `using Logging`, includes the new module, and calls configure_logging! from __init__ (re-read every load, unlike lmstudio.jl's precompiled BASE_URL const). - Project.toml: declares the (already-transitive) Logging stdlib dependency explicitly, matching the existing style for Dates/Random/UUIDs/etc. - test/observability_test.jl (new, wired into runtests.jl): correlation-id uniqueness, argument-hash order-independence and non-leakage, result-shape summaries, audit-record shape, audit_persistence_enabled parsing, log-level parsing, and captured-log assertions (Test.collect_test_logs) for both log_tool_call and process_tool_calls end to end. - QUICKSTART-MAINTAINER.adoc: documents STATISTIKLES_LOG_LEVEL and STATISTIKLES_AUDIT_PERSIST. Verification: full suite green under flock (WSL Debian, Julia 1.10.11) — 5710/5710 tests pass across all testsets, including the new 73-test Observability suite. No MANOVA flake encountered.  ## Summary  ## Changes  - ## RSR Quality Checklist  ### Required - [ ] Tests pass (`just test` or equivalent) - [ ] Code is formatted (`just fmt` or equivalent) - [ ] Linter is clean (no new warnings or errors) - [ ] No banned language patterns (no TypeScript, no npm/bun, no Go/Python) - [ ] No `unsafe` blocks without `// SAFETY:` comments - [ ] No banned functions (`believe_me`, `unsafeCoerce`, `Obj.magic`, `Admitted`, `sorry`) - [ ] SPDX license headers present on all new/modified source files - [ ] No secrets, credentials, or `.env` files included ### As Applicable - [ ] `.machine_readable/STATE.a2ml` updated (if project state changed) - [ ] `.machine_readable/ECOSYSTEM.a2ml` updated (if integrations changed) - [ ] `.machine_readable/META.a2ml` updated (if architectural decisions changed) - [ ] Documentation updated for user-facing changes - [ ] `TOPOLOGY.md` updated (if architecture changed) - [ ] `CHANGELOG` or release notes updated - [ ] New dependencies reviewed for license compatibility (MPL-2.0 / MPL-2.0) - [ ] ABI/FFI changes validated (`src/abi/` and `ffi/zig/` consistent) ## Testing  ## Screenshots  Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
diff --git a/Project.toml b/Project.toml
@@ -11,6 +11,7 @@ Distributions = "31c24e10-a181-5473-b8eb-7969acd0382f"
 HTTP = "cd3eb016-35fb-5094-929b-558a96fad6f3"
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
 LinearAlgebra = "37e2e46d-f89d-539d-b4ee-838fcccc9c8e"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7"
 Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c"
 Statistics = "10745b16-79ce-11e8-11f9-7d13ad32a3b2"
@@ -25,6 +26,7 @@ Distributions = "0.25.123"
 HTTP = "1.10.19"
 JSON3 = "1.14.3"
 LinearAlgebra = "1"
+Logging = "1"
 Printf = "1"
 Random = "1"
 Statistics = "1"
diff --git a/QUICKSTART-MAINTAINER.adoc b/QUICKSTART-MAINTAINER.adoc
@@ -86,6 +86,15 @@ variables (no config file):
 * `STATISTIKLES_LM_URL` — OpenAI-compatible endpoint (default `http://localhost:1234/v1`)
 * `STATISTIKLES_API_KEY` — API key if the endpoint requires one
 * `STATISTIKLES_MODEL` — model identifier
+* `STATISTIKLES_LOG_LEVEL` — structured-logging verbosity: `Debug`/`Info`/`Warn`/`Error`
+  (default `Info`). Logs go to stderr only — REPL prompts and answers stay on stdout
+  and are never interleaved with log lines. Unlike `STATISTIKLES_LM_URL` above, this
+  one is *not* baked into a precompile cache — it is re-read every time the package
+  loads (`__init__`), so it works from a precompiled image or container too.
+* `STATISTIKLES_AUDIT_PERSIST` — set to `true`/`1`/`yes`/`on` to actually persist
+  tool-call audit records to VeriSimDB (`STATISTIKLES_VERISIMDB_PORT`, default 8096).
+  Off by default: audit records are always constructed, never persisted, unless
+  explicitly opted in — no runtime or test dependency on a live VeriSimDB backend.
 
 == Health Checks
 
diff --git a/src/Statistikles.jl b/src/Statistikles.jl
@@ -30,6 +30,7 @@ using Dates
 using Printf
 using Random
 using UUIDs
+using Logging
 
 # --- SYMBOLIC KERNEL: Verified Statistical Methods ---
 include("stats/validation.jl")       # Shared ArgumentError input-validation helpers
@@ -99,12 +100,21 @@ include("integrations/zeroprob_integration.jl") # ZeroProb.jl zero-inflated mode
 include("integrations/quantum_integration.jl")  # QuantumCircuit.jl Bell tests
 
 # --- INTERFACE LAYER: LLM Integration ---
+include("tools/observability.jl") # Structured logging, correlation ids, audit-trail wiring
 include("tools/definitions.jl")  # MCP / Function calling schemas
 include("tools/executor.jl")     # Safe execution sandbox
 include("tools/lmstudio.jl")     # Local LLM connectivity
 include("tools/guardrail.jl")    # Neural-boundary numeric provenance enforcement
 include("tools/chat.jl")         # Interactive session management
 
+# Install the stderr-backed structured logger on every package load (not just
+# at precompile time), so STATISTIKLES_LOG_LEVEL is honoured even from a
+# precompiled image — unlike `const`s such as lmstudio.jl's BASE_URL, code in
+# __init__ re-runs each time `using Statistikles` happens.
+function __init__()
+    configure_logging!()
+end
+
 export main, run_examples, statistical_assistant_chat,
        # Descriptive
        descriptive_stats, power_mean, weighted_stats, frequency_table,
diff --git a/src/tools/chat.jl b/src/tools/chat.jl
@@ -98,19 +98,23 @@ function statistical_assistant_chat()
         lowercase(input) == "offline" && (run_examples(); continue)
 
         # One malformed turn must never kill the session — isolate the turn body.
+        # Every tool call this turn (including any guardrail retry) is logged
+        # and audited under one per-chat-turn correlation id.
+        correlation_id = new_correlation_id()
         try
             push!(messages, Dict{String,Any}("role" => "user", "content" => input))
 
             print("\n  Statistikles: ")
             response = call_lm_studio(messages, tools)
 
             if haskey(response, "error")
+                @warn "lm_studio_call_failed" correlation_id=correlation_id error=response["error"]
                 println("Error: $(response["error"])")
                 pop!(messages)
                 continue
             end
 
-            pr = process_tool_calls(response, messages; tools=tools)
+            pr = process_tool_calls(response, messages; tools=tools, correlation_id=correlation_id)
             final = pr.final
 
             content = nothing
@@ -124,11 +128,12 @@ function statistical_assistant_chat()
                 user_numbers = extract_numeric_values(input)
                 content = enforce_numeric_boundary!(
                     content, messages, tools, pr.tool_results,
-                    user_numbers, pr.tool_calls_made)
+                    user_numbers, pr.tool_calls_made; correlation_id=correlation_id)
                 println(content)
                 push!(messages, Dict{String,Any}("role" => "assistant", "content" => content))
             end
         catch e
+            @error "chat_turn_error" correlation_id=correlation_id exception=(e, catch_backtrace())
             println("\n  [turn error] $(sprint(showerror, e)) — continuing.")
             continue
         end
@@ -137,17 +142,23 @@ end
 
 """
     enforce_numeric_boundary!(content, messages, tools, tool_results,
-                              user_numbers, tool_calls_made) -> String
+                              user_numbers, tool_calls_made;
+                              correlation_id=new_correlation_id()) -> String
 
 Run the numeric-provenance guardrail on an assistant reply. If unverified
 numbers remain, do ONE retry asking the model to restate using only numbers
 from the tool results (or, when no tool ran this turn, to compute them or
 refrain). If orphans still persist, return the reply with a clear warning block
 appended. The model's text is NEVER silently rewritten — orphans are flagged,
 never fabricated.
+
+`correlation_id` is forwarded to the retry's `process_tool_calls` call so any
+tool calls it makes are logged/audited under the same per-chat-turn id as the
+original attempt.
 """
 function enforce_numeric_boundary!(content::AbstractString, messages, tools,
-                                   tool_results, user_numbers, tool_calls_made::Bool)
+                                   tool_results, user_numbers, tool_calls_made::Bool;
+                                   correlation_id::AbstractString=new_correlation_id())
     ok, orphans = validate_numeric_provenance(content, tool_results, user_numbers)
     ok && return String(content)
 
@@ -168,7 +179,7 @@ function enforce_numeric_boundary!(content::AbstractString, messages, tools,
     new_content = String(content)
     retry_resp = call_lm_studio(messages, tools)
     if !haskey(retry_resp, "error")
-        pr = process_tool_calls(retry_resp, messages; tools=tools)
+        pr = process_tool_calls(retry_resp, messages; tools=tools, correlation_id=correlation_id)
         append!(tool_results, pr.tool_results)
         if haskey(pr.final, "choices") && !isempty(pr.final["choices"])
             c = get(pr.final["choices"][1]["message"], "content", nothing)
diff --git a/src/tools/executor.jl b/src/tools/executor.jl
@@ -497,6 +497,9 @@ function execute_tool(tool_name::String, arguments::Dict)
         if get(ENV, "STATISTIKLES_DEBUG", "") != ""
             err["trace"] = sprint(showerror, e, catch_backtrace())
         end
+        # Structured breadcrumb (Debug level — off by default, opt in with
+        # STATISTIKLES_LOG_LEVEL=Debug). Never the raw arguments.
+        @debug "tool_execution_exception" tool=tool_name arg_hash=hash_arguments(arguments) error=string(e)
         return err
     end
 end
diff --git a/src/tools/lmstudio.jl b/src/tools/lmstudio.jl
@@ -65,8 +65,9 @@ function call_lm_studio(messages, tools=nothing; stream::Bool=false)
 end
 
 """
-    process_tool_calls(response, messages; tools=nothing, max_rounds=5)
-        -> (final, tool_results, tool_calls_made)
+    process_tool_calls(response, messages; tools=nothing, max_rounds=5,
+                       correlation_id=new_correlation_id())
+        -> (final, tool_results, tool_calls_made, correlation_id)
 
 Drive the symbolic tool-call loop. For each round the assistant requests tool
 calls, execute the (verified Julia) functions, feed the results back, and ask
@@ -79,13 +80,22 @@ Returns a NamedTuple:
   * `tool_results`    — every symbolic result produced this turn, in order, as
                         native Julia Dicts (fuel for the numeric guardrail).
   * `tool_calls_made` — whether any tool call was executed at all.
+  * `correlation_id`  — the per-chat-turn id every tool call in this run was
+                        logged and audited under (caller-supplied, or a fresh
+                        one minted when omitted).
 
 Each individual tool call is wrapped in try/catch: a malformed `tool_call`
 (missing keys, non-JSON `arguments`) yields a clean `Dict("error"=>...)` tool
 message so the model can recover instead of the session throwing. The `tools`
 parameter is forwarded on the follow-up call so the model can chain tools.
+
+Every tool call is timed and emits one structured log record
+(`log_tool_call`) plus an audit-trail record (`record_audit!`, pluggable and
+no-op-safe unless `STATISTIKLES_AUDIT_PERSIST=true`) — see
+`tools/observability.jl`. Neither logs nor persists raw arguments/results.
 """
-function process_tool_calls(response, messages; tools=nothing, max_rounds::Int=5)
+function process_tool_calls(response, messages; tools=nothing, max_rounds::Int=5,
+                            correlation_id::AbstractString=new_correlation_id())
     tool_results = Any[]
     tool_calls_made = false
     current = response
@@ -111,16 +121,23 @@ function process_tool_calls(response, messages; tools=nothing, max_rounds::Int=5
         # crash the turn — it becomes an error result the model can react to.
         for tool_call in message["tool_calls"]
             result = nothing
+            fn_name = "unknown"
+            args = Dict{String,Any}()
+            tc_id = tool_call_identifier(tool_call)
+            t0 = time()
             try
                 fn_name = tool_call["function"]["name"]
                 args = JSON3.read(tool_call["function"]["arguments"], Dict{String,Any})
-                println("\n  [symbolic] executing: $fn_name")
                 result = execute_tool(fn_name, args)
             catch e
                 result = Dict{String,Any}("error" => "Malformed tool call: $(string(e))")
             end
+            duration_s = time() - t0
             push!(tool_results, result)
 
+            log_tool_call(correlation_id, tc_id, fn_name, args, result, duration_s)
+            record_audit!(correlation_id, tc_id, fn_name, args, result; duration_s=duration_s)
+
             tool_msg = Dict{String,Any}(
                 "role" => "tool",
                 "content" => JSON3.write(result)
@@ -136,5 +153,6 @@ function process_tool_calls(response, messages; tools=nothing, max_rounds::Int=5
         haskey(current, "error") && break
     end
 
-    return (final = current, tool_results = tool_results, tool_calls_made = tool_calls_made)
+    return (final = current, tool_results = tool_results, tool_calls_made = tool_calls_made,
+            correlation_id = correlation_id)
 end
diff --git a/src/tools/observability.jl b/src/tools/observability.jl
diff --git a/test/observability_test.jl b/test/observability_test.jl
diff --git a/test/runtests.jl b/test/runtests.jl
