[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