Lager overflow. [JIRA: RIAK-2543]

[loguntsov]

I'm using lager and testing on high load with tsung.

I have many messages in message queue of default sink: I have loglevel as WARNING. And i see right behaviour in my log files. Have no tons messages in my log-files. But all messages (see below) from message queue are INFO level, and this situation need CPU and memory from machine to process them.

So i can decide that basic feature:

• When no handler is consuming a log level (eg. debug) no event is sent to the log handler

are broken or was implemented not right.

Please, could you explain me where i'm wrong ?

Thanks.

(ejabberd@ip-10-0-0-38)54> process_info(pid(0,186,0)).             
[{registered_name,lager_event},
 {current_function,{lager_util,level_to_num,1}},
 {initial_call,{proc_lib,init_p,5}},
 {status,running},
 {message_queue_len,29674},
 {messages,[{<0.21176.5>,
             {<0.21176.5>,#Ref<0.0.786435.194854>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,"<0.21176.5>"},
                                           {node,'ejabberd@ip-10-0-0-38'},
                                           {user,"14842"}],
                                          info,
                                          {["2016",45,"05",45,"05"],["06",58,"48",58,"19",46|...]},
                                          {1462,430899,745377},
                                          [76,111,111,107,117,112|...]}}}},
            {<0.6024.5>,
             {<0.6024.5>,#Ref<0.0.524295.70928>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,"<0.6024.5>"},
                                           {node,'ejabberd@ip-10-0-0-38'},
                                           {user,"7299"}],
                                          info,
                                          {["2016",45,"05",45,"05"],["06",58,"48",58,[...]|...]},
                                          {1462,430899,745385},
                                          [76,111,111,107,117|...]}}}},
            {<0.18924.5>,
             {<0.18924.5>,#Ref<0.0.262159.237765>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,"<0.18924.5>"},
                                           {node,'ejabberd@ip-10-0-0-38'},
                                           {user,[...]}],
                                          info,
                                          {["2016",45,"05",45,[...]],["06",58,"48",58|...]},
                                          {1462,430899,745380},
                                          [76,111,111,107|...]}}}},
            {<0.1814.7>,
             {<0.1814.7>,#Ref<0.0.524293.131603>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,"<0.1814.7>"},
                                           {node,'ejabberd@ip-10-0-0-38'},
                                           {user,...}],
                                          info,
                                          {["2016",45,"05",45|...],["06",58,[...]|...]},
                                          {1462,430899,745385},
                                          [76,111,111|...]}}}},
            {<0.26249.4>,
             {<0.26249.4>,#Ref<0.0.524298.33536>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,[...]},
                                           {node,...},
                                           {...}],
                                          info,
                                          {["2016",45,[...]|...],["06",58|...]},
                                          {1462,430899,745399},
                                          [76,111|...]}}}},
            {<0.7800.6>,
             {<0.7800.6>,#Ref<0.0.524294.130579>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,227},
                                           {pid,...},
                                           {...}|...],
                                          info,
                                          {["2016",45|...],[[...]|...]},
                                          {1462,430899,...},
                                          [76|...]}}}},
            {<0.13054.6>,
             {<0.13054.6>,#Ref<0.0.1572866.14507>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},
                                           {function,get_user_route},
                                           {line,...},
                                           {...}|...],
                                          info,
                                          {[[...]|...],[...]},
                                          {1462,...},
                                          [...]}}}},
            {<0.4002.5>,
             {<0.4002.5>,#Ref<0.0.524296.43809>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,mod_muc_registrar},{function,...},{...}|...],
                                          info,
                                          {[...],...},
                                          {...},...}}}},
            {<0.16338.5>,
             {<0.16338.5>,#Ref<0.0.1572865.200181>},
             {sync_notify,{log,{lager_msg,[],
                                          [{module,...},{...}|...],
                                          info,{...},...}}}},
            {<0.24666.5>,
             {<0.24666.5>,#Ref<0.0.524299.17115>},
             {sync_notify,{log,{lager_msg,[],[{...}|...],info,...}}}},
            {<0.19118.5>,
             {<0.19118.5>,#Ref<0.0.262158.244692>},
             {sync_notify,{log,{lager_msg,[],[...],...}}}},
            {<0.2482.5>,
             {<0.2482.5>,#Ref<0.0.262156.249257>},
             {sync_notify,{log,{lager_msg,[],...}}}},
            {<0.11147.5>,
             {<0.11147.5>,#Ref<0.0.262160.230341>},
             {sync_notify,{log,{lager_msg,...}}}},
            {<0.25351.7>,
             {<0.25351.7>,#Ref<0.0.262157.241744>},
             {sync_notify,{log,{...}}}},
            {<0.31316.6>,
             {<0.31316.6>,#Ref<0.0.524292.131940>},
             {sync_notify,{log,...}}},
            {<0.9033.5>,
             {<0.9033.5>,#Ref<0.0.786435.194855>},
             {sync_notify,{...}}},
            {<0.24505.4>,
             {<0.24505.4>,#Ref<0.0.262159.237766>},
             {sync_notify,...}},
            {<0.1568.6>,{<0.1568.6>,...},{...}},
            {<0.4521.6>,{...},...},
            {<0.12471.5>,...},
            {...}|...]},
 {links,[<0.189.0>,<0.193.0>,<0.195.0>,<0.668.0>,<0.191.0>,
         #Port<0.1981>,<0.185.0>,#Port<0.1980>]},
 {dictionary,[{'$ancestors',[lager_sup,<0.184.0>]},
              {'$initial_call',{gen_event,init_it,6}}]},
 {trap_exit,true},
 {error_handler,error_handler},
 {priority,normal},
 {group_leader,<0.183.0>},
 {total_heap_size,51408249},
 {heap_size,7427328},
 {stack_size,36},
 {reductions,505250072},
 {garbage_collection,[{min_bin_vheap_size,46422},
                      {min_heap_size,233},
                      {fullsweep_after,65535},
                      {minor_gcs,36}]},
 {suspending,[]}]

[loguntsov]

I have custom ejabberd with lager 3.2.0

[jadeallenx]

It's possible there's an error in the parse transformation code (assuming you're using parse transformation), but do you have traces defined for the sink?

That makes log dispatch bypass the filtering to drop messages that don't match the severity levels.

[loguntsov]

Yes. I'm using parse transform for lager. So what i should check from my side? How i can give you traces ?

by the way, i have manual way (via makefile) to compile ejabberd code with lager parse_tranform without rebar, and my compilation commands are like that: /usr/local/bin/erlc -W -DSSL40 -I .. -I ../../include -pa ../../deps/lager/ebin/ -pz .. -o .. ejabberd_http_bind.erl

May i should use some options of compilation ?

Version of erlang is 18.3

Thanks.

[jadeallenx]

I am talking about lager-specific "traces" that might be part of your lager configuration. What does your app.config file look like for lager?

[loguntsov]

I'm using dinamyc configuration of lager. No any traces. Just

    ConsoleLog = get_log_path(),
    ?INFO_MSG("Ejabberd's log is ~p~n", [ ConsoleLog ]),
    Dir = filename:dirname(ConsoleLog),
    Format = [ time, " [", severity, "]",
        {user, ["[u_", user, "]"], ""},
        {user_from, ["[u_", user_from, "f]"], ""},
        {user_to, ["[u_", user_to, "t]"], ""},
        {pid, [ pid ], ""},
        "[",
        {module, [
                module,
                {function, [":", function], ""},
                {line, [":",line], ""}
        ], "" }, "] ",
        message, "\n\n"
    ],
    FileFormat = [ date, " " ] ++ Format,
    ErrorLog = filename:join([Dir, "error.log"]),
    CrashLog = filename:join([Dir, "crash.log"]),
    LogRotateDate = get_string_env(log_rotate_date, ""),
    LogRotateSize = get_integer_env(log_rotate_size, 1000*1024*1024), %% 1 Gb of log.
    LogRotateCount = get_integer_env(log_rotate_count, 5),
    LogRateLimit = get_integer_env(log_rate_limit, 100),
    application:set_env(lager, error_logger_hwm, LogRateLimit),
    application:set_env(lager, handlers, [
    {lager_console_backend, info},
        {lager_file_backend, [
        {file, ConsoleLog},
        {level, info},
        {date, LogRotateDate},
        {count, LogRotateCount},
        {size, LogRotateSize},
            {formatter,lager_default_formatter},
            {formatter_config,FileFormat}
    ]},
        {lager_file_backend, [
            {file, ErrorLog},
            {level, error},
            {date, LogRotateDate},
            {count, LogRotateCount},
            {size, LogRotateSize},
            {formatter,lager_default_formatter},
            {formatter_config,FileFormat}
        ]}
    ]),
    application:set_env(lager, crash_log, CrashLog),
    application:set_env(lager, crash_log_date, LogRotateDate),
    application:set_env(lager, crash_log_size, LogRotateSize),
    application:set_env(lager, crash_log_count, LogRotateCount),

    application:set_env(lager, log_root, "/var/log/ejabberd"),

and changing log level dynamically:

lists:foreach(
              fun({lager_file_backend, File} = H) when File == ConsoleLog ->
                      lager:set_loglevel(H, LagerLogLevel);
                 (lager_console_backend = H) ->
                      lager:set_loglevel(H, LagerLogLevel);
                 (_) ->
                      ok
              end, gen_event:which_handlers(lager_event))

And yes, this code can be not good to change loglevel. Is there standard way to change minimal loglevel for ALL backends ? Because now we have other backends for lager and needs support them inside code above.

Now i think no issue inside lager. It is problem of our code. Thanks. Pls close this topic.