Update logging related code and tests after rebase

bigchaindb/commands/utils.py

@@ -25,10 +25,10 @@ def configure_bigchaindb(command):
     def configure(args):
         bigchaindb.config_utils.autoconfigure(filename=args.config, force=True)
 
-        logging_config = bigchaindb.config['logging'] or {}
+        logging_config = bigchaindb.config['log'] or {}
         if 'log_level' in args and args.log_level:
-            logging_config['level'] = args.log_level
+            logging_config['level_console'] = args.log_level
-        setup_logging(logging_config)
+        setup_logging(user_log_config=logging_config)
 
         command(args)
 

tests/commands/conftest.py

@@ -55,7 +55,7 @@ def run_start_args(request):
 @pytest.fixture
 def mocked_setup_logging(mocker):
     return mocker.patch(
-        'bigchaindb.commands.bigchain.setup_logging',
+        'bigchaindb.commands.utils.setup_logging',
         autospec=True,
         spec_set=True,
     )

tests/commands/rethinkdb/test_commands.py

@@ -16,7 +16,7 @@ def test_bigchain_run_start_with_rethinkdb(mock_start_rethinkdb,
     run_start(args)
 
     mock_start_rethinkdb.assert_called_with()
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @patch('subprocess.Popen')
@@ -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):
+def test_set_shards(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_set_shards
 
     # this will mock the call to retrieve the database config
@@ -50,6 +50,8 @@ def test_set_shards(mock_reconfigure, monkeypatch, b):
     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
@@ -59,9 +61,10 @@ def test_set_shards(mock_reconfigure, monkeypatch, b):
     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):
+def test_set_shards_raises_exception(monkeypatch, b, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_set_shards
 
     # test that we are correctly catching the exception
@@ -78,10 +81,11 @@ def test_set_shards_raises_exception(monkeypatch, b):
     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):
+def test_set_replicas(mock_reconfigure, monkeypatch, b, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_set_replicas
 
     # this will mock the call to retrieve the database config
@@ -93,6 +97,8 @@ def test_set_replicas(mock_reconfigure, monkeypatch, b):
     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
@@ -102,9 +108,10 @@ def test_set_replicas(mock_reconfigure, monkeypatch, b):
     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):
+def test_set_replicas_raises_exception(monkeypatch, b, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_set_replicas
 
     # test that we are correctly catching the exception
@@ -121,3 +128,4 @@ def test_set_replicas_raises_exception(monkeypatch, b):
     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

@@ -40,7 +40,7 @@ def test_bigchain_run_start(mock_run_configure,
     from bigchaindb.commands.bigchain import run_start
     args = Namespace(start_rethinkdb=False, allow_temp_keypair=False, config=None, yes=True)
     run_start(args)
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @pytest.mark.skipif(reason="BigchainDB doesn't support the automatic creation of a config file anymore")
@@ -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):
+def test_bigchain_show_config(capsys, mocked_setup_logging):
     from bigchaindb import config
     from bigchaindb.commands.bigchain import run_show_config
 
@@ -85,9 +85,11 @@ def test_bigchain_show_config(capsys):
     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
 
@@ -104,9 +106,11 @@ 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
 
@@ -122,41 +126,49 @@ 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(mock_db_init_with_existing_db):
+def test_bigchain_run_init_when_db_exists(mocked_setup_logging,
+                                          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):
+def test_drop_db_when_assumed_yes(mock_db_drop, mocked_setup_logging):
     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):
