diff --git a/config/test.exs b/config/test.exs index 5362d89..57fc0d8 100644 --- a/config/test.exs +++ b/config/test.exs @@ -12,7 +12,7 @@ config :git_hooks, auto_install: false # To enable verbose logging during debugging, set LOG_LEVEL env var: # LOG_LEVEL=debug mix test test/my_test.exs # -log_level = System.get_env("LOG_LEVEL", "debug") |> String.to_existing_atom() +log_level = System.get_env("LOG_LEVEL", "warning") |> String.to_existing_atom() config :logger, level: log_level, diff --git a/lib/jido/agent/directive/cron.ex b/lib/jido/agent/directive/cron.ex index 96ee7d6..1851160 100644 --- a/lib/jido/agent/directive/cron.ex +++ b/lib/jido/agent/directive/cron.ex @@ -25,10 +25,9 @@ defmodule Jido.Agent.Directive.Cron do %Cron{cron: "*/5 * * * *", message: check_signal, job_id: :check, timezone: "America/New_York"} """ - require Logger - alias Jido.AgentServer alias Jido.AgentServer.CronRuntimeSpec + alias Jido.Log @schema Zoi.struct( __MODULE__, @@ -70,9 +69,9 @@ defmodule Jido.Agent.Directive.Cron do {:ok, pid} <- AgentServer.start_runtime_cron_job(state, logical_id, runtime_spec), {:ok, persisted_state} <- persist_then_commit_registration(state, pid, logical_id, cron_spec, runtime_spec) do - Logger.debug( - "AgentServer #{agent_id} registered cron job #{inspect(logical_id)}: #{cron_expr}" - ) + Log.debug(fn -> + "AgentServer #{agent_id} registered cron job #{Log.safe_inspect(logical_id)}: #{cron_expr}" + end) AgentServer.emit_cron_telemetry_event(persisted_state, :register, %{ job_id: logical_id, @@ -82,9 +81,10 @@ defmodule Jido.Agent.Directive.Cron do {:ok, persisted_state} else {:error, reason} -> - Logger.error( - "AgentServer #{agent_id} failed to register cron job #{inspect(logical_id)}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{agent_id} failed to register cron job #{Log.safe_inspect(logical_id)}: " <> + Log.safe_inspect(reason) + end) {:ok, handle_failed_registration(state, logical_id, on_failure)} end diff --git a/lib/jido/agent/directive/cron_cancel.ex b/lib/jido/agent/directive/cron_cancel.ex index 0a680f6..4b3dab6 100644 --- a/lib/jido/agent/directive/cron_cancel.ex +++ b/lib/jido/agent/directive/cron_cancel.ex @@ -31,7 +31,7 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.CronCancel do @moduledoc false - require Logger + alias Jido.Log alias Jido.AgentServer.State def exec(%{job_id: logical_id}, _input_signal, state) do @@ -44,7 +44,9 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.CronCancel do new_state = %{runtime_state | cron_specs: proposed_specs} - Logger.debug("AgentServer #{agent_id} cancelled cron job #{inspect(logical_id)}") + Log.debug(fn -> + "AgentServer #{agent_id} cancelled cron job #{Log.safe_inspect(logical_id)}" + end) emit_telemetry(new_state, :cancel, %{job_id: logical_id}) {:ok, new_state} @@ -53,9 +55,10 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.CronCancel do {_pid, runtime_state} = drop_runtime_job(state, logical_id) new_state = %{runtime_state | cron_specs: proposed_specs} - Logger.error( - "AgentServer #{agent_id} failed to persist cron cancellation for #{inspect(logical_id)}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{agent_id} failed to persist cron cancellation for #{Log.safe_inspect(logical_id)}: " <> + Log.safe_inspect(reason) + end) emit_telemetry(state, :persist_failure, %{ job_id: logical_id, @@ -66,9 +69,10 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.CronCancel do {:ok, new_state} {:error, reason} -> - Logger.error( - "AgentServer #{agent_id} failed to persist cron cancellation for #{inspect(logical_id)}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{agent_id} failed to persist cron cancellation for #{Log.safe_inspect(logical_id)}: " <> + Log.safe_inspect(reason) + end) emit_telemetry(state, :persist_failure, %{ job_id: logical_id, diff --git a/lib/jido/agent/instance_manager.ex b/lib/jido/agent/instance_manager.ex index 7e42928..f9dcbdc 100644 --- a/lib/jido/agent/instance_manager.ex +++ b/lib/jido/agent/instance_manager.ex @@ -74,9 +74,8 @@ defmodule Jido.Agent.InstanceManager do use Supervisor - require Logger - alias Jido.Config.Defaults + alias Jido.Log alias Jido.Persist alias Jido.Storage @@ -380,16 +379,17 @@ defmodule Jido.Agent.InstanceManager do case Persist.thaw(storage, agent_module, persistence_key) do {:ok, agent} -> - Logger.debug("InstanceManager thawed agent for key #{inspect(key)}") + Log.debug(fn -> "InstanceManager thawed agent for key #{Log.safe_inspect(key)}" end) agent {:error, :not_found} -> nil {:error, reason} -> - Logger.warning( - "InstanceManager failed to thaw agent for key #{inspect(key)}: #{inspect(reason)}" - ) + Log.warning(fn -> + "InstanceManager failed to thaw agent for key #{Log.safe_inspect(key)}: " <> + Log.safe_inspect(reason) + end) nil end diff --git a/lib/jido/agent_server.ex b/lib/jido/agent_server.ex index 747ebbf..653300a 100644 --- a/lib/jido/agent_server.ex +++ b/lib/jido/agent_server.ex @@ -184,8 +184,6 @@ defmodule Jido.AgentServer do use GenServer - require Logger - alias Jido.AgentServer.{ ChildInfo, CronRuntimeSpec, @@ -201,6 +199,7 @@ defmodule Jido.AgentServer do alias Jido.Agent.Directive alias Jido.AgentServer.Signal.{ChildExit, ChildStarted, Orphaned} alias Jido.Config.Defaults + alias Jido.Log alias Jido.RuntimeStore alias Jido.Sensor.Runtime, as: SensorRuntime alias Jido.Signal @@ -796,9 +795,10 @@ defmodule Jido.AgentServer do {:ok, track_cron_job(state, logical_id, pid, runtime_spec: runtime_spec)} {:error, reason} -> - Logger.error( - "AgentServer #{state.id} failed to register #{runtime_cron_log_label(runtime_spec)} #{inspect(logical_id)}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{state.id} failed to register #{runtime_cron_log_label(runtime_spec)} " <> + "#{Log.safe_inspect(logical_id)}: #{Log.safe_inspect(reason)}" + end) {:error, reason, state} end @@ -978,7 +978,7 @@ defmodule Jido.AgentServer do enq_state {:error, :queue_overflow} -> - Logger.warning("AgentServer #{state.id} queue overflow during strategy init") + Log.warning(fn -> "AgentServer #{state.id} queue overflow during strategy init" end) state end else @@ -1563,7 +1563,7 @@ defmodule Jido.AgentServer do metadata ) - Logger.warning("AgentServer #{state.id} queue overflow, dropping directives") + Log.warning(fn -> "AgentServer #{state.id} queue overflow, dropping directives" end) GenServer.reply(from, {:error, :queue_overflow}) maybe_set_idle_status(state) end @@ -1591,10 +1591,10 @@ defmodule Jido.AgentServer do Map.merge(metadata, %{kind: kind, error: reason}) ) - Logger.error( - "Signal call task failed for #{state.id}: #{inspect(kind)} #{inspect(reason)}\n" <> - Exception.format_stacktrace(stacktrace) - ) + Log.error(fn -> + "Signal call task failed for #{state.id}: #{Log.safe_inspect(kind)} " <> + "#{Log.safe_inspect(reason)}\n#{Exception.format_stacktrace(stacktrace)}" + end) GenServer.reply(from, {:error, reason}) maybe_set_idle_status(state) @@ -1818,7 +1818,7 @@ defmodule Jido.AgentServer do metadata ) - Logger.warning("AgentServer #{state.id} queue overflow, dropping directives") + Log.warning(fn -> "AgentServer #{state.id} queue overflow, dropping directives" end) {:error, :queue_overflow, state} end end @@ -1991,9 +1991,9 @@ defmodule Jido.AgentServer do end rescue e -> - Logger.error( - "Plugin #{inspect(spec.module)} handle_signal crashed: #{Exception.message(e)}" - ) + Log.error(fn -> + "Plugin #{Log.safe_inspect(spec.module)} handle_signal crashed: #{Exception.message(e)}" + end) error = Jido.Error.execution_error( @@ -2032,9 +2032,9 @@ defmodule Jido.AgentServer do spec.module.transform_result(action_term, agent_acc, context) rescue e -> - Logger.error( - "Plugin #{inspect(spec.module)} transform_result crashed: #{Exception.message(e)}" - ) + Log.error(fn -> + "Plugin #{Log.safe_inspect(spec.module)} transform_result crashed: #{Exception.message(e)}" + end) agent_acc end @@ -2084,9 +2084,10 @@ defmodule Jido.AgentServer do end) other -> - Logger.warning( - "Invalid child_spec from plugin #{inspect(plugin_module)}: #{inspect(other)}" - ) + Log.warning(fn -> + "Invalid child_spec from plugin #{Log.safe_inspect(plugin_module)}: " <> + Log.safe_inspect(other) + end) state end @@ -2112,16 +2113,20 @@ defmodule Jido.AgentServer do %{state | children: new_children} {:error, reason} -> - Logger.error("Failed to start plugin child #{inspect(plugin_module)}: #{inspect(reason)}") + Log.error(fn -> + "Failed to start plugin child #{Log.safe_inspect(plugin_module)}: " <> + Log.safe_inspect(reason) + end) state end end defp start_plugin_child(%State{} = state, plugin_module, spec) do - Logger.warning( - "Plugin child_spec missing :start key for #{inspect(plugin_module)}: #{inspect(spec)}" - ) + Log.warning(fn -> + "Plugin child_spec missing :start key for #{Log.safe_inspect(plugin_module)}: " <> + Log.safe_inspect(spec) + end) state end @@ -2194,9 +2199,10 @@ defmodule Jido.AgentServer do %{state | children: new_children} {:error, reason} -> - Logger.warning( - "Failed to start subscription sensor #{inspect(sensor_module)} for plugin #{inspect(plugin_module)}: #{inspect(reason)}" - ) + Log.warning(fn -> + "Failed to start subscription sensor #{Log.safe_inspect(sensor_module)} for plugin " <> + "#{Log.safe_inspect(plugin_module)}: #{Log.safe_inspect(reason)}" + end) state end @@ -2208,7 +2214,7 @@ defmodule Jido.AgentServer do @doc false defp register_plugin_schedules(%State{skip_schedules: true} = state) do - Logger.debug("AgentServer #{state.id} skipping plugin schedules") + Log.debug(fn -> "AgentServer #{state.id} skipping plugin schedules" end) state end @@ -2241,9 +2247,10 @@ defmodule Jido.AgentServer do %{cron_expression: cron_expr, message: message, timezone: timezone} ) do if Map.has_key?(state.cron_jobs, job_id) do - Logger.warning( - "AgentServer #{state.id} skipping restored cron job #{inspect(job_id)} because declarative/plugin schedule already exists" - ) + Log.warning(fn -> + "AgentServer #{state.id} skipping restored cron job #{Log.safe_inspect(job_id)} " <> + "because declarative/plugin schedule already exists" + end) new_cron_specs = Map.delete(state.cron_specs, job_id) cleaned_state = %{state | cron_specs: new_cron_specs} @@ -2269,9 +2276,10 @@ defmodule Jido.AgentServer do end defp register_restored_cron_spec(%State{} = state, job_id, invalid_spec) do - Logger.error( - "AgentServer #{state.id} skipped invalid persisted cron spec #{inspect(job_id)}: #{inspect(invalid_spec)}" - ) + Log.error(fn -> + "AgentServer #{state.id} skipped invalid persisted cron spec #{Log.safe_inspect(job_id)}: " <> + Log.safe_inspect(invalid_spec) + end) state end @@ -2289,9 +2297,9 @@ defmodule Jido.AgentServer do case register_runtime_cron_job(state, job_id, runtime_spec) do {:ok, new_state} -> - Logger.debug( - "AgentServer #{state.id} registered schedule #{inspect(job_id)}: #{cron_expr}" - ) + Log.debug(fn -> + "AgentServer #{state.id} registered schedule #{Log.safe_inspect(job_id)}: #{cron_expr}" + end) new_state @@ -2333,9 +2341,10 @@ defmodule Jido.AgentServer do timer_ref = :erlang.start_timer(delay, self(), {:cron_restart, logical_id}) - Logger.warning( - "AgentServer #{state.id} scheduling cron restart for #{inspect(logical_id)} in #{delay}ms after #{inspect(reason)}" - ) + Log.warning(fn -> + "AgentServer #{state.id} scheduling cron restart for #{Log.safe_inspect(logical_id)} " <> + "in #{delay}ms after #{Log.safe_inspect(reason)}" + end) emit_cron_telemetry_event(state, :restart_scheduled, %{ job_id: logical_id, @@ -2587,9 +2596,10 @@ defmodule Jido.AgentServer do _ = clear_parent_binding(state.jido, state.id, state.partition) stop_reason = wrap_parent_down_reason(reason) - Logger.info( - "AgentServer #{state.id} stopping: parent died (#{inspect(reason)}), wrapped stop_reason: #{inspect(stop_reason)}" - ) + Log.info(fn -> + "AgentServer #{state.id} stopping: parent died (#{Log.safe_inspect(reason)}), " <> + "wrapped stop_reason: #{Log.safe_inspect(stop_reason)}" + end) {:stop, stop_reason, State.set_status(state, :stopping)} end @@ -2597,9 +2607,10 @@ defmodule Jido.AgentServer do defp handle_parent_down(%State{on_parent_death: :continue} = state, _pid, reason) do {former_parent, orphaned_state} = transition_to_orphan(state, reason) - Logger.info( - "AgentServer #{state.id} continuing as orphan after parent #{former_parent.id} died (#{inspect(reason)})" - ) + Log.info(fn -> + "AgentServer #{state.id} continuing as orphan after parent #{former_parent.id} died " <> + "(#{Log.safe_inspect(reason)})" + end) {:noreply, orphaned_state} end @@ -2635,7 +2646,9 @@ defmodule Jido.AgentServer do {tag, state} = State.remove_child_by_pid(state, pid) if tag do - Logger.debug("AgentServer #{state.id} child #{inspect(tag)} exited: #{inspect(reason)}") + Log.debug(fn -> + "AgentServer #{state.id} child #{Log.safe_inspect(tag)} exited: #{Log.safe_inspect(reason)}" + end) signal = ChildExit.new!( @@ -2719,9 +2732,9 @@ defmodule Jido.AgentServer do state {:error, reason} -> - Logger.warning( - "AgentServer #{state.id} failed to persist parent binding: #{inspect(reason)}" - ) + Log.warning(fn -> + "AgentServer #{state.id} failed to persist parent binding: #{Log.safe_inspect(reason)}" + end) state end @@ -2821,16 +2834,18 @@ defmodule Jido.AgentServer do when reason in [:normal, :completed, :ok, :done, :success] do directive_type = directive.__struct__ |> Module.split() |> List.last() - Logger.warning(""" - AgentServer #{state.id} received {:stop, #{inspect(reason)}, ...} from directive #{directive_type}. + Log.warning(fn -> + """ + AgentServer #{state.id} received {:stop, #{Log.safe_inspect(reason)}, ...} from directive #{directive_type}. - This is a HARD STOP: pending directives and async work will be lost, and on_after_cmd/3 will NOT run. + This is a HARD STOP: pending directives and async work will be lost, and on_after_cmd/3 will NOT run. - For normal completion, set state.status to :completed/:failed instead and avoid returning {:stop, ...}. - External code should poll AgentServer.state/1 and check status, not rely on process death. + For normal completion, set state.status to :completed/:failed instead and avoid returning {:stop, ...}. + External code should poll AgentServer.state/1 and check status, not rely on process death. - {:stop, ...} should only be used for abnormal/framework-level termination. - """) + {:stop, ...} should only be used for abnormal/framework-level termination. + """ + end) end defp warn_if_normal_stop(_reason, _directive, _state), do: :ok diff --git a/lib/jido/agent_server/directive_executors.ex b/lib/jido/agent_server/directive_executors.ex index 6eb42fb..37d1427 100644 --- a/lib/jido/agent_server/directive_executors.ex +++ b/lib/jido/agent_server/directive_executors.ex @@ -1,8 +1,7 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.Emit do @moduledoc false - require Logger - + alias Jido.Log alias Jido.Tracing.Context, as: TraceContext def exec(%{signal: signal, dispatch: dispatch}, input_signal, state) do @@ -32,7 +31,7 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.Emit do Jido.Signal.Dispatch.dispatch(traced_signal, cfg) end) else - Logger.warning("Jido.Signal.Dispatch not available, skipping emit") + Log.warning(fn -> "Jido.Signal.Dispatch not available, skipping emit" end) end end end @@ -50,8 +49,7 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.RunInstruction do @moduledoc false - require Logger - + alias Jido.Log alias Jido.AgentServer.State alias Jido.Observe.Config, as: ObserveConfig @@ -90,7 +88,7 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.RunInstruction {:ok, state} {:error, :queue_overflow} -> - Logger.warning("AgentServer #{state.id} queue overflow, dropping directives") + Log.warning(fn -> "AgentServer #{state.id} queue overflow, dropping directives" end) {:ok, state} end end @@ -131,7 +129,7 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.Spawn do @moduledoc false - require Logger + alias Jido.Log def exec(%{child_spec: child_spec, tag: tag}, _input_signal, state) do result = @@ -146,15 +144,21 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.Spawn do case result do {:ok, pid} -> - Logger.debug("Spawned child process #{inspect(pid)} with tag #{inspect(tag)}") + Log.debug(fn -> + "Spawned child process #{Log.safe_inspect(pid)} with tag #{Log.safe_inspect(tag)}" + end) + {:ok, state} {:ok, pid, _info} -> - Logger.debug("Spawned child process #{inspect(pid)} with tag #{inspect(tag)}") + Log.debug(fn -> + "Spawned child process #{Log.safe_inspect(pid)} with tag #{Log.safe_inspect(tag)}" + end) + {:ok, state} {:error, reason} -> - Logger.error("Failed to spawn child: #{inspect(reason)}") + Log.error(fn -> "Failed to spawn child: #{Log.safe_inspect(reason)}" end) {:ok, state} :ignored -> @@ -196,9 +200,8 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.SpawnAgent do @moduledoc false - require Logger - alias Jido.Agent.Directive + alias Jido.Log alias Jido.AgentServer alias Jido.AgentServer.{ChildInfo, State} alias Jido.RuntimeStore @@ -216,7 +219,10 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.SpawnAgent do spawn_child(state, agent, tag, opts, meta, restart) else {:error, reason} -> - Logger.error("AgentServer #{state.id} failed to spawn child: #{reason}") + Log.error(fn -> + "AgentServer #{state.id} failed to spawn child: #{Log.safe_inspect(reason)}" + end) + {:ok, state} end end @@ -271,26 +277,28 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.SpawnAgent do new_state = State.add_child(state, tag, child_info) - Logger.debug( - "AgentServer #{state.id} spawned child #{child_id} with tag #{inspect(tag)}" - ) + Log.debug(fn -> + "AgentServer #{state.id} spawned child #{child_id} with tag #{Log.safe_inspect(tag)}" + end) {:ok, new_state} {:error, reason} -> _ = DynamicSupervisor.terminate_child(supervisor, pid) - Logger.error( - "AgentServer #{state.id} failed to persist relationship for child #{child_id}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{state.id} failed to persist relationship for child #{child_id}: " <> + Log.safe_inspect(reason) + end) {:ok, state} end {:error, reason} -> - Logger.error( - "AgentServer #{state.id} failed to spawn child with restart #{inspect(restart)}: #{inspect(reason)}" - ) + Log.error(fn -> + "AgentServer #{state.id} failed to spawn child with restart #{Log.safe_inspect(restart)}: " <> + Log.safe_inspect(reason) + end) {:ok, state} end @@ -320,8 +328,7 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.AdoptChild do @moduledoc false - require Logger - + alias Jido.Log alias Jido.AgentServer alias Jido.AgentServer.{ChildInfo, ParentRef, State} @@ -341,16 +348,17 @@ defimpl Jido.AgentServer.DirectiveExec, for: Jido.Agent.Directive.AdoptChild do meta: meta }) - Logger.debug( - "AgentServer #{state.id} adopted child #{child_runtime.id} with tag #{inspect(tag)}" - ) + Log.debug(fn -> + "AgentServer #{state.id} adopted child #{child_runtime.id} with tag #{Log.safe_inspect(tag)}" + end) {:ok, State.add_child(state, tag, child_info)} else {:error, reason} -> - Logger.warning( - "AgentServer #{state.id} failed to adopt child #{inspect(child)} with tag #{inspect(tag)}: #{inspect(reason)}" - ) + Log.warning(fn -> + "AgentServer #{state.id} failed to adopt child #{Log.safe_inspect(child)} " <> + "with tag #{Log.safe_inspect(tag)}: #{Log.safe_inspect(reason)}" + end) {:ok, state} end @@ -414,10 +422,13 @@ end defimpl Jido.AgentServer.DirectiveExec, for: Any do @moduledoc false - require Logger + alias Jido.Log def exec(directive, _input_signal, state) do - Logger.debug("Ignoring unknown directive: #{inspect(directive.__struct__)}") + Log.debug(fn -> + "Ignoring unknown directive: #{Log.safe_inspect(directive.__struct__)}" + end) + {:ok, state} end end diff --git a/lib/jido/agent_server/error_policy.ex b/lib/jido/agent_server/error_policy.ex index 0399311..826950c 100644 --- a/lib/jido/agent_server/error_policy.ex +++ b/lib/jido/agent_server/error_policy.ex @@ -9,9 +9,8 @@ defmodule Jido.AgentServer.ErrorPolicy do # - `{:max_errors, n}` - Stop after n errors # - `fun/2` - Custom function - require Logger - alias Jido.Agent.Directive.Error, as: ErrorDirective + alias Jido.Log alias Jido.AgentServer.State alias Jido.Signal.Dispatch, as: SignalDispatch @@ -29,7 +28,7 @@ defmodule Jido.AgentServer.ErrorPolicy do :stop_on_error -> log_error(error, context, state) - Logger.error("Agent #{state.id} stopping due to error policy") + Log.error(fn -> "Agent #{state.id} stopping due to error policy" end) {:stop, {:agent_error, error}, state} {:emit_signal, dispatch_cfg} -> @@ -50,21 +49,21 @@ defmodule Jido.AgentServer.ErrorPolicy do defp log_error(error, context, state) do message = extract_message(error) - context_str = if context, do: " [#{context}]", else: "" + context_str = if context, do: " [#{Log.safe_inspect(context)}]", else: "" - Logger.error("Agent #{state.id}#{context_str}: #{message}#{details_suffix(error)}") + Log.error(fn -> "Agent #{state.id}#{context_str}: #{message}#{details_suffix(error)}" end) end defp extract_message(%{message: message}) when is_binary(message), do: message defp extract_message(%{message: %{message: message}}) when is_binary(message), do: message - defp extract_message(error), do: inspect(error) + defp extract_message(error), do: Log.safe_inspect(error) defp extract_details(%{details: details}) when is_map(details), do: details defp extract_details(_), do: %{} defp details_suffix(error) do case extract_details(error) do - details when map_size(details) > 0 -> " #{inspect(details)}" + details when map_size(details) > 0 -> " #{Log.safe_inspect(details)}" _ -> "" end end @@ -80,7 +79,7 @@ defmodule Jido.AgentServer.ErrorPolicy do SignalDispatch.dispatch(signal, dispatch_cfg) end) else - Logger.warning("Jido.Signal.Dispatch not available, skipping error signal emit") + Log.warning(fn -> "Jido.Signal.Dispatch not available, skipping error signal emit" end) end end @@ -102,12 +101,12 @@ defmodule Jido.AgentServer.ErrorPolicy do if count >= max do log_error(error, context, state) - Logger.error("Agent #{state.id} exceeded max errors (#{count}/#{max}), stopping") + Log.error(fn -> "Agent #{state.id} exceeded max errors (#{count}/#{max}), stopping" end) {:stop, {:max_errors_exceeded, count}, state} else - Logger.warning( + Log.warning(fn -> "Agent #{state.id} error #{count}/#{max}: #{extract_message(error)}#{details_suffix(error)}" - ) + end) {:ok, state} end @@ -125,16 +124,22 @@ defmodule Jido.AgentServer.ErrorPolicy do {:stop, reason, new_state} other -> - Logger.error("Custom error policy returned invalid result: #{inspect(other)}") + Log.error(fn -> + "Custom error policy returned invalid result: #{Log.safe_inspect(other)}" + end) + {:ok, state} end rescue e -> - Logger.error("Custom error policy crashed: #{Exception.message(e)}") + Log.error(fn -> "Custom error policy crashed: #{Exception.message(e)}" end) {:ok, state} catch kind, reason -> - Logger.error("Custom error policy failed: #{kind} - #{inspect(reason)}") + Log.error(fn -> + "Custom error policy failed: #{kind} - #{Log.safe_inspect(reason)}" + end) + {:ok, state} end end diff --git a/lib/jido/agent_server/lifecycle/keyed.ex b/lib/jido/agent_server/lifecycle/keyed.ex index 13916f4..204372c 100644 --- a/lib/jido/agent_server/lifecycle/keyed.ex +++ b/lib/jido/agent_server/lifecycle/keyed.ex @@ -29,8 +29,7 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do @behaviour Jido.AgentServer.Lifecycle - require Logger - + alias Jido.Log alias Jido.Persist @impl true @@ -60,9 +59,10 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do state = %{state | lifecycle: new_lifecycle} state = cancel_idle_timer(state) - Logger.debug( - "Lifecycle attached pid #{inspect(pid)} to #{lifecycle.pool}/#{inspect(lifecycle.pool_key)}" - ) + Log.debug(fn -> + "Lifecycle attached pid #{Log.safe_inspect(pid)} to #{lifecycle.pool}/" <> + Log.safe_inspect(lifecycle.pool_key) + end) {:cont, state} end @@ -86,9 +86,10 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do state = %{state | lifecycle: new_lifecycle} - Logger.debug( - "Lifecycle detached pid #{inspect(pid)} from #{lifecycle.pool}/#{inspect(lifecycle.pool_key)}" - ) + Log.debug(fn -> + "Lifecycle detached pid #{Log.safe_inspect(pid)} from #{lifecycle.pool}/" <> + Log.safe_inspect(lifecycle.pool_key) + end) if MapSet.size(new_lifecycle.attachments) == 0 do {:cont, maybe_start_idle_timer(state)} @@ -118,9 +119,10 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do state = %{state | lifecycle: new_lifecycle} - Logger.debug( - "Lifecycle owner #{inspect(pid)} down for #{lifecycle.pool}/#{inspect(lifecycle.pool_key)}" - ) + Log.debug(fn -> + "Lifecycle owner #{Log.safe_inspect(pid)} down for #{lifecycle.pool}/" <> + Log.safe_inspect(lifecycle.pool_key) + end) if MapSet.size(new_lifecycle.attachments) == 0 do {:cont, maybe_start_idle_timer(state)} @@ -136,7 +138,9 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do def handle_event(:idle_timeout, state) do lifecycle = state.lifecycle - Logger.debug("Lifecycle idle timeout for #{lifecycle.pool}/#{inspect(lifecycle.pool_key)}") + Log.debug(fn -> + "Lifecycle idle timeout for #{lifecycle.pool}/#{Log.safe_inspect(lifecycle.pool_key)}" + end) {:stop, {:shutdown, :idle_timeout}, state} end @@ -206,9 +210,10 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do state {:error, reason} -> - Logger.warning( - "Lifecycle restore failed for #{lifecycle.pool}/#{inspect(lifecycle.pool_key)}: #{inspect(reason)}" - ) + Log.warning(fn -> + "Lifecycle restore failed for #{lifecycle.pool}/#{Log.safe_inspect(lifecycle.pool_key)}: " <> + Log.safe_inspect(reason) + end) state end @@ -225,12 +230,15 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do case Persist.hibernate(storage, agent_module, persistence_key, agent) do :ok -> - Logger.debug("Lifecycle hibernated agent for #{lifecycle.pool}/#{inspect(pool_key)}") + Log.debug(fn -> + "Lifecycle hibernated agent for #{lifecycle.pool}/#{Log.safe_inspect(pool_key)}" + end) {:error, reason} -> - Logger.error( - "Lifecycle hibernate failed for #{lifecycle.pool}/#{inspect(pool_key)}: #{inspect(reason)}" - ) + Log.error(fn -> + "Lifecycle hibernate failed for #{lifecycle.pool}/#{Log.safe_inspect(pool_key)}: " <> + Log.safe_inspect(reason) + end) end end @@ -247,9 +255,11 @@ defmodule Jido.AgentServer.Lifecycle.Keyed do {cron_specs, invalid_cron_specs} = Jido.Scheduler.classify_cron_specs(staged_cron_specs) Enum.each(invalid_cron_specs, fn {job_id, spec, reason} -> - Logger.error( - "Lifecycle dropped malformed persisted cron spec #{inspect(job_id)} for #{inspect(agent_id)}: #{inspect(spec)} (#{inspect(reason)})" - ) + Log.error(fn -> + "Lifecycle dropped malformed persisted cron spec #{Log.safe_inspect(job_id)} for " <> + "#{Log.safe_inspect(agent_id)}: #{Log.safe_inspect(spec)} " <> + "(#{Log.safe_inspect(reason)})" + end) end) {cleaned_agent, cron_specs} diff --git a/lib/jido/agent_server/state.ex b/lib/jido/agent_server/state.ex index d1be386..360f8ea 100644 --- a/lib/jido/agent_server/state.ex +++ b/lib/jido/agent_server/state.ex @@ -10,8 +10,7 @@ defmodule Jido.AgentServer.State do the agent itself, directive queue, hierarchy tracking, and configuration. """ - require Logger - + alias Jido.Log alias Jido.AgentServer.{ChildInfo, Options, ParentRef} alias Jido.AgentServer.State.Lifecycle, as: LifecycleState @@ -148,9 +147,10 @@ defmodule Jido.AgentServer.State do Jido.Scheduler.classify_cron_specs(staged_cron_specs) Enum.each(invalid_cron_specs, fn {job_id, spec, reason} -> - Logger.error( - "AgentServer #{opts.id} dropped malformed persisted cron spec #{inspect(job_id)}: #{inspect(spec)} (#{inspect(reason)})" - ) + Log.error(fn -> + "AgentServer #{opts.id} dropped malformed persisted cron spec #{Log.safe_inspect(job_id)}: " <> + "#{Log.safe_inspect(spec)} (#{Log.safe_inspect(reason)})" + end) end) lifecycle_opts = [ diff --git a/lib/jido/agent_server/stop_child_runtime.ex b/lib/jido/agent_server/stop_child_runtime.ex index 14a4a5f..37c0c54 100644 --- a/lib/jido/agent_server/stop_child_runtime.ex +++ b/lib/jido/agent_server/stop_child_runtime.ex @@ -1,9 +1,8 @@ defmodule Jido.AgentServer.StopChildRuntime do @moduledoc false - require Logger - alias Jido.AgentServer.State + alias Jido.Log alias Jido.RuntimeStore alias Jido.Signal alias Jido.Tracing.Context, as: TraceContext @@ -14,13 +13,17 @@ defmodule Jido.AgentServer.StopChildRuntime do def exec(tag, reason, %Signal{} = input_signal, %State{} = state) do case State.get_child(state, tag) do nil -> - Logger.debug("AgentServer #{state.id} cannot stop child #{inspect(tag)}: not found") + Log.debug(fn -> + "AgentServer #{state.id} cannot stop child #{Log.safe_inspect(tag)}: not found" + end) + {:ok, state} %{pid: pid, id: child_id, partition: child_partition} -> - Logger.debug( - "AgentServer #{state.id} stopping child #{inspect(tag)} with reason #{inspect(reason)}" - ) + Log.debug(fn -> + "AgentServer #{state.id} stopping child #{Log.safe_inspect(tag)} with reason " <> + Log.safe_inspect(reason) + end) case RuntimeStore.delete( state.jido, @@ -31,9 +34,10 @@ defmodule Jido.AgentServer.StopChildRuntime do :ok {:error, delete_reason} -> - Logger.warning( - "AgentServer #{state.id} failed to clear relationship for child #{child_id}: #{inspect(delete_reason)}" - ) + Log.warning(fn -> + "AgentServer #{state.id} failed to clear relationship for child #{child_id}: " <> + Log.safe_inspect(delete_reason) + end) end stop_signal = diff --git a/lib/jido/discovery.ex b/lib/jido/discovery.ex index 52a36f8..f87cb24 100644 --- a/lib/jido/discovery.ex +++ b/lib/jido/discovery.ex @@ -61,9 +61,6 @@ defmodule Jido.Discovery do Reads are extremely fast (direct memory access) and never block. All processes can read concurrently without contention. """ - - require Logger - @catalog_key :jido_discovery_catalog @type component_type :: :actions | :sensors | :agents | :plugins | :demos diff --git a/lib/jido/log.ex b/lib/jido/log.ex new file mode 100644 index 0000000..b2bde79 --- /dev/null +++ b/lib/jido/log.ex @@ -0,0 +1,58 @@ +defmodule Jido.Log do + @moduledoc false + + require Logger + + @default_max_length 200 + @default_limit 10 + + @type metadata :: keyword() + @type level :: Logger.level() + + @doc false + @spec debug(Logger.message(), metadata()) :: :ok + def debug(message, metadata \\ []), do: Logger.debug(message, metadata) + + @doc false + @spec info(Logger.message(), metadata()) :: :ok + def info(message, metadata \\ []), do: Logger.info(message, metadata) + + @doc false + @spec warning(Logger.message(), metadata()) :: :ok + def warning(message, metadata \\ []), do: Logger.warning(message, metadata) + + @doc false + @spec error(Logger.message(), metadata()) :: :ok + def error(message, metadata \\ []), do: Logger.error(message, metadata) + + @doc false + @spec log(level(), Logger.message(), metadata()) :: :ok + def log(level, message, metadata \\ []), do: Logger.log(level, message, metadata) + + @doc false + @spec levels() :: [level()] + def levels, do: Logger.levels() + + @doc false + @spec compare_levels(level(), level()) :: :lt | :eq | :gt + def compare_levels(left, right), do: Logger.compare_levels(left, right) + + @doc false + @spec safe_inspect(term(), keyword()) :: String.t() + def safe_inspect(term, opts \\ []) do + max_length = Keyword.get(opts, :max_length, @default_max_length) + limit = Keyword.get(opts, :limit, @default_limit) + + term + |> inspect(limit: limit, printable_limit: max_length, width: max_length, charlists: :as_lists) + |> truncate(max_length) + end + + defp truncate(binary, max_length) when is_binary(binary) do + if String.length(binary) > max_length do + String.slice(binary, 0, max_length) <> "..." + else + binary + end + end +end diff --git a/lib/jido/observe.ex b/lib/jido/observe.ex index b0bc358..8e040f5 100644 --- a/lib/jido/observe.ex +++ b/lib/jido/observe.ex @@ -93,10 +93,9 @@ defmodule Jido.Observe do `prompt_size_bytes`) rather than the raw content. """ - require Logger - + alias Jido.Log alias Jido.Observe.Config, as: ObserveConfig - alias Jido.Observe.Log + alias Jido.Observe.Log, as: ObserveLog alias Jido.Observe.SpanCtx alias Jido.Tracing.Context, as: TracingContext @@ -253,7 +252,7 @@ defmodule Jido.Observe do """ @spec log(Logger.level(), Logger.message(), keyword()) :: :ok def log(level, message, metadata \\ []) do - Log.log(level, message, metadata) + ObserveLog.log(level, message, metadata) end @doc """ @@ -695,21 +694,21 @@ defmodule Jido.Observe do end defp log_tracer_warning(%SpanCtx{} = span_ctx, callback_name, failure) do - Logger.warning( + Log.warning(fn -> "Jido.Observe tracer #{callback_name} failed " <> - "(tracer=#{inspect(span_ctx.tracer_module || tracer(span_ctx.metadata))}, " <> - "event_prefix=#{inspect(span_ctx.event_prefix)}, " <> + "(tracer=#{Log.safe_inspect(span_ctx.tracer_module || tracer(span_ctx.metadata))}, " <> + "event_prefix=#{Log.safe_inspect(span_ctx.event_prefix)}, " <> "failure_mode=#{tracer_failure_mode(span_ctx.metadata)}): #{format_tracer_failure(failure)}" - ) + end) end defp log_scoped_contract_warning(%SpanCtx{} = span_ctx, message) do - Logger.warning( + Log.warning(fn -> "Jido.Observe tracer with_span_scope/3 contract violation " <> - "(tracer=#{inspect(span_ctx.tracer_module)}, " <> - "event_prefix=#{inspect(span_ctx.event_prefix)}, " <> + "(tracer=#{Log.safe_inspect(span_ctx.tracer_module)}, " <> + "event_prefix=#{Log.safe_inspect(span_ctx.event_prefix)}, " <> "failure_mode=#{tracer_failure_mode(span_ctx.metadata)}): #{message}" - ) + end) end defp raise_tracer_failure(%SpanCtx{} = span_ctx, callback_name, failure) do diff --git a/lib/jido/observe/config.ex b/lib/jido/observe/config.ex index 191ed91..2d93af6 100644 --- a/lib/jido/observe/config.ex +++ b/lib/jido/observe/config.ex @@ -153,6 +153,15 @@ defmodule Jido.Observe.Config do `:silent` to avoid leaking full action params/context through dependency telemetry spans. Full argument logging is only enabled when the instance opts into `log_args: :full` or `Jido.debug(:verbose)`. + + Quieter runtime behavior remains opt-in through `:jido` telemetry and + observability config; the library defaults stay aligned with the historical + `:info` baseline for compatibility. + + This function defines the supported boundary between `jido` and + downstream action execution. Human-readable dependency log strings are not a + stable contract; callers and tests should assert derived exec opts and + telemetry behavior instead. """ @spec action_exec_opts(instance(), keyword()) :: keyword() def action_exec_opts(instance \\ nil, opts \\ []) when is_list(opts) do diff --git a/lib/jido/observe/log.ex b/lib/jido/observe/log.ex index e07c0c3..4f66acf 100644 --- a/lib/jido/observe/log.ex +++ b/lib/jido/observe/log.ex @@ -6,13 +6,13 @@ defmodule Jido.Observe.Log do The log threshold can be configured per-environment to control verbosity: - `:debug` in development for verbose output - - `:info` or `:warning` in production for minimal noise + - `:warning` in production and test for minimal noise ## Configuration # config/config.exs config :jido, :observability, - log_level: :info + log_level: :warning # config/dev.exs config :jido, :observability, @@ -37,7 +37,7 @@ defmodule Jido.Observe.Log do Returns the current observability log threshold. Reads from application config `:jido, :observability, :log_level`. - Defaults to `:info` if not configured. + Defaults to `:warning` if not configured. """ @spec threshold() :: level() def threshold do @@ -58,11 +58,11 @@ defmodule Jido.Observe.Log do ## Examples - # With threshold at :info, this won't log + # With threshold at :warning, this won't log Log.log(:debug, "Verbose info", step: 1) - # With threshold at :info, this will log - Log.log(:info, "Important info", agent_id: "abc") + # With threshold at :warning, this will log + Log.log(:warning, "Important warning", agent_id: "abc") """ @spec log(level(), Logger.message(), keyword()) :: :ok def log(level, message, metadata \\ []) do diff --git a/lib/jido/persist.ex b/lib/jido/persist.ex index dddeac9..fb71e6d 100644 --- a/lib/jido/persist.ex +++ b/lib/jido/persist.ex @@ -48,8 +48,7 @@ defmodule Jido.Persist do If not implemented, default serialization is used. """ - require Logger - + alias Jido.Log alias Jido.Scheduler alias Jido.Thread @@ -166,19 +165,25 @@ defmodule Jido.Persist do defp do_hibernate(adapter, opts, agent_module, key, agent) do thread = get_thread(agent) - Logger.debug("Persist.hibernate starting for #{inspect(agent_module)} key=#{inspect(key)}") + Log.debug(fn -> + "Persist.hibernate starting for #{Log.safe_inspect(agent_module)} key=#{Log.safe_inspect(key)}" + end) with :ok <- flush_journal(adapter, opts, thread), {:ok, checkpoint} <- create_checkpoint(agent_module, agent, thread), checkpoint_key <- make_checkpoint_key(agent_module, key), :ok <- adapter.put_checkpoint(checkpoint_key, checkpoint, opts) do - Logger.debug("Persist.hibernate completed for #{inspect(agent_module)} key=#{inspect(key)}") + Log.debug(fn -> + "Persist.hibernate completed for #{Log.safe_inspect(agent_module)} key=#{Log.safe_inspect(key)}" + end) + :ok else {:error, reason} = error -> - Logger.error( - "Persist.hibernate failed for #{inspect(agent_module)} key=#{inspect(key)}: #{inspect(reason)}" - ) + Log.error(fn -> + "Persist.hibernate failed for #{Log.safe_inspect(agent_module)} " <> + "key=#{Log.safe_inspect(key)}: #{Log.safe_inspect(reason)}" + end) error end @@ -188,20 +193,26 @@ defmodule Jido.Persist do defp do_thaw(adapter, opts, agent_module, key) do checkpoint_key = make_checkpoint_key(agent_module, key) - Logger.debug("Persist.thaw starting for #{inspect(agent_module)} key=#{inspect(key)}") + Log.debug(fn -> + "Persist.thaw starting for #{Log.safe_inspect(agent_module)} key=#{Log.safe_inspect(key)}" + end) case Jido.Storage.fetch_checkpoint(adapter, checkpoint_key, opts) do {:ok, checkpoint} -> restore_from_checkpoint(adapter, opts, agent_module, checkpoint) {:error, :not_found} -> - Logger.debug("Persist.thaw: checkpoint not found for #{inspect(checkpoint_key)}") + Log.debug(fn -> + "Persist.thaw: checkpoint not found for #{Log.safe_inspect(checkpoint_key)}" + end) + {:error, :not_found} {:error, reason} = error -> - Logger.error( - "Persist.thaw failed to get checkpoint for #{inspect(checkpoint_key)}: #{inspect(reason)}" - ) + Log.error(fn -> + "Persist.thaw failed to get checkpoint for #{Log.safe_inspect(checkpoint_key)}: " <> + Log.safe_inspect(reason) + end) error end @@ -226,9 +237,9 @@ defmodule Jido.Persist do if thread.rev == entry_count do :ok else - Logger.error( + Log.error(fn -> "Persist: invalid local thread revision for #{thread.id}: rev=#{thread.rev}, entries=#{entry_count}" - ) + end) {:error, :invalid_thread_revision} end @@ -257,21 +268,21 @@ defmodule Jido.Persist do cond do stored_rev > local_rev -> - Logger.error( + Log.error(fn -> "Persist: thread rev regression for #{thread.id}: local_rev=#{local_rev}, stored_rev=#{stored_rev}" - ) + end) {:error, :thread_rev_regression} stored_rev > entry_count -> - Logger.error( + Log.error(fn -> "Persist: thread history truncated for #{thread.id}: entry_count=#{entry_count}, stored_rev=#{stored_rev}" - ) + end) {:error, :thread_history_truncated} stored_rev == local_rev -> - Logger.debug("Persist: thread #{thread.id} already persisted at rev=#{stored_rev}") + Log.debug(fn -> "Persist: thread #{thread.id} already persisted at rev=#{stored_rev}" end) :ok true -> @@ -282,9 +293,9 @@ defmodule Jido.Persist do |> maybe_put_thread_metadata(stored_rev, thread.metadata) |> Kernel.++(opts) - Logger.debug( + Log.debug(fn -> "Persist: flushing #{length(missing_entries)} new entries for thread #{thread.id} from rev=#{stored_rev}" - ) + end) case adapter.append_thread(thread.id, missing_entries, append_opts) do {:ok, _updated_thread} -> @@ -294,9 +305,9 @@ defmodule Jido.Persist do handle_thread_append_conflict(adapter, opts, thread.id, local_rev) {:error, reason} = error -> - Logger.error( - "Persist: failed to flush journal for thread #{thread.id}: #{inspect(reason)}" - ) + Log.error(fn -> + "Persist: failed to flush journal for thread #{thread.id}: #{Log.safe_inspect(reason)}" + end) error end @@ -314,23 +325,24 @@ defmodule Jido.Persist do defp handle_thread_append_conflict(adapter, opts, thread_id, local_rev) do case Jido.Storage.fetch_thread(adapter, thread_id, opts) do {:ok, %Thread{rev: stored_rev}} when stored_rev >= local_rev -> - Logger.debug( + Log.debug(fn -> "Persist: append conflict resolved for #{thread_id}; stored_rev=#{stored_rev} >= local_rev=#{local_rev}" - ) + end) :ok {:ok, %Thread{rev: stored_rev}} -> - Logger.error( + Log.error(fn -> "Persist: append conflict for #{thread_id}; stored_rev=#{stored_rev}, local_rev=#{local_rev}" - ) + end) {:error, :conflict} {:error, reason} = error -> - Logger.error( - "Persist: append conflict but failed to reload thread #{thread_id}: #{inspect(reason)}" - ) + Log.error(fn -> + "Persist: append conflict but failed to reload thread #{thread_id}: " <> + Log.safe_inspect(reason) + end) error end @@ -396,7 +408,11 @@ defmodule Jido.Persist do {:ok, agent} <- restore_agent(agent_module, checkpoint, ctx), {:ok, agent} <- rehydrate_thread(adapter, opts, agent, checkpoint) do agent = attach_scheduler_manifest(agent, checkpoint) - Logger.debug("Persist.thaw completed for #{inspect(agent_module)} id=#{checkpoint.id}") + + Log.debug(fn -> + "Persist.thaw completed for #{Log.safe_inspect(agent_module)} id=#{checkpoint.id}" + end) + {:ok, agent} end end @@ -431,7 +447,9 @@ defmodule Jido.Persist do defp rehydrate_thread(_adapter, _opts, agent, %{thread: nil}), do: {:ok, agent} defp rehydrate_thread(adapter, opts, agent, %{thread: %{id: thread_id, rev: expected_rev}}) do - Logger.debug("Persist: rehydrating thread #{thread_id} with expected rev=#{expected_rev}") + Log.debug(fn -> + "Persist: rehydrating thread #{thread_id} with expected rev=#{expected_rev}" + end) case Jido.Storage.fetch_thread(adapter, thread_id, opts) do {:ok, %Thread{rev: ^expected_rev} = thread} -> @@ -439,18 +457,24 @@ defmodule Jido.Persist do {:ok, agent_with_thread} {:ok, %Thread{rev: actual_rev}} -> - Logger.error( + Log.error(fn -> "Persist: thread rev mismatch for #{thread_id}: expected=#{expected_rev}, actual=#{actual_rev}" - ) + end) {:error, :thread_mismatch} {:error, :not_found} -> - Logger.error("Persist: thread #{thread_id} not found but referenced in checkpoint") + Log.error(fn -> + "Persist: thread #{thread_id} not found but referenced in checkpoint" + end) + {:error, :missing_thread} {:error, reason} = error -> - Logger.error("Persist: failed to load thread #{thread_id}: #{inspect(reason)}") + Log.error(fn -> + "Persist: failed to load thread #{thread_id}: #{Log.safe_inspect(reason)}" + end) + error end end diff --git a/lib/jido/scheduler/job.ex b/lib/jido/scheduler/job.ex index f7a28d3..8848545 100644 --- a/lib/jido/scheduler/job.ex +++ b/lib/jido/scheduler/job.ex @@ -3,10 +3,9 @@ defmodule Jido.Scheduler.Job do use GenServer - require Logger - alias Crontab.CronExpression.Parser alias Crontab.Scheduler, as: CronScheduler + alias Jido.Log @tick :tick @retry_schedule :retry_schedule @@ -200,11 +199,11 @@ defmodule Jido.Scheduler.Job do :ok rescue error -> - Logger.error("Scheduler callback raised: #{Exception.message(error)}") + Log.error(fn -> "Scheduler callback raised: #{Exception.message(error)}" end) :ok catch kind, reason -> - Logger.error("Scheduler callback #{kind}: #{inspect(reason)}") + Log.error(fn -> "Scheduler callback #{kind}: #{Log.safe_inspect(reason)}" end) :ok end end @@ -234,9 +233,10 @@ defmodule Jido.Scheduler.Job do @spec enter_retry(state(), term()) :: state() defp enter_retry(state, reason) do if not state.retrying? do - Logger.warning( - "Scheduler job entering retry mode for #{inspect(state.cron_expr)} after schedule failure: #{inspect(reason)}" - ) + Log.warning(fn -> + "Scheduler job entering retry mode for #{Log.safe_inspect(state.cron_expr, max_length: 80)} " <> + "after schedule failure: #{Log.safe_inspect(reason)}" + end) end timer_ref = Process.send_after(self(), @retry_schedule, @retry_delay_ms) @@ -246,7 +246,9 @@ defmodule Jido.Scheduler.Job do @spec clear_retry(state(), reference()) :: state() defp clear_retry(state, timer_ref) do if state.retrying? do - Logger.info("Scheduler job recovered schedule resolution for #{inspect(state.cron_expr)}") + Log.debug(fn -> + "Scheduler job recovered schedule resolution for #{Log.safe_inspect(state.cron_expr, max_length: 80)}" + end) end %{state | timer_ref: timer_ref, retrying?: false} diff --git a/lib/jido/sensor/runtime.ex b/lib/jido/sensor/runtime.ex index b160dc0..07b2eb9 100644 --- a/lib/jido/sensor/runtime.ex +++ b/lib/jido/sensor/runtime.ex @@ -46,8 +46,7 @@ defmodule Jido.Sensor.Runtime do use GenServer - require Logger - + alias Jido.Log alias Jido.Signal.Dispatch @type server :: pid() | atom() | {:via, module(), term()} @@ -157,7 +156,10 @@ defmodule Jido.Sensor.Runtime do @impl GenServer def handle_info(msg, state) do - Logger.debug("Sensor.Runtime #{state.id} received unexpected message: #{inspect(msg)}") + Log.debug(fn -> + "Sensor.Runtime #{state.id} received unexpected message: #{Log.safe_inspect(msg)}" + end) + {:noreply, state} end @@ -241,14 +243,17 @@ defmodule Jido.Sensor.Runtime do {:noreply, new_state} {:error, reason} -> - Logger.warning("Sensor.Runtime #{state.id} handle_event error: #{inspect(reason)}") + Log.warning(fn -> + "Sensor.Runtime #{state.id} handle_event error: #{Log.safe_inspect(reason)}" + end) {:noreply, state} other -> - Logger.warning( - "Sensor.Runtime #{state.id} handle_event returned invalid result: #{inspect(other)}" - ) + Log.warning(fn -> + "Sensor.Runtime #{state.id} handle_event returned invalid result: " <> + Log.safe_inspect(other) + end) {:noreply, state} end @@ -281,7 +286,9 @@ defmodule Jido.Sensor.Runtime do end defp apply_directive(directive, state) do - Logger.warning("Sensor.Runtime #{state.id} ignoring unknown directive: #{inspect(directive)}") + Log.warning(fn -> + "Sensor.Runtime #{state.id} ignoring unknown directive: #{Log.safe_inspect(directive)}" + end) state end @@ -312,7 +319,7 @@ defmodule Jido.Sensor.Runtime do dispatch_signal_async(signal, agent_ref, state) true -> - Logger.debug("Sensor.Runtime #{state.id} has no agent_ref, signal not delivered") + Log.debug(fn -> "Sensor.Runtime #{state.id} has no agent_ref, signal not delivered" end) end end @@ -322,9 +329,9 @@ defmodule Jido.Sensor.Runtime do dispatch_fun(state).(signal, agent_ref) rescue e -> - Logger.warning( + Log.warning(fn -> "Sensor.Runtime #{state.id} async dispatch failed: #{Exception.message(e)}" - ) + end) end end diff --git a/lib/jido/telemetry.ex b/lib/jido/telemetry.ex index 247580c..9c935c2 100644 --- a/lib/jido/telemetry.ex +++ b/lib/jido/telemetry.ex @@ -81,8 +81,7 @@ defmodule Jido.Telemetry do - `[:jido, :agent, :strategy, :tick, :exception]` - Strategy tick failed """ - require Logger - + alias Jido.Log alias Jido.Observe.Config, as: ObserveConfig alias Jido.Telemetry.Formatter @@ -235,7 +234,7 @@ defmodule Jido.Telemetry do directive_count = metadata[:directive_count] || 0 if interesting_agent_cmd?(instance, duration_ms, directive_count, metadata) do - Logger.debug( + Log.debug( fn -> "[agent.cmd] #{format_module(metadata[:agent_module])} " <> "action=#{Formatter.format_action(metadata[:action])} " <> @@ -254,11 +253,13 @@ defmodule Jido.Telemetry do def handle_event([:jido, :agent, :cmd, :exception], measurements, metadata, _config) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[agent.cmd.error] #{format_module(metadata[:agent_module])} " <> - "action=#{Formatter.format_action(metadata[:action])} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[agent.cmd.error] #{format_module(metadata[:agent_module])} " <> + "action=#{Formatter.format_action(metadata[:action])} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], span_id: metadata[:jido_span_id], @@ -279,7 +280,7 @@ defmodule Jido.Telemetry do duration = Map.get(measurements, :duration, 0) if ObserveConfig.trace_enabled?(instance) do - Logger.debug( + Log.debug( fn -> "[strategy.init] #{format_module(metadata[:strategy])} " <> "duration=#{Formatter.format_duration(duration)}" @@ -300,10 +301,12 @@ defmodule Jido.Telemetry do ) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[strategy.init.error] #{format_module(metadata[:strategy])} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[strategy.init.error] #{format_module(metadata[:strategy])} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], stacktrace: metadata[:stacktrace] @@ -321,7 +324,7 @@ defmodule Jido.Telemetry do directive_count = metadata[:directive_count] || 0 if interesting_strategy_cmd?(instance, duration_ms, directive_count) do - Logger.debug( + Log.debug( fn -> "[strategy.cmd] #{format_module(metadata[:strategy])} " <> "directives=#{directive_count} " <> @@ -343,10 +346,12 @@ defmodule Jido.Telemetry do ) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[strategy.cmd.error] #{format_module(metadata[:strategy])} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[strategy.cmd.error] #{format_module(metadata[:strategy])} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], stacktrace: metadata[:stacktrace] @@ -364,7 +369,7 @@ defmodule Jido.Telemetry do # Only log slow ticks - ticks are high frequency if duration_ms > ObserveConfig.slow_signal_threshold_ms(instance) do - Logger.debug( + Log.debug( fn -> "[strategy.tick] #{format_module(metadata[:strategy])} " <> "duration=#{Formatter.format_duration(duration)} (slow)" @@ -385,10 +390,12 @@ defmodule Jido.Telemetry do ) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[strategy.tick.error] #{format_module(metadata[:strategy])} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[strategy.tick.error] #{format_module(metadata[:strategy])} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], stacktrace: metadata[:stacktrace] @@ -436,10 +443,12 @@ defmodule Jido.Telemetry do ) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[signal.error] type=#{Formatter.format_signal_type(metadata[:signal_type])} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[signal.error] type=#{Formatter.format_signal_type(metadata[:signal_type])} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], span_id: metadata[:jido_span_id], @@ -487,10 +496,12 @@ defmodule Jido.Telemetry do ) do duration = Map.get(measurements, :duration, 0) - Logger.warning( - "[directive.error] type=#{metadata[:directive_type]} " <> - "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> - "duration=#{Formatter.format_duration(duration)}", + Log.warning( + fn -> + "[directive.error] type=#{metadata[:directive_type]} " <> + "error=#{Formatter.safe_inspect(metadata[:error], 200)} " <> + "duration=#{Formatter.format_duration(duration)}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id], span_id: metadata[:jido_span_id], @@ -499,26 +510,27 @@ defmodule Jido.Telemetry do end def handle_event([:jido, :agent_server, :queue, :overflow], measurements, metadata, _config) do - Logger.warning( - "[queue.overflow] signal_type=#{Formatter.format_signal_type(metadata[:signal_type])} " <> - "queue_size=#{measurements[:queue_size]}", + Log.warning( + fn -> + "[queue.overflow] signal_type=#{Formatter.format_signal_type(metadata[:signal_type])} " <> + "queue_size=#{measurements[:queue_size]}" + end, agent_id: metadata[:agent_id], trace_id: metadata[:jido_trace_id] ) end def handle_event([:jido, :agent_server, :cron, :register], _measurements, metadata, _config) do - Logger.debug( - "[cron.register] job_id=#{inspect(metadata[:job_id])} cron=#{inspect(metadata[:cron_expression])}", - agent_id: metadata[:agent_id] - ) + maybe_log_cron_debug(metadata, fn -> + "[cron.register] job_id=#{Log.safe_inspect(metadata[:job_id], max_length: 80)} " <> + "cron=#{Log.safe_inspect(metadata[:cron_expression], max_length: 80)}" + end) end def handle_event([:jido, :agent_server, :cron, :cancel], _measurements, metadata, _config) do - Logger.debug( - "[cron.cancel] job_id=#{inspect(metadata[:job_id])}", - agent_id: metadata[:agent_id] - ) + maybe_log_cron_debug(metadata, fn -> + "[cron.cancel] job_id=#{Log.safe_inspect(metadata[:job_id], max_length: 80)}" + end) end def handle_event( @@ -527,10 +539,11 @@ defmodule Jido.Telemetry do metadata, _config ) do - Logger.debug( - "[cron.restart_scheduled] job_id=#{inspect(metadata[:job_id])} reason=#{Formatter.safe_inspect(metadata[:reason], 120)} delay_ms=#{inspect(metadata[:delay_ms])}", - agent_id: metadata[:agent_id] - ) + maybe_log_cron_debug(metadata, fn -> + "[cron.restart_scheduled] job_id=#{Log.safe_inspect(metadata[:job_id], max_length: 80)} " <> + "reason=#{Formatter.safe_inspect(metadata[:reason], 120)} " <> + "delay_ms=#{Log.safe_inspect(metadata[:delay_ms], max_length: 40)}" + end) end def handle_event( @@ -539,10 +552,10 @@ defmodule Jido.Telemetry do metadata, _config ) do - Logger.debug( - "[cron.restart_succeeded] job_id=#{inspect(metadata[:job_id])} cron=#{inspect(metadata[:cron_expression])}", - agent_id: metadata[:agent_id] - ) + maybe_log_cron_debug(metadata, fn -> + "[cron.restart_succeeded] job_id=#{Log.safe_inspect(metadata[:job_id], max_length: 80)} " <> + "cron=#{Log.safe_inspect(metadata[:cron_expression], max_length: 80)}" + end) end def handle_event( @@ -551,8 +564,11 @@ defmodule Jido.Telemetry do metadata, _config ) do - Logger.warning( - "[cron.persist_failure] job_id=#{inspect(metadata[:job_id])} reason=#{Formatter.safe_inspect(metadata[:reason], 200)}", + Log.warning( + fn -> + "[cron.persist_failure] job_id=#{Log.safe_inspect(metadata[:job_id], max_length: 80)} " <> + "reason=#{Formatter.safe_inspect(metadata[:reason], 200)}" + end, agent_id: metadata[:agent_id] ) end @@ -562,7 +578,7 @@ defmodule Jido.Telemetry do # --------------------------------------------------------------------------- defp log_signal_stop(metadata, duration, directive_count) do - Logger.debug( + Log.debug( fn -> directive_types = metadata[:directive_types] @@ -587,7 +603,7 @@ defmodule Jido.Telemetry do end defp log_directive_stop(metadata, duration) do - Logger.debug( + Log.debug( fn -> "[directive] type=#{metadata[:directive_type]} " <> "result=#{metadata[:result]} " <> @@ -636,6 +652,14 @@ defmodule Jido.Telemetry do is_slow or has_directives end + defp maybe_log_cron_debug(metadata, message_fun) when is_function(message_fun, 0) do + if ObserveConfig.debug_enabled?(metadata[:jido_instance]) do + Log.debug(message_fun, agent_id: metadata[:agent_id]) + end + + :ok + end + defp format_module(nil), do: "unknown" defp format_module(module) when is_atom(module) do diff --git a/lib/jido/util.ex b/lib/jido/util.ex index 4d66ce1..504c420 100644 --- a/lib/jido/util.ex +++ b/lib/jido/util.ex @@ -18,10 +18,10 @@ defmodule Jido.Util do but they can also be useful for developers building applications with Jido. """ + alias Jido.Log alias Jido.Signal.ID, as: SignalID require OK - require Logger @name_regex ~r/^[a-zA-Z][a-zA-Z0-9_]*$/ @@ -371,7 +371,7 @@ defmodule Jido.Util do end end - @valid_levels Logger.levels() + @valid_levels Log.levels() @doc """ Conditionally logs a message based on comparing threshold and message log levels. @@ -385,7 +385,7 @@ defmodule Jido.Util do - `threshold_level`: The minimum log level threshold (e.g. :debug, :info, etc) - `message_level`: The log level for this specific message - `message`: The message to potentially log - - `opts`: Additional options passed to Logger.log/3 + - `opts`: Additional options passed to the logger backend ## Returns @@ -411,8 +411,8 @@ defmodule Jido.Util do threshold_level not in @valid_levels or message_level not in @valid_levels -> :ok - Logger.compare_levels(threshold_level, message_level) in [:lt, :eq] -> - Logger.log(message_level, message, opts) + Log.compare_levels(threshold_level, message_level) in [:lt, :eq] -> + Log.log(message_level, message, opts) true -> :ok diff --git a/test/jido/agent_server/agent_server_test.exs b/test/jido/agent_server/agent_server_test.exs index 58f13b8..74896b0 100644 --- a/test/jido/agent_server/agent_server_test.exs +++ b/test/jido/agent_server/agent_server_test.exs @@ -836,7 +836,7 @@ defmodule JidoTest.AgentServerTest do # Wait for scheduled atom message (10ms delay + processing) state = eventually_state(pid, fn state -> state.agent.state.received == :timeout end, - timeout: 100 + timeout: 250 ) assert state.agent.state.received == :timeout diff --git a/test/jido/agent_server/telemetry_test.exs b/test/jido/agent_server/telemetry_test.exs index 61450a6..beb9e49 100644 --- a/test/jido/agent_server/telemetry_test.exs +++ b/test/jido/agent_server/telemetry_test.exs @@ -1,11 +1,10 @@ defmodule JidoTest.AgentServer.TelemetryTest do use JidoTest.Case, async: false - import ExUnit.CaptureLog - alias Jido.Agent.Directive alias Jido.AgentServer alias Jido.Debug + alias Jido.Observe.Config, as: ObserveConfig alias Jido.Signal alias JidoTest.TestActions @@ -132,41 +131,36 @@ defmodule JidoTest.AgentServer.TelemetryTest do end end - describe "action logging integration" do - test "suppresses jido_action start logs when args are not full", %{jido: jido} do + describe "action execution observability integration" do + test "suppresses jido_action telemetry when args are not full", %{jido: jido} do {:ok, pid} = AgentServer.start_link(agent: TelemetryAgent, id: "telemetry-log-default", jido: jido) - signal = Signal.new!("increment", %{}, source: "/test") - - log = - capture_log(fn -> - assert {:ok, _agent} = AgentServer.call(pid, signal) - end) + exec_opts = ObserveConfig.action_exec_opts(jido, []) + assert Keyword.get(exec_opts, :log_level) == :warning + assert Keyword.get(exec_opts, :telemetry) == :silent - refute log =~ "Executing JidoTest.TestActions.IncrementAction" - refute log =~ "with params:" + signal = Signal.new!("increment", %{}, source: "/test") + assert {:ok, _agent} = AgentServer.call(pid, signal) refute_receive {:action_telemetry_event, [:jido, :action, :start], _, _}, 50 + refute_receive {:action_telemetry_event, [:jido, :action, :stop], _, _}, 50 GenServer.stop(pid) end - test "enables verbose jido_action logs when instance debug is verbose", %{jido: jido} do + test "enables full jido_action telemetry when instance debug is verbose", %{jido: jido} do Debug.enable(jido, :verbose) on_exit(fn -> Debug.disable(jido) end) {:ok, pid} = AgentServer.start_link(agent: TelemetryAgent, id: "telemetry-log-verbose", jido: jido) - signal = Signal.new!("increment", %{}, source: "/test") - - log = - capture_log(fn -> - assert {:ok, _agent} = AgentServer.call(pid, signal) - end) + exec_opts = ObserveConfig.action_exec_opts(jido, []) + assert Keyword.get(exec_opts, :log_level) == :debug + assert Keyword.get(exec_opts, :telemetry) == :full - assert log =~ "Executing JidoTest.TestActions.IncrementAction" - assert log =~ "with params:" + signal = Signal.new!("increment", %{}, source: "/test") + assert {:ok, _agent} = AgentServer.call(pid, signal) assert_receive {:action_telemetry_event, [:jido, :action, :start], _, %{action: JidoTest.TestActions.IncrementAction}} diff --git a/test/jido/observe/config_test.exs b/test/jido/observe/config_test.exs index f912633..0d7ec35 100644 --- a/test/jido/observe/config_test.exs +++ b/test/jido/observe/config_test.exs @@ -220,6 +220,19 @@ defmodule JidoTest.Observe.ConfigTest do assert Keyword.get(opts, :telemetry) == :silent assert Keyword.get(opts, :timeout) == 10 end + + test "honors verbose instance override when deriving exec opts" do + Application.put_env(:jido, :telemetry, log_level: :warning, log_args: :none) + Debug.enable(@test_instance, :verbose) + + opts = + Config.action_exec_opts(@test_instance, __jido_instance__: @test_instance, timeout: 10) + + refute Keyword.has_key?(opts, :__jido_instance__) + assert Keyword.get(opts, :log_level) == :debug + assert Keyword.get(opts, :telemetry) == :full + assert Keyword.get(opts, :timeout) == 10 + end end describe "observe_log_level/1" do @@ -334,13 +347,18 @@ defmodule JidoTest.Observe.ConfigTest do refute Config.level_enabled?(nil, :debug) end - test "trace is not enabled at debug level" do + test "trace is not enabled at info level" do refute Config.level_enabled?(nil, :trace) end - test "info is enabled at debug level" do + test "info is enabled at the default info level" do assert Config.level_enabled?(nil, :info) end + + test "warning is enabled when configured log level is warning" do + Application.put_env(:jido, :telemetry, log_level: :warning) + assert Config.level_enabled?(nil, :warning) + end end describe "interesting_signal_type?/2" do diff --git a/test/jido/observe/observe_test.exs b/test/jido/observe/observe_test.exs index 143a387..e316155 100644 --- a/test/jido/observe/observe_test.exs +++ b/test/jido/observe/observe_test.exs @@ -413,7 +413,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :debug) log = - capture_log(fn -> + capture_log([level: :info], fn -> Observe.log(:info, "test message", key: "value") end) @@ -474,7 +474,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :info) log = - capture_log(fn -> + capture_log([level: :info], fn -> Log.log(:info, "info message") end) @@ -485,7 +485,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :info) log = - capture_log(fn -> + capture_log([level: :warning], fn -> Log.log(:warning, "warning message") end) @@ -496,7 +496,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :warning) log = - capture_log(fn -> + capture_log([level: :debug], fn -> Log.log(:debug, "debug message") Log.log(:info, "info message") end) @@ -509,7 +509,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :debug) log = - capture_log(fn -> + capture_log([level: :info], fn -> Log.log(:info, "with metadata", agent_id: "agent-123") end) @@ -520,7 +520,7 @@ defmodule JidoTest.ObserveTest do Application.put_env(:jido, :observability, log_level: :debug) log = - capture_log(fn -> + capture_log([level: :debug], fn -> Log.log(:debug, "debug level message") end) diff --git a/test/jido/scheduler_test.exs b/test/jido/scheduler_test.exs index 5b7e4c4..746d281 100644 --- a/test/jido/scheduler_test.exs +++ b/test/jido/scheduler_test.exs @@ -150,11 +150,7 @@ defmodule JidoTest.SchedulerTest do Scheduler.run_every( fn -> send(test_pid, {:worker_started, self()}) - - receive do - after - :infinity -> :ok - end + Process.sleep(:infinity) end, "* * * * * * *" ) diff --git a/test/jido/telemetry_test.exs b/test/jido/telemetry_test.exs index e52c800..80cf8d9 100644 --- a/test/jido/telemetry_test.exs +++ b/test/jido/telemetry_test.exs @@ -39,6 +39,17 @@ defmodule JidoTest.TelemetryTest do end end + defp with_logger_level(level, fun) when is_atom(level) and is_function(fun, 0) do + previous_level = Logger.level() + + try do + Logger.configure(level: level) + fun.() + after + Logger.configure(level: previous_level) + end + end + describe "setup/0" do test "attaches telemetry handlers idempotently" do assert :ok = Telemetry.setup() @@ -369,7 +380,7 @@ defmodule JidoTest.TelemetryTest do ) end - test "does not emit signal summary logs at the default info level" do + test "does not emit signal summary logs at the default warning level" do log = with_telemetry_env(:delete, fn -> capture_log(fn -> @@ -394,19 +405,21 @@ defmodule JidoTest.TelemetryTest do test "includes directive type summary in signal logs when debug logging is enabled" do log = with_telemetry_env([log_level: :debug], fn -> - capture_log(fn -> - assert :ok = - Telemetry.handle_event( - [:jido, :agent_server, :signal, :stop], - %{duration: 1_000}, - %{ - agent_id: "test", - signal_type: "test.signal", - directive_count: 2, - directive_types: %{"Emit" => 1, "Schedule" => 1} - }, - nil - ) + with_logger_level(:debug, fn -> + capture_log(fn -> + assert :ok = + Telemetry.handle_event( + [:jido, :agent_server, :signal, :stop], + %{duration: 1_000}, + %{ + agent_id: "test", + signal_type: "test.signal", + directive_count: 2, + directive_types: %{"Emit" => 1, "Schedule" => 1} + }, + nil + ) + end) end) end)