erlang-lager / lager Goto Github PK

The following snippet of code

-module(lager_unicode).

-export([test/0]).

test() ->
    application:start(compiler),
    application:start(syntax_tools),
    application:start(lager),

    Data = {tuple, "string with umlauts ṏ"},
    lager:info("Data: ~p", [Data]).

displays

10:40:07.914 [info] Data: {tuple,[115,116,114,105,110,103,32,119,105,116,104,32,117,109,108,97,117,116,115,32,225,185,143]}

lager:debug("Accepted Socket: ~w~n", [AcceptSocket])

gives

03:10:27.235 [debug] Accepted Socket: #Port<0.3671, no module, function, line, pid info?

Is this the expected behavior?

I am running version - {vsn,"1.0.0"}.

-- satyam

Hi,

I have a dependency (erlware/resource_discovery) which has a dependency on log4erl, where as my main application uses Lager. I don't like have two logging frameworks and separate log files so I was wondering if I could write something or if something exists like a parse_transform which would replace log4erl statements with Lager log statements? Or would I be better just forking my dependency and manually changing all the log4erl statements to Lager logging statements?

Thanks,

Andy.

I try to make a separate access.log with lager and write there only messages with specific tag:

lager:debug([{request,web},{duration,Time}],"~3..0B ~5.. B ~B ~s ~p", [Code,Time, Size, Path, SessionId]),

or

lager:info([{request,web},{duration,Time}],"~3..0B ~5.. B ~B ~s ~p", [Code,Time, Size, Path, SessionId]),

Is it possible to make a trace file and configure it so, that only log events with meta {request,web} will get there?

As seen in the wild on a production Riak cluster:

2012-01-27 01:10:03.778 [warning] <0.20967.7> Mailbox size warning: 26945 messages: [{26945,<0.58.0>,lager_crash_log}]
2012-01-27 01:11:03.923 [warning] <0.20967.7> Mailbox size warning: 23011 messages: [{23011,<0.58.0>,lager_crash_log}]
2012-01-27 01:12:04.007 [warning] <0.20967.7> Mailbox size warning: 18748 messages: [{18748,<0.58.0>,lager_crash_log}]

The process that generated the messages above runs about every 60 seconds,
so the lager process managed to get at least 27K messages sent to it in a very
short period of time.

The good news is that the lager_crash_log process managed to consume all
of the backlog in about 3 minutes: there is no warning at time 01:13:04. The
bad news is that these messages were big enough that the lager_crash_log
process was only able to process roughly 70 items per second.

Lowering the maximum formatting size only reduces the problem by a small
amount: it's still possible for more events to come into Lager's system than
Lager can handle. Lager processes are capable of checking themselves
periodically and when the mailbox size reaches a high water mark, start
discarding messages.

If such a feature is added, then there ought to be a config knob to control
the high water limit. A new log message should be added to write to the
log that X messages have been dropped ... and that message should not
be queued or eligible for discard.

==> lager (compile)
Dependency not available: goldrush-.* ({git,
"git://github.com/DeadZen/goldrush.git",
{tag,"879c69874a"}})

Does not look like the tag exists anymore. .....

Some of the eunit tests including timeouts sometimes fail on slower machines.
(e.g. on an Intel Core2 Duo CPU U9400 @ 1.40GHz).
A hackish workaround would be a longer sleep:

