Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Undocumented logger env var #9436

Open
MarkoMin opened this issue Feb 14, 2025 · 4 comments · May be fixed by #9595
Open

Undocumented logger env var #9436

MarkoMin opened this issue Feb 14, 2025 · 4 comments · May be fixed by #9595
Assignees
Labels
bug Issue is reported as a bug team:VM Assigned to OTP team VM

Comments

@MarkoMin
Copy link
Contributor

Following to the discussion.

I thing that this behavior should be documented somewhere.
According to previous release notes, error_logger environment variable should be deprecated and replaced by env vars in logger.
However, there is no environment variable for logger configuration that makes simple handler to disappear.

My opinion is that simple handler should be removed after the configuration by default - current behavior was pretty unexpected to me. If I got it correctly, the purpose of simple handler is just not to loose logs while reconfiguration - I don't see simple logger being added anywhere else.

I'm open to make a PR if anyone can point me what exactly should be done.
Should be just document error_logger env or should we change the behavior?

@MarkoMin MarkoMin added the bug Issue is reported as a bug label Feb 14, 2025
@IngelaAndin IngelaAndin added the team:VM Assigned to OTP team VM label Feb 17, 2025
@garazdawi garazdawi self-assigned this Feb 17, 2025
@garazdawi
Copy link
Contributor

The simple logger is used to capture log events before the logging infrastructure is started. Any log events that happen before the default log handler is added is recorded in the simple handler and then replayed to the default handler when added. It is expected (though definitely not clear in the documentation) that when you disable the default handler, that you later will add a new default. We should make that clear in the documentation.

Possibly we should also add a silent option for the undefined handler, but if you set that you will loose any log messages emitted before you add your own handlers. Normally that is not an issue, until you get some strange crash very early due to file corruption or something.

@MarkoMin
Copy link
Contributor Author

MarkoMin commented Feb 18, 2025

then replayed to the default handler when added.

Okay, that's also undocumented.
As I understood it, it doesn't replay it only to default handler, it replays it to all handlers, but only if default is added and that's making it even more confusing.
I don't know how I'd even document that behavior: When you run a release, your build tool may call "logger:reconfigure/0" and that would add an extra logger handler which is permanent if "default" handler is disabled and temporary if "default" handler exists?

If we add default handler by calling logger:add_handler/3, then we'll have both simple and default handler at the same time. Also, assuming simple logged an event, it will get logged multiple times, first by simple and than by other handlers?

IMO simple should act just like an temporary buffer and should always be removed after reconfiguration. Missing the default handler could eventually result in a warning event logger by simple handler, but should not cause simple to be temporary.
Only thing that's concerning is if you add your handlers manually by calling logger:add_handler/3, but then again we could end up having both simple and default logger at the same time.

It is expected (though definitely not clear in the documentation) that when you disable the default handler, that you later will add a new default. We should make that clear in the documentation.

Hmm, only due to simple handler being removed or due to anything else?

@garazdawi
Copy link
Contributor

As I understood it, it doesn't replay it only to default handler, it replays it to all handlers, but only if default is added and that's making it even more confusing.

hmm, it should only replay to the default handler. If it replays to any other that is a bug.

If we add default handler by calling logger:add_handler/3, then we'll have both simple and default handler at the same time. Also, assuming simple logged an event, it will get logged multiple times, first by simple and than by other handlers?

If you add a default handler the simple will/should be removed. No matter how you add it, reconfigure or add_handler.

Hmm, only due to simple handler being removed or due to anything else?

That, and that otherwise you will loose log events which is not a good thing.

I don't know how I'd even document that behavior: When you run a release, your build tool may call "logger:reconfigure/0" and that would add an extra logger handler which is permanent if "default" handler is disabled and temporary if "default" handler exists?

The release part is rebar3 specific and not really an Erlang/OTP thing. The documentation should state that if you set the default handler to undefined, you should later during system startup add a new default handler, whether that is via logger:add_handler/3 or logger:reconfigure().

Missing the default handler could eventually result in a warning event logger by simple handler, but should not cause simple to be temporary.

Yes, I agree with this. If the simple handler is still present after the release has started, an error log message should be sent saying that the system a default logger handler. I'm not 100% sure when relx calls logger:reconfigure during boot, but that check needs to be done after that call is done.

@MarkoMin
Copy link
Contributor Author

hmm, it should only replay to the default handler. If it replays to any other that is a bug.

Yeah, now I tested it properly and it replays only to the default.

If you add a default handler the simple will/should be removed. No matter how you add it, reconfigure or add_handler.

So, I wrote a simple test for that and it seems to me that when calling add_handler, simple isn't removed:

-module(l).
-include_lib("stdlib/include/assert.hrl").
-export([test/0]).
test() ->
    %% 1. Set env
    ok = application:set_env([{kernel,
                                [{logger_level, notice},
                                 {logger,
                                    [{handler, default, undefined}]
                                 }]
                             }]),
    ok = logger:reconfigure(),
    %% 2. Add default handler
    ok = logger:add_handler(default,
                            logger_std_h,
                            #{level=>notice,
                              config=>
                              #{file=>"_log/default",
                               sync_mode_qlen=>0}}),
    %% 3. "simple" should be removed after `add_handler(default, ...)`
    ?assert(not lists:member(simple, logger:get_handler_ids())).

That, and that otherwise you will loose log events which is not a good thing.

I think I understand now - this way user can add/remove handlers after reconfiguration if handler configs are not in the kernel's env and it won't loose logs in the time between.

@MarkoMin MarkoMin linked a pull request Mar 17, 2025 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Issue is reported as a bug team:VM Assigned to OTP team VM
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants