From e488c8aa71fb41c8f74309fcf22fafbac8a20b84 Mon Sep 17 00:00:00 2001 From: Ivan Zemtsov Date: Mon, 24 Aug 2015 16:33:57 +0300 Subject: [PATCH 1/5] Set number level new logger as root level logger --- ethereum/slogging.py | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/ethereum/slogging.py b/ethereum/slogging.py index 69d52221d..dd2138c2f 100644 --- a/ethereum/slogging.py +++ b/ethereum/slogging.py @@ -87,7 +87,7 @@ def pop_records(self): DEFAULT_LOGLEVEL = logging.INFO JSON_FORMAT = '%(message)s' -PRINT_FORMAT = '%(levelname)s:%(name)s\t%(message)s' +PRINT_FORMAT = '%(levelname)s:%(name)s\t%(message)s #L%(lineno)s' def get_configuration(): @@ -124,6 +124,7 @@ def wrapper(self, msg, *args, **kwargs): return wrapper class EthLogger(logging.Logger): + #def __init__(self, name, level=DEFAULT_LOGLEVEL): def __init__(self, name, level=DEFAULT_LOGLEVEL): self.context_head = {} self.context_bind = {} @@ -286,7 +287,11 @@ def getLogger(name=None): """ if name: - ethlogger = EthLogger.manager.getLogger(name) + if name in rootLogger.manager.loggerDict: # is this a new logger ? + ethlogger = EthLogger.manager.getLogger(name) + else: + ethlogger = EthLogger.manager.getLogger(name) + ethlogger.setLevel(rootLogger.level) # set level as rootloger level ethlogger.log_json = rootLogger.log_json return ethlogger else: @@ -298,7 +303,6 @@ def set_level(name, level): logger.setLevel(getattr(logging, level.upper())) def configure_loglevels(config_string, format=PRINT_FORMAT): - global FLAG_FISRST_CONFIGURE_LEVEL """ config_string = ':debug,p2p:info,vm.op:trace' """ From 2e203490cf43a90f77c6c89ea9089a8607b41545 Mon Sep 17 00:00:00 2001 From: Ivan Zemtsov Date: Mon, 24 Aug 2015 20:31:18 +0300 Subject: [PATCH 2/5] creating a new test test_baseconfig2 for more thorough testing --- ethereum/tests/test_logging.py | 34 +++++++++++++++++++++++++++++++++- 1 file changed, 33 insertions(+), 1 deletion(-) diff --git a/ethereum/tests/test_logging.py b/ethereum/tests/test_logging.py index 375b505b7..35aa096a1 100644 --- a/ethereum/tests/test_logging.py +++ b/ethereum/tests/test_logging.py @@ -57,7 +57,6 @@ def test_testhandler(): assert th.does_log(log.warn) assert not th.does_log(log.debug) - def test_baseconfig(): # test default loglevel INFO th = setup_logging() @@ -72,6 +71,39 @@ def test_baseconfig(): config_string = ':inFO,a:trace,a.b:debug' th = setup_logging(config_string=config_string) +def test_baseconfig2(): + # test loglevels + th = setup_logging(':info,p2p.discovery:debug,p2p.peer:debug,p2p:warn,eth:debug,eth.chain.tx:info') + root = slogging.get_logger() + assert th.does_log(root.error) + assert th.does_log(root.info) + assert not th.does_log(root.debug) + p2p_discovery = slogging.get_logger('p2p.discovery') + assert th.does_log(p2p_discovery.error) + assert th.does_log(p2p_discovery.info) + assert th.does_log(p2p_discovery.debug) + p2p_peer = slogging.get_logger('p2p.peer') + assert th.does_log(p2p_peer.error) + assert th.does_log(p2p_peer.info) + assert th.does_log(p2p_peer.debug) + p2p = slogging.get_logger('p2p') + assert th.does_log(p2p.error) + assert th.does_log(p2p.warn) + assert th.does_log(p2p.warning) + assert not th.does_log(p2p.info) + assert not th.does_log(p2p.debug) + eth = slogging.get_logger('eth') + assert th.does_log(eth.error) + assert th.does_log(eth.warn) + assert th.does_log(eth.warning) + assert th.does_log(eth.info) + assert th.does_log(eth.debug) + eth_chain_tx = slogging.get_logger('eth.chain.tx') + assert th.does_log(eth_chain_tx.error) + assert th.does_log(eth_chain_tx.warn) + assert th.does_log(eth_chain_tx.warning) + assert th.does_log(eth_chain_tx.info) + assert not th.does_log(eth_chain_tx.debug) def test_is_active2(): setup_logging(':info') From afb01ad16e2e295e296d322ff9041518d700b308 Mon Sep 17 00:00:00 2001 From: Ivan Zemtsov Date: Tue, 25 Aug 2015 09:48:00 +0300 Subject: [PATCH 3/5] Colored debug output --- ethereum/slogging.py | 95 +++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 93 insertions(+), 2 deletions(-) diff --git a/ethereum/slogging.py b/ethereum/slogging.py index 219e63d26..e660a1ce9 100644 --- a/ethereum/slogging.py +++ b/ethereum/slogging.py @@ -33,6 +33,10 @@ def hexprint(x): logging.addLevelName(TRACE, "TRACE") logging.TRACE = TRACE +# add level DEV into logging +DEV = 15 +logging.addLevelName(DEV, "DEV") +logging.DEV = DEV formatter_set = frozenset(['name', 'levelno', 'levelname', 'pathname', 'filename', 'module', 'lineno', 'funcName', 'created', 'asctime', 'msecs', 'relativeCreated', 'thread', @@ -123,6 +127,68 @@ def wrapper(self, msg, *args, **kwargs): fun(self, msg, *args, **kwargs) return wrapper +class EthLogRecord(logging.LogRecord): + def __init__(self, *args, **kwargs): + super(EthLogRecord, self).__init__(*args, **kwargs) + + def getMessage(self): + msg = super(EthLogRecord, self).getMessage() + if self.levelno == logging.DEV: + return msg + else: + return msg + +try: + unicode + _unicode = True +except NameError: + _unicode = False + +class EthStreamHandler(logging.StreamHandler): + def __init__(self, stream=None ): + super(EthStreamHandler, self).__init__(stream) + self.dict_colors = {} + self.dict_colors["HEADER"] = '\033[95m' + self.dict_colors["OKBLUE"] = '\033[94m' + self.dict_colors["OKGREEN"] = '\033[92m' + self.dict_colors["WARNING"] = '\033[91m' + self.dict_colors["FAIL"] = '\033[91m' + self.dict_colors["ENDC"] = '\033[0m' + self.dict_colors["BOLD"] = '\033[1m' + self.dict_colors["UNDERLINE"] = '\033[4m' + + def emit(self, record): + """ + Emit a record. + This function from standart logging module with some changes + """ + try: + msg = self.format(record) + if record.levelno == logging.DEV: + msg = self.dict_colors["FAIL"] + msg + self.dict_colors["ENDC"] + stream = self.stream + fs = "%s\n" + if not _unicode: #if no unicode support... + stream.write(fs % msg) + else: + try: + if (isinstance(msg, unicode) and + getattr(stream, 'encoding', None)): + ufs = u'%s\n' + try: + stream.write(ufs % msg) + except UnicodeEncodeError: + stream.write((ufs % msg).encode(stream.encoding)) + else: + stream.write(fs % msg) + except UnicodeError: + stream.write(fs % msg.encode("UTF-8")) + self.flush() + except (KeyboardInterrupt, SystemExit): + raise + except: + self.handleError(record) + class EthLogger(logging.Logger): def __init__(self, name, level=DEFAULT_LOGLEVEL): self.context_head = {} @@ -229,6 +295,30 @@ def critical(self, msg, *args, **kwargs): new_kws, new_message = self.help_make_kws(kwargs, self.name, msg, getattr(self, "log_json", False)) self._log(logging.CRITICAL, new_message, args, **new_kws) + @bind_decorator + def dev(self, msg, *args, **kwargs): + new_message = "" + if self.isEnabledFor(logging.DEV): + new_kws, new_message = self.help_make_kws(kwargs, self.name, msg, getattr(self, "log_json", False)) + self._log(logging.DEV, new_message, args, **new_kws) + + @bind_decorator + def DEV(self, msg, *args, **kwargs): + self.dev(msg, *args, **kwargs) + + def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None): + """ + A factory method which can be overridden in subclasses to create + specialized LogRecords. + """ + rv = EthLogRecord(name, level, fn, lno, msg, args, exc_info, func) + if extra is not None: + for key in extra: + if (key in ["message", "asctime"]) or (key in rv.__dict__): + raise KeyError("Attempt to overwrite %r in LogRecord" % key) + rv.__dict__[key] = extra[key] + return rv + class RootLogger(EthLogger): """ A root logger is not that different to any other logger, except that @@ -312,7 +402,7 @@ def configure_loglevels(config_string, format=PRINT_FORMAT): logger = getLogger(name) logger.setLevel(getattr(logging, level.upper())) if not len(logger.handlers): - ch = logging.StreamHandler() + ch = EthStreamHandler() formatter = logging.Formatter(format) ch.setFormatter(formatter) logger.addHandler(ch) @@ -327,8 +417,9 @@ def configure(config_string='', log_json=False): logging.basicConfig(format=format, level=DEFAULT_LOGLEVEL) # work only first time ethlogger = getLogger() + ethlogger.DEV("------------------------ configure function ------------------------------------------") if not len(ethlogger.handlers): - ch = logging.StreamHandler() + ch = EthStreamHandler() formatter = logging.Formatter(format) ch.setFormatter(formatter) ethlogger.addHandler(ch) From d136e0ae02d28c54118b59e54951bf49d35f00a3 Mon Sep 17 00:00:00 2001 From: Ivan Zemtsov Date: Tue, 25 Aug 2015 14:31:14 +0300 Subject: [PATCH 4/5] Correct slogging code for many times using configure --- ethereum/slogging.py | 17 ++++++++++++----- ethereum/tests/test_logging.py | 23 +++++++++++++++++++---- 2 files changed, 31 insertions(+), 9 deletions(-) diff --git a/ethereum/slogging.py b/ethereum/slogging.py index e660a1ce9..2a86b780c 100644 --- a/ethereum/slogging.py +++ b/ethereum/slogging.py @@ -396,16 +396,23 @@ def configure_loglevels(config_string, format=PRINT_FORMAT): config_string = ':debug,p2p:info,vm.op:trace' """ assert ':' in config_string + conf_dict = {} for name_levels in config_string.split(','): name, level = name_levels.split(':') + conf_dict[name] = level + + root_logger = getLogger() + root_logger.setLevel(logging._checkLevel(conf_dict[""].upper())) + + for i in root_logger.manager.loggerDict: + if isinstance(root_logger.manager.loggerDict[i], EthLogger): + root_logger.manager.loggerDict[i].setLevel(root_logger.level) # set all logers level as root logger. Protection from many execute configure + + for name in conf_dict: + level = conf_dict[name] assert not isinstance(level, int) logger = getLogger(name) logger.setLevel(getattr(logging, level.upper())) - if not len(logger.handlers): - ch = EthStreamHandler() - formatter = logging.Formatter(format) - ch.setFormatter(formatter) - logger.addHandler(ch) def configure(config_string='', log_json=False): if log_json: diff --git a/ethereum/tests/test_logging.py b/ethereum/tests/test_logging.py index 35aa096a1..9c2735f99 100644 --- a/ethereum/tests/test_logging.py +++ b/ethereum/tests/test_logging.py @@ -105,6 +105,21 @@ def test_baseconfig2(): assert th.does_log(eth_chain_tx.info) assert not th.does_log(eth_chain_tx.debug) + #---------------- configure again ------------------ + th = setup_logging(':error') + assert th.does_log(root.error) + assert not th.does_log(root.info) + p2p_discovery = slogging.get_logger('p2p.discovery') + assert th.does_log(p2p_discovery.error) + assert not th.does_log(p2p_discovery.debug) + p2p_peer = slogging.get_logger('p2p.peer') + assert th.does_log(p2p_peer.error) + assert not th.does_log(p2p_peer.info) + p2p = slogging.get_logger('p2p') + assert th.does_log(p2p.error) + assert not th.does_log(p2p.warn) + + def test_is_active2(): setup_logging(':info') tester = slogging.get_logger('tester') @@ -510,16 +525,16 @@ def test_count_logging_handlers(): # check named logger eth_logger = slogging.getLogger('eth') slogging.configure(config_string1) - assert len(eth_logger.handlers) == 1 + assert len(eth_logger.handlers) == 0 slogging.configure(config_string1) - assert len(eth_logger.handlers) == 1 + assert len(eth_logger.handlers) == 0 # check child of named logger eth_vm_logger = slogging.getLogger('eth.vm') slogging.configure(config_string2) - assert len(eth_vm_logger.handlers) == 1 + assert len(eth_vm_logger.handlers) == 0 slogging.configure(config_string2) - assert len(eth_vm_logger.handlers) == 1 + assert len(eth_vm_logger.handlers) == 0 if __name__ == '__main__': pass \ No newline at end of file From 699dde8ab9febebcb891b1b33641417a1aff5013 Mon Sep 17 00:00:00 2001 From: Ivan Zemtsov Date: Thu, 27 Aug 2015 22:00:10 +0300 Subject: [PATCH 5/5] 1 Changes print messages to output with logging stream handler(sys.stderr as default) --- ethereum/abi.py | 6 ++++- ethereum/blocks.py | 2 +- ethereum/pruning_trie.py | 9 ++++--- ethereum/slogging.py | 2 +- ethereum/spv.py | 6 +++-- ethereum/tests/test_logging.py | 15 +++++++++++- ethereum/trie.py | 9 ++++--- ethereum/utils.py | 43 ++++++++++++++++++++-------------- 8 files changed, 62 insertions(+), 30 deletions(-) diff --git a/ethereum/abi.py b/ethereum/abi.py index 12428fe4d..c75e2c88b 100644 --- a/ethereum/abi.py +++ b/ethereum/abi.py @@ -2,10 +2,13 @@ import re import yaml # use yaml instead of json to get non unicode (works with ascii only data) from ethereum import utils +from ethereum import slogging from rlp.utils import decode_hex, encode_hex from ethereum.utils import encode_int, zpad, big_endian_to_int, is_numeric, is_string, ceil32 +from ethereum.slogging import get_logger import ast +log = get_logger('eth.abi') def json_decode(x): return yaml.safe_load(x) @@ -105,7 +108,8 @@ def listen(self, log, noprint=False): c2 += 1 o["_event_type"] = utils.to_string(name) if not noprint: - print(o) + logger = slogging.getLogger() + log.info(o) return o diff --git a/ethereum/blocks.py b/ethereum/blocks.py index de1c09380..43c4e525f 100644 --- a/ethereum/blocks.py +++ b/ethereum/blocks.py @@ -1439,4 +1439,4 @@ def dump_genesis_block_tests_data(db): for addr, balance in GENESIS_INITIAL_ALLOC.items(): data['initial_alloc'][addr] = to_string(balance) - print(json.dumps(data, indent=1)) + log.info(json.dumps(data, indent=1)) diff --git a/ethereum/pruning_trie.py b/ethereum/pruning_trie.py index 38412585e..78e508079 100644 --- a/ethereum/pruning_trie.py +++ b/ethereum/pruning_trie.py @@ -5,10 +5,13 @@ from ethereum import utils from ethereum.utils import to_string from ethereum.utils import is_string +from ethereum.slogging import get_logger import copy from rlp.utils import decode_hex, encode_hex, ascii_chr, str_to_bytes import sys +log = get_logger('eth.pruning_trie') + bin_to_nibbles_cache = {} hti = {} @@ -952,7 +955,7 @@ def verify_spv_proof(root, key, proof): proof.pop() return True except Exception as e: - print(e) + log.error(e) proof.pop() return False @@ -972,7 +975,7 @@ def encode_node(nd): if sys.argv[1] == 'insert': t = Trie(_db, decode_hex(sys.argv[3])) t.update(sys.argv[4], sys.argv[5]) - print(encode_node(t.root_hash)) + log.info(encode_node(t.root_hash)) elif sys.argv[1] == 'get': t = Trie(_db, decode_hex(sys.argv[3])) - print(t.get(sys.argv[4])) + log.info(t.get(sys.argv[4])) diff --git a/ethereum/slogging.py b/ethereum/slogging.py index 2a86b780c..d96502c4c 100644 --- a/ethereum/slogging.py +++ b/ethereum/slogging.py @@ -160,7 +160,7 @@ def __init__(self, stream=None ): def emit(self, record): """ Emit a record. - This function from standart logging module with some changes + This function from standart logging module from StreamHandler with some changes """ try: msg = self.format(record) diff --git a/ethereum/spv.py b/ethereum/spv.py index 6ee479bc5..944e66b2b 100644 --- a/ethereum/spv.py +++ b/ethereum/spv.py @@ -4,7 +4,9 @@ from ethereum import utils import rlp from ethereum import trie +from ethereum.slogging import get_logger +log = get_logger('eth.spv') def mk_transaction_spv_proof(block, tx): trie.proof.push(trie.RECORDING) @@ -22,7 +24,7 @@ def verify_transaction_spv_proof(block, tx, proof): trie.proof.pop() return True except Exception as e: - print(e) + log.error(e) trie.proof.pop() return False @@ -42,7 +44,7 @@ def mk_independent_transaction_spv_proof(block, index): if index > 0: nodes.extend(block.transactions.produce_spv_proof(rlp.encode(utils.encode_int(index - 1)))) nodes = list(map(rlp.decode, list(set(map(rlp.encode, nodes))))) - print(nodes) + log.info(nodes) return rlp.encode([utils.encode_int(64), block.get_parent().list_header(), block.list_header(), utils.encode_int(index), nodes]) diff --git a/ethereum/tests/test_logging.py b/ethereum/tests/test_logging.py index 9c2735f99..8774cc63f 100644 --- a/ethereum/tests/test_logging.py +++ b/ethereum/tests/test_logging.py @@ -536,5 +536,18 @@ def test_count_logging_handlers(): slogging.configure(config_string2) assert len(eth_vm_logger.handlers) == 0 +def mytest(): + th = setup_logging(config_string=":debug") + #rl.info("this is info %s %s", 'hi', 'hellow') + from ethereum.utils import debug + + @debug("debug_test") + def debug_test(): + pass + + debug_test() + + assert "debug_test" in th.logged + if __name__ == '__main__': - pass \ No newline at end of file + mytest() \ No newline at end of file diff --git a/ethereum/trie.py b/ethereum/trie.py index 2424651aa..45a8eb2e6 100644 --- a/ethereum/trie.py +++ b/ethereum/trie.py @@ -5,9 +5,12 @@ from ethereum import utils from ethereum.utils import to_string from ethereum.abi import is_string +from ethereum.slogging import get_logger import copy from rlp.utils import decode_hex, encode_hex, ascii_chr, str_to_bytes +log = get_logger('eth.trie') + bin_to_nibbles_cache = {} hti = {} @@ -880,7 +883,7 @@ def verify_spv_proof(root, key, proof): proof.pop() return True except Exception as e: - print(e) + log.error(e) proof.pop() return False @@ -901,7 +904,7 @@ def encode_node(nd): if sys.argv[1] == 'insert': t = Trie(_db, decode_hex(sys.argv[3])) t.update(sys.argv[4], sys.argv[5]) - print(encode_node(t.root_hash)) + log.info(encode_node(t.root_hash)) elif sys.argv[1] == 'get': t = Trie(_db, decode_hex(sys.argv[3])) - print(t.get(sys.argv[4])) + log.info(t.get(sys.argv[4])) diff --git a/ethereum/utils.py b/ethereum/utils.py index 4ef850969..6ac243ccf 100644 --- a/ethereum/utils.py +++ b/ethereum/utils.py @@ -9,6 +9,9 @@ from rlp.sedes import big_endian_int, BigEndianInt, Binary from rlp.utils import decode_hex, encode_hex, ascii_chr, str_to_bytes import random +from ethereum.slogging import get_logger + +log = get_logger('eth.utils') big_endian_to_int = lambda x: big_endian_int.deserialize(str_to_bytes(x).lstrip(b'\x00')) int_to_big_endian = lambda x: big_endian_int.serialize(x) @@ -69,9 +72,11 @@ def debug(label): def deb(f): def inner(*args, **kwargs): i = random.randrange(1000000) - print(label, i, 'start', args) + #print(label, i, 'start', args) + log.debug("%s %d %s %s", repr(label), i, 'start', repr(args)) x = f(*args, **kwargs) - print(label, i, 'end', x) + #print(label, i, 'end', x) + log.debug("%s %d %s %s", repr(label), i, 'end', repr(x)) return x return inner return deb @@ -342,18 +347,30 @@ def wrapper(*args, **kwargs): local['call_number'] += 1 tmp_args = args[1:] if ignore_first_arg and len(args) else args this_call_number = local['call_number'] - print(('{0}#{1} args: {2}, {3}'.format( + #print(('{0}#{1} args: {2}, {3}'.format( + # f.__name__, + # this_call_number, + # ', '.join([display(x) for x in tmp_args]), + # ', '.join(display(key) + '=' + to_string(value) + # for key, value in kwargs.items()) + #))) + log.dev('{0}#{1} args: {2}, {3}'.format( f.__name__, this_call_number, ', '.join([display(x) for x in tmp_args]), ', '.join(display(key) + '=' + to_string(value) for key, value in kwargs.items()) - ))) + )) + res = f(*args, **kwargs) - print(('{0}#{1} return: {2}'.format( + #print(('{0}#{1} return: {2}'.format( + # f.__name__, + # this_call_number, + # display(res)))) + log.dev('{0}#{1} return: {2}'.format( f.__name__, this_call_number, - display(res)))) + display(res))) if local['call_number'] > 100: raise Exception("Touch max call number!") @@ -391,16 +408,6 @@ def __init__(self): hash32 = Binary.fixed_length(32) trie_root = Binary.fixed_length(32, allow_empty=True) -class bcolors: - HEADER = '\033[95m' - OKBLUE = '\033[94m' - OKGREEN = '\033[92m' - WARNING = '\033[91m' - FAIL = '\033[91m' - ENDC = '\033[0m' - BOLD = '\033[1m' - UNDERLINE = '\033[4m' - - def DEBUG(*args, **kargs): - print(bcolors.FAIL + repr(args) + repr(kargs) + bcolors.ENDC) + #print(bcolors.FAIL + repr(args) + repr(kargs) + bcolors.ENDC) + log.dev(repr(args) + repr(kargs))