Per-module logging (#3590)

doc/code_snippets/test/logging/log_existing_c_modules_test.lua

@@ -0,0 +1,48 @@
+local fio = require('fio')
+local server = require('luatest.server')
+local t = require('luatest')
+local g = t.group()
+
+g.before_each(function(cg)
+    cg.server = server:new {
+        workdir = fio.cwd() .. '/tmp',
+        box_cfg = { log_level = 'warn',
+                    log_modules = { tarantool = 'info' } }
+    }
+    cg.server:start()
+    cg.server:exec(function()
+        ffi = require('ffi')
+
+        -- Prints 'info' messages --
+        ffi.C._say(ffi.C.S_INFO, nil, 0, nil, 'Info message from C module')
+        --[[
+        [6024] main/103/interactive I> Info message from C module
+        ---
+        ...
+        --]]
+
+        -- Swallows 'debug' messages --
+        ffi.C._say(ffi.C.S_DEBUG, nil, 0, nil, 'Debug message from C module')
+        --[[
+        ---
+        ...
+        --]]
+    end)
+end)
+
+g.after_each(function(cg)
+    cg.server:stop()
+    cg.server:drop()
+end)
+
+local function find_in_log(cg, str, must_be_present)
+    t.helpers.retrying({ timeout = 0.3, delay = 0.1 }, function()
+        local found = cg.server:grep_log(str) ~= nil
+        t.assert(found == must_be_present)
+    end)
+end
+
+g.test_log_contains_messages = function(cg)
+    find_in_log(cg, 'Info message from C module', true)
+    find_in_log(cg, 'Debug message from C module', false)
+end

doc/code_snippets/test/logging/log_existing_modules_test.lua

@@ -0,0 +1,56 @@
+local fio = require('fio')
+local server = require('luatest.server')
+local t = require('luatest')
+local g = t.group()
+
+local run_before_cfg = [[
+    module1 = require('test.logging.module1')
+    module2 = require('test.logging.module2')
+]]
+
+g.before_each(function(cg)
+    cg.server = server:new {
+        env = {
+            ['TARANTOOL_RUN_BEFORE_BOX_CFG'] = run_before_cfg,
+        },
+        workdir = fio.cwd() .. '/tmp',
+        box_cfg = { log_modules = {
+            ['test.logging.module1'] = 'verbose',
+            ['test.logging.module2'] = 'error' }
+        }
+    }
+    cg.server:start()
+    cg.server:exec(function()
+        -- Prints 'info' messages --
+        module1.say_hello()
+        --[[
+        [92617] main/103/interactive/test.logging.module1 I> Info message from module1
+        ---
+        ...
+        --]]
+
+        -- Swallows 'info' messages --
+        module2.say_hello()
+        --[[
+        ---
+        ...
+        --]]
+    end)
+end)
+
+g.after_each(function(cg)
+    cg.server:stop()
+    cg.server:drop()
+end)
+
+local function find_in_log(cg, str, must_be_present)
+    t.helpers.retrying({ timeout = 0.3, delay = 0.1 }, function()
+        local found = cg.server:grep_log(str) ~= nil
+        t.assert(found == must_be_present)
+    end)
+end
+
+g.test_log_contains_messages = function(cg)
+    find_in_log(cg, 'Info message from module1', true)
+    find_in_log(cg, 'Info message from module2', false)
+end

doc/code_snippets/test/logging/log_new_modules_test.lua

@@ -0,0 +1,61 @@
+local fio = require('fio')
+local server = require('luatest.server')
+local t = require('luatest')
+local g = t.group()
+
+g.before_each(function(cg)
+    cg.server = server:new {
+        workdir = fio.cwd() .. '/tmp',
+        box_cfg = { log_level = 'warn',
+                    log_modules = {
+                        module1 = 'verbose',
+                        module2 = 'error' }
+        }
+    }
+    cg.server:start()
+    cg.server:exec(function()
+        -- Creates new loggers --
+        module1_log = require('log').new('module1')
+        module2_log = require('log').new('module2')
+
+        -- Prints 'info' messages --
+        module1_log.info('Info message from module1')
+        --[[
+        [16300] main/103/interactive/module1 I> Info message from module1
+        ---
+        ...
+        --]]
+
+        -- Swallows 'debug' messages --
+        module1_log.debug('Debug message from module1')
+        --[[
+        ---
+        ...
+        --]]
+
+        -- Swallows 'info' messages --
+        module2_log.info('Info message from module2')
+        --[[
+        ---
+        ...
+        --]]
+    end)
+end)
+
+g.after_each(function(cg)
+    cg.server:stop()
+    cg.server:drop()
+end)
+
+local function find_in_log(cg, str, must_be_present)
+    t.helpers.retrying({ timeout = 0.3, delay = 0.1 }, function()
+        local found = cg.server:grep_log(str) ~= nil
+        t.assert(found == must_be_present)
+    end)
+end
+
+g.test_log_contains_messages = function(cg)
+    find_in_log(cg, 'Info message from module1', true)
+    find_in_log(cg, 'Debug message from module1', false)
+    find_in_log(cg, 'Info message from module2', false)
+end

doc/code_snippets/test/logging/log_test.lua

@@ -0,0 +1,47 @@
+local fio = require('fio')
+local server = require('luatest.server')
+local t = require('luatest')
+local g = t.group()
+
+g.before_each(function(cg)
+    cg.server = server:new {
+        workdir = fio.cwd() .. '/tmp',
+        box_cfg = { log_level = 'warn' }
+    }
+    cg.server:start()
+    cg.server:exec(function()
+        log = require('log')
+
+        -- Prints 'warn' messages --
+        log.warn('Warning message')
+        --[[
+        2023-07-20 11:03:57.029 [16300] main/103/interactive/tarantool [C]:-1 W> Warning message
+        ---
+        ...
+        --]]
+
+        -- Swallows 'debug' messages --
+        log.debug('Debug message')
+        --[[
+        ---
+        ...
+        --]]
+    end)
+end)
+
+g.after_each(function(cg)
+    cg.server:stop()
+    cg.server:drop()
+end)
+
+local function find_in_log(cg, str, must_be_present)
+    t.helpers.retrying({ timeout = 0.3, delay = 0.1 }, function()
+        local found = cg.server:grep_log(str) ~= nil
+        t.assert(found == must_be_present)
+    end)
+end
+
+g.test_log_contains_messages = function(cg)
+    find_in_log(cg, 'Warning message', true)
+    find_in_log(cg, 'Debug message', false)
+end

doc/code_snippets/test/logging/module1.lua

@@ -0,0 +1,6 @@
+return {
+    say_hello = function()
+        local log = require('log')
+        log.info('Info message from module1')
+    end
+}

doc/code_snippets/test/logging/module2.lua

@@ -0,0 +1,6 @@
+return {
+    say_hello = function()
+        local log = require('log')
+        log.info('Info message from module2')
+    end
+}

doc/reference/configuration/cfg_logging.rst

@@ -9,6 +9,7 @@ application.
 * :ref:`log_nonblock <cfg_logging-log_nonblock>`
 * :ref:`too_long_threshold <cfg_logging-too_long_threshold>`
 * :ref:`log_format <cfg_logging-log_format>`
+* :ref:`log_modules <cfg_logging-log_modules>`
 
 .. _cfg_logging-log_level:
 
@@ -208,6 +209,113 @@ application.
     | Environment variable: TT_LOG_FORMAT
     | Dynamic: **yes**
 
+
+.. _cfg_logging-log_modules:
+
+.. confval:: log_modules
+
+    Since version :doc:`2.11.0 </release/2.11.0>`.
+    Configure the specified log levels (:ref:`log_level <cfg_logging-log_level>`) for different modules.
+
+    You can specify a logging level for the following module types:
+
+    *   Modules (files) that use the default logger.
+        Example: :ref:`Set log levels for files that use the default logger <cfg_logging-logging_example_existing_modules>`.
+
+    *   Modules that use custom loggers created using the :ref:`log.new() <log-new>` function.
+        Example: :ref:`Set log levels for modules that use custom loggers <cfg_logging-logging_example_new_modules>`.
+
+    *   The ``tarantool`` module that enables you to configure the logging level for Tarantool core messages. Specifically, it configures the logging level for messages logged from non-Lua code, including C modules.
+        Example: :ref:`Set a log level for C modules <cfg_logging-logging_example_tarantool_module>`.
+
+    | Type: table
+    | Default: blank
+    | Environment variable: TT_LOG_MODULES
+    | Dynamic: **yes**
+    |
+
+
+    .. _cfg_logging-logging_example_existing_modules:
+
+    **Example 1: Set log levels for files that use the default logger**
+
+    Suppose you have two identical modules placed by the following paths: ``test/logging/module1.lua`` and ``test/logging/module2.lua``.
+    These modules use the default logger and look as follows:
+
+    ..  literalinclude:: /code_snippets/test/logging/module1.lua
+        :language: lua
+        :dedent:
+
+    To load these modules in your application, you need to add the corresponding ``require`` directives:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_existing_modules_test.lua
+        :language: lua
+        :lines: 7-8
+        :dedent:
+
+    To configure logging levels, you need to provide module names corresponding to paths to these modules.
+    In the example below, the ``box_cfg`` variable contains logging settings that can be passed to the ``box.cfg()`` function:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_existing_modules_test.lua
+        :language: lua
+        :lines: 17-20
+        :dedent:
+
+    Given that ``module1`` has the ``verbose`` logging level and ``module2`` has the ``error`` level, calling ``module1.say_hello()`` shows a message but ``module2.say_hello()`` is swallowed:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_existing_modules_test.lua
+        :language: lua
+        :lines: 24-37
+        :dedent:
+
+    .. _cfg_logging-logging_example_new_modules:
+
+    **Example 2: Set log levels for modules that use custom loggers**
+
+    In the example below, the ``box_cfg`` variable contains logging settings that can be passed to the ``box.cfg()`` function.
+    This example shows how to set the ``verbose`` level for ``module1`` and the ``error`` level for ``module2``:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_new_modules_test.lua
+        :language: lua
+        :lines: 9-13
+        :dedent:
+
+    To create custom loggers, call the :ref:`log.new() <log-new>` function:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_new_modules_test.lua
+        :language: lua
+        :lines: 17-19
+        :dedent:
+
+    Given that ``module1`` has the ``verbose`` logging level and ``module2`` has the ``error`` level, calling ``module1_log.info()`` shows a message but ``module2_log.info()`` is swallowed:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_new_modules_test.lua
+        :language: lua
+        :lines: 21-41
+        :dedent:
+
+    .. _cfg_logging-logging_example_tarantool_module:
+
+    **Example 3: Set a log level for C modules**
+
+    In the example below, the ``box_cfg`` variable contains logging settings that can be passed to the ``box.cfg()`` function.
+    This example shows how to set the ``info`` level for the ``tarantool`` module:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_existing_c_modules_test.lua
+        :language: lua
+        :lines: 9-10
+        :dedent:
+
+    The specified level affects messages logged from C modules:
+
+    ..  literalinclude:: /code_snippets/test/logging/log_existing_c_modules_test.lua
+        :language: lua
+        :lines: 14-29
+        :dedent:
+
+    The example above uses the `LuaJIT ffi library <http://luajit.org/ext_ffi.html>`_ to call C functions provided by the ``say`` module.
+
+
 .. _cfg_logging-logging_example:
 
 *********************