diff --git a/CLAUDE.md b/CLAUDE.md index 22328f3..0a203a9 100644 --- a/CLAUDE.md +++ b/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 = """ + + + + + + +""" + +# 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: diff --git a/config/config.exs b/config/config.exs new file mode 100644 index 0000000..4603fb2 --- /dev/null +++ b/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 diff --git a/lib/statifier/actions/action_executor.ex b/lib/statifier/actions/action_executor.ex index 513f2ed..2458102 100644 --- a/lib/statifier/actions/action_executor.ex +++ b/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 diff --git a/lib/statifier/actions/assign_action.ex b/lib/statifier/actions/assign_action.ex index 03d6728..763821c 100644 --- a/lib/statifier/actions/assign_action.ex +++ b/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] diff --git a/lib/statifier/actions/foreach_action.ex b/lib/statifier/actions/foreach_action.ex index 8aa48ac..3acd44b 100644 --- a/lib/statifier/actions/foreach_action.ex +++ b/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] diff --git a/lib/statifier/actions/log_action.ex b/lib/statifier/actions/log_action.ex index 3195ef6..c314002 100644 --- a/lib/statifier/actions/log_action.ex +++ b/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 diff --git a/lib/statifier/actions/raise_action.ex b/lib/statifier/actions/raise_action.ex index 9b897ab..5494e79 100644 --- a/lib/statifier/actions/raise_action.ex +++ b/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, diff --git a/lib/statifier/actions/send_action.ex b/lib/statifier/actions/send_action.ex index a87a3e4..d60851b 100644 --- a/lib/statifier/actions/send_action.ex +++ b/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, diff --git a/lib/statifier/datamodel.ex b/lib/statifier/datamodel.ex index 33dfb17..a4b1aa3 100644 --- a/lib/statifier/datamodel.ex +++ b/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() diff --git a/lib/statifier/interpreter.ex b/lib/statifier/interpreter.ex index 81388d7..1629925 100644 --- a/lib/statifier/interpreter.ex +++ b/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 diff --git a/lib/statifier/interpreter/transition_resolver.ex b/lib/statifier/interpreter/transition_resolver.ex index 672f1bf..f7f65eb 100644 --- a/lib/statifier/interpreter/transition_resolver.ex +++ b/lib/statifier/interpreter/transition_resolver.ex @@ -23,19 +23,22 @@ defmodule Statifier.Interpreter.TransitionResolver do """ alias Statifier.{Configuration, Document, Evaluator, Event, StateChart, StateHierarchy} + alias Statifier.Logging.LogManager + require LogManager @doc """ Find enabled transitions for a given event. - Returns transitions that match the event and have enabled conditions, - filtered by SCXML conflict resolution rules. + Returns a tuple with updated state chart (with logging) and transitions that match + the event and have enabled conditions, filtered by SCXML conflict resolution rules. ## Examples - {:ok, transitions} = TransitionResolver.find_enabled_transitions(state_chart, event) + {state_chart, transitions} = TransitionResolver.find_enabled_transitions(state_chart, event) """ - @spec find_enabled_transitions(StateChart.t(), Event.t()) :: [Statifier.Transition.t()] + @spec find_enabled_transitions(StateChart.t(), Event.t()) :: + {StateChart.t(), [Statifier.Transition.t()]} def find_enabled_transitions(%StateChart{} = state_chart, %Event{} = event) do find_enabled_transitions_for_event(state_chart, event) end @@ -43,15 +46,15 @@ defmodule Statifier.Interpreter.TransitionResolver do @doc """ Find eventless transitions (also called NULL transitions in SCXML spec). - Returns transitions without event attributes that have enabled conditions, - filtered by SCXML conflict resolution rules. + Returns a tuple with updated state chart (with logging) and transitions without + event attributes that have enabled conditions, filtered by SCXML conflict resolution rules. ## Examples - transitions = TransitionResolver.find_eventless_transitions(state_chart) + {state_chart, transitions} = TransitionResolver.find_eventless_transitions(state_chart) """ - @spec find_eventless_transitions(StateChart.t()) :: [Statifier.Transition.t()] + @spec find_eventless_transitions(StateChart.t()) :: {StateChart.t(), [Statifier.Transition.t()]} def find_eventless_transitions(%StateChart{} = state_chart) do find_enabled_transitions_for_event(state_chart, nil) end @@ -122,31 +125,136 @@ defmodule Statifier.Interpreter.TransitionResolver do # Private helper functions # Unified transition finding logic for both named events and eventless transitions - @spec find_enabled_transitions_for_event(StateChart.t(), Event.t() | nil) :: [ - Statifier.Transition.t() - ] + @spec find_enabled_transitions_for_event(StateChart.t(), Event.t() | nil) :: { + StateChart.t(), + [Statifier.Transition.t()] + } defp find_enabled_transitions_for_event(%StateChart{} = state_chart, event_or_nil) do # Get all currently active states (including ancestors) active_states_with_ancestors = Configuration.all_active_states(state_chart.configuration, state_chart.document) + # Log the start of transition evaluation + event_name = if event_or_nil, do: event_or_nil.name, else: "eventless" + + state_chart = + LogManager.trace(state_chart, "Starting transition evaluation", %{ + action_type: "transition_evaluation", + event: event_name, + active_states: MapSet.to_list(active_states_with_ancestors), + search_type: if(event_or_nil, do: "event_triggered", else: "eventless") + }) + # Update the state chart with current event for context building state_chart_with_event = %{state_chart | current_event: event_or_nil} # Find transitions from all active states (including ancestors) that match the event/NULL and condition - active_states_with_ancestors - |> Enum.flat_map(fn state_id -> - # Use O(1) lookup for transitions from this state - transitions = Document.get_transitions_from_state(state_chart.document, state_id) - - transitions - |> Enum.filter(fn transition -> - matches_event_or_eventless?(transition, event_or_nil) and - transition_condition_enabled?(transition, state_chart_with_event) + enabled_transitions = + active_states_with_ancestors + |> Enum.flat_map(fn state_id -> + # Use O(1) lookup for transitions from this state + transitions = Document.get_transitions_from_state(state_chart.document, state_id) + + LogManager.trace(state_chart, "Evaluating transitions from state", %{ + action_type: "state_transition_check", + source_state: state_id, + transition_count: length(transitions) + }) + + transitions + |> Enum.filter( + &transition_enabled?(&1, event_or_nil, state_chart, state_chart_with_event) + ) end) - end) - # Process in document order - |> Enum.sort_by(& &1.document_order) + # Process in document order + |> Enum.sort_by(& &1.document_order) + + state_chart = + LogManager.debug(state_chart, "Transition evaluation completed", %{ + action_type: "transition_evaluation_result", + event: event_name, + total_enabled: length(enabled_transitions), + enabled_transitions: Enum.map(enabled_transitions, &transition_summary/1) + }) + + {state_chart, enabled_transitions} + end + + # Create a summary of a transition for logging + defp transition_summary(%Statifier.Transition{} = transition) do + %{ + source: transition.source, + event: transition.event, + targets: transition.targets, + type: transition.type, + condition: transition.cond + } + end + + # Check if a transition is enabled (matches event and passes condition) + @spec transition_enabled?( + Statifier.Transition.t(), + Event.t() | nil, + StateChart.t(), + StateChart.t() + ) :: boolean() + defp transition_enabled?(transition, event_or_nil, state_chart, state_chart_with_event) do + event_matches = matches_event_or_eventless?(transition, event_or_nil) + + condition_enabled = + if event_matches do + evaluate_transition_condition(transition, state_chart, state_chart_with_event) + else + false + end + + log_transition_evaluation(transition, state_chart, event_matches, condition_enabled) + + event_matches and condition_enabled + end + + # Evaluate transition condition + defp evaluate_transition_condition(transition, state_chart, state_chart_with_event) do + case transition.compiled_cond do + nil -> + true + + _compiled_cond -> + result = transition_condition_enabled?(transition, state_chart_with_event) + + # Log condition evaluation failures for debugging + if not result and transition.cond do + LogManager.warn( + state_chart, + "Condition evaluation failed or returned false", + %{ + action_type: "condition_evaluation", + source_state: transition.source, + condition: transition.cond, + event: transition.event, + targets: transition.targets, + result: result + } + ) + end + + result + end + end + + # Log transition evaluation results if tracing is enabled + defp log_transition_evaluation(transition, state_chart, event_matches, condition_enabled) do + LogManager.trace(state_chart, "Transition evaluation result", %{ + action_type: "transition_check", + source_state: transition.source, + event_pattern: transition.event, + condition: transition.cond, + type: transition.type, + targets: transition.targets, + event_matches: event_matches, + condition_enabled: condition_enabled, + overall_enabled: event_matches and condition_enabled + }) end # Check if transition matches the event (or eventless for transitions without event attribute) diff --git a/lib/statifier/logging/elixir_logger_adapter.ex b/lib/statifier/logging/elixir_logger_adapter.ex index e5e2040..ff0cac7 100644 --- a/lib/statifier/logging/elixir_logger_adapter.ex +++ b/lib/statifier/logging/elixir_logger_adapter.ex @@ -76,8 +76,11 @@ defmodule Statifier.Logging.ElixirLoggerAdapter do """ @spec enabled?(Statifier.Logging.ElixirLoggerAdapter.t(), atom()) :: boolean() def enabled?(%{logger_module: Logger}, level) do + # Map our trace level to debug since Elixir's Logger doesn't support trace + elixir_level = map_to_elixir_level(level) + # Handle Elixir's Logger specifically - it uses compare_levels - Logger.compare_levels(level, Logger.level()) != :lt + Logger.compare_levels(elixir_level, Logger.level()) != :lt end def enabled?(%{logger_module: logger_module}, level) do @@ -89,5 +92,9 @@ defmodule Statifier.Logging.ElixirLoggerAdapter do true end end + + # Map Statifier log levels to Elixir Logger levels + defp map_to_elixir_level(:trace), do: :debug + defp map_to_elixir_level(level), do: level end end diff --git a/lib/statifier/logging/log_manager.ex b/lib/statifier/logging/log_manager.ex index 1c6e82e..c16264d 100644 --- a/lib/statifier/logging/log_manager.ex +++ b/lib/statifier/logging/log_manager.ex @@ -35,16 +35,15 @@ defmodule Statifier.Logging.LogManager do condition: "x > 5" }) - # Check if level is enabled before expensive operations - if LogManager.enabled?(state_chart, :debug) do - expensive_debug_info = build_complex_debug_data() - state_chart = LogManager.debug(state_chart, expensive_debug_info) - end + # No need to manually check - macros handle this automatically! + state_chart = LogManager.debug(state_chart, "Debug info", %{ + expensive_data: build_complex_debug_data() # Only evaluated if debug enabled + }) """ alias Statifier.{Configuration, StateChart} - alias Statifier.Logging.{Adapter, ElixirLoggerAdapter} + alias Statifier.Logging.{Adapter, ElixirLoggerAdapter, LogManager} @levels [:trace, :debug, :info, :warn, :error] @@ -108,50 +107,114 @@ defmodule Statifier.Logging.LogManager do Logs a trace message with automatic metadata extraction. Trace level is for very detailed diagnostic information. + This is a macro that only evaluates the message and metadata arguments + if trace logging is enabled, providing optimal performance. + + ## Examples + + # Arguments are only evaluated if trace logging is enabled + state_chart = LogManager.trace(state_chart, "Complex operation", %{ + expensive_data: build_debug_info() # Only called if trace enabled + }) + """ - @spec trace(StateChart.t(), String.t(), map()) :: StateChart.t() - def trace(state_chart, message, metadata \\ %{}) do - log(state_chart, :trace, message, metadata) + defmacro trace(state_chart, message, metadata \\ quote(do: %{})) do + build_logging_macro(:trace, state_chart, message, metadata) end @doc """ Logs a debug message with automatic metadata extraction. Debug level is for information useful for debugging. + This is a macro that only evaluates the message and metadata arguments + if debug logging is enabled, providing optimal performance. + + ## Examples + + # Arguments are only evaluated if debug logging is enabled + state_chart = LogManager.debug(state_chart, "Processing step", %{ + current_data: expensive_calculation() # Only called if debug enabled + }) + """ - @spec debug(StateChart.t(), String.t(), map()) :: StateChart.t() - def debug(state_chart, message, metadata \\ %{}) do - log(state_chart, :debug, message, metadata) + defmacro debug(state_chart, message, metadata \\ quote(do: %{})) do + build_logging_macro(:debug, state_chart, message, metadata) end @doc """ Logs an info message with automatic metadata extraction. Info level is for general informational messages. + This is a macro that only evaluates the message and metadata arguments + if info logging is enabled, providing optimal performance. + + ## Examples + + # Arguments are only evaluated if info logging is enabled + state_chart = LogManager.info(state_chart, "Operation complete", %{ + result_summary: summarize_results() # Only called if info enabled + }) + """ - @spec info(StateChart.t(), String.t(), map()) :: StateChart.t() - def info(state_chart, message, metadata \\ %{}) do - log(state_chart, :info, message, metadata) + defmacro info(state_chart, message, metadata \\ quote(do: %{})) do + build_logging_macro(:info, state_chart, message, metadata) end @doc """ Logs a warning message with automatic metadata extraction. Warning level is for potentially problematic situations. + This is a macro that only evaluates the message and metadata arguments + if warn logging is enabled, providing optimal performance. + + ## Examples + + # Arguments are only evaluated if warn logging is enabled + state_chart = LogManager.warn(state_chart, "Unexpected condition", %{ + diagnostic_info: gather_diagnostics() # Only called if warn enabled + }) + """ - @spec warn(StateChart.t(), String.t(), map()) :: StateChart.t() - def warn(state_chart, message, metadata \\ %{}) do - log(state_chart, :warn, message, metadata) + defmacro warn(state_chart, message, metadata \\ quote(do: %{})) do + build_logging_macro(:warn, state_chart, message, metadata) end @doc """ Logs an error message with automatic metadata extraction. Error level is for error conditions that don't halt execution. + This is a macro that only evaluates the message and metadata arguments + if error logging is enabled, providing optimal performance. + + ## Examples + + # Arguments are only evaluated if error logging is enabled + state_chart = LogManager.error(state_chart, "Processing failed", %{ + error_context: build_error_context() # Only called if error enabled + }) + """ - @spec error(StateChart.t(), String.t(), map()) :: StateChart.t() - def error(state_chart, message, metadata \\ %{}) do - log(state_chart, :error, message, metadata) + defmacro error(state_chart, message, metadata \\ quote(do: %{})) do + build_logging_macro(:error, state_chart, message, metadata) + end + + # Builds the logging macro implementation that checks if level is enabled before evaluating arguments + defp build_logging_macro(level, state_chart, message, metadata) do + quote bind_quoted: [ + level: level, + state_chart: state_chart, + message: message, + metadata: metadata + ] do + # Check if logging is enabled before evaluating expensive arguments + if LogManager.enabled?(state_chart, level) do + # Only evaluate message and metadata if logging is enabled + LogManager.log(state_chart, level, message, metadata) + else + # Return unchanged state chart if logging is disabled + state_chart + end + end end # Extracts core metadata from the StateChart @@ -203,6 +266,7 @@ defmodule Statifier.Logging.LogManager do ## Options * `:log_adapter` - Logging adapter configuration. Can be: + * Atom shorthand: `:elixir`, `:internal`, `:test`, or `:silent` * An adapter struct (e.g., `%TestAdapter{max_entries: 100}`) * A tuple `{AdapterModule, opts}` (e.g., `{TestAdapter, [max_entries: 50]}`) * If not provided, uses environment-specific defaults @@ -210,9 +274,22 @@ defmodule Statifier.Logging.LogManager do * `:log_level` - Minimum log level (`:trace`, `:debug`, `:info`, `:warn`, `:error`) * Defaults to `:debug` in test environment, `:info` otherwise + ## Adapter Shortcuts + + * `:elixir` - Uses ElixirLoggerAdapter (integrates with Elixir's Logger) + * `:internal` - Uses TestAdapter for internal debugging + * `:test` - Uses TestAdapter (alias for test environments) + * `:silent` - Uses TestAdapter with no log storage (disables logging) + ## Examples - # Use with runtime options + # Simple atom configuration for debugging + state_chart = LogManager.configure_from_options(state_chart, [ + log_adapter: :elixir, + log_level: :trace + ]) + + # Traditional module+options configuration state_chart = LogManager.configure_from_options(state_chart, [ log_adapter: {TestAdapter, [max_entries: 100]}, log_level: :debug @@ -247,11 +324,11 @@ defmodule Statifier.Logging.LogManager do # Check application configuration case Application.get_env(:statifier, :default_log_adapter) do nil -> get_default_adapter_config() - config -> config + config -> resolve_adapter_shorthand(config) end config -> - config + resolve_adapter_shorthand(config) end end @@ -270,7 +347,14 @@ defmodule Statifier.Logging.LogManager do end end - # Build adapter from configuration (struct or {module, opts} tuple) + # Resolve adapter shorthand atoms to full configuration + defp resolve_adapter_shorthand(:elixir), do: {ElixirLoggerAdapter, []} + defp resolve_adapter_shorthand(:internal), do: {Statifier.Logging.TestAdapter, []} + defp resolve_adapter_shorthand(:test), do: {Statifier.Logging.TestAdapter, []} + defp resolve_adapter_shorthand(:silent), do: {Statifier.Logging.TestAdapter, [max_entries: 0]} + defp resolve_adapter_shorthand(config), do: config + + # Build adapter from configuration (struct, {module, opts} tuple, or atom shorthand) defp build_adapter(adapter_struct) when is_struct(adapter_struct) do {:ok, adapter_struct} end @@ -288,7 +372,8 @@ defmodule Statifier.Logging.LogManager do # Default configuration - ElixirLoggerAdapter is always the default defp get_default_adapter_config do - {ElixirLoggerAdapter, []} + # Check application config first, then sensible defaults + Application.get_env(:statifier, :default_log_adapter, {ElixirLoggerAdapter, []}) end defp get_default_adapter do @@ -296,6 +381,17 @@ defmodule Statifier.Logging.LogManager do end defp get_default_log_level do - :info + # Use application environment with environment-aware defaults + Application.get_env(:statifier, :default_log_level, get_environment_default_log_level()) + end + + # Environment-aware defaults without using Mix.env() + defp get_environment_default_log_level do + # Check for common development/test indicators + cond do + System.get_env("MIX_ENV") == "dev" -> :trace + System.get_env("MIX_ENV") == "test" -> :debug + true -> :info + end end end diff --git a/mix.exs b/mix.exs index ed00712..72ccb1b 100644 --- a/mix.exs +++ b/mix.exs @@ -27,6 +27,7 @@ defmodule Statifier.MixProject do elixir: "~> 1.17", elixirc_paths: elixirc_paths(Mix.env()), start_permanent: Mix.env() == :prod, + config_path: "config/config.exs", deps: @deps, docs: docs(), description: @description, diff --git a/test/statifier/interpreter/transition_resolver_test.exs b/test/statifier/interpreter/transition_resolver_test.exs index 7784cc1..ec2535e 100644 --- a/test/statifier/interpreter/transition_resolver_test.exs +++ b/test/statifier/interpreter/transition_resolver_test.exs @@ -22,7 +22,9 @@ defmodule Statifier.Interpreter.TransitionResolverTest do {:ok, state_chart} = Interpreter.initialize(document) event = %Event{name: "start"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, event) assert length(transitions) == 1 assert hd(transitions).event == "start" @@ -44,7 +46,9 @@ defmodule Statifier.Interpreter.TransitionResolverTest do {:ok, state_chart} = Interpreter.initialize(document) event = %Event{name: "unknown"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, event) assert transitions == [] end @@ -69,7 +73,9 @@ defmodule Statifier.Interpreter.TransitionResolverTest do # Should find reset transition from app state even when in idle event = %Event{name: "reset"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, event) assert length(transitions) == 1 assert hd(transitions).event == "reset" @@ -100,7 +106,7 @@ defmodule Statifier.Interpreter.TransitionResolverTest do external_queue: [] } - transitions = TransitionResolver.find_eventless_transitions(state_chart) + {_state_chart, transitions} = TransitionResolver.find_eventless_transitions(state_chart) assert length(transitions) == 1 assert hd(transitions).event == nil @@ -121,7 +127,7 @@ defmodule Statifier.Interpreter.TransitionResolverTest do {:ok, document, _warnings} = Statifier.parse(xml) {:ok, state_chart} = Interpreter.initialize(document) - transitions = TransitionResolver.find_eventless_transitions(state_chart) + {_state_chart, transitions} = TransitionResolver.find_eventless_transitions(state_chart) assert transitions == [] end @@ -268,7 +274,9 @@ defmodule Statifier.Interpreter.TransitionResolverTest do {:ok, state_chart} = Interpreter.initialize(document) event = %Event{name: "test"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, event) # Should be sorted by document order document_orders = Enum.map(transitions, & &1.document_order) @@ -298,14 +306,18 @@ defmodule Statifier.Interpreter.TransitionResolverTest do # Local event should only trigger the deepest transition due to conflict resolution local_event = %Event{name: "local"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, local_event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, local_event) assert length(transitions) == 1 assert hd(transitions).source == "level3" # Global event should be available from any active state global_event = %Event{name: "global"} - transitions = TransitionResolver.find_enabled_transitions(state_chart, global_event) + + {_state_chart, transitions} = + TransitionResolver.find_enabled_transitions(state_chart, global_event) assert length(transitions) == 1 assert hd(transitions).source == "level1" diff --git a/test/statifier/logging/elixir_logger_adapter_test.exs b/test/statifier/logging/elixir_logger_adapter_test.exs index b784bfe..717603d 100644 --- a/test/statifier/logging/elixir_logger_adapter_test.exs +++ b/test/statifier/logging/elixir_logger_adapter_test.exs @@ -9,6 +9,10 @@ defmodule Statifier.Logging.ElixirLoggerAdapterTest do describe "log/5" do test "logs to Elixir Logger and returns unchanged state chart" do + # Set Logger level to debug to ensure info messages are captured + original_level = Logger.level() + Logger.configure(level: :debug) + adapter = %ElixirLoggerAdapter{logger_module: Logger} state_chart = %StateChart{} metadata = %{action_type: "test"} @@ -23,9 +27,16 @@ defmodule Statifier.Logging.ElixirLoggerAdapterTest do # Verify the message was logged assert log_output =~ "Test message" + + # Restore original level + Logger.configure(level: original_level) end test "passes metadata to Logger" do + # Set Logger level to debug to ensure info messages are captured + original_level = Logger.level() + Logger.configure(level: :debug) + adapter = %ElixirLoggerAdapter{logger_module: Logger} state_chart = %StateChart{} metadata = %{action_type: "test", custom: "value"} @@ -39,6 +50,9 @@ defmodule Statifier.Logging.ElixirLoggerAdapterTest do # Note: Testing exact metadata format can be tricky with Logger # The main thing is that it doesn't crash and the message appears assert log_output =~ "Test message" + + # Restore original level + Logger.configure(level: original_level) end test "works with different log levels" do diff --git a/test/statifier/logging/log_manager_test.exs b/test/statifier/logging/log_manager_test.exs index 553d70a..d10bd2d 100644 --- a/test/statifier/logging/log_manager_test.exs +++ b/test/statifier/logging/log_manager_test.exs @@ -3,6 +3,7 @@ defmodule Statifier.Logging.LogManagerTest do alias Statifier.{Configuration, Document, Event, StateChart} alias Statifier.Logging.{LogManager, TestAdapter} + require LogManager describe "log/4" do test "logs message with automatic metadata extraction" do @@ -172,4 +173,56 @@ defmodule Statifier.Logging.LogManagerTest do assert log_entry.metadata.custom == "value" end end + + describe "configure_from_options/2" do + test "supports atom-based adapter configuration" do + document = %Document{states: [], state_lookup: %{}} + configuration = Configuration.new([]) + state_chart = StateChart.new(document, configuration) + + # Test :elixir shorthand + result = + LogManager.configure_from_options(state_chart, + log_adapter: :elixir, + log_level: :debug + ) + + assert %Statifier.Logging.ElixirLoggerAdapter{} = result.log_adapter + assert result.log_level == :debug + + # Test :internal shorthand + result = + LogManager.configure_from_options(state_chart, + log_adapter: :internal, + log_level: :trace + ) + + assert %Statifier.Logging.TestAdapter{} = result.log_adapter + assert result.log_level == :trace + + # Test :silent shorthand + result = + LogManager.configure_from_options(state_chart, + log_adapter: :silent + ) + + assert %Statifier.Logging.TestAdapter{max_entries: 0} = result.log_adapter + end + + test "maintains backward compatibility with tuple configuration" do + document = %Document{states: [], state_lookup: %{}} + configuration = Configuration.new([]) + state_chart = StateChart.new(document, configuration) + + # Test traditional {module, opts} format still works + result = + LogManager.configure_from_options(state_chart, + log_adapter: {TestAdapter, [max_entries: 50]}, + log_level: :warn + ) + + assert %TestAdapter{max_entries: 50} = result.log_adapter + assert result.log_level == :warn + end + end end