--- a/test/lager_test_backend.erl
+++ b/test/lager_test_backend.erl
@@ -505,7 +505,7 @@ lager_test_() ->
             {"record printing fails gracefully when module is invalid",
                 fun() ->
                         spawn(fun() -> lager:info("State ~p", [lager:pr({state, 1}, not_a_module)]) end),
-                        timer:sleep(100),
+                        timer:sleep(200),
                         {Level, _Time, Message, _Metadata}  = pop(),
                         ?assertMatch(Level, lager_util:level_to_num(info)),
                         ?assertEqual("State {state,1}", lists:flatten(Message)),
@@ -1180,7 +1180,7 @@ async_threshold_test_() ->
                         %% serialize ont  the mailbox again
                         _ = gen_event:which_handlers(lager_event),
                         %% just in case...
-                        timer:sleep(100),
+                        timer:sleep(200),

                         %% async is true again now that the mailbox has drained
                         ?assertEqual(true, lager_config:get(async)),

A real solution for this issue would be to wait the appropriate time. Could you think of a way to wait w/o a timer, e.g. using a monitor or some messages?

The way to reproduce:

1. Clone https://github.com/doubleyou/rels, checkout the first commit
2. Generate and start a relase
3. Checkout to the second commit
4. Generate upgrade, install it
5. Lager and compiler aren't started.
6. Start compiler manually. Try to start lager – and an error should occur:

.:none: internal error in v3_life;
crash reason: {{case_clause,
                {'EXIT',
                 {undef,
                  [{v3_life,module,
                    [{k_mdef,[],'lager_mochiglobal:loglevel',
                      [{module_info,0},{module_info,1},{term,0}],
                      [],
                      [{k_fdef,
                        {k,[],[],[0,{file,[]}]},
                        term,0,[],
                        {k_return,
                         {k,[],[],[]},
                         [{k_literal,[0,{file,[]}],{7,[]}}]}},
                       {k_fdef,
                        {k,[],[],[0,{file,[]}]},
                        module_info,0,[],
                        {k_enter,
                         {k,[],[],[0,{file,[]}]},
                         {k_remote,[],
                          {k_atom,[0,{file,[]}],erlang},
                          {k_atom,[0,{file,[]}],get_module_info},
                          1},
                         [{k_atom,
                           [0,{file,[]}],
                           'lager_mochiglobal:loglevel'}]}},
                       {k_fdef,
                        {k,[],[],[0,{file,[]}]},
                        module_info,1,
                        [{k_var,[0,{file,[]}],cor0}],
                        {k_enter,
                         {k,[cor0],[],[0,{file,[]}]},
                         {k_remote,[],
                          {k_atom,[0,{file,[]}],erlang},
                          {k_atom,[0,{file,[]}],get_module_info},
                          2},
                         [{k_atom,[0,{file,[]}],'lager_mochiglobal:loglevel'},
                          {k_var,[0,{file,[]}],cor0}]}}]},
                     [binary,verbose,report_errors]]},
                   {compile,'-select_passes/2-anonymous-2-',2},
                   {compile,'-internal_comp/4-anonymous-1-',2},
                   {compile,fold_comp,3},
                   {compile,internal_comp,4},
                   {compile,internal,3}]}}},
               [{compile,'-select_passes/2-anonymous-2-',2},
                {compile,'-internal_comp/4-anonymous-1-',2},
                {compile,fold_comp,3},
                {compile,internal_comp,4},
                {compile,internal,3}]}

That looks like a mochiglobal problem, but so far I haven't figured out what's going on.

I have problem with formatting lager:error from catch section on lager 169cffd on R15B02

I've tried to make a minimal example for reproducing and have found, that I can reproduce this problem only inside gen_server, when try/catch is done and a moderately big message (70 kbytes) is written via lager:error inside catch section.

Below goes link to tgz file with escript failure.erl and a.dump. failure.erl reads this big message from a.dump and tries to reproduce the problem. It is written so that you should unpack it in lager root folder.

http://debian.erlyvideo.org/lager-error.tgz

cd lager
wget http://debian.erlyvideo.org/lager-error.tgz
tar zxf lager-error.tgz
./failure.erl

I have turned off error_logger interception and can see in console:

=ERROR REPORT==== 7-May-2013::13:18:36 ===
** Generic server <0.42.0> terminating
** Last message in was go
** When Server state == state
** Reason for termination ==
** {function_clause,[{lager_trunc_io,alist,3,
[{file,"src/lager_trunc_io.erl"},
{line,412}]},
{lager_trunc_io,alist,3,
[{file,"src/lager_trunc_io.erl"},
{line,388}]},
{lager_trunc_io,alist,3,
[{file,"src/lager_trunc_io.erl"},
{line,382}]},
{lager_trunc_io,print,3,
[{file,"src/lager_trunc_io.erl"},
{line,171}]},
{lager_trunc_io,list_body,4,
[{file,"src/lager_trunc_io.erl"},
{line,305}]},
{lager_trunc_io,alist_start,3,
[{file,"src/lager_trunc_io.erl"},
{line,370}]},
{lager_trunc_io,list_bodyc,4,
[{file,"src/lager_trunc_io.erl"},
{line,317}]},
{lager_trunc_io,list_bodyc,4,
[{file,"src/lager_trunc_io.erl"},
{line,318}]}]}

https://github.com/basho/lager/blob/169cffd94759e99e2e8870b125861a91e3c1482a/src/lager_trunc_io.erl#L412:

alist([H|_L], _Max, _Options) ->
  throw({unprintable, H});

Perhaps, erlang doesn't like unhandled throw inside try/catch?

My app installs a trace to a file using lager:trace_file/3. During normal application execution, this works fine. However, when running common tests, this call may get made multiple times. On all calls after the first, it reports an error:

CRASH REPORT Process <0.2423.0> with 0 neighbours crashed with reason: no case clause matching ok in lager:trace_file/3 line 136

The problem appears to be the catch-all clause of the first inner case statement in the function. Line 134 returns "ok", but the second inner case statement is expecting to match "{ok, _}" (line 137).

15:27 < ponton> I wanna log something like: lager:warning([{my_tag, foo}], "Some message")
15:27 < ponton> but from Erlang shell, so parse_transform is not used
15:37 < Vagabond> ponton: lager has a direct API, but its less convienient
15:37 < Vagabond> lager:log(level, self(), "Message ~p", FormatArgs).
15:58 < ponton> Vagabond: but how to pass tags to it?
16:00 < Vagabond> hmm
16:00 < Vagabond> you probably can't
16:01 < Vagabond> you should open a GH issue, and I can try to fix that
16:02 < Vagabond> actually
16:02 < Vagabond> you can do it, but its ugly
16:03 < Vagabond> you can use lager:dispatch_log directly, although its not really supposed to be a public API

OS: Linux herdserver 2.6.38-8-generic #42-Ubuntu SMP Mon Apr 11 03:31:50 UTC 2011 i686 i686 i386 GNU/Linux
Arch: i686
Erlang: R14B02 (erts-5.8.3)

When sending the wrong data type to function, which should error out and correctly does, the error console crashes with the following:

2011-08-29 11:55:32.635 [error] <0.737.0> CRASH REPORT Process lager_crash_log with 0 neighbours crashed with reason: bad argument in call to io_lib:format("ss~s", [[[[50,48,49,49],45,[[48],56],45,[50,57]],[32],[[49,49],58,[53,53],58,[51,50]],[32,61],[69,82,82,79,82,32,82,69,80,79,82,84],[61,61,61,61,10]],[91,[[34,119,101,98,32,114,101,113,117,101,115,116,32,102,97,105,108,101,100,34],44,[123,[[109,101,116,104,111,100],44,[80,79,83,84]],125],44,[123,[[112,97,116,104],44,[34,102,105,110,100,34]],125],44,[123,[[116,121,112,101],44,[101,114,114,111,114]],125],44,[123,[[119,104,97,116],44,[98,97,100,97,114,103]],125],44,[123,[[116,114,97,99,101],44,[91,[[123,[[101,114,108,97,110,103],44,[98,105,110,97,114,121,95,116,111,95,108,105,115,116],44,[34,38.233913133184835,34]],125],44,[123,[[104,101,114,100,95,119,101,98],44,[116,111,95,108,111,99],44,[52]],125],44,[123,[[104,101,114,100,95,119,101,98],44,[97,99,116,105,111,110],44,[50]],125],44,[123,[[104,101,114,100,95,119,101,98],44,[108,111,111,112],44,[50]],125],44,[123,[[109,111,99,104,105,119,101,98,95,104,116,116,112],44,[104,101,97,100,101,114,115],44,[53]],125],44,[123,[[112,114,111,99,95,108,105,98],44,[105,110,105,116,95,112,95,100,111,95,97,112,112,108,121],44,[51]],125]],93]],125],44,[123,[[114,101,113,117,101,115,116],44,[123,[[109,111,99,104,105,119,101,98,95,114,101,113,117,101,115,116],44,[35,80,111,114,116,60,48,46,52,56,53,53,62],44,[80,79,83,84],44,[34,47,102,105,110,100,34],44,[123,[[49],44,[49]],125],44,[123,[[53],44,[123,[[34,99,111,110,116,101,110,116,45,116,121,112,101,34],44,[123,[[67,111,110,116,101,110,116,45,84,121,112,101],44,[34,116,101,120,116,47,112,108,97,105,110,34]],125],44,[123,[[34,99,111,110,116,101,110,116,45,108,101,110,103,116,104,34],44,[123,[[67,111,110,116,101,110,116,45,76,101,110,103,116,104],44,[34,49,48,49,34]],125],44,[123,[[34,99,111,110,110,101,99,116,105,111,110,34],44,[123,[[67,111,110,110,101,99,116,105,111,110],44,[34,107,101,101,112,45,97,108,105,118,101,34]],125],44,[110,105,108],44,[110,105,108]],125],44,[110,105,108]],125],44,[123,[[34,116,101,34],44,[123,[[34,84,101,34],44,[91,93]],125],44,[123,[[34,104,111,115,116,34],44,[123,[[72,111,115,116],44,[34,104,101,114,100,115,101,114,118,101,114,58,56,48,56,48,34]],125],44,[110,105,108],44,[110,105,108]],125],44,[110,105,108]],125]],125]],125]],125]],125]],93],[]]) in lager_crash_log:handle_cast/2

After inspecting the byte list, I was able to at least determine where the error was occurring in our code that resulted in Lager error. Changing the data type still produced an error, but this time it did not crash Lager:

2011-08-29 12:27:21.239 [error] <0.727.0> "web request failed", method: POST, path: "find", type: error, what: badarg, trace: [{erlang,binary_to_list,["3.86201126468098507871e+01"]},{herd_web,to_loc,4},{herd_web,action,2},{herd_web,loop,2},{mochiweb_http,headers,5},{proc_lib,init_p_do_apply,3}], request: {mochiweb_request,#Port<0.4899>,POST,"/find",{1,1},{5,{"content-type",{Content-Type,"text/plain"},{"content-length",{Content-Length,"381"},{"connection",{Connection,"keep-alive"},nil,nil},nil},{"te",{"Te",[]},{"host",{Host,"herdserver:8080"},nil,nil},nil}}}}

Note, the error is produced in our local function to_loc() because we incorrectly do not handle the case when the data is not a binary. So to recap, lager crashes when the error is produced because the values are floats and we try to do a binary_to_list() on them. If we pass in the values as a list (as you see in the error message above), it still errors out as it should, but does not crash lager and lager correctly reports the error.

One other issue I noticed on this machine versus the development machine. The formatted results using ~w on a float is inconsistent between machines. This is also present in the output above (not sure if it is related):

On the Linux instance:

([email protected])4> lager:log(info, self(), "~w", [1.0]).
22:33:32.329 [info] 1.00000000000000000000e+00
ok

On the Mac:

([email protected])2> lager:log(info, self(), "~w", [1.0]).
22:43:22.208 [info] 1.0
ok

~p formats correctly, but it also prettifies the output which is not desirable for logs that may be parsed later.

Let me know if you need any more information.

Cheers,
Bryan
(bryan at wobblesoft dot com)

Why is starting compiler and syntax_tools library user's responsibility?

Looking through the lager_mochiglobal source it looks like you use 'mochiglobal:' when constructing the module names.
https://github.com/basho/lager/blob/master/src/lager_mochiglobal.erl#L47
This means if you happen to have mochiglobal installed, they can possibly trample over each other.

Running R16, on Ubuntu 12.04.2 LTS, my application is now crashing with the following error:

2013-04-21 06:41:25.876 [error] <0.654.0> CRASH REPORT Process <0.654.0> with 0 neighbours exited with reason: {compile_forms,error} in glc_code:compile_forms/2 line 347 in application_master:init/4 line 138

There is no additional details in the crash log. I'm trying to get a fresh crash_dump now to see if that helps. I'll post anything interesting I find in there.

I cannot reproduce this issue on OS X at the moment.

The following example is on the README.md:

{lager, [
  {handlers, [
    {lager_console_backend, info},
    {lager_file_backend, [{file, "error.log"}, {level, error}]},
    {lager_file_backend, [{file, "console.log"}, {level, info}]}
    ]}
  ]}
]}.

