[jira] [Created] (COUCHDB-2968) couch_log doesn't use the configured backend in the couchdb OTP release

["Mike Wallace (JIRA)" <ji...@apache.org>]

Mike Wallace created COUCHDB-2968:
-------------------------------------

             Summary: couch_log doesn't use the configured backend in the couchdb OTP release
                 Key: COUCHDB-2968
                 URL: https://issues.apache.org/jira/browse/COUCHDB-2968
             Project: CouchDB
          Issue Type: Bug
          Components: Logging
            Reporter: Mike Wallace


When testing the couch_log backends with the OTP release generated by {{make dist}} I found couch_log wasn't using the couch_log_lager backend, however when testing with a dev/run cluster it works as expected.

To test I used the following for rel/files/sys.config:

{code}
    [
        {lager, [
            {error_logger_hwm, 1000},
            {error_logger_redirect, true},
            {handlers, [
                {lager_file_backend,
                       [{file,"/tmp/allthelogs.log"},
                        {level,debug},
                        {size,10485760},
                        {date,"$D0"},
                        {count,5}]},
                {lager_console_backend, [error, {
                    lager_default_formatter,
                    [
                        date, " ", time,
                        " [", severity, "] ",
                        node, " ", pid, " ",
                        message,
                        "\n"
                    ]
                }]}
            ]}
        ]}
    ].
{code}

In a dev/run node I can do the following in a remsh:

{code}
    $ erl -name ohai@127.0.0.1 -remsh node1@127.0.0.1 -setcookie monster -hidden
    (node1@127.0.0.1)1> couch_log:info("A log statement", []). 
    ok
{code}

Then I can verify the log statement appears in the expected location:

{code}
    $ tail -n 5 /tmp/allthelogs.log
    2016-03-10 13:40:54.353 [notice] <0.711.0>@couch_log_lager:notice:43 Setup: [{<<"action">>,<<"receive_cookie">>},{<<"cookie">>,<<"monster">>}]
    2016-03-10 13:40:54.353 [notice] <0.711.0>@couch_log_lager:notice:43 receive_cookie: [{<<"action">>,<<"receive_cookie">>},{<<"cookie">>,<<"monster">>}]
    2016-03-10 13:40:54.354 [notice] <0.711.0>@couch_log_lager:notice:43 37ad126c7d 127.0.0.1 127.0.0.1:35984 POST /_cluster_setup 201 ok 1
    2016-03-10 13:40:55.172 [notice] <0.844.0>@couch_log_lager:notice:43 7f57dc0474 127.0.0.1 127.0.0.1:15984 POST /_cluster_setup 400 ok 673
    2016-03-10 13:43:44.887 [info] <0.3844.0>@couch_log_lager:info:39 A log statement
{code}

But for a node running from the OTP release created by {{make dist}} nothing
appears in the log until I have explictly called couch_log_lager:

{code}
    $ erl -name ohai@127.0.0.1 -remsh couchdb@127.0.0.1 -setcookie monster -hidden
    (couchdb@127.0.0.1)1> couch_log:info("A log statement", []). 
    ok
    (couchdb@127.0.0.1)2> module_loaded(couch_log_lager).
    false
    (couchdb@127.0.0.1)3> couch_log_lager:info("Another log statement", []).
    ok
    (couchdb@127.0.0.1)4> couch_log:info("One more log statement", []).
    ok
{code}

{code}
    $ tail -n 5 /tmp/allthelogs.log 
    2016-03-10 13:14:37.507 [info] <0.7.0> Application setup started on node 'couchdb@127.0.0.1'
    2016-03-10 13:14:37.507 [info] <0.7.0> Application snappy started on node 'couchdb@127.0.0.1'
    2016-03-10 13:14:37.855 [debug] <0.374.0>@lager_handler_watcher:94 Lager installed handler lager_backend_throttle into lager_event
    2016-03-10 13:18:52.264 [info] <0.3927.0>@couch_log_lager:info:39 Another log statement
    2016-03-10 13:19:00.521 [info] <0.3927.0>@couch_log_lager:info:39 One more log statement
{code}

Note the first log statement does not appear in /tmp/allthelogs.

I think this is a result of testing for whether the backend module is loaded
before we use it in couch_log *(1). With a dev/run node, {{module_loaded(couch_log_lager).}} returns {{true}} whereas with a built node it returns {{false}} until called explicitly.

I read up on Erlang's code server and thought I understood why - when running in {{interactive}} mode, the code server will load modules dynamically so if nothing calls couch_log_lager, it will never get loaded and couch_log will never use it. However what I don't understand is why it works with a dev/run node since that is also running in {{interactive}} mode - yet couch_log_lager is
automatically loaded.

The fix would appear to be to remove the test for module_loaded however we
should verify whether there are any negative implications if we do that.

(1) https://github.com/apache/couchdb-couch-log/blob/master/src/couch_log.erl#L116



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)