Separate log configuration from logging process

Closes #1317

bigchaindb/commands/bigchain.py

@@ -24,7 +24,8 @@ from bigchaindb.commands.messages import (
     CANNOT_START_KEYPAIR_NOT_FOUND,
     RETHINKDB_STARTUP_ERROR,
 )
-from bigchaindb.commands.utils import configure_bigchaindb, input_on_stderr
+from bigchaindb.commands.utils import (
+    configure_bigchaindb, start_logging_process, input_on_stderr)
 
 
 logging.basicConfig(level=logging.INFO)
@@ -169,6 +170,7 @@ def run_drop(args):
 
 
 @configure_bigchaindb
+@start_logging_process
 def run_start(args):
     """Start the processes to run the node"""
     logger.info('BigchainDB Version %s', bigchaindb.__version__)

bigchaindb/commands/utils.py

@@ -21,20 +21,56 @@ from bigchaindb.version import __version__
 
 
 def configure_bigchaindb(command):
+    """Decorator to be used by command line functions, such that the
+    configuration of bigchaindb is performed before the execution of
+    the command.
+
+    Args:
+        command: The command to decorate.
+
+    Returns:
+        The command wrapper function.
+
+    """
     @functools.wraps(command)
     def configure(args):
-        bigchaindb.config_utils.autoconfigure(filename=args.config, force=True)
+        try:
-
+            config_from_cmdline = {'log': {'level_console': args.log_level}}
-        logging_config = bigchaindb.config['log'] or {}
+        except AttributeError:
-        if 'log_level' in args and args.log_level:
+            config_from_cmdline = None
-            logging_config['level_console'] = args.log_level
+        bigchaindb.config_utils.autoconfigure(
-        setup_logging(user_log_config=logging_config)
+            filename=args.config, config=config_from_cmdline, force=True)
-
         command(args)
 
     return configure
 
 
+def start_logging_process(command):
+    """Decorator to start the logging subscriber process.
+
+    Args:
+        command: The command to decorate.
+
+    Returns:
+        The command wrapper function.
+
+    .. important::
+
+        Configuration, if needed, should be applied before invoking this
+        decorator, as starting the subscriber process for logging will
+        configure the root logger for the child process based on the
+        state of :obj:`bigchaindb.config` at the moment this decorator
+        is invoked.
+
+    """
+    @functools.wraps(command)
+    def start_logging(args):
+        from bigchaindb import config
+        setup_logging(user_log_config=config.get('log'))
+        command(args)
+    return start_logging
+
+
 # We need this because `input` always prints on stdout, while it should print
 # to stderr. It's a very old bug, check it out here:
 # - https://bugs.python.org/issue1927

tests/commands/rethinkdb/test_commands.py

@@ -38,7 +38,7 @@ def test_start_rethinkdb_exits_when_cannot_start(mock_popen):
 
 
 @patch('rethinkdb.ast.Table.reconfigure')
