[tor-commits] [stem/master] Avoid trace logging when unused

atagar at torproject.org atagar at torproject.org
Thu Sep 21 17:32:54 UTC 2017


commit 5cd78b36aa6608bd570eb7536f90aa5b9048fe58
Author: Damian Johnson <atagar at torproject.org>
Date:   Sun Sep 17 13:52:15 2017 -0700

    Avoid trace logging when unused
    
    If a tree falls in an empty forest does it make a sound? Constructing trace
    runlevel log messages in stem.socket is absolutley *killing* performance on
    busy relays. As in pegging cpu to the point of killing the tor process.
    
    ... ouch.
    
    Only constructing trace log messages if someone's actually listening for them.
---
 docs/change_log.rst        |  3 ++-
 stem/socket.py             | 31 ++++++++++++++++++-------------
 stem/util/log.py           | 19 +++++++++++++++++++
 stem/util/system.py        | 18 ++++++++++--------
 test/settings.cfg          |  1 +
 test/unit/util/__init__.py |  1 +
 test/unit/util/log.py      | 23 +++++++++++++++++++++++
 7 files changed, 74 insertions(+), 22 deletions(-)

diff --git a/docs/change_log.rst b/docs/change_log.rst
index 60457e48..8d9c10aa 100644
--- a/docs/change_log.rst
+++ b/docs/change_log.rst
@@ -79,6 +79,8 @@ The following are only available within Stem's `git repository
  * **Utilities**
 
   * Support connection resolution on OpenBSD using fstat (:trac:`13807`)
+  * Added :func:`~stem.util.system.size_of`
+  * Added :func:`~stem.util.log.is_tracing`
   * Added timeout argument to :func:`~stem.util.system.call`
   * Added cwd argument to :func:`~stem.util.system.call`
   * Added round argument to :func:`~stem.util.str_tools.size_label`
@@ -86,7 +88,6 @@ The following are only available within Stem's `git repository
   * Supporing pid arguments in :func:`~stem.util.system.is_running`
   * Normalized :func:`~stem.util.term.format` to return unicode
   * Don't load vim swap files as configurations
-  * Added :func:`~stem.util.system.size_of`
 
  * **Interpreter**
 
diff --git a/stem/socket.py b/stem/socket.py
index d10b40d2..171e9417 100644
--- a/stem/socket.py
+++ b/stem/socket.py
@@ -80,6 +80,8 @@ import stem.util.str_tools
 
 from stem.util import log
 
+MESSAGE_PREFIX = re.compile(b'^[a-zA-Z0-9]{3}[-+ ]')
+
 # lines to limit our trace logging to, you can disable this by setting it to None
 
 TRUNCATE_LOGS = 10
@@ -484,9 +486,10 @@ def send_message(control_file, message, raw = False):
     control_file.write(stem.util.str_tools._to_bytes(message))
     control_file.flush()
 
-    log_message = message.replace('\r\n', '\n').rstrip()
-    msg_div = '\n' if '\n' in log_message else ' '
-    log.trace('Sent to tor:%s%s' % (msg_div, log_message))
+    if log.is_tracing():
+      log_message = message.replace('\r\n', '\n').rstrip()
+      msg_div = '\n' if '\n' in log_message else ' '
+      log.trace('Sent to tor:%s%s' % (msg_div, log_message))
   except socket.error as exc:
     log.info('Failed to send message: %s' % exc)
 
@@ -557,7 +560,7 @@ def recv_message(control_file):
     # Parses the tor control lines. These are of the form...
     # <status code><divider><content>\r\n
 
-    if len(line) == 0:
+    if not line:
       # if the socket is disconnected then the readline() method will provide
       # empty content
 
@@ -568,7 +571,7 @@ def recv_message(control_file):
       prefix = logging_prefix % 'ProtocolError'
       log.info(prefix + 'line too short, "%s"' % log.escape(line))
       raise stem.ProtocolError('Badly formatted reply line: too short')
-    elif not re.match(b'^[a-zA-Z0-9]{3}[-+ ]', line):
+    elif not MESSAGE_PREFIX.match(line):
       prefix = logging_prefix % 'ProtocolError'
       log.info(prefix + 'malformed status code/divider, "%s"' % log.escape(line))
       raise stem.ProtocolError('Badly formatted reply line: beginning is malformed')
@@ -593,16 +596,18 @@ def recv_message(control_file):
       parsed_content.append((status_code, divider, content))
 
       raw_content_str = b''.join(raw_content)
-      log_message = stem.util.str_tools._to_unicode(raw_content_str.replace(b'\r\n', b'\n').rstrip())
-      log_message_lines = log_message.split('\n')
 
-      if TRUNCATE_LOGS and len(log_message_lines) > TRUNCATE_LOGS:
-        log_message = '\n'.join(log_message_lines[:TRUNCATE_LOGS] + ['... %i more lines...' % (len(log_message_lines) - TRUNCATE_LOGS)])
+      if log.is_tracing():
+        log_message = stem.util.str_tools._to_unicode(raw_content_str.replace(b'\r\n', b'\n').rstrip())
+        log_message_lines = log_message.split('\n')
+
+        if TRUNCATE_LOGS and len(log_message_lines) > TRUNCATE_LOGS:
+          log_message = '\n'.join(log_message_lines[:TRUNCATE_LOGS] + ['... %i more lines...' % (len(log_message_lines) - TRUNCATE_LOGS)])
 