@@ -245,7 +257,7 @@ def test_allow_temp_keypair_generates_one_on_the_fly(
     args = Namespace(allow_temp_keypair=True, start_rethinkdb=False, config=None, yes=True)
     run_start(args)
 
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
     assert bigchaindb.config['keypair']['private'] == 'private_key'
     assert bigchaindb.config['keypair']['public'] == 'public_key'
 
@@ -270,7 +282,7 @@ def test_allow_temp_keypair_doesnt_override_if_keypair_found(mock_gen_keypair,
     args = Namespace(allow_temp_keypair=True, start_rethinkdb=False, config=None, yes=True)
     run_start(args)
 
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
     assert bigchaindb.config['keypair']['private'] == original_private_key
     assert bigchaindb.config['keypair']['public'] == original_public_key
 
@@ -289,7 +301,7 @@ def test_run_start_when_db_already_exists(mocker,
     monkeypatch.setattr(
         'bigchaindb.commands.bigchain._run_init', mock_run_init)
     run_start(run_start_args)
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
     assert mocked_start.called
 
 
@@ -311,7 +323,7 @@ def test_run_start_when_keypair_not_found(mocker,
     with pytest.raises(SystemExit) as exc:
         run_start(run_start_args)
 
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
     assert len(exc.value.args) == 1
     assert exc.value.args[0] == CANNOT_START_KEYPAIR_NOT_FOUND
     assert not mocked_start.called
@@ -337,7 +349,7 @@ def test_run_start_when_start_rethinkdb_fails(mocker,
     with pytest.raises(SystemExit) as exc:
         run_start(run_start_args)
 
-    mocked_setup_logging.assert_called_once_with()
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
     assert len(exc.value.args) == 1
     assert exc.value.args[0] == RETHINKDB_STARTUP_ERROR.format(err_msg)
     assert not mocked_start.called
@@ -405,7 +417,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):
+def test_run_add_replicas(mock_add_replicas, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_add_replicas
     from bigchaindb.backend.exceptions import OperationError
 
@@ -415,7 +427,9 @@ def test_run_add_replicas(mock_add_replicas):
     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')
@@ -423,7 +437,9 @@ def test_run_add_replicas(mock_add_replicas):
         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')
@@ -431,12 +447,14 @@ def test_run_add_replicas(mock_add_replicas):
         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):
+def test_run_remove_replicas(mock_remove_replicas, mocked_setup_logging):
     from bigchaindb.commands.bigchain import run_remove_replicas
     from bigchaindb.backend.exceptions import OperationError
 
@@ -446,6 +464,8 @@ def test_run_remove_replicas(mock_remove_replicas):
     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`
@@ -454,6 +474,8 @@ def test_run_remove_replicas(mock_remove_replicas):
         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`
@@ -462,4 +484,6 @@ def test_run_remove_replicas(mock_remove_replicas):
         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

@@ -12,7 +12,7 @@ def reset_bigchaindb_config(monkeypatch):
 
 
 @pytest.mark.usefixtures('ignore_local_config_file', 'reset_bigchaindb_config')
-def test_configure_bigchaindb_configures_bigchaindb():
+def test_configure_bigchaindb_configures_bigchaindb(mocked_setup_logging):
     from bigchaindb.commands.utils import configure_bigchaindb
     from bigchaindb.config_utils import is_configured
     assert not is_configured()
@@ -23,26 +23,31 @@ def test_configure_bigchaindb_configures_bigchaindb():
 
     args = Namespace(config=None)
     test_configure(args)
+    mocked_setup_logging.assert_called_once_with(user_log_config={})
 
 
 @pytest.mark.usefixtures('ignore_local_config_file',
                          'reset_bigchaindb_config',
                          'reset_logging_config')
 @pytest.mark.parametrize('log_level', ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'))
-def test_configure_bigchaindb_configures_logging(log_level):
+def test_configure_bigchaindb_configures_logging(log_level,
+                                                 mocked_setup_sub_logger):
     import logging
     from logging import getLogger
     from bigchaindb.commands.utils import configure_bigchaindb
+    from bigchaindb.log.configs import PUBLISHER_LOGGING_CONFIG
     root_logger = getLogger()
     assert root_logger.level == 0
 
     @configure_bigchaindb
     def test_configure_logger(args):
         root_logger = getLogger()
-        assert root_logger.level == getattr(logging, log_level)
+        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(
+        user_log_config={'level_console': log_level})
 
 
 def test_start_raises_if_command_not_implemented():

tests/conftest.py

@@ -442,3 +442,15 @@ def db_name(db_config):
 def db_conn():
     from bigchaindb.backend import connect
     return connect()
+
+
+@pytest.fixture
+def mocked_setup_pub_logger(mocker):
+    return mocker.patch(
+        'bigchaindb.log.setup.setup_pub_logger', autospec=True, spec_set=True)
+
+
+@pytest.fixture
+def mocked_setup_sub_logger(mocker):
+    return mocker.patch(
+        'bigchaindb.log.setup.setup_sub_logger', autospec=True, spec_set=True)

tests/log/test_setup.py

@@ -30,18 +30,6 @@ def mocked_socket_server(mocker):
     )
 
 
-@fixture
-def mocked_setup_pub_logger(mocker):
-    return mocker.patch(
-        'bigchaindb.log.setup.setup_pub_logger', autospec=True, spec_set=True)
-
-
-@fixture
-def mocked_setup_sub_logger(mocker):
-    return mocker.patch(
-        'bigchaindb.log.setup.setup_sub_logger', autospec=True, spec_set=True)
-
-
 @fixture
 def log_record_dict():
     return {
@@ -225,6 +213,7 @@ class TestLogRecordSocketServer:
         assert server.server_address == (
             '127.0.0.1', logging.handlers.DEFAULT_TCP_LOGGING_PORT)
         assert server.RequestHandlerClass == LogRecordStreamHandler
+        server.server_close()
 
     @mark.parametrize('side_effect', (None, KeyboardInterrupt))
     def test_server_forever(self, mocker, side_effect):