Pretty (Pretty v1.0.8) View Source

Inspect values with syntax colors despite your remote console.

This module addresses two surprises you'll encounter trying to dump data to the remote console like you did during development with iex -S mix:

  • IO.inspect/1 et al work fine at the iex> prompt but somehow not when called from a :telemetry handler function or other troubleshooting mechanism… unless you think to look at the log output

  • The syntax colors aren't working like you think they should, either

  • The inspection width is 80… just like iex, now that you think of it

Why? See the explanation.

In case of emergency, BREAK GLASS to get what you need with some copying and pasting.

Usage

To get the right syntax colors and inspection width, replace your calls to IO.inspect/1 with calls to Pretty.inspect/1:

Pretty.inspect(<<0, 1, 2>>, width: 40)

… and IO.inspect/2 with Pretty.inspect/2:

[1, 2, 3]
|> Pretty.inspect(label: "before")
|> Enum.map(&(&1 * 2))
|> Pretty.inspect(label: "after")
|> Enum.sum()

To get the right colors, width, and output device, use Pretty.bind/1 to get an inspector/1 function, and use it instead of IO.inspect/1 or Pretty.inspect/1:

dump = Pretty.bind(label: "Ecto")
handler = fn name, m10s, m6a, nil -> dump.({name, m10s, m6a}) end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

BREAK GLASS

If you're sitting at a remote console right now and just need some output without taking a new dependency and re-releasing, paste this in to get most of the functionality of Pretty.bind/1 right away:

bind = fn opts ->
  device = Process.group_leader()
  width = with {:ok, n} <- :io.columns(device), do: n, else: (_ -> %Inspect.Opts{}.width)
  opts = Keyword.merge(:rpc.call(:erlang.node(device), IEx.Config, :inspect_opts, []), opts)
  opts = Keyword.merge(opts, pretty: true, width: width)
  reset = Enum.find_value(Keyword.get(opts, :syntax_colors, []), [], fn _ -> IO.ANSI.reset() end)
  fn term -> IO.puts(device, [Kernel.inspect(term, opts), reset]); term end
end
# I never said it'd be Pretty...
# Can you make it shorter? PR or it didn't happen.

… and then use that:

dump = bind.(label: "ecto")
handler = fn name, m10s, m6a, nil -> dump.({name, m10s, m6a}) end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

What's going on? See the explanation.

Explanation

The Case of the Missing Output

Hooking up telemetry to Ecto.Adapters.SQL to watch your requests in action works from the iex -S mix phx.server prompt, but when you do it on a remote console you only see output for requests you made at the prompt:

handler = fn name, m10s, m6a, nil -> IO.inspect({name, m10s, m6a}, label: "Ecto") end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

To understand why, we need to look a little into how iex works at all.

Your shell is a process, started by IEx.Server.run/1. It evaluates the code you type in another process called an evaluator running code starting with IEx.Evaluator.init/4.

Input and output devices are also processes, sending and receiving messages according to the Erlang I/O Protocol. The Erlang documentation for :erlang.group_leader/0 says:

Every process is a member of some process group and all groups have a group leader. All I/O from the group is channeled to the group leader.

It doesn't say how the I/O from the group is channeled, but it's pretty simple: any function doing I/O will end up with some lower level function looking up your group leader and using it as the device if a specific device wasn't given.

Sometimes this is direct: :io.put_chars/1 calls :erlang.group_leader/0 and gives it as the first argument to :io.put_chars/2. :io.request/1 similarly calls :io.request/2 with the group leader.

Most of the time, though, it's indirect. I/O from almost everywhere else in OTP arrives at :io.request/2 (and, rarely, :io.requests/2) with an atom as its first argument. If that atom is :standard_io, it's replaced with the group leader. If not, the device is looked up by name in the process registry with :erlang.whereis/1.

In Elixir, IO.puts/2 maps its device argument from :stdio to Erlang's :standard_io, :stderr to :standard_error, leaves other device arguments alone, and calls :io.put_chars/2 which proceeds as above.

Given the above, these calls do the same thing:

:io.put_chars('pretty!\\n')
:io.put_chars(:erlang.group_leader(), 'pretty!\\n')
:io.put_chars(:standard_io, 'pretty!\\n')
IO.puts("pretty!")
IO.puts(:stdio, "pretty!")
IO.puts(:standard_io, "pretty!")
IO.puts(Process.group_leader(), "pretty!")

Back to our "missing" output, consider what happens when you send I/O to various device aliases while your group leader is set to device other than your terminal. Paste this code into the iex prompt:

test_output = fn device -> IO.puts(device, ["output to ", Kernel.inspect(device)]) end

run_experiments = fn ->
  {:ok, dev_null} = File.open("/dev/null", [:read, :write])
  group_leader = Process.group_leader()

  try do
    Process.group_leader(self(), dev_null)

    [:stdio, :standard_io, :stderr, :standard_error, :user]
    |> Enum.map(fn device -> {device, test_output.(device)} end)
    |> Enum.into(%{})
  after
    Process.group_leader(self(), group_leader)
    File.close(dev_null)
  end
end

run_experiments |> Task.async() |> Task.await()

At the iex prompt, you'll see output for :stderr, :standard_error, and :user but not for :dev_null, stdio, or :standard_io despite the result showing IO.puts/2 returned :ok every time.

The same is happening when Ecto.Adapters.SQL calls :telemetry.execute/3:

  • Your telemetry handler is run in the same process that ran the query — often, it's

  • handling the request end-to-end including Plug and Phoenix and Absinthe

  • Your handler's call to IO.inspect/2 gets the default device :stdio

  • That default gets resolved to the request's group leader

  • Your output ends up in the node's standard output

  • At the iex -S mix phx.server prompt, your shell is on the same node and you can't see the difference, setting up the surprise for when you use a remote shell

