Ugly errors are raised when logging non-loggable stuff

[whatyouhide]

I was going down the rabbit hole of Logger formatters, and I found a few interesting behaviours.

Let's start by logging something that doesn't look like a binary or a charlist. If we do this, we get a nice (and expected) Protocol.UndefinedError for String.Chars:

iex> Logger.info(%{})
** (Protocol.UndefinedError) protocol String.Chars not implemented for %{}

This is good™. Now, what actually calls to_string/1 is Logger.truncate/2. However, truncate/2 treats binaries and what look like charlists in a special way:

elixir/lib/logger/lib/logger.ex

Lines 771 to 772 in e703bb8

	defp truncate(data, n) when is_list(data) or is_binary(data), do: Logger.Utils.truncate(data, n)
	defp truncate(data, n), do: Logger.Utils.truncate(to_string(data), n)

The problem is that is_list/1 definitely doesn't tell if something is a charlist all the way down. Hence, it's easy to make Logger raise a (IMO) nasty FunctionClauseError:

iex> Logger.info([%{}])
** (FunctionClauseError) no function clause matching in Logger.Utils.truncate_n/2

Things get even worse when I trick Logger into bypassing truncate/2 altogether, that is, by configuring :truncate to be :infinity. In this case, if I pass a list, Logger still mistakes it for chardata and either gives it to a formatter (like the default one in the console backend) that crashes on it:

iex> Logger.configure(truncate: :infinity)
iex> Logger.info([%{}])
02:06:14.509 [error] GenEvent handler Logger.Backends.Console installed in Logger terminating
** (ArgumentError) argument error
    (stdlib) :unicode.characters_to_binary([[[] | "\e[22m"], ["\n", [[48, "2"], 58, [48, "6"], 58, "14", 46, "502"], " ", "", "[", "info", "] ", " ", [%{}], "\n"] | "\e[0m"])

or passes it down to custom formatters (like {module, function}) which will receive a message that they cannot turn to chardata straight away.

This is somehow of a problem with metadata as well, as they're only tried to be turned into a string by each specific formatter. However, with metadata I guess that this is good because smarted backends or formatters can use non-string-friendly metadata for their own specialized purposes. However, it feels like we should ensure formatters and backends that the message they will get is a binary or chardata. Thoughts?

Also, sorry for the brain dump as the issue report instead of a more formal issue, it's late and I'm headed to sleep and wanted to get this right and detailed before I forget to :) I'll clean it up tomorrow if necessary!

[josevalim]

@whatyouhide I think this requires three fixes:

• We need to change the console backend to handle the inappropriate characters_to_binary call. When it fails, we need to catch that and instead ask it to log a message that says we were unable to do X because the input was malformed.

• Regarding the log message and metadata in the formatter, the formatter should never fail. This implies our formatter and it is a responsibility for custom formatters as well. I believe this is documented but if not, we should. In particular, the built-in formatter should never fail, if it happens, we need to rescue that and return a different message to be logged. Something that says we were trying to format X but we couldn't because of failed metadata.

• We could also raise a better message in truncate_n, yeah.

[whatyouhide]

@josevalim sounds good, yes. I made your three fixes checkboxes, I'll try to cover all three.

[whatyouhide]

Closed in #7478.