Pipes, dbg/2 and debugging in IEx

Enum.uniq(Enum.map(String.split(String.downcase(String.trim(text)), ","), &String.trim/1)) cleans a list of cities in five steps, and it reads from the inside out: the first step is the call in the middle. The pipe operatorpipe operator: |>, which passes the value on its left as the first argument of the call on its right: text |> String.trim() is String.trim(text), so nested calls can be written as steps from top to bottom. |> writes the same five steps from top to bottom, one a line, and once every step is a line of its own, Elixir can print each step’s value for you.

Below, you will write pipelines with |>, then/2 and tap/2, print values along the way with IO.inspect/2 and dbg/2, keep colour codes out of your logs, stop a running function in IEx and step through it line by line, and pick the right tool for what you need to see. The sessions come from Elixir 1.20.4, built for Erlang/OTP 29.1.1.

The pipe passes each result on as the first argument

a |> f(b) is f(a, b): the Kernel documentation says the pipe puts the value on its left “as the first argument to the function call on the right-hand side”. This script cleans one line of city names both ways:

# The same five steps, written inside out and as a pipeline.
text = " Pune,Agra , pune "

nested = Enum.uniq(Enum.map(String.split(String.downcase(String.trim(text)), ","), &String.trim/1))
IO.inspect(nested, label: "nested")

piped =
  text
  |> String.trim()
  |> String.downcase()
  |> String.split(",")
  |> Enum.map(&String.trim/1)
  |> Enum.uniq()

IO.inspect(piped, label: "piped")

from session import run

run("""
elixir pipe.exs
""")

$ elixir pipe.exs
nested: ["pune", "agra"]
piped: ["pune", "agra"]

Both gave ["pune", "agra"]. The pipeline lists the steps in the order they happen, and an argument such as "," stays next to the function it belongs to, instead of ending up three closing brackets later. Step through what each line hands to the next:

Each step’s value became the first argument of the next call, ahead of the arguments written in its brackets. That is why pipelines suit Elixir’s libraries: String, Enum and Map take the data they work on as their first argument.

then/2 and tap/2 handle the other positions and side effects

Two Kernel functions fill the gaps of the pipe. then/2 “pipes the first argument, value, into the second argument, a function fun, and returns the result of calling fun”, so it handles a step where the value is not the first argument, or where the step is a function you hold. tap/2 calls the function too but “returns value itself”, so it suits a side effect such as a log line in the middle of a pipeline:

# then/2 for a step whose value is not the first argument; tap/2 for a side effect that keeps the value.
summary =
  [" Pune", "Agra ", " pune"]
  |> Enum.map(&String.trim/1)
  |> tap(fn names -> IO.puts("cleaned #{length(names)} names") end)
  |> Enum.uniq_by(&String.downcase/1)
  |> then(fn names -> %{cities: names, count: length(names)} end)

IO.inspect(summary)

# A function held in a name is piped into with a dot, or through then/2.
shout = fn text -> String.upcase(text) end
IO.puts("pune" |> shout.())
IO.puts("agra" |> then(shout))

from session import run, shell

run("""
elixir then_tap.exs
""")

# Piping into the name of a function value, without a dot or then/2.
shell([
    "shout = fn text -> String.upcase(text) end",
    "\"pune\" |> shout",
    "System.halt()",
])

$ elixir then_tap.exs
cleaned 3 names
%{count: 2, cities: ["Pune", "Agra"]}
PUNE
AGRA
$ iex
Erlang/OTP 29 [erts-17.1] [source] [64-bit] [smp:18:18] [ds:18:18:10] [async-threads:1] [jit]

