commit 5cd78b36aa6608bd570eb7536f90aa5b9048fe58 Author: Damian Johnson atagar@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