Fix broken logging tests

Author: ulope

ethereum/slogging.py

@@ -35,15 +35,32 @@ class LogRecorder(object):
     """
     max_capacity = 1000 * 1000  # check we are not forgotten or abused
 
-    def __init__(self):
+    def __init__(self, disable_other_handlers=False, log_config=None):
         self._records = []
         log_listeners.append(self._add_log_record)
+        self._saved_config = None
+        if log_config:
+            self._saved_config = get_configuration()
+            configure(log_config)
+        self._saved_handlers = []
+        if disable_other_handlers:
+            self._saved_handlers = rootLogger.handlers[:]
+            rootLogger.handlers = []
 
     def pop_records(self):
-        # can only be called once
+        # only returns records on the first call
         r = self._records[:]
-        self._records = None
-        log_listeners.remove(self._add_log_record)
+        self._records = []
+        try:
+            log_listeners.remove(self._add_log_record)
+        except ValueError:
+            pass
+        if self._saved_config:
+            configure(**self._saved_config)
+            self._saved_config = None
+        if self._saved_handlers:
+            rootLogger.handlers = self._saved_handlers[:]
+            self._saved_handlers = []
         return r
 
     def _add_log_record(self, msg):
@@ -59,9 +76,13 @@ def get_configuration():
     """
     root = getLogger()
     name_levels = [('', logging.getLevelName(root.level))]
+    name_levels.extend(
+        (name, logging.getLevelName(logger.level))
+        for name, logger
+        in root.manager.loggerDict.items()
+        if hasattr(logger, 'level')
+    )
 
-    for name, logger in list(root.manager.loggerDict.items()):
-        name_levels.append((name, logging.getLevelName(logger.level)))
     config_string = ','.join('%s:%s' % x for x in name_levels)
 
     return dict(config_string=config_string, log_json=root.log_json)
@@ -222,6 +243,7 @@ def configure(config_string=None, log_json=False, log_file=None):
         if hasattr(logger, 'setLevel'):
             # Guard against `logging.PlaceHolder` instances
             logger.setLevel(logging.NOTSET)
+            logger.propagate = True
 
     for name_levels in config_string.split(','):
         name, _, level = name_levels.partition(':')

ethereum/tester.py

@@ -13,6 +13,17 @@
 import rlp
 from rlp.utils import decode_hex, encode_hex, ascii_chr
 
+
+TRACE_LVL_MAP = [
+    ':info',
+    'eth.vm.log:trace',
+    ':info,eth.vm.log:trace,eth.vm.exit:trace',
+    ':info,eth.vm.log:trace,eth.vm.op:trace,eth.vm.stack:trace',
+    ':info,eth.vm.log:trace,eth.vm.op:trace,eth.vm.stack:trace,' +
+    'eth.vm.storage:trace,eth.vm.memory:trace'
+]
+
+
 serpent = None
 
 u = ethereum.utils