Interactive Elixir (1.20.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> shout = fn text -> String.upcase(text) end
#Function<42.130099583/1 in :erl_eval.expr/6>
iex(2)> "pune" |> shout
error: undefined function shout/1 (there is no such import)
└─ iex:2

** (CompileError) cannot compile code (errors have been logged)

iex(2)> System.halt()

tap/2 printed “cleaned 3 names” and passed the three names on unchanged, so Enum.uniq_by/2 still got all three and kept “Pune” and “Agra”. then/2 built a map around the list, a value no function of Enum returns, and the pipeline’s result is that map. The last two lines piped into the function held in shout, once with .() and once through then/2. Typed into IEx without either, "pune" |> shout did not compile: “undefined function shout/1”.

IO.inspect/2 with a label prints a value and returns it

The simplest way to see inside a pipeline is to print what passes through it. The debugging guide points out that IO.inspect/2 returns its argument “without affecting the behavior of the original code”, so it can sit between any two steps, and its label option names each printout:

# IO.inspect/2 prints a value with a label and returns it, so it can sit between two steps.
" Pune,Agra , pune "
|> String.trim()
|> String.split(",")
|> IO.inspect(label: "after split")
|> Enum.map(&String.trim/1)
|> IO.inspect(label: "after trim")
|> Enum.uniq()
|> IO.inspect(label: "result")

from session import run

run("""
elixir inspect_steps.exs
""")

$ elixir inspect_steps.exs
after split: ["Pune", "Agra ", " pune"]
after trim: ["Pune", "Agra", "pune"]
result: ["Pune", "Agra", "pune"]

The labels show where the value changed. After String.split/2 the list held “Agra “ with a space and “ pune” with one in front; after Enum.map/2 both were trimmed. And the result kept “Pune” and “pune” side by side: this version has no String.downcase/1, which the printout makes plain at a glance. Remove the inspects once you have found what you were looking for: each one is a line of output in every run, tests included.

dbg/2 prints the code and the value of every step

dbg/2 at the end of a pipeline prints each step’s code next to the value it produced, with the file and line at the top: the debugging guide says it prints values “at every step of the pipeline”. The session runs it, then shows the bytes it wrote through cat -v, which turns the escape character of each colour code into the visible ^[:

# dbg/2 at the end of a pipeline prints the code of every step and the value it gave.
" Pune,Agra , pune "
|> String.trim()
|> String.downcase()
|> String.split(",")
|> Enum.map(&String.trim/1)
|> Enum.uniq()
|> dbg()

# The same pipeline, with dbg/2 told to print no colour codes.
" Pune,Agra , pune "
|> String.trim()
|> String.downcase()
|> String.split(",")
|> Enum.map(&String.trim/1)
|> Enum.uniq()
|> dbg(syntax_colors: [])

from session import run

# The first run as a terminal shows it; then the bytes dbg/2 wrote, through cat -v, which shows the escape
# character of each colour code as ^[; then the bytes IO.inspect/2 wrote, for comparison.
run("""
elixir pipeline_dbg.exs
elixir pipeline_dbg.exs | cat -v | head -3
NO_COLOR=1 elixir pipeline_dbg.exs | cat -v | head -3
elixir inspect_steps.exs | cat -v | head -1
elixir pipeline_plain.exs | cat -v | head -3
""")

$ elixir pipeline_dbg.exs
[pipeline_dbg.exs:8: (file)]
" Pune,Agra , pune " #=> " Pune,Agra , pune "
|> String.trim() #=> "Pune,Agra , pune"
|> String.downcase() #=> "pune,agra , pune"
|> String.split(",") #=> ["pune", "agra ", " pune"]
|> Enum.map(&String.trim/1) #=> ["pune", "agra", "pune"]
|> Enum.uniq() #=> ["pune", "agra"]
$ elixir pipeline_dbg.exs | cat -v | head -3
^[[36m^[[3m[pipeline_dbg.exs:8: (file)]^[[0m
^[[0m" Pune,Agra , pune "^[[2m #=>^[[0m " Pune,Agra , pune "
^[[0m^[[2m|> ^[[0mString.trim()^[[2m #=>^[[0m "Pune,Agra , pune"
$ NO_COLOR=1 elixir pipeline_dbg.exs | cat -v | head -3
^[[36m^[[3m[pipeline_dbg.exs:8: (file)]^[[0m
^[[0m" Pune,Agra , pune "^[[2m #=>^[[0m " Pune,Agra , pune "
^[[0m^[[2m|> ^[[0mString.trim()^[[2m #=>^[[0m "Pune,Agra , pune"
$ elixir inspect_steps.exs | cat -v | head -1
after split: ["Pune", "Agra ", " pune"]
$ elixir pipeline_plain.exs | cat -v | head -3
[pipeline_plain.exs:8: (file)]
" Pune,Agra , pune " #=> " Pune,Agra , pune "
|> String.trim() #=> "Pune,Agra , pune"

The first run is what you read: one line per step, #=> and the value, and the two spellings of Pune merging at String.downcase(). The second shows what a file or a CI log receives from the same run: colour codes such as ^[[36m on every line, although the output went into a pipe and not to a terminal. NO_COLOR=1 changed nothing, while IO.inspect/2, run through the same cat -v, wrote no codes at all. dbg(syntax_colors: []), in the last run, wrote plain text: the Kernel documentation says the options of dbg/2 are the options of inspect/2, and :syntax_colors is the one that sets the colours of the printed code and values.

IEx can stop a running function: break! and IEx.pry

Printing tells you what happened. Sometimes you need the program to stop where it is, so that you can look around. IEx can do that for code it runs, which is why the session starts IEx with the project loaded, iex -S mix. break! Report.total/1 sets a breakpointbreakpoint: A place where running code stops so that you can look at its values. In IEx, break! Module.fun/arity sets one without changing the code; next runs one more line and continue lets the code finish. without changing the code; IEx.pry/0, written into the code, stops at its own line:

defmodule Report do
  def total(orders) do
    paid = Enum.filter(orders, & &1.paid)
    amounts = Enum.map(paid, & &1.amount)
    Enum.sum(amounts)
  end
end

defmodule Audit do
  require IEx

  def check(orders) do
    unpaid = Enum.reject(orders, & &1.paid)
    IEx.pry()
    length(unpaid)
  end
end

from session import run, shell

# source/1, new in Elixir 1.20, says where a function is defined. break! stops Report.total/1 without changing its code; next goes on one line at a time, continue to the end.
# Then IEx.pry/0, written into Audit.check/1, stops it at that line. Last, the same pry outside IEx.
run("""
cd report
""")
shell([
    "source Report.total/1",
    "break! Report.total/1",
    "Report.total([%{paid: true, amount: 300}, %{paid: false, amount: 50}, %{paid: true, amount: 120}])",
    "orders",
    "next",
    "paid",
    "next",
    "amounts",
    "continue",
    "breaks",
    "Audit.check([%{paid: true, amount: 300}, %{paid: false, amount: 50}])",
    "binding()",
    "continue",
    "System.halt()",
], command="iex -S mix")
run("""
mix run -e 'IO.inspect(Audit.check([%{paid: false, amount: 50}]))'
""")

$ cd report
$ iex -S mix
Erlang/OTP 29 [erts-17.1] [source] [64-bit] [smp:18:18] [ds:18:18:10] [async-threads:1] [jit]

Compiling 2 files (.ex)
Generated report app
Interactive Elixir (1.20.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> source Report.total/1
lib/report.ex:2
iex(2)> break! Report.total/1
1
iex(3)> Report.total([%{paid: true, amount: 300}, %{paid: false, amount: 50}, %{paid: true, amount: 120}])
Break reached: Report.total/1 (lib/report.ex:3)

    1: defmodule Report do
    2:   def total(orders) do
    3:     paid = Enum.filter(orders, & &1.paid)
    4:     amounts = Enum.map(paid, & &1.amount)
    5:     Enum.sum(amounts)
    6:   end

iex(4)> orders
[
  %{paid: true, amount: 300},
  %{paid: false, amount: 50},
  %{paid: true, amount: 120}
]
iex(5)> next
Break reached: Report.total/1 (lib/report.ex:4)

    1: defmodule Report do
    2:   def total(orders) do
    3:     paid = Enum.filter(orders, & &1.paid)
    4:     amounts = Enum.map(paid, & &1.amount)
    5:     Enum.sum(amounts)
    6:   end
    7: end

iex(6)> paid
[%{paid: true, amount: 300}, %{paid: true, amount: 120}]
iex(7)> next
Break reached: Report.total/1 (lib/report.ex:5)

    2:   def total(orders) do
    3:     paid = Enum.filter(orders, & &1.paid)
    4:     amounts = Enum.map(paid, & &1.amount)
    5:     Enum.sum(amounts)
    6:   end
    7: end

iex(8)> amounts
[300, 120]
iex(9)> continue
420
** (EXIT from #PID<0.175.0>) shell process exited with reason: normal

Interactive Elixir (1.20.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(9)> breaks

 ID   Module.function/arity   Pending stops
---- ----------------------- ---------------
 1    Report.total/1          0

iex(10)> Audit.check([%{paid: true, amount: 300}, %{paid: false, amount: 50}])
Break reached: Audit.check/1 (lib/audit.ex:6)

    3:
    4:   def check(orders) do
    5:     unpaid = Enum.reject(orders, & &1.paid)
    6:     IEx.pry()
    7:     length(unpaid)
    8:   end
    9: end

iex(11)> binding()
[
  orders: [%{paid: true, amount: 300}, %{paid: false, amount: 50}],
  unpaid: [%{paid: false, amount: 50}]
]
iex(12)> continue
1
** (EXIT from #PID<0.177.0>) shell process exited with reason: normal

Interactive Elixir (1.20.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(12)> System.halt()
$ mix run -e 'IO.inspect(Audit.check([%{paid: false, amount: 50}]))'
Cannot pry #PID<0.101.0> at Audit.check/1 (lib/audit.ex:6). Is an IEx shell running?
1

source Report.total/1, new in Elixir 1.20, printed where the function is defined. The call then stopped before line 3 with “Break reached”, and the prompt evaluated in the function’s own bindings: orders showed its argument. next ran one line and stopped before the next, so paid and then amounts could be read, and continue let it finish with 420. The ** (EXIT …) line and the new banner after it are no failure: the stop ran in the shell’s own process, and the IEx documentation says a new IEx session is started when that process ends. breaks listed breakpoint 1 with no stops left: the IEx documentation says a breakpoint stops once by default, and break! Report.total/1, 10 stops ten times. Follow the five commands:

Audit.check/1 stopped at its IEx.pry() line, and binding() listed orders and unpaid. Both stops worked at once because the code ran in the shell’s own process; when another process reaches a breakpoint or IEx.pry/0, such as a request handled by a server started from IEx, IEx first asks whether you allow it to pry. Outside IEx, in the last command, IEx.pry/0 printed “Cannot pry … Is an IEx shell running?” and the code ran on: a forgotten pry does not stop a program, it only prints.

Choose the tool by what you need to see

The four tools overlap. Three questions decide most cases: does the code run in a shell you can type into, may you change the code, and must it stop? Answer them for the bug in front of you:

In short: IO.inspect/2 with a label for one value in any run, dbg/2 for every step of a pipeline, with syntax_colors: [] when the output goes to a log, break! when the code must stop and you would rather not touch it, and IEx.pry/0 when you want it to stop at one exact line every time. The debugging guide adds iex --dbg pry, which turns every dbg/2 call into a place where IEx offers to pry.

Practise: a pipeline that keeps its output

Report.build/1 turns a list of orders into a text report: one line per paid order, “CITY: amount”, the largest first. It works, but it is written as nested calls. Rewrite it as a pipeline of at least three steps without changing what it returns. The first three tests check the output, which the starter already gets right, and the last reads the file and counts the pipes. Copy the two files into an empty folder:

defmodule Report do
  @moduledoc "A text report of the paid orders, largest first."

  @doc """
  One line per paid order, "CITY: amount", the largest amount first, joined with newlines. Orders are maps with
  :city, :amount and :paid. Rewrite the body as a pipeline: the tests check that its output does not change.
  """
  def build(orders) do
    Enum.join(Enum.map(Enum.sort(Enum.filter(orders, & &1.paid), &(&1.amount >= &2.amount)), &line/1), "\n")
  end

  defp line(order), do: String.upcase(String.trim(order.city)) <> ": " <> Integer.to_string(order.amount)
end

Code.require_file("report.ex", __DIR__)
ExUnit.start(seed: 0)

defmodule ReportTest do
  use ExUnit.Case

  @orders [
    %{city: " Pune", amount: 1_200, paid: true},
    %{city: "agra ", amount: 3_400, paid: true},
    %{city: "Nagpur", amount: 9_000, paid: false}
  ]

  test "paid orders only, the largest first" do
    assert Report.build(@orders) == "AGRA: 3400\nPUNE: 1200"
  end

  test "a report of no paid orders is empty" do
    assert Report.build([]) == ""
    assert Report.build([%{city: "Kochi", amount: 500, paid: false}]) == ""
  end

  test "one paid order is one line" do
    assert Report.build([%{city: "kochi", amount: 500, paid: true}]) == "KOCHI: 500"
  end

  test "build/1 is a pipeline of at least three steps" do
    {:ok, ast} = Code.string_to_quoted(File.read!(Path.join(__DIR__, "report.ex")))
    {_ast, pipes} = Macro.prewalk(ast, 0, fn
      {:|>, _meta, _args} = node, count -> {node, count + 1}
      node, count -> {node, count}
    end)

    assert pipes >= 3
  end
end

Run elixir report_test.exs. The output tests pass and the pipeline test fails, with 0 pipes counted:

from session import run

# The tests against the starter: its output is right, but it is not a pipeline yet.
run("""
cd practice
!elixir report_test.exs
""")

$ cd practice
$ elixir report_test.exs
Running ExUnit with seed: 0, max_cases: 36

...

  1) test build/1 is a pipeline of at least three steps (ReportTest)
     report_test.exs:26
     Assertion with >= failed
     code:  assert pipes >= 3
     left:  0
     right: 3
     stacktrace:
       report_test.exs:33: (test)


Finished in 0.03 seconds (0.02s on load, 0.00s async, 0.01s sync)

Result: 3/4 passed
Failed: 1 test
[exit status 2]

Read the nested call from the inside out and write each call as a line: start with orders, then Enum.filter/2, Enum.sort/2 with the same comparison, Enum.map/2 and Enum.join/2, each without its first argument, which the pipe now supplies. Keep the functions and their other arguments exactly as they were: the output tests are what prove that the behaviour did not change. A finished version passes all four:

from session import run

# The same tests against the pipeline version.
run("""
cd finished
cp ../practice/report_test.exs .
elixir report_test.exs
""")

$ cd finished
$ cp ../practice/report_test.exs .
$ elixir report_test.exs
Running ExUnit with seed: 0, max_cases: 36

....
Finished in 0.02 seconds (0.02s on load, 0.00s async, 0.00s sync)

Result: 4 passed

To close, a short self-check on pipes, then/2 and tap/2, inspecting, dbg/2, stopping code and choosing a tool. Your weakest idea comes first, and every answer is explained right away:

Interview questions

Warm-up: what does the pipe operator do in Elixir, and when do you use then/2?

|> takes the value on its left and passes it as the first argument of the call on its right, so text |> String.trim() |> String.split(",") is String.split(String.trim(text), ","), written in the order the steps happen. It fits Elixir’s libraries because String, Enum and Map take the data they work on first. When a step needs the value somewhere else, or the step is a function held in a name, use then/2: it calls the function with the value and returns its result, as in |> then(fn names -> %{cities: names} end). tap/2 is its partner for side effects: it calls the function, such as a log line, and passes the value on unchanged. "pune" |> shout fails to compile when shout holds a function; write shout.() or then(shout).

Two questions from debugging real code:

Key takeaways

• a |> f(b) is f(a, b): a pipeline writes nested calls in the order they run, with each step’s value passed on as the first argument.
• then/2 returns what its function returns, for any argument position, and tap/2 runs a function for a side effect and passes the value on unchanged.
• IO.inspect(value, label: "…") prints a value and returns it, so it can sit between any two steps of a pipeline.
• dbg/2 prints the code and value of every step of a pipeline, with colour codes even in a pipe or a log, unless it is given syntax_colors: [].
• In IEx, break! stops a function without changing its code and IEx.pry/0 stops at its line; next runs one line, continue runs to the end, and outside IEx a pry only prints “Cannot pry”.
• Choose IO.inspect/2 or dbg/2 to print and run on, and break! or IEx.pry/0 to stop and look around.