Logger.Utils.truncate_n/2 should handle invalid log data gracefully

[mpoeter]

Current behavior

When truncation of log messages is enabled, the Logger crashes with No function clause matching in Logger.Utils.truncate_n/2 when the log data is invalid (e.g., contains nil).
When truncation is disabled (i.e., truncate is set to :infinity), the Logger doesn't crash, because the console logger handles this error gracefully:

elixir/lib/logger/lib/logger/backends/console.ex

Lines 237 to 242 in 43a4c85

	try do
	:unicode.characters_to_binary(dirty)
	rescue
	ArgumentError ->
	clean = ["failure while trying to log malformed data: ", inspect(dirty), ?\n]
	%{state | ref: async_io(device, clean), output: clean}

Expected behavior

I think truncate should handle invalid log data more gracefully - similar to the console logger:

How about something like this?

def truncate(chardata, n) when n >= 0 do
    {chardata, n} = truncate_n(chardata, n)
    if n >= 0, do: chardata, else: [chardata, " (truncated)"]
rescue
  ArgumentError ->
    ["failure while trying to log malformed data: ", inspect(chardata)] |> truncate_n(n)
end

[josevalim]

Can you please fill in the full template, which includes your Elixir and OTP versions?

The reason I ask is because the Logger doesn't crash in my case but rather the client:

iex(1)> require Logger
Logger
iex(2)> Logger.debug [nil]
** (ArgumentError) cannot truncate chardata because it contains something that is not valid chardata: nil

The server rescues because we don't want to shutdown the Logger process (it is the receiver). But I think we should raise on the client if given invalid input. For example, I don't expect something like Logger.debug {1, 2, 3} to work either.

[mpoeter]

Sorry, I was not at my workstation when I created this issue, and I did not remember the exact versions. Here they are:

• Ubuntu 18.04
• Erlang/OTP 21 [erts-10.0.7] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe]
• Elixir 1.7.3 (compiled with Erlang/OTP 21)

But you are right, it is of course not the Logger process that crashes, but the client. As it is now, the behavior is inconsistent. With truncation disabled, Logger.debug [nil] does not throw. I would prefer it, if this was also the case with truncation enabled.

[josevalim]

I would prefer it, if this was also the case with truncation enabled.

Is there a rationale for so? My rationale is that we can afford to fail when we detect this on the client - if we detect it. But we can't afford to fail when we detect on the server (and it may be async).

One could argue for consistency but I would say that the consistency here would make things worse (because failing early is better than having bad messages in the logger).

[mpoeter]

I am not disinclined to failing early, but we had a few cases where a nil value crept into the log data, causing the process to crash. And because logging is usually irrelevant for the correctness of a function, I would prefer it if the logging mechanism would handle these cases gracefully.

Don't get me wrong, I definitely want to know that there has been a bad message! I just would prefer it, if it would not cause my process to crash.

[josevalim]

Thanks!

We can leave this open for a week or two to collect more feedback, or perhaps moved to the mailing list for further discussion, but I think the general assumption that the Logger functions are not going to raise is not true. If you pass bad metadata to Logger data, it may raise. If you pass an invalid level, it may raise. If you pass an invalid message, it may raise.

The main concern about not raising on the client is that you may have bad warnings during development and tests that will never get caught because you usually don't check the logs on those environments. By allowing it to simply pass through, now you will have more bad messages in production, that will go unnoticed for longer periods of time.

[josevalim]

Given the lack of new input, I will go ahead and close this for the reasons above. We can always collect more feedback and change the behaviour in the future. Thank you.