Debugging KV live · Elixir by Example

A user reports that KV ignores updates: they set a key, set it again, and still read the first value. The node is running in production. You could add logging, build, deploy and wait for it to happen again. On the BEAM you can instead look inside the running node, find the bug, and fix it there, without a restart and without losing the data in memory.

This step runs KV with that bug and fixes it live:

Reproduce the report against the running node with rpc.
Look at the state of the replica process with :sys.get_state/1.
Trace the replica while one update happens, to see what it receives and what it does with it.
Patch the running code: compile the fixed module into the node. The replica keeps its state and starts using the new code at once.

The project

KV from step 12, with one line changed: handle_call/3 for :put uses Map.put_new/3, which only adds keys that aren't there yet. That's the bug.

mix.exs

defmodule KV.MixProject do
  use Mix.Project

  def project do
    [app: :kv, version: "0.1.0", elixir: "~> 1.20", deps: deps()]
  end

  def application do
    [mod: {KV.Application, []}]
  end

  defp deps do
    [{:libcluster, "~> 3.4"}]
  end
end

mix.lock

%{
  "jason": {:hex, :jason, "1.4.5", "2e3a008590b0b8d7388c20293e9dcc9cf3e5d642fd2a114e4cbbb52e595d940a", [:mix], [{:decimal, "~> 1.0 or ~> 2.0 or ~> 3.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "b0c823996102bcd0239b3c2444eb00409b72f6a140c1950bc8b457d836b30684"},
  "libcluster": {:hex, :libcluster, "3.6.0", "06085e9f67f78783608b81c89a62fa974d846f0b79569da4742441e57e4ca480", [:mix], [{:jason, "~> 1.1", [hex: :jason, repo: "hexpm", optional: false]}, {:telemetry, "~> 1.3", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "02b56995b57a38e12040d4ab0ce1bd20bece53d460970e665aa5c89b82a5b455"},
  "telemetry": {:hex, :telemetry, "1.4.2", "a0cb522801dffb1c49fe6e30561badffc7b6d0e180db1300df759faa22062855", [:rebar3], [], "hexpm", "928f6495066506077862c0d1646609eed891a4326bee3126ba54b60af61febb1"},
}

config/runtime.exs

import Config

# The nodes to cluster with, read when each node boots:
# CLUSTER_NODES=kv_a@127.0.0.1,kv_b@127.0.0.1
nodes =
  System.fetch_env!("CLUSTER_NODES")
  |> String.split(",", trim: true)
  |> Enum.map(&String.to_atom/1)

config :kv, cluster_nodes: nodes

lib/kv/application.ex

defmodule KV.Application do
  use Application

  @impl true
  def start(_type, _args) do
    hosts = Application.fetch_env!(:kv, :cluster_nodes)
    topologies = [kv: [strategy: Cluster.Strategy.Epmd, config: [hosts: hosts, timeout: 500]]]

    children = [
      %{id: :pg, start: {:pg, :start_link, []}},
      {Cluster.Supervisor, [topologies, [name: KV.ClusterSupervisor]]},
      KV.Replica
    ]

    Supervisor.start_link(children, strategy: :one_for_one, name: KV.Supervisor)
  end
end

lib/kv/replica.ex

defmodule KV.Replica do
  @moduledoc "One replica of the store; every write goes to all of them (step 8)."
  use GenServer

  def start_link(_opts), do: GenServer.start_link(__MODULE__, %{}, name: __MODULE__)

  def put(key, value) do
    for replica <- :pg.get_members(:kv_replicas) do
      :ok = GenServer.call(replica, {:put, key, value})
    end

    :ok
  end

  def get(key), do: GenServer.call(__MODULE__, {:get, key})

  @doc "How many replicas this node can see."
  def count, do: length(:pg.get_members(:kv_replicas))

  @impl true
  def init(map) do
    :ok = :pg.join(:kv_replicas, self())
    {:ok, map}
  end

  @impl true
  def handle_call({:put, k, v}, _from, map), do: {:reply, :ok, Map.put_new(map, k, v)}
  def handle_call({:get, k}, _from, map), do: {:reply, Map.get(map, k), map}
end

Start it

One node is enough. As in step 12, the environment names it; here the cluster is just itself.

$ mix deps.get > /dev/null
$ MIX_ENV=prod mix release --quiet > /dev/null
$ export RELEASE_DISTRIBUTION=name RELEASE_NODE=kv_live@127.0.0.1 CLUSTER_NODES=kv_live@127.0.0.1
$ kv() { _build/prod/rel/kv/bin/kv "$@"; }
$ kv daemon
$ until kv pid > /dev/null 2>&1; do sleep 0.1; done

1. Reproduce

$ kv rpc 'KV.Replica.put("lang", "elixir")'
$ kv rpc 'KV.Replica.put("lang", "erlang")'
$ kv rpc 'IO.inspect(KV.Replica.get("lang"), label: "lang")'

lang: "elixir"

2. Look at the state

:sys.get_state/1 asks any OTP process (GenServer, Agent, Supervisor...) for its current state. The replica holds the old value, so get isn't the problem: the update never landed.

$ kv rpc 'IO.inspect(:sys.get_state(KV.Replica), label: "replica state")'

replica state: %{"lang" => "elixir"}

3. Trace one update

A small script, run inside the node with Code.eval_file/1, traces the replica's handle_call/3 (see Tracing) while it makes one put, and prints what came in and what state went out.

debug/trace_put.exs

# Run inside the live node: traces the replica's handle_call/3 while one
# put happens, then prints what the replica received and what it returned.
session = :trace.session_create(:debug_put, self(), [])
replica = Process.whereis(KV.Replica)
:trace.process(session, replica, true, [:call])
:trace.function(session, {KV.Replica, :handle_call, 3}, [{:_, [], [{:return_trace}]}], [])

KV.Replica.put("lang", "erlang")

ref = :trace.delivered(session, replica)

receive do
  {:trace_delivered, ^replica, ^ref} -> :ok
end

receive do
  {:trace, ^replica, :call, {_mod, _fun, [message, _from, state]}} ->
    IO.inspect(message, label: "received")
    IO.inspect(state, label: "state before")
end

receive do
  {:trace, ^replica, :return_from, _mfa, {:reply, _reply, new_state}} ->
    IO.inspect(new_state, label: "state after")
end

:trace.session_destroy(session)

$ kv rpc 'Code.eval_file("debug/trace_put.exs")'

received: {:put, "lang", "erlang"}
state before: %{"lang" => "elixir"}
state after: %{"lang" => "elixir"}

The message arrives with the new value, and the state comes back unchanged. The bug is in the :put clause of handle_call/3: Map.put_new/3 should be Map.put/3.

4. Patch the running node

The fix is one line, in a copy of the module:

patch/replica.ex

defmodule KV.Replica do
  @moduledoc "One replica of the store; every write goes to all of them (step 8)."
  use GenServer

  def start_link(_opts), do: GenServer.start_link(__MODULE__, %{}, name: __MODULE__)

  def put(key, value) do
    for replica <- :pg.get_members(:kv_replicas) do
      :ok = GenServer.call(replica, {:put, key, value})
    end

    :ok
  end

  def get(key), do: GenServer.call(__MODULE__, {:get, key})

  @doc "How many replicas this node can see."
  def count, do: length(:pg.get_members(:kv_replicas))

  @impl true
  def init(map) do
    :ok = :pg.join(:kv_replicas, self())
    {:ok, map}
  end

  @impl true
  def handle_call({:put, k, v}, _from, map), do: {:reply, :ok, Map.put(map, k, v)}
  def handle_call({:get, k}, _from, map), do: {:reply, Map.get(map, k), map}
end

Compiling that file inside the node loads the new version of KV.Replica (see Hot Code Loading). The replica is a GenServer, and OTP's loop calls handle_call/3 with a fully qualified call, so the very next request runs the new code. The state, with every key in it, is untouched. Redefining a module normally warns; here it's the point, so the warning is switched off.

$ kv rpc 'Code.put_compiler_option(:ignore_module_conflict, true); Code.compile_file("patch/replica.ex")'
$ kv rpc 'KV.Replica.put("lang", "erlang")'
$ kv rpc 'IO.inspect(KV.Replica.get("lang"), label: "lang")'

lang: "erlang"

$ kv stop

Pitfall: a live patch exists only in that node's memory. A restart, a new pod, or the next deploy brings the bug back. Treat it as first aid: put the same fix in the code, build a release and deploy it.

Pitfall: rpc and remote give whoever runs them full control of the node, the same power that fixed this bug. Guard that access as carefully as production database credentials.

Pitfall: :sys.get_state/1 copies the whole state to the caller, and waits for the process to answer. On a process with a huge state, or one that is stuck, it can be slow or time out. Ask for what you need, and give it a timeout (:sys.get_state(pid, 1_000)).

Go deeper: The BEAM Book by Erik Stenman has chapters on debugging (18), tracing (19) and connecting to a live system (17).