-def test_set_shards(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
+def test_set_shards(mock_reconfigure, monkeypatch, b):
     from bigchaindb.commands.bigchain import run_set_shards
 
     # this will mock the call to retrieve the database config
@@ -50,8 +50,6 @@ def test_set_shards(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     args = Namespace(num_shards=3, config=None)
     run_set_shards(args)
     mock_reconfigure.assert_called_with(replicas=1, shards=3, dry_run=False)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
-    mocked_setup_logging.reset_mock()
 
     # this will mock the call to retrieve the database config
     # we will set it to return three replica
@@ -61,10 +59,9 @@ def test_set_shards(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     monkeypatch.setattr(rethinkdb.RqlQuery, 'run', mockreturn_three_replicas)
     run_set_shards(args)
     mock_reconfigure.assert_called_with(replicas=3, shards=3, dry_run=False)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
-def test_set_shards_raises_exception(monkeypatch, b, mocked_setup_logging):
+def test_set_shards_raises_exception(monkeypatch, b):
     from bigchaindb.commands.bigchain import run_set_shards
 
     # test that we are correctly catching the exception
@@ -81,11 +78,10 @@ def test_set_shards_raises_exception(monkeypatch, b, mocked_setup_logging):
     with pytest.raises(SystemExit) as exc:
         run_set_shards(args)
     assert exc.value.args == ('Failed to reconfigure tables.',)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @patch('rethinkdb.ast.Table.reconfigure')
-def test_set_replicas(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
+def test_set_replicas(mock_reconfigure, monkeypatch, b):
     from bigchaindb.commands.bigchain import run_set_replicas
 
     # this will mock the call to retrieve the database config
@@ -97,8 +93,6 @@ def test_set_replicas(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     args = Namespace(num_replicas=2, config=None)
     run_set_replicas(args)
     mock_reconfigure.assert_called_with(replicas=2, shards=2, dry_run=False)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
-    mocked_setup_logging.reset_mock()
 
     # this will mock the call to retrieve the database config
     # we will set it to return three shards
@@ -108,10 +102,9 @@ def test_set_replicas(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     monkeypatch.setattr(rethinkdb.RqlQuery, 'run', mockreturn_three_shards)
     run_set_replicas(args)
     mock_reconfigure.assert_called_with(replicas=2, shards=3, dry_run=False)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
-def test_set_replicas_raises_exception(monkeypatch, b, mocked_setup_logging):
+def test_set_replicas_raises_exception(monkeypatch, b):
     from bigchaindb.commands.bigchain import run_set_replicas
 
     # test that we are correctly catching the exception
@@ -128,4 +121,3 @@ def test_set_replicas_raises_exception(monkeypatch, b, mocked_setup_logging):
     with pytest.raises(SystemExit) as exc:
         run_set_replicas(args)
     assert exc.value.args == ('Failed to reconfigure tables.',)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})

tests/commands/test_commands.py

@@ -74,7 +74,7 @@ def test_bigchain_run_start_assume_yes_create_default_config(
 # interfere with capsys.
 # See related issue: https://github.com/pytest-dev/pytest/issues/128
 @pytest.mark.usefixtures('ignore_local_config_file')
-def test_bigchain_show_config(capsys, mocked_setup_logging):
+def test_bigchain_show_config(capsys):
     from bigchaindb import config
     from bigchaindb.commands.bigchain import run_show_config
 
@@ -85,11 +85,9 @@ def test_bigchain_show_config(capsys, mocked_setup_logging):
     del config['CONFIGURED']
     config['keypair']['private'] = 'x' * 45
     assert output_config == config
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
-def test_bigchain_export_my_pubkey_when_pubkey_set(capsys, monkeypatch,
+def test_bigchain_export_my_pubkey_when_pubkey_set(capsys, monkeypatch):
-                                                   mocked_setup_logging):
     from bigchaindb import config
     from bigchaindb.commands.bigchain import run_export_my_pubkey
 
@@ -106,11 +104,9 @@ def test_bigchain_export_my_pubkey_when_pubkey_set(capsys, monkeypatch,
     lines = out.splitlines()
     assert config['keypair']['public'] in lines
     assert 'Charlie_Bucket' in lines
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
-def test_bigchain_export_my_pubkey_when_pubkey_not_set(monkeypatch,
+def test_bigchain_export_my_pubkey_when_pubkey_not_set(monkeypatch):
-                                                       mocked_setup_logging):
     from bigchaindb import config
     from bigchaindb.commands.bigchain import run_export_my_pubkey
 
@@ -126,49 +122,41 @@ def test_bigchain_export_my_pubkey_when_pubkey_not_set(monkeypatch,
     # https://docs.python.org/3/library/exceptions.html#SystemExit
     assert exc_info.value.code == \
         "This node's public key wasn't set anywhere so it can't be exported"
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
-def test_bigchain_run_init_when_db_exists(mocked_setup_logging,
+def test_bigchain_run_init_when_db_exists(mock_db_init_with_existing_db):
-                                          mock_db_init_with_existing_db):
     from bigchaindb.commands.bigchain import run_init
     args = Namespace(config=None)
     run_init(args)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @patch('bigchaindb.backend.schema.drop_database')
-def test_drop_db_when_assumed_yes(mock_db_drop, mocked_setup_logging):
+def test_drop_db_when_assumed_yes(mock_db_drop):
     from bigchaindb.commands.bigchain import run_drop
     args = Namespace(config=None, yes=True)
 
     run_drop(args)
     assert mock_db_drop.called
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @patch('bigchaindb.backend.schema.drop_database')
-def test_drop_db_when_interactive_yes(mock_db_drop, monkeypatch,
+def test_drop_db_when_interactive_yes(mock_db_drop, monkeypatch):
-                                      mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_drop
     args = Namespace(config=None, yes=False)
     monkeypatch.setattr('bigchaindb.commands.bigchain.input_on_stderr', lambda x: 'y')
 
     run_drop(args)
     assert mock_db_drop.called
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @patch('bigchaindb.backend.schema.drop_database')
-def test_drop_db_does_not_drop_when_interactive_no(mock_db_drop, monkeypatch,
+def test_drop_db_does_not_drop_when_interactive_no(mock_db_drop, monkeypatch):
-                                                   mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_drop
     args = Namespace(config=None, yes=False)
     monkeypatch.setattr('bigchaindb.commands.bigchain.input_on_stderr', lambda x: 'n')
 
     run_drop(args)
     assert not mock_db_drop.called
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 def test_run_configure_when_config_exists_and_skipping(monkeypatch):
@@ -417,7 +405,7 @@ def test_calling_main(start_mock, base_parser_mock, parse_args_mock,
 
 @pytest.mark.usefixtures('ignore_local_config_file')
 @patch('bigchaindb.commands.bigchain.add_replicas')
-def test_run_add_replicas(mock_add_replicas, mocked_setup_logging):
+def test_run_add_replicas(mock_add_replicas):
     from bigchaindb.commands.bigchain import run_add_replicas
     from bigchaindb.backend.exceptions import OperationError
 
@@ -427,9 +415,7 @@ def test_run_add_replicas(mock_add_replicas, mocked_setup_logging):
     mock_add_replicas.return_value = None
     assert run_add_replicas(args) is None
     assert mock_add_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
     mock_add_replicas.reset_mock()
-    mocked_setup_logging.reset_mock()
 
     # test add_replicas with `OperationError`
     mock_add_replicas.side_effect = OperationError('err')
@@ -437,9 +423,7 @@ def test_run_add_replicas(mock_add_replicas, mocked_setup_logging):
         run_add_replicas(args)
     assert exc.value.args == ('err',)
     assert mock_add_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
     mock_add_replicas.reset_mock()
-    mocked_setup_logging.reset_mock()
 
     # test add_replicas with `NotImplementedError`
     mock_add_replicas.side_effect = NotImplementedError('err')
@@ -447,14 +431,12 @@ def test_run_add_replicas(mock_add_replicas, mocked_setup_logging):
         run_add_replicas(args)
     assert exc.value.args == ('err',)
     assert mock_add_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
     mock_add_replicas.reset_mock()
-    mocked_setup_logging.reset_mock()
 
 
 @pytest.mark.usefixtures('ignore_local_config_file')
 @patch('bigchaindb.commands.bigchain.remove_replicas')
-def test_run_remove_replicas(mock_remove_replicas, mocked_setup_logging):
+def test_run_remove_replicas(mock_remove_replicas):
     from bigchaindb.commands.bigchain import run_remove_replicas
     from bigchaindb.backend.exceptions import OperationError
 
@@ -464,8 +446,6 @@ def test_run_remove_replicas(mock_remove_replicas, mocked_setup_logging):
     mock_remove_replicas.return_value = None
     assert run_remove_replicas(args) is None
     assert mock_remove_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
-    mocked_setup_logging.reset_mock()
     mock_remove_replicas.reset_mock()
 
     # test add_replicas with `OperationError`
@@ -474,8 +454,6 @@ def test_run_remove_replicas(mock_remove_replicas, mocked_setup_logging):
         run_remove_replicas(args)
     assert exc.value.args == ('err',)
     assert mock_remove_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
-    mocked_setup_logging.reset_mock()
     mock_remove_replicas.reset_mock()
 
     # test add_replicas with `NotImplementedError`
@@ -484,6 +462,4 @@ def test_run_remove_replicas(mock_remove_replicas, mocked_setup_logging):
         run_remove_replicas(args)
     assert exc.value.args == ('err',)
     assert mock_remove_replicas.call_count == 1
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
-    mocked_setup_logging.reset_mock()
     mock_remove_replicas.reset_mock()

tests/commands/test_utils.py

@@ -1,7 +1,6 @@
 import argparse
 from argparse import ArgumentTypeError, Namespace
 import logging
-from logging import getLogger
 
 import pytest
 
@@ -15,7 +14,7 @@ def reset_bigchaindb_config(monkeypatch):
 
 
 @pytest.mark.usefixtures('ignore_local_config_file', 'reset_bigchaindb_config')
-def test_configure_bigchaindb_configures_bigchaindb(mocked_setup_logging):
+def test_configure_bigchaindb_configures_bigchaindb():
     from bigchaindb.commands.utils import configure_bigchaindb
     from bigchaindb.config_utils import is_configured
     assert not is_configured()
@@ -26,7 +25,6 @@ def test_configure_bigchaindb_configures_bigchaindb(mocked_setup_logging):
 
     args = Namespace(config=None)
     test_configure(args)
-    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @pytest.mark.usefixtures('ignore_local_config_file',
@@ -39,22 +37,19 @@ def test_configure_bigchaindb_configures_bigchaindb(mocked_setup_logging):
     logging.ERROR,
     logging.CRITICAL,
 ))
-def test_configure_bigchaindb_configures_logging(log_level,
+def test_configure_bigchaindb_logging(log_level):
-                                                 mocked_setup_sub_logger):
     from bigchaindb.commands.utils import configure_bigchaindb
-    from bigchaindb.log.configs import PUBLISHER_LOGGING_CONFIG
+    from bigchaindb import config
-    root_logger = getLogger()
+    assert not config['log']
-    assert root_logger.level == logging.NOTSET
 
     @configure_bigchaindb
     def test_configure_logger(args):
-        root_logger = getLogger()
+        pass
-        assert root_logger.level == PUBLISHER_LOGGING_CONFIG['root']['level']
 
     args = Namespace(config=None, log_level=log_level)
     test_configure_logger(args)
-    mocked_setup_sub_logger.assert_called_once_with(
+    from bigchaindb import config
-        user_log_config={'level_console': log_level})
+    assert config['log'] == {'level_console': log_level}
 
 
 def test_start_raises_if_command_not_implemented():