diff --git a/bigchaindb/commands/bigchaindb.py b/bigchaindb/commands/bigchaindb.py index e0c959da..ad02d33e 100644 --- a/bigchaindb/commands/bigchaindb.py +++ b/bigchaindb/commands/bigchaindb.py @@ -16,10 +16,11 @@ import bigchaindb from bigchaindb import backend from bigchaindb.backend import schema from bigchaindb.backend import query -from bigchaindb.commands import utils -from bigchaindb.commands.utils import ( - configure_bigchaindb, start_logging_process, input_on_stderr) from bigchaindb.backend.query import VALIDATOR_UPDATE_ID, PRE_COMMIT_ID +from bigchaindb.commands import utils +from bigchaindb.commands.utils import (configure_bigchaindb, + input_on_stderr) +from bigchaindb.log import setup_logging from bigchaindb.tendermint.lib import BigchainDB from bigchaindb.tendermint.utils import public_key_from_base64 @@ -159,11 +160,13 @@ def run_recover(b): @configure_bigchaindb -@start_logging_process def run_start(args): """Start the processes to run the node""" - logger.info('BigchainDB Version %s', bigchaindb.__version__) + # Configure Logging + setup_logging() + + logger.info('BigchainDB Version %s', bigchaindb.__version__) run_recover(BigchainDB()) try: diff --git a/bigchaindb/commands/utils.py b/bigchaindb/commands/utils.py index ea035a80..3ce8ab7f 100644 --- a/bigchaindb/commands/utils.py +++ b/bigchaindb/commands/utils.py @@ -10,9 +10,7 @@ import sys import bigchaindb import bigchaindb.config_utils -from bigchaindb.log import DEFAULT_LOGGING_CONFIG from bigchaindb.version import __version__ -from logging.config import dictConfig as set_logging_config def configure_bigchaindb(command): @@ -48,51 +46,6 @@ def configure_bigchaindb(command): 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): - logging_configs = DEFAULT_LOGGING_CONFIG - new_logging_configs = bigchaindb.config['log'] - - # Update log file location - logging_configs['handlers']['file']['filename'] = new_logging_configs['file'] - logging_configs['handlers']['errors']['filename'] = new_logging_configs['error_file'] - - # Update log levels - logging_configs['handlers']['console']['level'] = \ - new_logging_configs['level_console'].upper() - logging_configs['handlers']['file']['level'] = new_logging_configs['level_logfile'].upper() - - # Update log date format - logging_configs['formatters']['console']['datefmt'] = new_logging_configs['datefmt_console'] - logging_configs['formatters']['file']['datefmt'] = new_logging_configs['datefmt_logfile'] - - # Update log string format - logging_configs['formatters']['console']['format'] = new_logging_configs['fmt_console'] - logging_configs['formatters']['file']['format'] = new_logging_configs['fmt_console'] - - set_logging_config(logging_configs) - command(args) - return start_logging - - def _convert(value, default=None, convert=None): def convert_bool(value): if value.lower() in ('true', 't', 'yes', 'y'): @@ -190,7 +143,7 @@ base_parser.add_argument('-c', '--config', # the environment variables provided to configure the logger. base_parser.add_argument('-l', '--log-level', type=str.upper, # convert to uppercase for comparison to choices - choices=['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], + choices=['DEBUG', 'BENCHMARK', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], help='Log level') base_parser.add_argument('-y', '--yes', '--yes-please', diff --git a/bigchaindb/log.py b/bigchaindb/log.py index ffcbac98..47892509 100644 --- a/bigchaindb/log.py +++ b/bigchaindb/log.py @@ -1,8 +1,13 @@ +import bigchaindb import logging + +from bigchaindb.common.exceptions import ConfigurationError +from logging.config import dictConfig as set_logging_config from os.path import expanduser, join DEFAULT_LOG_DIR = expanduser('~') +BENCHMARK_LOG_LEVEL = 15 DEFAULT_LOGGING_CONFIG = { @@ -21,6 +26,11 @@ DEFAULT_LOGGING_CONFIG = { '%(message)s (%(processName)-10s - pid: %(process)d)'), 'datefmt': '%Y-%m-%d %H:%M:%S', }, + 'benchmark': { + 'class': 'logging.Formatter', + 'format': ('%(asctime)s, %(levelname)s, %(message)s'), + 'datefmt': '%Y-%m-%d %H:%M:%S', + } }, 'handlers': { 'console': { @@ -46,10 +56,98 @@ DEFAULT_LOGGING_CONFIG = { 'formatter': 'file', 'level': logging.ERROR, }, + 'benchmark': { + 'class': 'logging.handlers.RotatingFileHandler', + 'filename': 'bigchaindb-benchmark.log', + 'mode': 'w', + 'maxBytes': 209715200, + 'backupCount': 5, + 'formatter': 'benchmark', + 'level': BENCHMARK_LOG_LEVEL, + } }, 'loggers': {}, 'root': { 'level': logging.DEBUG, - 'handlers': ['console', 'file', 'errors'], + 'handlers': ['console', 'file', 'errors', 'benchmark'], }, } + + +def benchmark(self, message, *args, **kws): + # Yes, logger takes its '*args' as 'args'. + if self.isEnabledFor(BENCHMARK_LOG_LEVEL): + self._log(BENCHMARK_LOG_LEVEL, message, args, **kws) + + +def _normalize_log_level(level): + try: + return level.upper() + except AttributeError as exc: + raise ConfigurationError('Log level must be a string!') from exc + + +def setup_logging(): + """Function to configure log hadlers. + + .. 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. + + """ + + # Add a new logging level for logging benchmark + logging.addLevelName(BENCHMARK_LOG_LEVEL, 'BENCHMARK') + logging.BENCHMARK = BENCHMARK_LOG_LEVEL + logging.Logger.benchmark = benchmark + + logging_configs = DEFAULT_LOGGING_CONFIG + new_logging_configs = bigchaindb.config['log'] + + if 'file' in new_logging_configs: + filename = new_logging_configs['file'] + logging_configs['handlers']['file']['filename'] = filename + + if 'error_file' in new_logging_configs: + error_filename = new_logging_configs['error_file'] + logging_configs['handlers']['errors']['filename'] = error_filename + + if 'level_console' in new_logging_configs: + level = _normalize_log_level(new_logging_configs['level_console']) + logging_configs['handlers']['console']['level'] = level + + if 'level_logfile' in new_logging_configs: + level = _normalize_log_level(new_logging_configs['level_logfile']) + logging_configs['handlers']['file']['level'] = level + logging_configs['handlers']['benchmark']['level'] = level + + if 'fmt_console' in new_logging_configs: + fmt = new_logging_configs['fmt_console'] + logging_configs['formatters']['console']['format'] = fmt + + if 'fmt_logfile' in new_logging_configs: + fmt = new_logging_configs['fmt_logfile'] + logging_configs['formatters']['file']['format'] = fmt + + if 'datefmt_console' in new_logging_configs: + fmt = new_logging_configs['datefmt_console'] + logging_configs['formatters']['console']['datefmt'] = fmt + + if 'datefmt_logfile' in new_logging_configs: + fmt = new_logging_configs['datefmt_logfile'] + logging_configs['formatters']['file']['datefmt'] = fmt + + log_levels = new_logging_configs.get('granular_levels', {}) + + for logger_name, level in log_levels.items(): + level = _normalize_log_level(level) + try: + logging_configs['loggers'][logger_name]['level'] = level + except KeyError: + logging_configs['loggers'][logger_name] = {'level': level} + + set_logging_config(logging_configs) diff --git a/bigchaindb/tendermint/core.py b/bigchaindb/tendermint/core.py index f838457b..d82e0266 100644 --- a/bigchaindb/tendermint/core.py +++ b/bigchaindb/tendermint/core.py @@ -38,7 +38,6 @@ class App(BaseApplication): def info(self): """Return height of the latest committed block.""" - r = ResponseInfo() block = self.bigchaindb.get_latest_block() if block: @@ -55,13 +54,17 @@ class App(BaseApplication): Args: raw_tx: a raw string (in bytes) transaction.""" + + logger.benchmark('CHECK_TX_INIT') logger.debug('check_tx: %s', raw_transaction) transaction = decode_transaction(raw_transaction) if self.bigchaindb.is_valid_transaction(transaction): logger.debug('check_tx: VALID') + logger.benchmark('CHECK_TX_END, tx_id:%s', transaction['id']) return Result.ok() else: logger.debug('check_tx: INVALID') + logger.benchmark('CHECK_TX_END, tx_id:%s', transaction['id']) return Result.error() def begin_block(self, req_begin_block): @@ -70,6 +73,9 @@ class App(BaseApplication): req_begin_block: block object which contains block header and block hash. """ + logger.benchmark('BEGIN BLOCK, height:%s, num_txs:%s', + req_begin_block.header.height, + req_begin_block.header.num_txs) self.block_txn_ids = [] self.block_transactions = [] @@ -98,7 +104,6 @@ class App(BaseApplication): Args: height (int): new height of the chain.""" - self.new_height = height block_txn_hash = calculate_hash(self.block_txn_ids) block = self.bigchaindb.get_latest_block() @@ -130,7 +135,6 @@ class App(BaseApplication): def commit(self): """Store the new height and along with block hash.""" - data = self.block_txn_hash.encode('utf-8') # register a new block only when new transactions are received @@ -146,6 +150,7 @@ class App(BaseApplication): logger.debug('Commit-ing new block with hash: apphash=%s ,' 'height=%s, txn ids=%s', data, self.new_height, self.block_txn_ids) + logger.benchmark('COMMIT_BLOCK, height:%s', self.new_height) return data diff --git a/docs/server/source/server-reference/configuration.md b/docs/server/source/server-reference/configuration.md index daa685a3..3bc1ca31 100644 --- a/docs/server/source/server-reference/configuration.md +++ b/docs/server/source/server-reference/configuration.md @@ -289,7 +289,7 @@ defined by [Python](https://docs.python.org/3.6/library/logging.html#levels), but case insensitive for convenience's sake: ``` -"critical", "error", "warning", "info", "debug", "notset" +"critical", "error", "warning", "info", "benchmark", "debug", "notset" ``` **Example**: @@ -311,7 +311,7 @@ defined by [Python](https://docs.python.org/3.6/library/logging.html#levels), but case insensitive for convenience's sake: ``` -"critical", "error", "warning", "info", "debug", "notset" +"critical", "error", "warning", "info", "benchmark", "debug", "notset" ``` **Example**: diff --git a/tests/conftest.py b/tests/conftest.py index 6b5be367..64ded511 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -16,6 +16,7 @@ import pytest from pymongo import MongoClient from bigchaindb.common import crypto +from bigchaindb.log import setup_logging from bigchaindb.tendermint.lib import Block TEST_DB_NAME = 'bigchain_test' @@ -111,6 +112,10 @@ def _configure_bigchaindb(request): config = config_utils.env_config(config) config_utils.set_config(config) + # NOTE: since we use a custom log level + # for benchmark logging we need to setup logging + setup_logging() + @pytest.fixture(scope='session') def _setup_database(_configure_bigchaindb): diff --git a/tests/tendermint/test_core.py b/tests/tendermint/test_core.py index 165f69f9..ef34d4b6 100644 --- a/tests/tendermint/test_core.py +++ b/tests/tendermint/test_core.py @@ -1,7 +1,8 @@ import json - import pytest +from abci.types_pb2 import RequestBeginBlock + pytestmark = [pytest.mark.tendermint, pytest.mark.bdb] @@ -57,8 +58,10 @@ def test_deliver_tx__valid_create_updates_db(b): .sign([alice.private_key]) app = App(b) + + begin_block = RequestBeginBlock() app.init_chain(['ignore']) - app.begin_block('ignore') + app.begin_block(begin_block) result = app.deliver_tx(encode_tx_to_bytes(tx)) assert result.is_ok() @@ -89,7 +92,9 @@ def test_deliver_tx__double_spend_fails(b): app = App(b) app.init_chain(['ignore']) - app.begin_block('ignore') + + begin_block = RequestBeginBlock() + app.begin_block(begin_block) result = app.deliver_tx(encode_tx_to_bytes(tx)) assert result.is_ok() @@ -109,7 +114,9 @@ def test_deliver_transfer_tx__double_spend_fails(b): app = App(b) app.init_chain(['ignore']) - app.begin_block('ignore') + + begin_block = RequestBeginBlock() + app.begin_block(begin_block) alice = generate_key_pair() bob = generate_key_pair() @@ -152,7 +159,9 @@ def test_end_block_return_validator_updates(b): app = App(b) app.init_chain(['ignore']) - app.begin_block('ignore') + + begin_block = RequestBeginBlock() + app.begin_block(begin_block) validator = {'pub_key': {'type': 'ed25519', 'data': 'B0E42D2589A455EAD339A035D6CE1C8C3E25863F268120AA0162AD7D003A4014'}, @@ -182,7 +191,8 @@ def test_store_pre_commit_state_in_end_block(b, alice): app = App(b) app.init_chain(['ignore']) - app.begin_block('ignore') + begin_block = RequestBeginBlock() + app.begin_block(begin_block) app.deliver_tx(encode_tx_to_bytes(tx)) app.end_block(99) @@ -191,7 +201,7 @@ def test_store_pre_commit_state_in_end_block(b, alice): assert resp['height'] == 99 assert resp['transactions'] == [tx.id] - app.begin_block('ignore') + app.begin_block(begin_block) app.deliver_tx(encode_tx_to_bytes(tx)) app.end_block(100) resp = query.get_pre_commit_state(b.connection, PRE_COMMIT_ID) diff --git a/tests/tendermint/test_integration.py b/tests/tendermint/test_integration.py index 6f1644ea..c1d86684 100644 --- a/tests/tendermint/test_integration.py +++ b/tests/tendermint/test_integration.py @@ -1,12 +1,13 @@ -import json -from copy import deepcopy - -import pytest -from abci.server import ProtocolHandler -from io import BytesIO import abci.types_pb2 as types +import json +import pytest + + +from abci.server import ProtocolHandler from abci.encoding import read_message from abci.messages import to_request_deliver_tx, to_request_check_tx +from copy import deepcopy +from io import BytesIO @pytest.mark.tendermint