I couldn't use it as it is. Did the configuration changed?

Hi.

Now, I'm trying some logging tools for my advertising system.
I benchmarked log4erl, error_logger and lager.
I try to write some simple application log to file from yaws (an erlang web server) application.

result in lager was 100+ times slower than others.

did I make any miss configuration or insane use of lager?
entire my benchmark code is here

each benchmark code are blow. ( these are appmods on embedded yaws ).

• lager
• error_handler
• log4erl

ab result:

lagger
Requests per second:    47.78 [#/sec] (mean)

error_handler
Requests per second:    8138.14 [#/sec] (mean)

log4erl
Requests per second:    7291.94 [#/sec] (mean)

• lager config is such like this
• I use latest lager (master branch on github)
• I use "ab" command (a HTTP benchmark tool A.K.A. apache bench ) to benchmark.
  • ab's concurrency level is 10 (this is not so heavy condition for our advertising server).
• Erlang VM " Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:4:4] [async-threads:0] [kernel-poll:false] "
• benchmark on Debian 3.2.32-1 with Intel(R) Core(TM)2 Quad CPU Q9550 @ 2.83GHz
  • the machine is slow. but i think this is NOT machine power issue.

Hi,

I can't get the compilation for a simple lager:info call to work. I'm not sure whether this is due to the use of boss_compiler (from ChicagoBoss) or not. The error:

== build:erlang ==================
failed to load: {{badmatch,
                  {error,
                   [{[],
                     [{none,compile,
                       {parse_transform,lager_transform,
                        {badarg,
                         [{erlang,integer_to_list,[{45,10}],[]},
                          {lager_transform,make_varname,2,
                           [{file,"src/lager_transform.erl"},{line,204}]},
                          {lager_transform,transform_statement,1,
                           [{file,"src/lager_transform.erl"},{line,140}]},
                          {lager_transform,walk_body,2,
                           [{file,"src/lager_transform.erl"},{line,71}]},
                          {lager_transform,walk_clauses,2,
                           [{file,"src/lager_transform.erl"},{line,66}]},
                          {lager_transform,walk_ast,2,
                           [{file,"src/lager_transform.erl"},{line,51}]},
                          {compile,'-foldl_transform/2-anonymous-2-',2,
                           [{file,"compile.erl"},{line,843}]},
                          {compile,foldl_transform,2,
                           [{file,"compile.erl"},{line,845}]}]}}}]}]}},
                 [{boss_load,load_all_modules,3,
                   [{file,"src/boss/boss_load.erl"},{line,26}]},
                  {tetrapak_boss,run,2,
                   [{file,
                     "/home/tino/Documents/2working/tetrapak_boss/src/tetrapak_boss.erl"},
                    {line,87}]},
                  {tetrapak_task,try_run,3,
                   [{file,"src/tetrapak_task.erl"},{line,147}]},
                  {tetrapak_task,worker,4,
                   [{file,"src/tetrapak_task.erl"},{line,85}]}]}

The code which crashes expects Line to be a interger, while it is a tuple here. Any idea where that could come from?

Hello I have a supervisor that has a restart strategy of {one_for_all, 0, 1} and a child with a restart of permanent. With Lager errors get logged when the child goes down with {stop, normal, NewState} but the standard error logger doesn't report errors when I do this. Is this considered a bug or working as intended? Either way I don't want errors logged in this situation, is there something I can do to suppress these?

-Xavier

Compiling a project, containgin the uuid module:
{uuid, ".*", {git, "http://git.gitorious.org/avtobiff/erlang-uuid.git", {tag, "v0.3.3"}}}
crashes with a lengthy error message:

https://gist.github.com/2919452

According to the docs, {crash_log, undefined} should disable the crash log, instead it creates a crash log named undefined.

If you have some subsystem go haywire and spam the same message over and over, lager currently doesn't have any protections to suppress the duplicates. Syslog, for example, will print 'last message repeated N times'.

Unfortunately, it's problematic to detect duplicate messages like this in a gen_event. One idea would be to add a 'proxy process' that is solely responsible for detecting duplicate messages and counting the number of duplicates before a different message comes in. The process could be a simple loop that just kept track of the last message and a duplicate count and it'd sit between the process calling the log functions and the gen_event.

All calls to lager:log end up calling safe_format_chop with limit hard-coded to 4096. Users should be able to pass in a limit (or specify no limit) when the logging function, whether through lager:log or parse transform, is called.

lager:error("error R3: ~p",[[13,11,10,8,5,4]]),
this code will output:
16:46:00.063 [error] error R3: "[11,10,8,5,4]
so,where is 13?
:)

Hi,

I randomly get this crash sometimes. Why do you think would this be happening?

2012-06-21 18:52:23 =CRASH REPORT====
crasher:
initial call: tcp_handler_stream_manager:init/1
pid: <0.87.0>
registered_name: []
exception exit: {{undef,[{lager,debug,["~s",["2e397cc9-cb3e-4486-9526-675c509d1640"]],[]},{tcp_handler_stream_manager,init,1,[{file,"/home/satyamshekhar/Projects/directi/tcp-handler-erlang/src/tcp_handler_stream_manager.erl"},{line,70}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,304}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]},[{gen_server,init_it,6,[{file,"gen_server.erl"},{line,328}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
ancestors: [<0.85.0>,tcp_handler_session_sup,tcp_handler_sup,<0.34.0>]
messages: []
links: [<0.85.0>]
dictionary: []
trap_exit: false
status: running
heap_size: 987
stack_size: 24
reductions: 167
neighbours:
neighbour: [{pid,<0.86.0>},{registered_name,[]},{initial_call,{tcp_handler_event_machine,init,['Argument__1']}},{current_function,{gen_server,loop,6}},{ancestors,[<0.85.0>,tcp_handler_session_sup,tcp_handler_sup,<0.34.0>]},{messages,[]},{links,[<0.85.0>]},{dictionary,[]},{trap_exit,false},{status,waiting},{heap_size,377},{stack_size,9},{reductions,1163}]
neighbour: [{pid,<0.85.0>},{registered_name,[]},{initial_call,{tcp_handler_session,init,['Argument__1']}},{current_function,{proc_lib,sync_wait,2}},{ancestors,[tcp_handler_session_sup,tcp_handler_sup,<0.34.0>]},{messages,[{ack,<0.87.0>,{error,{undef,[{lager,debug,["~s",["2e397cc9-cb3e-4486-9526-675c509d1640"]],[]},{tcp_handler_stream_manager,init,1,[{file,"/home/satyamshekhar/Projects/directi/tcp-handler-erlang/src/tcp_handler_stream_manager.erl"},{line,70}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,304}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}}}]},{links,[<0.86.0>,<0.87.0>,<0.78.0>]},{dictionary,[{random_seed,{18691,19201,259}}]},{trap_exit,false},{status,runnable},{heap_size,610},{stack_size,23},{reductions,1227}]

They should be there.

Hi, I've recently upgraded to Lager 1.2.1 and now our console configuration...

{lager_console_backend, [info, debug]},

... to print verbose MFA & line number details cause the following error...

"Lager failed to install handler lager_console_backend into lager_event"

lager_console_backend.erl line 39 was reported as the problem, and looking at the src i can see that the args [info, debug] is now only for backward compatibility. I changed the list to a single atom which solves the problem but i no longer have MFA, line numbers etc on the console when developing.

Thought it worth mentioning,

Andy.

When lager_backend_throttle is active and logger is constantly little overloaded, such that message_queue_len is near async_threshold, it is possible that throttle backend will switch async between true/false too frequently (oscillation). There is not a big problem, but leads to frequent ETS updates and addition (but minor) delays. So, it may be better to add some "switch window" to prevent that.

So, you configure (or hardcode) async_threshold_window and async_threshold.

WindowMin = Threshold - (Window / 2),
WindowMax = Threshold + (Window / 2),

case {Len > WindowMax, Len < WindowMin, IsAsync} of
    {true, _, true} ->
        lager_config:set(async, false),
        ...;
    {_, true, false} ->
        lager_config:set(async, true),
        ...;
    _ -> ok
end.

Hi,

I am getting this crash in one of our eunit tests. Unfortunately, I do not have too much more detail other than to show how the call to lager is being used in the function in our code. We are using the manual call rather than the parse_transform due to how this is used to boot strap:

encode_fields(Fields, Values, Encode) ->
lager:log(debug, self(), "herd_proto:encode_fields: Fields=~p, Values=~p", [Fields, Values]),
[encode_field(F, V, Encode) || {F, V} <- lists:zip(Fields, Values), V =/= undefined].

Here is the error from the console. Also note, this is not present in any of the logs:

herd_proto_tests: encoder_test...22:12:52.162 [debug] --------- parser_test() START ---------
failed
::error:badarg
in function io_lib:format/2
called as format("FORMAT ERROR: ~s ~s",[""herd_proto:encode_fields: Fields=~p, Values=~p"",
[91,
[[91,
[[123,["float",44,"lat",44|...],125],
44,
[123,["float",44|...],125],
44,
[123,[...]|...],
44,
[...]],
93],
44,
[34,100.0,100.0,34,91,[[...]|...],93]],
93]])
in call from lager:safe_format_chop/3
in call from lager:log/4
in call from herd_proto:encode_fields/3
in call from herd_proto:'-message_encoder/1-fun-0-'/5
in call from herd_proto:encode_field/3
in call from herd_proto:'-encode_fields/3-lc$^0/1-0-'/2

A bit more information. When I comment out the call to lager:log(), the tests pass with no issues. The failure occurs on field definitions and values that involve floats - not sure if that has any baring because of the previous float bugs.

Finally, this is happening on a MacBook Pro with Erlang R14B02 (erts-5.8.3). I will test it out on our Ubuntu instances in the morning.

Hi,

It would be nice for lager to support multiple log files.
My common scenario is to provide a system log (basically just everything, debug levels matter) and audit log (only certain ✨business✨ actions usually with no debug level distinction).

I guess I could write a custom file backend for this, just wanted to ask if there's a better way or would you consider adding support for multiple log types.

Thanks

Hi,

I have just started to play with Lager so probably I'm doing something but I'm no able to log to file.

My setup:

• I have included the lager_transform directive in rebar.config

• I have copied the lager app config to my app.config

  [
  {lager, [
    {handlers, [
      {lager_console_backend, info},
      {lager_file_backend, [
        {"info.log", info, 0, "", 5},
        {"debug.log", debug, 0, "", 5}
      ]}
    ]}
  ]}
  ].

• Inside my code I have several calls to lager

  handle_cast(_, State) ->
  %lager:error("Error msg"),
  lager:info("Info msg"),
  lager:debug("Debug msg"),
  lager:warning("Warming msg"),
  {noreply, State}.

I have an escript script to run a quick test:

 main(_) ->
  inets:start(),
  lager:start(),
  {ok, Worker} = qrauth_worker:start_link(),
  qrauth_worker:request(Worker).

Inside qrauth_worker:request/1 I do a gen_server:cast which is handled by the code above.

When I run the escript this is the output in the console:

>>./worker 
11:07:35.394 [info] Application lager started on node nonode@nohost
11:07:35.399 [info] Application amqp_client started on node nonode@nohost
11:07:35.443 [info] Info msg
11:07:35.443 [warning] Warming msg

Which is the expected output according to my lager statements and my lager config.

But my info.log and debug.log files are empty.

To make things a bit more weird for me, if I include a lager:error statement this one flushes the log to the files but fails to output the error msg to the console.

This is the code with the lager:error

handle_cast(_, State) ->
  lager:info("Info msg"),
  lager:debug("Debug msg"),
  lager:warning("Warming msg"),
  lager:error("Error msg"),
  {noreply, State}.

This is the console output

>>./worker 
11:07:35.394 [info] Application lager started on node nonode@nohost
11:07:35.399 [info] Application amqp_client started on node nonode@nohost
11:07:35.443 [info] Info msg
11:07:35.443 [warning] Warming msg

Notice that the [error] log is missing in the console output

And this is my info.log

>>cat info.log 
2012-07-14 11:17:24.379 [info] <0.6.0> Application lager started on node nonode@nohost
2012-07-14 11:17:24.384 [info] <0.6.0> Application amqp_client started on node nonode@nohost
2012-07-14 11:17:24.424 [info] <0.75.0>@qrauth_worker:init:62 Starting worker
2012-07-14 11:17:24.434 [info] <0.75.0>@qrauth_worker:handle_cast:93 Info msg
2012-07-14 11:17:24.434 [warning] <0.75.0>@qrauth_worker:handle_cast:95 Warming msg
2012-07-14 11:17:24.435 [error] <0.75.0>@qrauth_worker:handle_cast:96 Error msg

Any hints or ideas. Thanks

The error_logger_lager_h gen_event handler crashes with a badarg on a crashing gen_server which has a name which is not an atom. Supervisor children can be named with any term. See http://www.erlang.org/doc/man/supervisor.html#type-child_id

(Besides, the original code only works since for some odd reason Erlang allows atoms as arguments to ~s)

Line 182 in error_logger_lager_h.erl

io_lib:format("~s started with ~s at ~w",

should change into

io_lib:format("~w started with ~s at ~w",

Webmachine generates crash_reports like this:

[{initial_call,
            {mochiweb_acceptor,init,
                ['Argument__1','Argument__2','Argument__3']}},
        {pid,<0.1061.0>},
        {registered_name,[]},
        {error_info,
            {error,function_clause,
                [{mochiweb,new_request,
                     [{#Port<0.6956>,{"WTF","1.1",{0,9}},[]}]},
                 {mochiweb_http,headers,5},
                 {proc_lib,init_p_do_apply,3}]}},
        {ancestors,['http_127.0.0.1:8098',riak_core_sup,<0.75.0>]},
        {messages,[]},
        {links,[<0.91.0>,#Port<0.6956>]},
        {dictionary,[]},
        {trap_exit,false},
        {status,running},
        {heap_size,377},
        {stack_size,24},
        {reductions,1152}]

These are unusual in that the error_info is {error, Reason, Stacktrace} as opposed to the more common:

{exit,
                {function_clause,
                    [{crash,function,[{}]},
                     {crash,handle_call,3},
                     {gen_server,handle_msg,5},
                     {proc_lib,init_p_do_apply,3}]},
                [{gen_server,terminate,6},{proc_lib,init_p_do_apply,3}]}

Which is {exit, Reason, Stacktrace}, but Reason has more information in it, for some reason.

I can't even generate the first style of crash reports without sending garbage to webmachine on the http port. exit(), erlang:error() and spawn_link all generate the {exit, ...} style crash reports.

I had this error while compiling lager, please help me to fix this error:

ERROR: compile failed while processing /home/user/myapp/deps/lager: {'EXIT',{undef,[{epp,set_encoding,[<0.38.0>],[]},
{epp_dodger,parse_file,3,[{file,"epp_dodger.erl"},{line,189}]},
{rebar_erlc_compiler,compile_priority,1,[]},
{rebar_erlc_compiler,'-doterl_compile/3-fun-0-',2,[]},
{lists,foldl,3,[{file,"lists.erl"},{line,1197}]},
{rebar_erlc_compiler,doterl_compile,3,[]},
{rebar_core,run_modules,4,[]},
{rebar_core,execute,5,[]}]}}
make: *** [compile] Error 1

It will be useful to be able to write to several log files.
A use case is logging from several databases or a webserver with several virtual hosts.

Each log file will be tagged with an erlang term(not just an atom).
This is useful if the host name is a string or binary for example:

LogFile = "example1.com",
lager:set_filename(LogFile, "/path/to/filename")

To log an error for a specific virtual host you'll use:

lager:error(LogFile, "Some message")

Thanks

Can lager work with R15B as well as previous.

Been seeing this in my logs lately, sometimes resulting in a VM crash, do you have any idea what is is?

2012-02-03 10:50:11.841 [error] <0.23285.0> Lager event handler error_logger_lager_h exited with reason {'EXIT',{{case_clause,<<255,248,0,0,0,0,0,0>>},[{io_lib_format,mantissa_exponent,1},{io_lib_format,fwrite_g,1},{lager_trunc_io,print,3},{lager_trunc_io,list_body,4},{lager_trunc_io,alist_start,3},{lager_trunc_io,list_bodyc,4},{lager_trunc_io,list_bodyc,4},{lager_trunc_io,list_body,4}]}}

When building a simple_one_for_one supervisor the Id part of the child spec is ignored and is implicitly set to undefined. This means that certain information is missing in the console.log because format_offender will treat it as a supervisor_bridge. It's not a huge deal because a crash report will also be logged to crash.log but it would be nice to fix this.

Given a crash like this:

https://gist.github.com/goshh/5289943/raw/d2a53673b7b115813a891b202a3feec2e465ac1d/gistfile1.txt

we output a message like this

no function clause matching gen_server:terminate/6

Which is sort of a lie, handle_cast actually function_claused, but the stacktrace that terminate() spits out is kind of misleading, thus we mislead you, gentle logfile reader.

We should try to do something more like this:

no function clause matching pivot_call:handle_cast({wh_amqp_channel,{new_channel,false}})

All of the necessary information is provided, it's just not terribly accessible, especially the module name.

Example:

15:46:09.807 [info] Application riak_search exited with reason: {bad_return,{{riak_search_app,start,[normal,[]]},{'EXIT',{{case_clause,search},[{riak_search_app,start,2},{application_master,start_it_old,4}]}}}}

One thing I found with lager was that it was incredibly frustrating to look at crash dumps and stacks on the console output compared to the sasl formatted version. Lager currently stuffs the entire thing in to one gargantuan unreadable line. It just adds to the hassle of debugging a problem.

I don't suppose it'd be possible to setup lager to generate developer friendly dumps in some manner?

Sometimes I could observe something like that in error.log:

2012-10-17 13:40:29.228 [error] <0.57.0> Lager event handler error_logger_lager_h exited with reason {'EXIT',{function_clause,[{lager,log,[error,emulator,["Error in process <0.1678.0> on node 'n1@localhost' with exit value: {function_clause,[{cowboy_protocol,parse_method,[<<0 bytes>>,{state,<0.87.0>,#Port<0.19453>,ranch_tcp,[{'_',[{['...'],http_handlers,{}}]}],undefined,undefined,5,1,infinity,4096,64,4096,100,5000,false,infinity,undefined},<<5 bytes>>],[{file,\"src/cowboy_protocol.erl\"},{line... \n","\n"]],[{file,"src/lager.erl"},{line,86}]},{error_logger_lager_h,handle_event,2,...},...]}}

Seems that it is caused by second argument to lager:log. It is emulator but lager:log handles only pids and lists, but not atoms.

Lager is at

ed7e2aa Test and fix for a printable yet improper list

Erlang is

Erlang R15B02 (erts-5.9.2) [source] [64-bit] [async-threads:0] [hipe] [kernel-poll:true]

but HiPE feature is not used anywhere.

The error_logger_lager_h.erl uses macro overloading that was added in Erlang 5.7.5/OTP R13B04. Therefore, Lager cannot be compiled with Erlang/OTP R13B01.

Since this is the only blocking issue preventing Lager from running with OTP R13B01 I'd suggest to avoid overloading the LOG macro in error_logger_lager_h.erl and using two macros instead.

erlang:system_flag(scheduler_bind_type, spread).

20:24:56.530 [error] Lager event handler error_logger_lager_h exited with reason {'EXIT',{function_clause,[{lager,log,[error,emulator,["A call to erlang:system_flag(scheduler_bind_type, _) was\nmade. The scheduler_bind_type argument is deprecated and\nscheduled for removal in erts-5.10/OTP-R16. For more\ninformation see the erlang:system_flag/2 documentation.\n","\n"]],[{file,"src/lager.erl"},{line,86}]},{error_logger_lager_h,handle_event,2,[{file,"src/error_logger_lager_h.erl"},{line,91}]},{gen_event,server_update,4,[{file,"gen_event.erl"},{line,504}]},{gen_event,server_notify,...},...]}}

I think that problem is in error emulator

I had lager working with my server application on R15B03-1, after porting the app to R16B lager app doesn't start, i.e. freezes. When testing in Erlang REPL:

([email protected])1> application:start(lager).

... waited few minutes and then pressed CTRL-C ...

[os_mon] cpu supervisor port (cpu_sup): Erlang has closed
[os_mon] memory supervisor port (memsup): Erlang has closed
$ ^C

This reproducing with lager application only from Erlang REPL.
Tested with latest master branch - same problem.