Switch from lager to built in logger #99

telezynski · 2019-10-16T08:32:50Z

No description provided.

telezynski · 2019-10-23T08:20:59Z

The following log is produced
less _build/default/rel/amoc/log/logger.log

2019-10-14 03:57:33.268 [info] <0.1019.0>@supervisor:report_progress:1419 Supervisor {local,runtime_tools_sup} started child ttb_autostart at pid <0.1020.0>
2019-10-14 03:57:33.268 [info] <0.866.0>@application_controller:info_started:1929 Application runtime_tools started on node '[email protected]'
2019-10-14 03:57:33.268 [info] <0.1023.0>@amoc_app:start:21 **** Started lager
2019-10-14 03:57:33.268 [info] <0.1023.0> **** Started logger
2019-10-14 03:57:33.268 [info] <0.1026.0>@supervisor:report_progress:1419 Supervisor {local,amoc_sup} started child amoc_event at pid <0.1027.0>
2019-10-14 03:57:33.268 [info] <0.1026.0>@supervisor:report_progress:1419 Supervisor {local,amoc_sup} started child amoc_users_sup at pid <0.1028.0>
2019-10-14 03:57:33.268 [info] <0.1026.0>@supervisor:report_progress:1419 Supervisor {local,amoc_sup} started child amoc_controller at pid <0.1029.0>
2019-10-14 03:57:33.268 [info] <0.1026.0>@supervisor:report_progress:1419 Supervisor {local,amoc_sup} started child amoc_slave at pid <0.1030.0>
2019-10-14 03:57:33.268 [info] <0.896.0>@supervisor:report_progress:1419 Supervisor {local,kernel_safe_sup} started child pg2 at pid <0.1031.0>
2019-10-14 03:57:33.268 [info] <0.1026.0>@supervisor:report_progress:1419 Supervisor {local,amoc_sup} started child amoc_throttle_controller at pid <0.1032.0>```

There are two issues:
Timestamp is fixed, not taken from metadata
The format of lager and logger messages are different

michalwski · 2019-10-23T20:26:43Z

@telezynski what would happen if we removed the dependency on lager completely? I know that some of our deps use lager to log things so lager would be included in the release anyway, right? Maybe there is no need to try combining lager with logger and just let them work one next to the other, what do you think?

michalwski · 2019-10-28T12:23:58Z

src/amoc_lager_logger_formatter.erl

@@ -1,9 +1,14 @@
+%% This module is copied from: https://github.com/erlang-lager/lager/blob/adt/lager_use_logger-option/src/lager_logger_formatter.erl
+%% with amendments. Original comments left intact.
+%% Fixed timestamp formatting, added catch all clause for report_cb.


Can we contribute back the timestamp fix?

Or all the changes? I think we'll need this formatter in other places like amoc-arsenal-xmpp and possibly MongooseIM. It's better to use one file instead of coping it to every repo.

The whole thing is quite controversial. Maybe I focused on the wrong thing which is the seamless combination of lager and logger.

Unfortunately the integration of the two by the lager author Andrew Thompson is left not quite finished. It seems to work, but it is in a feature branch of lager, not promoted to a release (as the author announced at his presentation this spring in SF - https://codesync.global/media/erlang-logging-for-the-21st-otp-andrew-thompson/).
Given the state of affairs I wouldn't recommend including lager_logger integration in Mongoose yet, let's wait for the next release of Lager).

Should we include it in Amoc at all? Well perhaps as a way of testing it, for example performance and be prepared for the final version.

Based on this issue erlang-lager/lager#519 I think the author may need some external help to get this integration moving. I think we can try contributing the fixes and see if they get accepted.

michalwski

The code looks good, I have only one "operational" issue. Console logs disappeared in this PR, on master branch when you run amoc in the console:

 _build/prod/rel/amoc/bin/amoc console

It prints logs to the standard output. When I tried the same with this PR, there is no log in the console. I think heaving logs in the console is important when we use Amoc to develop a scenario. Is it possible to get console logs with changes introduced in this PR?

michalwski · 2019-10-29T08:42:13Z

As far as I'm concerned, console logs doesn't have integrate well with lager if that's a big effort.

telezynski · 2019-10-29T14:21:16Z

Restored previous behaviour: log to console and file, level warning (so no progress reports)

michalwski · 2019-10-30T09:09:48Z

src/amoc_lager_logger_formatter.erl

+            {"Application ~w exited with reason: ~s", [Name, Formatted]}
+    end;
+report_cb(Other) ->
+    {"Unexpected logger report_cb: ~w", [Other]}.


As far as I know this is our addition to the formater, right? I think it makes unexpected logs unreadable in some case. For instance I have this error (it's my fault in Erlang and docsh configuration) printed by pure logger:

(amoc@MichalPiotrowski-MacBookPro2018)1> 09:25:05.869 [error] file:path_eval(["/Users/michalpiotrowski"],".erlang"): error on line 50: 50: evaluation failed with reason error:undef and stacktrace [{docsh,activated,[path],[]},{erl_eval,do_apply,6,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,680}]},{erl_eval,exprs,5,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,126}]},{erl_eval,expr,5,[{file,[101,114,108,95,101,118,97,108,46,101,114,108]},{line,462}]},{file,eval_stream2,6,[{file,[102,105,108,101,46,101,114,108]},{line,1393}]},{file,path_eval,3,[{file,[102,105,108,101,46,101,114,108]},{line,1059}]},{c,f_p_e,2,[{file,[99,46,101,114,108]},{line,693}]},{init,eval_script,2,[]}]

Which is readable and I know what to do about it. When the lager/logger integration is enabled the above log looks like the following:

2019-10-30 09:54:30.965 [error] <0.8.0> Unexpected logger report_cb: #{args => [[[47,85,115,101,114,115,47,109,105,99,104,97,108,112,105,111,116,114,111,119,115,107,105]],[46,101,114,108,97,110,103],50,[[53,48],58,32,101,118,97,108,117,97,116,105,111,110,32,102,97,105,108,101,100,32,119,105,116,104,32,114,101,97,115,111,110,32,[101,114,114,111,114],58,[117,110,100,101,102],32,97,110,100,32,115,116,97,99,107,116,114,97,99,101,32,[91,[[123,[[100,111,99,115,104],44,[97,99,116,105,118,97,116,101,100],44,[91,[[112,97,116,104]],93],44,[91,93]],125],44,[123,[[101,114,108,95,101,118,97,108],44,[100,111,95,97,112,112,108,121],44,[54],44,[91,[[123,[[102,105,108,101],44,[91,[[49,48,49],44,[49,49,52],44,[49,48,56],44,[57,53],44,[49,48,49],44,[49,49,56],44,[57,55],44,[49,48,56],44,[52,54],44,[49,48,49],44,[49,49,52],44,[49,48,56]],93]],125],44,[123,[[108,105,110,101],44,[54,56,48]],125]],93]],125],44,[123,[[101,114,108,95,101,118,97,108],44,[101,120,112,114,115],44,[53],44,[91,[[123,[[102,105,108,101],44,[91,[[49,48,49],44,[49,...],...],...]],...],...],...]],...],...],...]]],...}

This is very cryptic and it's close to impossible to figure out what's wrong.

Current master branch of Amoc produces the same output as my first example.

I'm not sure if trying to unify lager and logger logs makes sense, at least for Amoc.

telezynski · 2019-10-31T15:27:47Z

Decline this PR as the decision was not to implement integration with lager, instead use logger in amoc while let dependencies use lager (this work is done in a separate PR)

aleklisi approved these changes Oct 24, 2019

View reviewed changes

michalwski reviewed Oct 28, 2019

View reviewed changes

Andrzej Telezynski added 4 commits October 28, 2019 13:41

Switch lager to a branch with logger backend

ad45403

Configure lager_logger

6be70cb

Add local formatter for lager_logger

54aa839

Switch log messages to logger using macro

5ab7b6c

telezynski force-pushed the at/lager_logger branch from 035320d to 5ab7b6c Compare October 28, 2019 12:54

michalwski suggested changes Oct 29, 2019

View reviewed changes

Restore previous behaviour: log to console and file, level warning

a6b5133

michalwski reviewed Oct 30, 2019

View reviewed changes

telezynski closed this Oct 31, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Switch from lager to built in logger #99

Switch from lager to built in logger #99

telezynski commented Oct 16, 2019

telezynski commented Oct 23, 2019

michalwski commented Oct 23, 2019

michalwski Oct 28, 2019

michalwski Oct 28, 2019

telezynski Oct 28, 2019

michalwski Oct 28, 2019

michalwski left a comment •

edited

Loading

michalwski commented Oct 29, 2019

telezynski commented Oct 29, 2019

michalwski Oct 30, 2019

telezynski commented Oct 31, 2019

Switch from lager to built in logger #99

Switch from lager to built in logger #99

Conversation

telezynski commented Oct 16, 2019

telezynski commented Oct 23, 2019

michalwski commented Oct 23, 2019

michalwski Oct 28, 2019

Choose a reason for hiding this comment

michalwski Oct 28, 2019

Choose a reason for hiding this comment

telezynski Oct 28, 2019

Choose a reason for hiding this comment

michalwski Oct 28, 2019

Choose a reason for hiding this comment

michalwski left a comment • edited Loading

Choose a reason for hiding this comment

michalwski commented Oct 29, 2019

telezynski commented Oct 29, 2019

michalwski Oct 30, 2019

Choose a reason for hiding this comment

telezynski commented Oct 31, 2019

michalwski left a comment •

edited

Loading