Fix json-logging regression

(Properly) json-formatted logging got lost somewhere in the process
of factoring out the `structlog` dependency. This commit (re)enables
json formatted kwargs when logging is configured with `log_json=True`.

related to #327 since the bug investigation is facilitated by machine-
readable vm traces.

Author: konradkonrad

ethereum/processblock.py

@@ -108,6 +108,27 @@ def rp(what, actual, target):
     return True
 
 
+class lazy_safe_encode(object):
+    """Creates a lazy and logging safe representation of transaction data.
+    Use this in logging of transactions; instead of
+
+        >>> log.debug(data=data)
+
+    do this:
+
+        >>> log.debug(data=lazy_safe_encode(data))
+    """
+
+    def __init__(self, data):
+        self.data = data
+
+    def __str__(self):
+        if not isinstance(self.data, (str, unicode)):
+            return self.data
+        else:
+            return encode_hex(self.data)
+
+
 def apply_transaction(block, tx):
     validate_transaction(block, tx)
 
@@ -139,16 +160,16 @@ def rp(what, actual, target):
     ext = VMExt(block, tx)
     if tx.to and tx.to != CREATE_CONTRACT_ADDRESS:
         result, gas_remained, data = apply_msg(ext, message)
-        log_tx.debug('_res_', result=result, gas_remained=gas_remained, data=data)
+        log_tx.debug('_res_', result=result, gas_remained=gas_remained, data=lazy_safe_encode(data))
     else:  # CREATE
         result, gas_remained, data = create_contract(ext, message)
         assert utils.is_numeric(gas_remained)