To send the telemetry inspection to your remote console, capture your group leader outside the handler and write to it explicitly from inside the handler:

device = Process.group_leader()
handler = fn name, m10s, m6a, nil ->
  IO.inspect(device, {name, m10s, m6a}, label: "Ecto")
end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

You can almost get it down to a one-liner if you lose the label:

dev = Process.group_leader()
:telemetry.attach(self(), [:my_app, :repo, :query], &IO.inspect(&4, {&1, &2, &3}, []), dev)

The Case of the Missing Colors

Trying to read pages of data structures without syntax coloring is hard. Where'd the colors go?

Let's check which nodes are running our shell and its evaluator when we run iex:

iex> self() |> :erlang.node()
:nonode@nohost

iex> :erlang.group_leader() |> :erlang.node()
:nonode@nohost

… and again when we run _build/dev/rel/my_app/bin/my_app remote:

iex> self() |> :erlang.node()
:"my_app@127.0.0.1"

iex> :erlang.group_leader() |> :erlang.node()
:"rem-b987-my_app@127.0.0.1"

If the latter is less colorful than the former, it's because:

  • Your remote shell called IEx.Config.inspect_opts/0 from a process on :"my_app@127.0.0.1", not the hidden node running the other end of your shell

  • IEx.Config.color/1 fell through to IO.ANSI.enabled?/0 because you didn't config :iex

  • ANSI wasn't enabled because your application node had its output redirected at startup

To put some color into your telemetry inspection, get the inspection options from your hidden node with :rpc.call/4. Extending our example above:

device = Process.group_leader()
opts = device |> :erlang.node() |> :rpc.call(IEx.Config, :inspect_opts, [])
opts = Keyword.merge(opts, pretty: true, label: "Ecto")
handler = fn name, m10s, m6a, nil ->
IO.puts(device, [Kernel.inspect({name, m10s, m6a}, opts), IO.ANSI.reset()])
end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

You'll need the IO.ANSI.reset/0 result to avoid the yellow reset handling numbers and functions for you also bleeding through to your prompt.

The Case of the Fixed Width

IEx.Config.width/0 returns the minimum of:

  • Your console's width
  • Application.get_env(:iex, :width, 80)

To inspect at your console's full width, measure it outside your handler with io.columns/1. Extending our example again:

device = Process.group_leader()
opts = device |> :erlang.node() |> :rpc.call(IEx.Config, :inspect_opts, [])
{:ok, width} = :io.columns(device)
opts = Keyword.merge(opts, pretty: true, width: width, label: "Ecto")
handler = fn name, m10s, m6a, nil ->
IO.puts(device, [Kernel.inspect({name, m10s, m6a}, opts), IO.ANSI.reset()])
end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

We've done it! All three problems, solved… until you run them from a console for which io.columns/1 returns {:error, :enotsup}, or for which ANSI is genuinely not available and the reset will pollute your output. Go ahead, fix those; I'll wait right here.

(Y'know, you could cheat. Just sayin'.)

The Case of Great Relief

To get the right colors, width, and output device, use Pretty.bind/1 to get a Pretty.inspector/1 function:

dump = Pretty.bind(label: "Ecto")

Use that function instead of IO.inspect/1 or Pretty.inspect/1. Our Ecto.Adapters.SQL example becomes:

dump = Pretty.bind(label: "Ecto")
handler = fn name, m10s, m6a, nil -> dump.({name, m10s, m6a}) end
:telemetry.attach(self(), [:my_app, :repo, :query], handler, nil)

Link to this section Summary

Types

Keyword options supported by IO.inspect/2.

A 1-ary inspection function returning its argument unchanged e.g. IO.inspect/1.

Functions

Bind an inspection function to the current standard output.

Bind an inspection function to a particular device.

Inspect an item, writing the report to the standard output. Return the item unchanged.

Inspect an item, writing the report to a device. Return the item unchanged.

Link to this section Types

Specs

inspect_opts() :: keyword()

Keyword options supported by IO.inspect/2.

Specs

inspector(item) :: (item -> item)

A 1-ary inspection function returning its argument unchanged e.g. IO.inspect/1.

Link to this section Functions

Specs

bind(inspect_opts()) :: inspector(any())

Bind an inspection function to the current standard output.

See bind/2 for more details.

Specs

bind(IO.device(), inspect_opts()) :: inspector(any())

Bind an inspection function to a particular device.

The inspector's device and options are resolved when bind/2 is called, not when the inspector is called. If you bind at the remote console prompt, the device and options will remain appropriate for your console no matter which process calls the inspector.

See inspect/3 for details on option handling.

Link to this function

inspect(item, opts \\ [])

View Source

Specs

inspect(item, inspect_opts()) :: item when item: var

Inspect an item, writing the report to the standard output. Return the item unchanged.

Like IO.inspect/2, but with pretty defaults appropriate to the device.

See inspect/3 for details on option handling.

Link to this function

inspect(device, item, opts)

View Source

Specs

inspect(IO.device(), item, inspect_opts()) :: item when item: var

Inspect an item, writing the report to a device. Return the item unchanged.

Like IO.inspect/3, but with pretty defaults appropriate to the device:

  • Set pretty to true
  • Set width according to the device's :io.columns/1 if possible, else the Inspect.Opts default of 80
  • Set syntax_colors according to the device node's IEx.Config.inspect_opts/1