@@ -199,31 +210,35 @@ def _send(self, sender, to, value, evmdata='', output=None,
         tx = t.Transaction(sendnonce, gas_price, gas_limit, to, value, evmdata)
         self.last_tx = tx
         tx.sign(sender)
+        recorder = None
         if profiling > 1:
-            set_logging_level(3)
-            recorder = LogRecorder()
-        (s, o) = pb.apply_transaction(self.block, tx)
-        if not s:
-            raise TransactionFailed()
-        out = {"output": o}
-        if profiling > 0:
-            zero_bytes = tx.data.count(ascii_chr(0))
-            non_zero_bytes = len(tx.data) - zero_bytes
-            intrinsic_gas_used = opcodes.GTXCOST + \
-                opcodes.GTXDATAZERO * zero_bytes + \
-                opcodes.GTXDATANONZERO * non_zero_bytes
-            ntm, ng = time.time(), self.block.gas_used
-            out["time"] = ntm - tm
-            out["gas"] = ng - g - intrinsic_gas_used
-        if profiling > 1:
-            trace = recorder.pop_records()
-            set_logging_level(0)
-            ops = [x['op'] for x in trace if x['event'] == 'vm']
-            opdict = {}
-            for op in ops:
-                opdict[op] = opdict.get(op, 0) + 1
-            out["ops"] = opdict
-        return out
+            recorder = LogRecorder(disable_other_handlers=True, log_config=TRACE_LVL_MAP[3])
+        try:
+            (s, o) = pb.apply_transaction(self.block, tx)
+            if not s:
+                raise TransactionFailed()
+            out = {"output": o}
+            if profiling > 0:
+                zero_bytes = tx.data.count(ascii_chr(0))
+                non_zero_bytes = len(tx.data) - zero_bytes
+                intrinsic_gas_used = opcodes.GTXCOST + \
+                    opcodes.GTXDATAZERO * zero_bytes + \
+                    opcodes.GTXDATANONZERO * non_zero_bytes
+                ntm, ng = time.time(), self.block.gas_used
+                out["time"] = ntm - tm
+                out["gas"] = ng - g - intrinsic_gas_used
+            if profiling > 1:
+                trace = recorder.pop_records()
+                ops = [x['op'] for x in trace if x['event'] == 'vm']
+                opdict = {}
+                for op in ops:
+                    opdict[op] = opdict.get(op, 0) + 1
+                out["ops"] = opdict
+            return out
+        finally:
+            # ensure LogRecorder has been disabled
+            if recorder:
+                recorder.pop_records()
 
     def profile(self, *args, **kwargs):
         kwargs['profiling'] = True
@@ -281,41 +296,6 @@ def revert(self, data):
         self.block._cached_rlp = None
         self.block.header._cached_rlp = None
 
-# logging
-
-
-def set_logging_level(lvl=0):
-    trace_lvl_map = [
-        ':info',
-        'eth.vm.log:trace',
-        ':info,eth.vm.log:trace,eth.vm.exit:trace',
-        ':info,eth.vm.log:trace,eth.vm.op:trace,eth.vm.stack:trace',
-        ':info,eth.vm.log:trace,eth.vm.op:trace,eth.vm.stack:trace,' +
-        'eth.vm.storage:trace,eth.vm.memory:trace'
-    ]
-    configure_logging(config_string=trace_lvl_map[lvl])
-    if lvl == 0:
-        set_level(None, 'info')
-    print('Set logging level: %d' % lvl)
-
-
-def set_log_trace(logger_names=[]):
-    """
-    sets all named loggers to level 'trace'
-    attention: vm.op.* are only active if vm.op is active
-    """
-    for name in logger_names:
-        assert name in slogging.get_logger_names()
-        slogging.set_level(name, 'trace')
-
-
-def enable_logging():
-    set_logging_level(1)
-
-
-def disable_logging():
-    set_logging_level(0)
-
 
 gas_limit = 3141592
 gas_price = 1

ethereum/tests/conftest.py

@@ -7,7 +7,7 @@
 
 
 # Connect catchlog's handler to slogging's root logger
-@pytest.hookimpl(hookwrapper=True)
+@pytest.hookimpl(hookwrapper=True, trylast=True)
 def pytest_runtest_call(item):
     catchlog_handler = getattr(item, CATCH_LOG_HANDLER_NAME, None)
     if catchlog_handler and catchlog_handler not in slogging.rootLogger.handlers:

ethereum/tests/test_chain.py

@@ -10,9 +10,8 @@
 from ethereum.db import EphemDB
 from ethereum.tests.utils import new_db
 
-from ethereum.slogging import get_logger, configure_logging
+from ethereum.slogging import get_logger
 logger = get_logger()
-# configure_logging('eth.vm:trace,eth.vm.memory:info')
 
 _db = new_db()
 

ethereum/tests/test_contracts.py

@@ -8,15 +8,9 @@
 from rlp.utils import decode_hex
 
 from ethereum import tester, utils, abi
-from ethereum.slogging import set_level
 from ethereum.utils import safe_ord, big_endian_to_int
 
 
-# customize VM log output to your needs
-# hint: use 'py.test' with the '-s' option to dump logs to the console
-tester.set_logging_level(0)
-
-
 # Test EVM contracts
 serpent_code = '''
 def main(a,b):
@@ -1056,7 +1050,6 @@ def sort(args:arr):
 
 @pytest.mark.timeout(100)
 def test_sort():
-    set_level(None, 'info')
     s = tester.state()
     c = s.abi_contract(sort_code)
     assert c.sort([9]) == [9]
@@ -1081,7 +1074,6 @@ def test(args:arr):
 
 @pytest.mark.timeout(100)
 def test_indirect_sort():
-    set_level(None, 'info')
     s = tester.state()
     open(filename9, 'w').write(sort_code)
     c = s.abi_contract(sort_tester_code)
@@ -1326,7 +1318,6 @@ def get_prevhashes(k):
 
 @pytest.mark.timeout(100)
 def test_prevhashes():
-    set_level(None, 'info')
     s = tester.state()
     c = s.abi_contract(prevhashes_code)
     s.mine(7)

ethereum/tests/test_genesis.py

@@ -6,9 +6,8 @@
 import ethereum.utils as utils
 from rlp.utils import encode_hex
 from ethereum.tests.utils import new_env
-from ethereum.slogging import get_logger, configure_logging
+from ethereum.slogging import get_logger
 logger = get_logger()
-# configure_logging(':trace')
 
 
 @pytest.fixture(scope="module")

ethereum/tests/test_logging.py

@@ -12,9 +12,9 @@ def test_basic(caplog, level_name):
     with caplog.at_level('TRACE'):
         getattr(log, level_name)(level_name)
 
-    assert len(caplog.records()) == 1
-    assert caplog.records()[0].levelname == level_name.upper()
-    assert level_name in caplog.records()[0].msg
+    assert len(caplog.records) == 1
+    assert caplog.records[0].levelname == level_name.upper()
+    assert level_name in caplog.records[0].msg
 
 
 def test_initial_config():

ethereum/tests/test_remoteblocks.py

@@ -1,5 +1,5 @@
 from ethereum.db import DB
-from ethereum.slogging import get_logger, configure_logging
+from ethereum.slogging import get_logger
 from ethereum import testutils
 import sys
 logger = get_logger()

ethereum/tests/test_state.py

@@ -1,9 +1,8 @@
 import json
-import os
 import sys
 import ethereum.testutils as testutils
 
-from ethereum.slogging import get_logger, configure_logging, set_level
+from ethereum.slogging import get_logger, configure_logging
 logger = get_logger()
 # customize VM log output to your needs
 # hint: use 'py.test' with the '-s' option to dump logs to the console
@@ -13,7 +12,6 @@
 
 
 def test_state(filename, testname, testdata):
-    set_level(None, 'info')
     logger.debug('running test:%r in %r' % (testname, filename))
     testutils.check_state_test(testutils.fixture_to_bytes(testdata))
 

ethereum/tests/test_transactions.py

@@ -7,9 +7,8 @@
 import ethereum.config as config
 import sys
 import json
-import os
 
-from ethereum.slogging import get_logger, configure_logging
+from ethereum.slogging import get_logger
 logger = get_logger()
 # customize VM log output to your needs
 # hint: use 'py.test' with the '-s' option to dump logs to the console