-        log_tx.debug('_create_', result=result, gas_remained=gas_remained, data=data)
+        log_tx.debug('_create_', result=result, gas_remained=gas_remained, data=lazy_safe_encode(data))
 
     assert gas_remained >= 0
 
     log_tx.debug("TX APPLIED", result=result, gas_remained=gas_remained,
-                 data=data)
+                 data=lazy_safe_encode(data))
 
     if not result:  # 0 = OOG failure in both cases
         log_tx.debug('TX FAILED', reason='out of gas',
@@ -158,7 +179,7 @@ def rp(what, actual, target):
         output = b''
         success = 0
     else:
-        log_tx.debug('TX SUCCESS', data=data)
+        log_tx.debug('TX SUCCESS', data=lazy_safe_encode(data))
         gas_used = tx.startgas - gas_remained
         block.refunds += len(set(block.suicides)) * opcodes.GSUICIDEREFUND
         if block.refunds > 0:

ethereum/slogging.py

@@ -85,7 +85,7 @@ def get_configuration():
 
     config_string = ','.join('%s:%s' % x for x in name_levels)
 
-    return dict(config_string=config_string, log_json=root.log_json)
+    return dict(config_string=config_string, log_json=SLogger.manager.log_json)
 
 
 def get_logger_names():
@@ -121,17 +121,22 @@ def __init__(self, name, level=DEFAULT_LOGLEVEL):
         self.warn = self.warning
         super(SLogger, self).__init__(name, level=level)
 
+    @property
+    def log_json(self):
+        return SLogger.manager.log_json
+
     def is_active(self, level_name='trace'):
         return self.isEnabledFor(logging._checkLevel(level_name.upper()))
 
-    def format_message(self, msg, kwargs, highlight):
+    def format_message(self, msg, kwargs, highlight, level):
         if getattr(self, 'log_json', False):
             message = {
                 k: v if isnumeric(v) or isinstance(v, (float, complex)) else repr(v)
                 for k, v in kwargs.items()
             }
 
-            message['event'] = "{}.{}".format(self.name, msg)
+            message['event'] = '{}.{}'.format(self.name, msg.lower().replace(' ', '_'))
+            message['level'] = logging.getLevelName(level)
             msg = json.dumps(message)
         else:
             msg = "{}{} {}{}".format(
@@ -140,7 +145,6 @@ def format_message(self, msg, kwargs, highlight):
                 " ".join("{}={!s}".format(k, v) for k, v in kwargs.items()),
                 bcolors.ENDC if highlight else ""
             )
-
         return msg
 
     def bind(self, **kwargs):
@@ -152,7 +156,7 @@ def _log(self, level, msg, args, **kwargs):
         highlight = kwargs.pop('highlight', False)
         extra['kwargs'] = kwargs
         extra['original_msg'] = msg
-        msg = self.format_message(msg, kwargs, highlight)
+        msg = self.format_message(msg, kwargs, highlight, level)
         super(SLogger, self)._log(level, msg, args, exc_info, extra)
 
     def DEV(self, msg, *args, **kwargs):
@@ -174,7 +178,6 @@ def __init__(self, level):
         Initialize the logger with the name "root".
         """
         super(RootLogger, self).__init__("root", level)
-        self.log_json = False
 
     def handle(self, record):
         if log_listeners:
@@ -189,6 +192,7 @@ class SManager(logging.Manager):
 
     def __init__(self, rootnode):
         self.loggerClass = SLogger
+        self.log_json = False
         super(SManager, self).__init__(rootnode)
 
     def getLogger(self, name):
@@ -209,7 +213,6 @@ def getLogger(name=None):
 
     if name:
         logger = SLogger.manager.getLogger(name)
-        logger.log_json = rootLogger.log_json
         return logger
     else:
         return rootLogger
@@ -220,11 +223,11 @@ def configure(config_string=None, log_json=False, log_file=None):
         config_string = ":{}".format(DEFAULT_LOGLEVEL)
 
     if log_json:
+        SLogger.manager.log_json = True
         log_format = JSON_FORMAT
-        rootLogger.log_json = True
     else:
+        SLogger.manager.log_json = False
         log_format = PRINT_FORMAT
-        rootLogger.log_json = False
 
     if len(rootLogger.handlers) == 0:
         handler = StreamHandler()

ethereum/tests/test_logging.py

@@ -5,6 +5,20 @@
 from ethereum import slogging
 
 
+def setup_function(function):
+    """ setup any state tied to the execution of the given function.
+    Invoked for every test function in the module.
+    """
+    function.snapshot = slogging.get_configuration()
+
+
+def teardown_function(function):
+    """ teardown any state that was previously setup with a setup_function
+    call.
+    """
+    slogging.configure(**function.snapshot)
+
+
 @pytest.mark.parametrize('level_name', ['critical', 'error', 'warning', 'info', 'debug', 'trace'])
 def test_basic(caplog, level_name):
     slogging.configure(":trace")
@@ -35,7 +49,7 @@ def test_jsonconfig(caplog):
     slogging.configure(log_json=True)
     log = slogging.get_logger('prefix')
     log.warn('abc', a=1)
-    assert json.loads(caplog.records()[0].msg) == dict(event='prefix.abc', a=1)
+    assert json.loads(caplog.records()[0].msg) == dict(event='prefix.abc', a=1, level='WARNING')
 
 
 def test_configuration():
@@ -237,14 +251,14 @@ def test_bound_logger(caplog):
     with caplog.at_level(slogging.TRACE):
         bound_log_1.info("test1")
         assert "test1" in caplog.text
-        assert "key1=value1" in caplog.text
+        assert 'key1=value1' in caplog.text
 
     bound_log_2 = bound_log_1.bind(key2="value2")
     with caplog.at_level(slogging.TRACE):
         bound_log_2.info("test2")
         assert "test2" in caplog.text
-        assert "key1=value1" in caplog.text
-        assert "key2=value2" in caplog.text
+        assert 'key1=value1' in caplog.text
+        assert 'key2=value2' in caplog.text
 
 
 def test_bound_logger_isolation(caplog):
@@ -260,18 +274,18 @@ def test_bound_logger_isolation(caplog):
         records = caplog.records()
         assert len(records) == 1
         assert "test1" in records[0].msg
-        assert "key1=value1" in records[0].msg
+        assert 'key1=value1' in records[0].msg
 
     with caplog.at_level(slogging.TRACE):
         real_log.info("test2")
         records = caplog.records()
         assert len(records) == 2
         assert "test2" in records[1].msg
-        assert "key1=value1" not in records[1].msg
+        assert 'key1=value1' not in records[1].msg
 
 
 def test_highlight(caplog):
-    slogging.configure()
+    slogging.configure(log_json=False)
     log = slogging.getLogger()
 
     log.DEV('testmessage')

ethereum/transactions.py

@@ -157,6 +157,7 @@ def log_dict(self):
         d = self.to_dict()
         d['sender'] = encode_hex(d['sender'] or '')
         d['to'] = encode_hex(d['to'])
+        d['data'] = encode_hex(d['data'])
         return d
 
     @property