Trace option to ignore keepalive frames

Z/IP KeepAlive frames are fairly noisy and recording them is really only
useful for debugging the keepalives themselves. Keepalive frames can
quickly fill the trace buffer, especially in networks with many active
nodes.

This also makes a minor change to the default trace format to include the
expected delay field when printing nack+waiting Z/IP Packet frames.

lib/grizzly/trace.ex

@@ -22,6 +22,8 @@ defmodule Grizzly.Trace do
 
   alias Grizzly.Trace.Record
 
+  @type trace_opt :: {:name, atom()} | {:size, pos_integer()} | {:record_keepalives, boolean()}
+
   @type src() :: String.t()
   @type dest() :: String.t()
 
@@ -35,9 +37,10 @@ defmodule Grizzly.Trace do
   @doc """
   Start the trace server
   """
-  @spec start_link(keyword()) :: GenServer.on_start()
-  def start_link(args \\ []) do
-    GenServer.start_link(__MODULE__, args, name: __MODULE__)
+  @spec start_link([trace_opt()]) :: GenServer.on_start()
+  def start_link(opts \\ []) do
+    {name, opts} = Keyword.pop(opts, :name, __MODULE__)
+    GenServer.start_link(__MODULE__, opts, name: name)
   end
 
   @doc """
@@ -91,64 +94,86 @@ defmodule Grizzly.Trace do
   @doc """
   Add a record to the trace buffer.
   """
-  @spec log(binary(), [log_opt()]) :: :ok
-  def log(binary, opts \\ []) do
-    GenServer.cast(__MODULE__, {:log, binary, opts})
+  @spec log(GenServer.name(), binary(), [log_opt()]) :: :ok
+  def log(name, binary, opts) do
+    GenServer.cast(name, {:log, binary, opts})
   end
 
+  @doc "See `log/3`"
+  @spec log(binary(), [log_opt()]) :: :ok
+  def log(binary, opts \\ []) when is_binary(binary), do: log(__MODULE__, binary, opts)
+
   @doc """
   Reset the trace buffer.
   """
-  @spec clear() :: :ok
-  def clear() do
-    GenServer.call(__MODULE__, :clear)
+  @spec clear(GenServer.name()) :: :ok
+  def clear(name \\ __MODULE__) do
+    GenServer.call(name, :clear)
   end
 
   @doc """
   List all records in the trace buffer.
   """
-  @spec list() :: [Record.t()]
-  def list() do
-    GenServer.call(__MODULE__, :list)
+  @spec list(GenServer.name()) :: [Record.t()]
+  def list(name \\ __MODULE__) do
+    GenServer.call(name, :list)
   end
 
   @doc """
   Change the max size of the trace buffer from the default of #{@default_size}.
   """
-  @spec resize(pos_integer()) :: :ok
-  def resize(size) do
-    GenServer.call(__MODULE__, {:resize, size})
+  @spec resize(GenServer.name(), pos_integer()) :: :ok
+  def resize(name \\ __MODULE__, size) do
+    GenServer.call(name, {:resize, size})
+  end
+
+  @doc """
+  Enable or disable logging of keepalive frames.
+  """
+  @spec record_keepalives(GenServer.name(), boolean()) :: :ok
+  def record_keepalives(name \\ __MODULE__, enabled? \\ true) do
+    GenServer.call(name, {:record_keepalives, enabled?})
   end
 
   @impl GenServer
-  def init(_args) do
-    {:ok, CircularBuffer.new(@default_size)}
+  def init(opts) do
+    size = Keyword.get(opts, :size, @default_size)
+    record_keepalives = Keyword.get(opts, :record_keepalives, true)
+    {:ok, %{buffer: CircularBuffer.new(size), record_keepalives: record_keepalives}}
   end
 
   @impl GenServer
-  def handle_cast({:log, binary, opts}, records) do
+  def handle_cast({:log, <<0x23, 0x03, _ack_flag>>, _opts}, %{record_keepalives: false} = state) do
+    {:noreply, state}
+  end
+
+  def handle_cast({:log, binary, opts}, state) do
     record = Record.new(binary, opts)
 
-    {:noreply, CircularBuffer.insert(records, record)}
+    {:noreply, %{state | buffer: CircularBuffer.insert(state.buffer, record)}}
   end
 
   @impl GenServer
-  def handle_call(:clear, _from, %CircularBuffer{max_size: size} = _records) do
-    {:reply, :ok, CircularBuffer.new(size)}
+  def handle_call(:clear, _from, %{buffer: %CircularBuffer{max_size: size}} = state) do
+    {:reply, :ok, %{state | buffer: CircularBuffer.new(size)}}
+  end
+
+  def handle_call(:list, _from, %{buffer: buffer} = state) do
+    {:reply, CircularBuffer.to_list(buffer), state}
   end
 
-  def handle_call(:list, _from, records) do
-    {:reply, CircularBuffer.to_list(records), records}
+  def handle_call({:record_keepalives, enabled?}, _from, state) do
+    {:reply, :ok, %{state | record_keepalives: enabled?}}
   end
 
-  def handle_call({:resize, size}, _from, records) do
-    new_records =
-      records
+  def handle_call({:resize, size}, _from, %{buffer: buffer} = state) do
+    new_buffer =
+      buffer
       |> CircularBuffer.to_list()
       |> Enum.reduce(CircularBuffer.new(size), fn record, buffer ->
         CircularBuffer.insert(buffer, record)
       end)
 
-    {:reply, :ok, new_records}
+    {:reply, :ok, %{state | buffer: new_buffer}}
   end
 end

lib/grizzly/trace/record.ex

@@ -7,6 +7,7 @@ defmodule Grizzly.Trace.Record do
 
   alias Grizzly.{Trace, ZWave}
   alias Grizzly.ZWave.Command
+  alias Grizzly.ZWave.Commands.ZIPPacket
 
   @type t() :: %__MODULE__{
           timestamp: Time.t(),
@@ -76,6 +77,12 @@ defmodule Grizzly.Trace.Record do
     flag = Command.param!(zip_packet, :flag)
 
     cond do
+      flag == :nack_waiting ->
+        expected_delay = ZIPPacket.extension(zip_packet, :expected_delay, nil)
+
+        command_info_empty_response(seq_number, flag) <>
+          " expected_delay=#{inspect(expected_delay)}"
+
       flag in [:ack_response, :nack_response, :nack_waiting] ->
         command_info_empty_response(seq_number, flag)
 

test/grizzly/trace_test.exs

@@ -0,0 +1,138 @@
+defmodule Grizzly.TraceTest do
+  use ExUnit.Case, async: true
+
+  alias Grizzly.Trace
+  alias Grizzly.ZWave
+  alias Grizzly.ZWave.Commands.{SwitchBinaryGet, ZIPKeepAlive, ZIPPacket}
+
+  setup %{test: test} = ctx do
+    opts =
+      ctx
+      |> Map.take([:size, :record_keepalives])
+      |> Map.put(:name, test)
+      |> Enum.into([])
+
+    pid = start_supervised!({Trace, opts})
+    Map.put(ctx, :tracer, pid)
+  end
+
+  @tag size: 2
+  test "log/3", %{tracer: tracer} do
+    {:ok, cmd} = SwitchBinaryGet.new()
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 1)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 2)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), src: "src1", dest: "dest1")
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 3)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), src: "src2", dest: "dest2")
+
+    list = Trace.list(tracer)
+    assert length(list) == 2
+
+    assert [
+             %{binary: <<_::32, 2, _::binary>>, src: "src1", dest: "dest1"},
+             %{binary: <<_::32, 3, _::binary>>, src: "src2", dest: "dest2"}
+           ] = list
+  end
+
+  @tag size: 1
+  test "resize/2", %{tracer: tracer} do
+    {:ok, cmd} = SwitchBinaryGet.new()
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 1)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 2)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    list = Trace.list(tracer)
+    assert length(list) == 1
+
+    assert [%{binary: <<_::32, 2, _::binary>>}] = list
+
+    Trace.resize(tracer, 3)
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 3)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 4)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 5)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    list = Trace.list(tracer)
+    assert length(list) == 3
+
+    assert [
+             %{binary: <<_::32, 3, _::binary>>},
+             %{binary: <<_::32, 4, _::binary>>},
+             %{binary: <<_::32, 5, _::binary>>}
+           ] = list
+
+    Trace.resize(tracer, 2)
+
+    list = Trace.list(tracer)
+    assert length(list) == 2
+
+    assert [
+             %{binary: <<_::32, 4, _::binary>>},
+             %{binary: <<_::32, 5, _::binary>>}
+           ] = list
+  end
+
+  test "clear/1", %{tracer: tracer} do
+    {:ok, cmd} = SwitchBinaryGet.new()
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 1)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    {:ok, zip_packet} = ZIPPacket.with_zwave_command(cmd, 2)
+    Trace.log(tracer, ZWave.to_binary(zip_packet), [])
+
+    list = Trace.list(tracer)
+    assert length(list) == 2
+
+    Trace.clear(tracer)
+
+    list = Trace.list(tracer)
+    assert list == []
+  end
+
+  test "records keepalives by default", %{tracer: tracer} do
+    {:ok, keepalive} = ZIPKeepAlive.new(ack_flag: :ack_request)
+    Trace.log(tracer, ZWave.to_binary(keepalive), [])
+
+    {:ok, keepalive} = ZIPKeepAlive.new(ack_flag: :ack_response)
+    Trace.log(tracer, ZWave.to_binary(keepalive), [])
+
+    list = Trace.list(tracer)
+    assert length(list) == 2
+
+    assert [
+             %{binary: <<0x23, 0x03, 0x80>>},
+             %{binary: <<0x23, 0x03, 0x40>>}
+           ] = list
+  end
+
+  @tag record_keepalives: false
+  test "enable/disable keepalives", %{tracer: tracer} do
+    {:ok, keepalive} = ZIPKeepAlive.new(ack_flag: :ack_request)
+    Trace.log(tracer, ZWave.to_binary(keepalive), [])
+
+    list = Trace.list(tracer)
+    assert list == []
+
+    Trace.record_keepalives(tracer, true)
+    Trace.log(tracer, ZWave.to_binary(keepalive), [])
+
+    Trace.record_keepalives(tracer, false)
+    Trace.log(tracer, ZWave.to_binary(keepalive), [])
+
+    list = Trace.list(tracer)
+    assert [%{binary: <<0x23, 0x03, 0x80>>}] = list
+  end
+end