Does Logger have a hidden cap for message size?

Questions / Help
,
1

Background

In one of our projects a client of ours complained that the logs he is getting are being capped at 2000 characters.

This client is gettign his logs via a tool called Splunk and perhaps some other systems I am not aware of.

Instead of capping the messages at 2K characters, I need to cap them at 8K.

Config

To me this is strange, because we specifically truncate the log to :infinity, as our config shows:

use Mix.Config

config :logger,
  level: :info,
  backends: [:console],
  utc_log: true,
  sync_threshold: 100,
  truncate: :infinity

if Mix.env() != :prod do
  config :logger,
    level: :debug
end

config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [
    :module,
    :line,
    :function,
    :trace,
    :perf,
    :duration,
    :namespace
  ]

Furthermore, I didn’t find any specific Logger limits documented:

https://hexdocs.pm/logger/Logger.html

Question

  • Does the Logger have some internal limit that cuts messages down to 2000 characters? If so, how can I change it?
2

At least on the console backend I’m not seeing such a limit. You can test it easily with:

iex> require Logger
iex> Logger.debug String.duplicate("A", 8000)
:ok

23:04:58.307 [debug] AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA.......
1 Like
3

Just for giggles I put it in a test case:

defmodule ThingTest do
  use ExUnit.Case
  import ExUnit.CaptureLog
  require Logger

  @message_size 8_000

  test "Logger backend end" do
    assert capture_log(fn -> Logger.error(String.duplicate("A", @message_size)) end) >= @message_size
  end
end

And ran the test:

kip@Kips-iMac-Pro thing % mix test
.

Finished in 0.04 seconds
1 test, 0 failures
2 Likes
4

Thanks for the super quick answer!
I have made the test you have mentioned in the first post and concluded that it is very unlikely for the issue to be in the Elixir code we have.

Once again thank you!

5

Is it perhaps the :truncate option? By default it’s 8kiB.

:truncate - the maximum message size to be logged (in bytes). Defaults to 8192 bytes. Note this configuration is approximate. Truncated messages will have " (truncated)" at the end. The atom :infinity can be passed to disable this behavior.

1 Like
6

FWIW there is a limiter (see @NobbZ’s post) but there can also be intermediate steps that trim things shorter - at work, lines long enough to hit Logger’s limit (and get (truncated) at the end) are still split into multiple lines someplace between Logger -> syslog -> CloudWatch. Not sure what specifically is causing that…

1 Like
7

just so my headache is logged somewhere.

there’s two different layers you can config in the logger. one for backends, one for logger itself. so in my case this helper a lot:

config :logger, truncate: :infinity
config :logger, :console, truncate: :infinity

thanks goes to @JonRowe and @LostKobrakai in Slack.

8 Likes
8

Apparently, the first line is enough. So happy to have found it :raised_hands:t2:

1 Like
9

Updates that fit the current situation:

disable log truncation

As of Elixir 1.14:

config :logger, truncate: :infinity is enough for disabling log truncation.

config :logger, :console, truncate: doesn’t exist anymore.

log data

Another point to note if you are planing to print data with inspect/2:

Logger.info( inspect(data) )

Make sure that inspect will print all the information you want. The following line is a good start:

Logger.info( inspect(data, structs: false, limit: :infinity, printable_limit: :infinity) )

performance consideration

If the data is large, carefully consider before using the above two steps.

5 Likes
10

To enable infinite truncation in the new Logger (since Elixir 1.15) do:

config :logger, :default_formatter,
  ...,
  truncate: :infinity
2 Likes
11

For future reference: I added config :logger, :default_formatter, truncate: :infinity to config/config.exs in Phoenix and this additionally

  • disabled colored log output
  • ignored the logger format configured in config/dev.exs

… so I ended up having to remove it. I wish there were more documentation on this.

12

I wanted to ask is there a way to log specific messages without truncation?

When I run migrations that replaces data, as an extra safety measure (in addition to backups) I like to log out diffs and before/after messages. For those logs specifically I want to set truncate to infinity.

13

Could this be due to an interaction between the now-deprecated :console backend interacting with your use of :default_formatter? Maybe try changing any config :logger, :console ... to use :default_formatter. I couldn’t recreate the issue of not getting colors working, but mismatched logger config keys can cause non-obvious behavior.

For what it’s worth, some upcoming version of Phoenix will set the minimum Elixir version to 1.15 and use :default_formatter instead of :console.

You can update the formatter config, log a message, and update it again. There’s an example of that here: Logger — Logger v1.18.2. It would be similar with a custom formatter as well.

That sounds like it may be a good option for your situation, but you could also add another handler with a formatter with no truncating, and filter for specific messages. If it’s infrequent, it’s probably better to go with the update, log, update strategy instead, though.

1 Like
14

Thanks for the tip!

Yes it’s infrequent.

I only need this when we are running certain kinds of migrations. We do backup our database but for the extra confidence I like have full logs of what exactly happened during the migration. The before/after/diff of each row updated helps me confirm that everything went through correctly.

1 Like
15

Yeah, in that case I think just doing something like

def migrate do
  formatter = Logger.default_formatter(truncate: :infinity)
  :logger.update_handler_config(:default, :formatter, formatter)

  # do migrations

  :logger.update_handler_config(:default, :formatter, Logger.default_formatter())
end

would suffice. You’d maybe want to take care to ensure that if the migrations fail or something you still properly update the handler, but that may not matter in this case.

Just for posterity, here’s the other option I mentioned:

# config/config.exs

config :logs, :logger, [
  {
    :handler,
    :custom_logger,
    :logger_std_h,
    %{
      filters: [
        remote_gl: {&:logger_filters.remote_gl/2, :stop},
        custom_filter: {&Logs.custom_filter/2, []}
      ],
      filter_default: :log,
      formatter: Logger.default_formatter(truncate: :infinity),
      level: :all,
      module: :logger_std_h
    }
  }
]

# lib/logs.ex
defmodule Logs do
  def custom_filter(%{meta: %{no_truncate: true}} = event, _extra) do
    event
  end
  def custom_filter(_event, _extra), do: :stop
end

# lib/logs/application.ex

defmodule Logs.Application do
  use Application

  def start(_type, _args) do
    Logger.add_handlers(:logs)

    # ...
  end

# ...
end

Then when you need to log something without truncation, you would just do something like:

Logger.info("this won't be truncated", no_truncate: true)

One issue with that is that the default handler will still log it, truncated, but you’ll also get the non-truncated form. If you want to avoid that you would need to add an inverse filter to the default handler, like:

# config/config.exs
config :logger, :default_handler,
  filters: [
    inverse_custom_filter: {&Logs.inverse_custom_filter/2, []}
  ]

# lib/logs.ex
defmodule Logs do
  # ...

  def inverse_custom_filter(event, extra) do
    if custom_filter(event, extra) == :stop do
      event
    else
      :stop
    end
  end

  # ...
end

Maybe I should’ve written a blog post instead. :slight_smile: