Enhances logging with better ergonomics and performance (#91)

Enhances logging system with improved ergonomics and debugging

- Adds atom-based log adapter configuration (:elixir, :internal, :test, :silent)
- Adds metadata_fields/0 function to LogManager for centralized field definitions
- Adds environment-aware logging defaults (trace in dev, debug in test, info in prod)
- Adds enhanced debugging logs throughout transition resolution and action execution
- Adds comprehensive trace logging for transition evaluation, condition checking, and state changes
- Adds better error context logging for failed conditions and expression evaluations
- Fixes ElixirLoggerAdapter to support :trace level by mapping to :debug
- Fixes TransitionResolver to return state chart tuples for proper logging threading
- Fixes credo issues by extracting helper functions to reduce complexity and nesting
- Adds config/config.exs for environment-specific Logger configuration
- Updates CLAUDE.md with comprehensive debugging configuration examples

Converts logging functions to performance-optimized macros

- Converts all LogManager level functions (trace, debug, info, warn, error) to macros
- Adds lazy evaluation for optimal performance - arguments only evaluated when logging is enabled
- Adds zero overhead when logging is disabled through early bailout
- Maintains familiar LogManager.level/3 API while providing significant performance benefits
- Adds bind_quoted macro implementation for proper variable scoping
- Adds require LogManager statements to all consuming modules for macro usage
- Removes manual LogManager.enabled? checks since macros handle this automatically
- Removes @SPEC declarations from macro functions to fix dialyzer warnings
- Updates CLAUDE.md with performance optimization documentation and examples
- Maintains all existing functionality while providing hot path performance improvements

🤖 Generated with [Claude Code](https://claude.ai/code)

Co-authored-by: Claude <noreply@anthropic.com>

Author: johnnyt

CLAUDE.md

@@ -533,6 +533,103 @@ The implementation plan transforms Statifier from a basic state machine library
 
 This logging system will integrate seamlessly with both the current functional API and future GenServer-based persistent interpreters.
 
+## Debugging State Charts
+
+When debugging state chart execution, configure enhanced logging for detailed visibility:
+
+```elixir
+# Enable detailed tracing for debugging
+{:ok, state_chart} = Interpreter.initialize(document, [
+  log_adapter: :elixir,
+  log_level: :trace
+])
+
+# Alternative: use internal adapter for testing/development
+{:ok, state_chart} = Interpreter.initialize(document, [
+  log_adapter: :internal,  
+  log_level: :trace
+])
+```
+
+### Log Adapter Options
+
+- `:elixir` - Uses ElixirLoggerAdapter (integrates with Elixir's Logger system)
+- `:internal` - Uses TestAdapter for internal debugging
+- `:test` - Uses TestAdapter (alias for test environments)  
+- `:silent` - Uses TestAdapter with no log storage (disables logging)
+
+### Log Levels
+
+- `:trace` - Very detailed execution tracing (transitions, conditions, actions)
+- `:debug` - General debugging information (state changes, events)
+- `:info` - High-level execution flow
+- `:warn` - Unusual conditions
+- `:error` - Execution errors
+
+### Performance-Optimized Logging
+
+All LogManager logging functions (`trace/3`, `debug/3`, `info/3`, `warn/3`, `error/3`) are implemented as macros that provide lazy evaluation for optimal performance:
+
+```elixir
+# Expensive computations are only performed if logging level is enabled
+state_chart = LogManager.debug(state_chart, "Complex operation", %{
+  expensive_data: build_debug_info(),        # Only called if debug enabled
+  complex_calculation: heavy_computation()   # Only called if debug enabled
+})
+
+# Zero overhead when logging is disabled - arguments are never evaluated
+state_chart = LogManager.trace(state_chart, "Detailed info", %{
+  massive_object: serialize_entire_state()  # Never called if trace disabled
+})
+```
+
+This provides significant performance benefits in hot code paths while maintaining the familiar `LogManager.level/3` API.
+
+### Automatic Environment Configuration
+
+Statifier automatically detects your environment and configures appropriate logging defaults:
+
+- **Development (`MIX_ENV=dev`)**: `:trace` level with `:elixir` adapter for detailed debugging
+- **Test (`MIX_ENV=test`)**: `:debug` level with `:test` adapter for clean test output  
+- **Production (other)**: `:info` level with `:elixir` adapter for essential information
+
+Users can override these defaults via application configuration:
+
+```elixir
+# config/config.exs
+config :statifier,
+  default_log_adapter: :elixir,
+  default_log_level: :trace
+```
+
+### Debugging Examples
+
+```elixir
+# In dev environment, no additional configuration needed
+{:ok, document, _warnings} = Statifier.parse(xml)
+{:ok, state_chart} = Interpreter.initialize(document)  # Auto-configured for dev
+
+# Manual configuration for other environments
+{:ok, state_chart} = Interpreter.initialize(document, [
+  log_adapter: :elixir,
+  log_level: :trace
+])
+
+# Debug specific state chart behavior
+xml = """
+<scxml initial="s1">
+  <state id="s1">
+    <transition event="go" target="s2"/>
+  </state>
+  <state id="s2"/>
+</scxml>
+"""
+
+# Send event - will show detailed trace logs with full metadata
+event = %Event{name: "go"}
+{:ok, new_state_chart} = Interpreter.send_event(state_chart, event)
+```
+
 - Always refer to state machines as state charts
 - Always run 'mix format' after writing an Elixir file.
 - When creating git commit messages:

config/config.exs

@@ -0,0 +1,35 @@
+import Config
+
+# Configure Elixir Logger for enhanced debugging in dev environment
+if config_env() == :dev do
+  config :logger,
+    level: :debug
+
+  config :logger, :console,
+    format: "[$level] $message $metadata\n",
+    metadata: [
+      :current_state,
+      :event,
+      :action_type,
+      :state_id,
+      :phase,
+      :transition_type,
+      :source_state,
+      :condition,
+      :targets
+    ]
+
+  # Default Statifier logging configuration for dev
+  config :statifier,
+    default_log_adapter: :elixir,
+    default_log_level: :trace
+end
+
+# Test environment uses TestAdapter for clean test output
+if config_env() == :test do
+  config :logger, level: :warning
+
+  config :statifier,
+    default_log_adapter: :test,
+    default_log_level: :debug
+end

lib/statifier/actions/action_executor.ex

@@ -17,6 +17,7 @@ defmodule Statifier.Actions.ActionExecutor do
   }
 
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @doc """
   Execute onentry actions for a list of states being entered.
@@ -82,6 +83,16 @@ defmodule Statifier.Actions.ActionExecutor do
   # Private functions
 
   defp execute_actions(actions, state_id, phase, state_chart) do
+    # Log the start of action execution
+    state_chart =
+      LogManager.trace(state_chart, "Executing actions", %{
+        action_type: "action_execution",
+        phase: phase,
+        state_id: state_id,
+        action_count: length(actions),
+        actions: summarize_actions(actions)
+      })
+
     actions
     |> Enum.reduce(state_chart, fn action, acc_state_chart ->
       execute_single_action(action, state_id, phase, acc_state_chart)
@@ -94,7 +105,9 @@ defmodule Statifier.Actions.ActionExecutor do
       LogManager.debug(state_chart, "Executing log action", %{
         action_type: "log_action",
         state_id: state_id,
-        phase: phase
+        phase: phase,
+        log_expr: log_action.expr,
+        log_label: log_action.label
       })
 
     # Delegate to LogAction's own execute method
@@ -107,7 +120,8 @@ defmodule Statifier.Actions.ActionExecutor do
       LogManager.debug(state_chart, "Executing raise action", %{
         action_type: "raise_action",
         state_id: state_id,
-        phase: phase
+        phase: phase,
+        event_name: raise_action.event
       })
 
     # Delegate to RaiseAction's own execute method
@@ -117,8 +131,8 @@ defmodule Statifier.Actions.ActionExecutor do
   defp execute_single_action(%AssignAction{} = assign_action, state_id, phase, state_chart) do
     # Log context information for debugging
     state_chart =
-      LogManager.debug(state_chart, "Executing assign action", %{
-        action_type: "assign_action",
+      LogManager.trace(state_chart, "Executing assign action", %{
+        action_type: "assign_action_execution",
         state_id: state_id,
         phase: phase,
         location: assign_action.location,
@@ -132,8 +146,8 @@ defmodule Statifier.Actions.ActionExecutor do
   defp execute_single_action(%IfAction{} = if_action, state_id, phase, state_chart) do
     # Log context information for debugging
     state_chart =
-      LogManager.debug(state_chart, "Executing if action", %{
-        action_type: "if_action",
+      LogManager.trace(state_chart, "Executing if action", %{
+        action_type: "if_action_execution",
         state_id: state_id,
         phase: phase,
         conditional_blocks_count: length(if_action.conditional_blocks)
@@ -203,4 +217,32 @@ defmodule Statifier.Actions.ActionExecutor do
         end)
     end
   end
+
+  # Create a summary of actions for logging
+  defp summarize_actions(actions) do
+    Enum.map(actions, fn action ->
+      case action do
+        %LogAction{expr: expr} ->
+          %{type: "log", expr: expr}
+
+        %RaiseAction{event: event} ->
+          %{type: "raise", event: event}
+
+        %AssignAction{location: location, expr: expr} ->
+          %{type: "assign", location: location, expr: expr}
+
+        %IfAction{} ->
+          %{type: "if", condition: "..."}
+
+        %ForeachAction{} ->
+          %{type: "foreach", array: "..."}
+
+        %SendAction{} ->
+          %{type: "send", event: "..."}
+
+        _unknown_action ->
+          %{type: "unknown"}
+      end
+    end)
+  end
 end

lib/statifier/actions/assign_action.ex

@@ -29,6 +29,7 @@ defmodule Statifier.Actions.AssignAction do
 
   alias Statifier.{Evaluator, StateChart}
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @enforce_keys [:location, :expr]
   defstruct [:location, :expr, :compiled_expr, :source_location]

lib/statifier/actions/foreach_action.ex

@@ -46,6 +46,7 @@ defmodule Statifier.Actions.ForeachAction do
 
   alias Statifier.{Actions.ActionExecutor, Evaluator, Event, StateChart}
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @enforce_keys [:array, :item, :actions]
   defstruct [:array, :item, :index, :actions, :compiled_array, :source_location]

lib/statifier/actions/log_action.ex

@@ -12,6 +12,7 @@ defmodule Statifier.Actions.LogAction do
 
   alias Statifier.Evaluator
   alias Statifier.Logging.LogManager
+  require LogManager
 
   defstruct [:label, :expr, :source_location]
 
@@ -71,7 +72,15 @@ defmodule Statifier.Actions.LogAction do
         result = safe_to_string(value)
         if result == "", do: expr, else: result
 
-      {:error, _reason} ->
+      {:error, reason} ->
+        # Log the evaluation error for debugging
+        LogManager.warn(state_chart, "Log expression evaluation failed", %{
+          action_type: "log_evaluation_error",
+          expression: expr,
+          error: inspect(reason),
+          fallback: "using string parsing"
+        })
+
         # Fall back to simple string parsing for basic quoted strings
         parse_quoted_string_fallback(expr)
     end

lib/statifier/actions/raise_action.ex

@@ -9,6 +9,7 @@ defmodule Statifier.Actions.RaiseAction do
 
   alias Statifier.{Event, StateChart}
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @type t :: %__MODULE__{
           event: String.t() | nil,

lib/statifier/actions/send_action.ex

@@ -12,6 +12,7 @@ defmodule Statifier.Actions.SendAction do
 
   alias Statifier.{Evaluator, Event, StateChart}
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @type t :: %__MODULE__{
           event: String.t() | nil,

lib/statifier/datamodel.ex

@@ -29,6 +29,7 @@ defmodule Statifier.Datamodel do
 
   alias Statifier.{Configuration, Evaluator}
   alias Statifier.Logging.LogManager
+  require LogManager
 
   @type t :: map()
 

lib/statifier/interpreter.ex

@@ -21,6 +21,8 @@ defmodule Statifier.Interpreter do
     Validator
   }
 
+  require LogManager
+
   @doc """
   Initialize a state chart from a parsed document.
 
@@ -131,7 +133,8 @@ defmodule Statifier.Interpreter do
   @spec send_event(StateChart.t(), Event.t()) :: {:ok, StateChart.t()}
   def send_event(%StateChart{} = state_chart, %Event{} = event) do
     # Find optimal transition set enabled by this event
-    enabled_transitions = TransitionResolver.find_enabled_transitions(state_chart, event)
+    {state_chart, enabled_transitions} =
+      TransitionResolver.find_enabled_transitions(state_chart, event)
 
     case enabled_transitions do
       [] ->
@@ -170,13 +173,31 @@ defmodule Statifier.Interpreter do
   # Recursive helper with cycle detection (max 1000 iterations)
   defp execute_microsteps(%StateChart{} = state_chart, iterations)
        when iterations >= 1000 do
+    # Log performance warning for high iteration count
+    state_chart =
+      LogManager.warn(state_chart, "High microstep iteration count", %{
+        action_type: "performance_warning",
+        iteration: iterations,
+        threshold: 1000,
+        suggestion: "Check for infinite eventless transition loops"
+      })
+
     # Prevent infinite loops - return current state
     state_chart
   end
 
   defp execute_microsteps(%StateChart{} = state_chart, iterations) do
+    # Log microstep processing
+    state_chart =
+      LogManager.trace(state_chart, "Processing microstep", %{
+        action_type: "microstep",
+        iteration: iterations,
+        current_states: state_chart.configuration.active_states |> MapSet.to_list()
+      })
+
     # Per SCXML specification: eventless transitions have higher priority than internal events
-    eventless_transitions = TransitionResolver.find_eventless_transitions(state_chart)
+    {state_chart, eventless_transitions} =
+      TransitionResolver.find_eventless_transitions(state_chart)
 
     case eventless_transitions do
       [] ->
@@ -463,6 +484,17 @@ defmodule Statifier.Interpreter do
       |> MapSet.difference(states_to_exit)
       |> MapSet.union(new_target_set)
 
+    # Log configuration change
+    state_chart =
+      LogManager.debug(state_chart, "Configuration change (internal transition)", %{
+        action_type: "state_change",
+        transition_type: "internal",
+        from_states: MapSet.to_list(current_active),
+        to_states: MapSet.to_list(final_active_states),
+        exited_states: MapSet.to_list(states_to_exit),
+        entered_states: MapSet.to_list(states_to_enter)
+      })
+
     new_config = Configuration.new(MapSet.to_list(final_active_states))
     StateChart.update_configuration(state_chart, new_config)
   end
@@ -502,6 +534,19 @@ defmodule Statifier.Interpreter do
 
     # Combine preserved states with new target states
     final_active_states = MapSet.union(preserved_states, new_target_set)
+
+    # Log configuration change
+    state_chart =
+      LogManager.debug(state_chart, "Configuration change (external transition)", %{
+        action_type: "state_change",
+        transition_type: "external",
+        from_states: MapSet.to_list(current_active),
+        to_states: MapSet.to_list(final_active_states),
+        exited_states: MapSet.to_list(exit_set),
+        entered_states: MapSet.to_list(entering_states),
+        preserved_states: MapSet.to_list(preserved_states)
+      })
+
     new_config = Configuration.new(MapSet.to_list(final_active_states))
 
     # Update the state chart with the new configuration