-      if len(log_message_lines) > 2:
-        log.trace('Received from tor:\n%s' % log_message)
-      else:
-        log.trace('Received from tor: %s' % log_message.replace('\n', '\\n'))
+        if len(log_message_lines) > 2:
+          log.trace('Received from tor:\n%s' % log_message)
+        else:
+          log.trace('Received from tor: %s' % log_message.replace('\n', '\\n'))
 
       return stem.response.ControlMessage(parsed_content, raw_content_str)
     elif divider == '+':
diff --git a/stem/util/log.py b/stem/util/log.py
index e157c7c0..88b533e6 100644
--- a/stem/util/log.py
+++ b/stem/util/log.py
@@ -88,6 +88,9 @@ DEDUPLICATION_MESSAGE_IDS = set()
 
 
 class _NullHandler(logging.Handler):
+  def __init__(self):
+    logging.Handler.__init__(self, level = logging.FATAL + 5)  # disable logging
+
   def emit(self, record):
     pass
 
@@ -119,6 +122,22 @@ def logging_level(runlevel):
     return logging.FATAL + 5
 
 
+def is_tracing():
+  """
+  Checks if we're logging at the trace runlevel.
+
+  .. versionadded:: 1.6.0
+
+  :returns: **True** if we're logging at the trace runlevel and **False** otherwise
+  """
+
+  for handler in get_logger().handlers:
+    if handler.level <= logging_level(TRACE):
+      return True
+
+  return False
+
+
 def escape(message):
   """
   Escapes specific sequences for logging (newlines, tabs, carriage returns). If
diff --git a/stem/util/system.py b/stem/util/system.py
index 3a40e13d..fb799227 100644
--- a/stem/util/system.py
+++ b/stem/util/system.py
@@ -1284,14 +1284,16 @@ def call(command, default = UNDEFINED, ignore_exit_status = False, timeout = Non
     runtime = time.time() - start_time
 
     log.debug('System call: %s (runtime: %0.2f)' % (command, runtime))
-    trace_prefix = 'Received from system (%s)' % command
-
-    if stdout and stderr:
-      log.trace(trace_prefix + ', stdout:\n%s\nstderr:\n%s' % (stdout, stderr))
-    elif stdout:
-      log.trace(trace_prefix + ', stdout:\n%s' % stdout)
-    elif stderr:
-      log.trace(trace_prefix + ', stderr:\n%s' % stderr)
+
+    if log.is_tracing():
+      trace_prefix = 'Received from system (%s)' % command
+
+      if stdout and stderr:
+        log.trace(trace_prefix + ', stdout:\n%s\nstderr:\n%s' % (stdout, stderr))
+      elif stdout:
+        log.trace(trace_prefix + ', stdout:\n%s' % stdout)
+      elif stderr:
+        log.trace(trace_prefix + ', stderr:\n%s' % stderr)
 
     exit_status = process.poll()
 
diff --git a/test/settings.cfg b/test/settings.cfg
index 4cc9d7ee..5b3ba6bc 100644
--- a/test/settings.cfg
+++ b/test/settings.cfg
@@ -189,6 +189,7 @@ test.unit_tests
 |test.unit.util.enum.TestEnum
 |test.unit.util.connection.TestConnection
 |test.unit.util.conf.TestConf
+|test.unit.util.log.TestLog
 |test.unit.util.proc.TestProc
 |test.unit.util.str_tools.TestStrTools
 |test.unit.util.system.TestSystem
diff --git a/test/unit/util/__init__.py b/test/unit/util/__init__.py
index 866ec4b3..89190f7e 100644
--- a/test/unit/util/__init__.py
+++ b/test/unit/util/__init__.py
@@ -12,6 +12,7 @@ __all__ = [
   'conf',
   'connection',
   'enum',
+  'log',
   'proc',
   'str_tools',
   'system',
diff --git a/test/unit/util/log.py b/test/unit/util/log.py
new file mode 100644
index 00000000..615d8d36
--- /dev/null
+++ b/test/unit/util/log.py
@@ -0,0 +1,23 @@
+"""
+Unit tests for the stem.util.log functions.
+"""
+
+import unittest
+
+from stem.util import log
+
+
+class TestLog(unittest.TestCase):
+  def test_is_tracing(self):
+    logger = log.get_logger()
+    original_handlers = logger.handlers
+    logger.handlers = [log._NullHandler()]
+
+    try:
+      self.assertFalse(log.is_tracing())
+      logger.addHandler(log.LogBuffer(log.DEBUG))
+      self.assertFalse(log.is_tracing())
+      logger.addHandler(log.LogBuffer(log.TRACE))
+      self.assertTrue(log.is_tracing())
+    finally:
+      logger.handlers = original_handlers





More information about the tor-commits mailing list