Extra blank lines in iex when background proceess log messages with OTP 28

[nshafer]

Elixir and Erlang/OTP versions

Erlang/OTP 28 [erts-16.1] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [jit:ns]

Elixir 1.19.0 (compiled with Erlang/OTP 28)

Also Elixir 1.18.4 with OTP 28

Operating system

Linux, bash

Current behavior

With OTP 28 and elixir 1.18 or 1.19, running iex -S mix phx.server, request logs produce extra blank lines.

For example:

iex(1)> :ok
:ok
iex(2)>

Then make a request to "https://localhost:4000/", and the console changes to:

iex(1)> :ok
:ok
[info] GET /

[debug] Processing with SandboxWeb.PageController.home/2
  Parameters: %{}
  Pipelines: [:browser]

[info] Sent 200 in 62ms

iex(2)>

It's minor, but annoying. I have traced through all Logger code that I can find, and see no extra newlines in any formatter templates or anything.

I believe I have traced it to something to do with iex/erl and how it handles background messages and repainting the prompt. I draw this conclusion from this code:

defmodule Sandbox do
  require Logger

  def log(msg, times \\ 1) do
    for _ <- 1..times do
      # IO.puts(msg)
      Logger.info(msg)
    end
  end


  def log_async(msg, times \\ 1, delay \\ 0) do
    Task.start(fn ->
      Process.sleep(delay)
      log(msg, times)
    end)
  end
end

If I just log messages synchronously, it's fine.

iex(1)> Sandbox.log("This is a message", 3)
[info] This is a message
[info] This is a message
[info] This is a message
[:ok, :ok, :ok]
iex(2)>

Even if I log the messages from a background process, it's fine.

iex(2)> Sandbox.log_async("This is a message", 3)
[info] This is a message
[info] This is a message
[info] This is a message
{:ok, #PID<0.732.0>}
iex(3)>

However, if the prompt is allowed to paint before the message come in, then it results in extra blank lines:

iex(3)> Sandbox.log_async("This is a message", 3, 250)
{:ok, #PID<0.733.0>}
[info] This is a message

[info] This is a message

[info] This is a message

iex(4)>

What's also strange is that if I use IO.puts instead of Logger.info then it doesn't have any issues?

iex(3)> Sandbox.log_async("This is a message", 3, 250)
{:ok, #PID<0.796.0>}
This is a message
This is a message
This is a message
iex(4)>

Expected behavior

To not print log messages with extra lines in between. This does not happen with OTP 27 or earlier. It also doesn't happen with mix phx.server.

[info] GET /
[debug] Processing with SandboxWeb.PageController.home/2
  Parameters: %{}
  Pipelines: [:browser]
[info] Sent 200 in 65ms

[josevalim]

Based on your description, this is most likely a Erlang/OTP 28 issue. My suggestion is to provide a simple reproduction without Phoenix, so I can translate it to Erlang and report it upstream. Thanks!

[nshafer]

No problem! Here is a basic mix project to reproduce it, with info in the "README.md":

https://github.com/nshafer/otp_28_spaces

I also duplicated the problem on OTP 28.0, 28.0.4 as well as 28.1. And I duplicated it with Arch and Ubuntu, bash and zsh. The only thing I've been able to determine is that it's a change in OTP 28.

[josevalim]

I was able to isolate it down to this:

9> spawn(fun() -> receive after 1000 -> ok end, io:put_chars(["omg"]) end).
<0.108.0>
omg
10> spawn(fun() -> receive after 1000 -> ok end, io:put_chars(["omg\n"]) end).
<0.110.0>
omg
11> spawn(fun() -> receive after 1000 -> ok end, io:put_chars(["omg\n", <<27,91,48,109>>]) end).
<0.112.0>
omg

12>

The newline detection doesn't work properly when there are ansi escape codes after the newline. This was not an issue in previous Erlang versions because the shell did not try to be smart about it and introduce newlines.

[josevalim]

Reported here: erlang/otp#10299

Closed as it is being tracked upstream. Thanks for the repro!