[tor-commits] [nyx/master] read_tor_log() for reading tor log files

atagar at torproject.org atagar at torproject.org
Tue May 5 05:42:06 UTC 2015


commit b20b60df25a5f99f32b0f347173083883e6fb409
Author: Damian Johnson <atagar at torproject.org>
Date:   Mon Apr 6 15:41:50 2015 -0700

    read_tor_log() for reading tor log files
    
    Replacing get_log_file_entries() with a tested, simpler function. This is still
    a lot grosser than I'd like, but not much I can do unless something happens
    with #15607.
---
 nyx/config/strings.cfg                |    1 +
 nyx/log_panel.py                      |  149 ++++-----------------------------
 nyx/util/__init__.py                  |    9 +-
 nyx/util/log.py                       |   77 +++++++++++++++++
 run_tests.py                          |    5 +-
 test/util/data/malformed_date         |   21 +++++
 test/util/data/malformed_line         |   21 +++++
 test/util/data/malformed_runlevel     |   21 +++++
 test/util/data/multiple_tor_instances |   33 ++++++++
 test/util/data/tor_log                |   21 +++++
 test/util/read_tor_log.py             |   59 +++++++++++++
 11 files changed, 282 insertions(+), 135 deletions(-)

diff --git a/nyx/config/strings.cfg b/nyx/config/strings.cfg
index d1169b9..7660bfb 100644
--- a/nyx/config/strings.cfg
+++ b/nyx/config/strings.cfg
@@ -24,6 +24,7 @@ msg.panel.graphing.prepopulation_successful Bandwidth graph has information for
 msg.panel.graphing.bw_event_cache_malformed Tor's 'GETINFO bw-event-cache' provided malformed output: {response}
 msg.panel.header.fd_used_at_sixty_percent Tor's file descriptor usage is at {percentage}%.
 msg.panel.header.fd_used_at_ninety_percent Tor's file descriptor usage is at {percentage}%. If you run out Tor will be unable to continue functioning.
+msg.panel.log.read_from_log_file Read {count} entries from tor's log file: {path} (read limit: {read_limit}, runtime: {runtime})
 
 msg.setup.nyx_is_running_as_root Nyx is currently running with root permissions. This isn't a good idea, nor should it be necessary. Try starting nyx with "sudo -u {tor_user} nyx" instead.
 msg.setup.chroot_doesnt_exist The chroot path set in your config ({path}) doesn't exist.
diff --git a/nyx/log_panel.py b/nyx/log_panel.py
index b314eaa..8650996 100644
--- a/nyx/log_panel.py
+++ b/nyx/log_panel.py
@@ -14,12 +14,13 @@ import threading
 import stem
 from stem.control import State
 from stem.response import events
-from stem.util import conf, log, str_tools, system
+from stem.util import conf, log, str_tools
 
 import nyx.arguments
 import nyx.popups
 from nyx import __version__
 from nyx.util import panel, tor_controller, ui_tools
+from nyx.util.log import read_tor_log
 
 RUNLEVEL_EVENT_COLOR = {
   log.DEBUG: 'magenta',
@@ -124,136 +125,12 @@ def load_log_messages():
       COMMON_LOG_MESSAGES[event_type] = messages
 
 
-def get_log_file_entries(runlevels, read_limit = None, add_limit = None):
-  """
-  Parses tor's log file for past events matching the given runlevels, providing
-  a list of log entries (ordered newest to oldest). Limiting the number of read
-  entries is suggested to avoid parsing everything from logs in the GB and TB
-  range.
-
-  Arguments:
-    runlevels - event types (DEBUG - ERR) to be returned
-    read_limit - max lines of the log file that'll be read (unlimited if None)
-    add_limit  - maximum entries to provide back (unlimited if None)
-  """
-
-  start_time = time.time()
-
-  if not runlevels:
-    return []
-
-  # checks tor's configuration for the log file's location (if any exists)
-
-  logging_types, logging_location = None, None
-
-  for logging_entry in tor_controller().get_conf('Log', [], True):
-    # looks for an entry like: notice file /var/log/tor/notices.log
-
-    entry_comp = logging_entry.split()
+def log_file_path():
+  for log_entry in tor_controller().get_conf('Log', [], True):
+    entry_comp = log_entry.split()  # looking for an entry like: notice file /var/log/tor/notices.log
 
     if entry_comp[1] == 'file':
-      logging_types, logging_location = entry_comp[0], entry_comp[2]
-      break
-
-  if not logging_location:
-    return []
-
-  # includes the prefix for tor paths
-
-  logging_location = CONFIG['tor.chroot'] + logging_location
-
-  # if the runlevels argument is a superset of the log file then we can
-  # limit the read contents to the add_limit
-
-  runlevels = list(log.Runlevel)
-  logging_types = logging_types.upper()
-
-  if add_limit and (not read_limit or read_limit > add_limit):
-    if '-' in logging_types:
-      div_index = logging_types.find('-')
-      start_index = runlevels.index(logging_types[:div_index])
-      end_index = runlevels.index(logging_types[div_index + 1:])
-      log_file_run_levels = runlevels[start_index:end_index + 1]
-    else:
-      start_index = runlevels.index(logging_types)
-      log_file_run_levels = runlevels[start_index:]
-
-    # checks if runlevels we're reporting are a superset of the file's contents
-
-    is_file_subset = True
-
-    for runlevel_type in log_file_run_levels:
-      if runlevel_type not in runlevels:
-        is_file_subset = False
-        break
-
-    if is_file_subset:
-      read_limit = add_limit
-
-  logged_events = []
-  current_unix_time, current_local_time = time.time(), time.localtime()
-
-  try:
-    for line in system.tail(logging_location, read_limit):
-      # entries look like:
-      # Jul 15 18:29:48.806 [notice] Parsing GEOIP file.
-
-      line_comp = line.split()
-
-      # Checks that we have all the components we expect. This could happen if
-      # we're either not parsing a tor log or in weird edge cases (like being
-      # out of disk space)
-
-      if len(line_comp) < 4:
-        continue
-
-      event_type = line_comp[3][1:-1].upper()
-
-      if event_type in runlevels:
-        # converts timestamp to unix time
-
-        timestamp = ' '.join(line_comp[:3])
-
-        # strips the decimal seconds
-
-        if '.' in timestamp:
-          timestamp = timestamp[:timestamp.find('.')]
-
-        # Ignoring wday and yday since they aren't used.
-        #
-        # Pretend the year is 2012, because 2012 is a leap year, and parsing a
-        # date with strptime fails if Feb 29th is passed without a year that's
-        # actually a leap year. We can't just use the current year, because we
-        # might be parsing old logs which didn't get rotated.
-        #
-        # https://trac.torproject.org/projects/tor/ticket/5265
-
-        timestamp = '2012 ' + timestamp
-        event_time_comp = list(time.strptime(timestamp, '%Y %b %d %H:%M:%S'))
-        event_time_comp[8] = current_local_time.tm_isdst
-        event_time = time.mktime(event_time_comp)  # converts local to unix time
-
-        # The above is gonna be wrong if the logs are for the previous year. If
-        # the event's in the future then correct for this.
-
-        if event_time > current_unix_time + 60:
-          event_time_comp[0] -= 1
-          event_time = time.mktime(event_time_comp)
-
-        event_msg = ' '.join(line_comp[4:])
-        logged_events.append(LogEntry(event_time, event_type, event_msg, RUNLEVEL_EVENT_COLOR[event_type]))
-
-      if 'opening log file' in line:
-        break  # this entry marks the start of this tor instance
-  except IOError:
-    log.warn("Unable to read tor's log file: %s" % logging_location)
-
-  if add_limit:
-    logged_events = logged_events[:add_limit]
-
-  log.info("Read %i entries from tor's log file: %s (read limit: %i, runtime: %0.3f)" % (len(logged_events), logging_location, read_limit, time.time() - start_time))
-
-  return logged_events
+      return CONFIG['tor.chroot'] + entry_comp[2]
 
 
 def get_daybreaks(events, ignore_time_for_cache = False):
@@ -571,10 +448,18 @@ class LogPanel(panel.Panel, threading.Thread, logging.Handler):
     if CONFIG['features.log.prepopulate']:
       set_runlevels = list(set.intersection(set(self.logged_events), set(list(log.Runlevel))))
       read_limit = CONFIG['features.log.prepopulateReadLimit']
-      add_limit = CONFIG['cache.log_panel.size']
 
-      for entry in get_log_file_entries(set_runlevels, read_limit, add_limit):
-        self.msg_log.append(entry)
+      logging_location = log_file_path()
+
+      if logging_location:
+        try:
+          for entry in read_tor_log(logging_location, read_limit):
+            if entry.runlevel in set_runlevels:
+              self.msg_log.append(LogEntry(entry.timestamp, entry.runlevel, entry.message, RUNLEVEL_EVENT_COLOR[entry.runlevel]))
+        except IOError as exc:
+          log.info("Unable to read log located at %s: %s" % (logging_location, exc))
+        except ValueError as exc:
+          log.info(str(exc))
 
     # crops events that are either too old, or more numerous than the caching size
 
diff --git a/nyx/util/__init__.py b/nyx/util/__init__.py
index 0e07dfc..58e739c 100644
--- a/nyx/util/__init__.py
+++ b/nyx/util/__init__.py
@@ -17,11 +17,13 @@ import sys
 
 import stem.connection
 import stem.util.conf
+import stem.util.log
 
 from nyx.util import log
 
 TOR_CONTROLLER = None
 BASE_DIR = os.path.sep.join(__file__.split(os.path.sep)[:-2])
+TESTING = False
 
 try:
   uses_settings = stem.util.conf.uses_settings('nyx', os.path.join(BASE_DIR, 'config'), lazy_load = False)
@@ -105,5 +107,10 @@ def msg(message, config, **attr):
   try:
     return config.get('msg.%s' % message).format(**attr)
   except:
-    log.notice('BUG: We attempted to use an undefined string resource (%s)' % message)
+    msg = 'BUG: We attempted to use an undefined string resource (%s)' % message
+
+    if TESTING:
+      raise ValueError(msg)
+
+    stem.util.log.notice(msg)
     return ''
diff --git a/nyx/util/log.py b/nyx/util/log.py
index 05061b9..d2e2eff 100644
--- a/nyx/util/log.py
+++ b/nyx/util/log.py
@@ -3,10 +3,22 @@ Logging utilities, primiarily short aliases for logging a message at various
 runlevels.
 """
 
+import collections
+import time
+
 import stem.util.log
+import stem.util.system
 
 import nyx.util
 
+LogEntry = collections.namedtuple('LogEntry', [
+  'timestamp',
+  'runlevel',
+  'message',
+])
+
+TOR_RUNLEVELS = ['DEBUG', 'INFO', 'NOTICE', 'WARN', 'ERR']
+
 
 def trace(msg, **attr):
   _log(stem.util.log.TRACE, msg, **attr)
@@ -42,3 +54,68 @@ def _log(runlevel, message, **attr):
   """
 
   stem.util.log.log(runlevel, nyx.util.msg(message, **attr))
+
+
+def read_tor_log(path, read_limit = None):
+  """
+  Provides logging messages from a tor log file, from newest to oldest.
+  LogEntry this provides have three attributes...
+
+    * **timestamp** (int)
+    * **runlevel** (str)
+    * **message** (str)
+
+  **Note:** The 'timestamp' has a hardcoded year of 2012 due to :trac:`15607`.
+
+  :param str path: logging location to read from
+  :param int read_limit: maximum number of lines to read from the file
+
+  :returns: **iterator** for **LogEntry** for the file's contents
+
+  :raises:
+    * **ValueError** if the log file has unrecognized content
+    * **IOError** if unable to read the file
+  """
+
+  start_time = time.time()
+  count, isdst = 0, time.localtime().tm_isdst
+
+  for line in stem.util.system.tail(path, read_limit):
+    # entries look like:
+    # Jul 15 18:29:48.806 [notice] Parsing GEOIP file.
+
+    line_comp = line.split()
+
+    # Checks that we have all the components we expect. This could happen if
+    # we're either not parsing a tor log or in weird edge cases (like being
+    # out of disk space).
+
+    if len(line_comp) < 4:
+      raise ValueError("Log located at %s has a line that doesn't match the format we expect: %s" % (path, line))
+    elif len(line_comp[3]) < 3 or line_comp[3][1:-1].upper() not in TOR_RUNLEVELS:
+      raise ValueError('Log located at %s has an unrecognized runlevel: %s' % (path, line_comp[3]))
+
+    runlevel = line_comp[3][1:-1].upper()
+    msg = ' '.join(line_comp[4:])
+
+    # Pretending the year is 2012 because 2012 is a leap year. We don't know
+    # the actual year (#15607) so picking something else risks strptime failing
+    # when it reads Feb 29th (#5265).
+
+    try:
+      timestamp_str = '2012 ' + ' '.join(line_comp[:3])
+      timestamp_str = timestamp_str.split('.', 1)[0]  # drop fractional seconds
+      timestamp_comp = list(time.strptime(timestamp_str, '%Y %b %d %H:%M:%S'))
+      timestamp_comp[8] = isdst
+
+      timestamp = int(time.mktime(timestamp_comp))  # converts local to unix time
+    except ValueError:
+      raise ValueError("Log located at %s has a timestamp we don't recognize: %s" % (path, ' '.join(line_comp[:3])))
+
+    count += 1
+    yield LogEntry(timestamp, runlevel, msg)
+
+    if 'opening log file' in msg:
+      break  # this entry marks the start of this tor instance
+
+  info('panel.log.read_from_log_file', count = count, path = path, read_limit = read_limit if read_limit else 'none', runtime = '%0.3f' % (time.time() - start_time))
diff --git a/run_tests.py b/run_tests.py
index d239393..17e879d 100755
--- a/run_tests.py
+++ b/run_tests.py
@@ -13,7 +13,7 @@ import unittest
 import stem.util.conf
 import stem.util.test_tools
 
-from nyx.util import uses_settings
+import nyx.util
 
 NYX_BASE = os.path.dirname(__file__)
 
@@ -25,8 +25,9 @@ SRC_PATHS = [os.path.join(NYX_BASE, path) for path in (
 )]
 
 
- at uses_settings
+ at nyx.util.uses_settings
 def main():
+  nyx.util.TESTING = True
   test_config = stem.util.conf.get_config('test')
   test_config.load(os.path.join(NYX_BASE, 'test', 'settings.cfg'))
 
diff --git a/test/util/data/empty_file b/test/util/data/empty_file
new file mode 100644
index 0000000..e69de29
diff --git a/test/util/data/malformed_date b/test/util/data/malformed_date
new file mode 100644
index 0000000..712149d
--- /dev/null
+++ b/test/util/data/malformed_date
@@ -0,0 +1,21 @@
+Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
+Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:03:39.833 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:03:39.833 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:03:39.838 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:03:39.838 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:03:39.000 [notice] Bootstrapped 0%: Starting
+Apr 06 11:03:42.000 [notice] Bootstrapped 45%: Asking for relay descriptors
+Apr 06 11:03:43.000 [notice] Bootstrapped 50%: Loading relay descriptors
+Apr 06 11:03:49.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:03:51.000 [notice] Bootstrapped 55%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 63%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 69%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 74%: Loading relay descriptors
+Apr 06 11:03:52.000 [notice] Bootstrapped 80%: Connecting to the Tor network
+Zed 06 11:03:52.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
+Apr 06 11:03:53.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
+Apr 06 11:03:53.000 [notice] Bootstrapped 100%: Done
+Apr 06 11:03:55.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:53:46.000 [notice] Interrupt: exiting cleanly.
diff --git a/test/util/data/malformed_line b/test/util/data/malformed_line
new file mode 100644
index 0000000..ac9a367
--- /dev/null
+++ b/test/util/data/malformed_line
@@ -0,0 +1,21 @@
+Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
+Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:03:39.833 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:03:39.833 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:03:39.838 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:03:39.838 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:03:39.000 [notice] Bootstrapped 0%: Starting
+Apr 06 11:03:42.000 [notice] Bootstrapped 45%: Asking for relay descriptors
+Apr 06 11:03:43.000 [notice] Bootstrapped 50%: Loading relay descriptors
+Apr 06 11:03:49.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:03:51.000 [notice] Bootstrapped 55%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 63%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 69%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 74%: Loading relay descriptors
+Apr 06 11:03:52.000 [notice] Bootstrapped 80%: Connecting to the Tor network
+Apr 06 11:03:52.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
+Apr 06 11:03:53.000
+Apr 06 11:03:53.000 [notice] Bootstrapped 100%: Done
+Apr 06 11:03:55.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:53:46.000 [notice] Interrupt: exiting cleanly.
diff --git a/test/util/data/malformed_runlevel b/test/util/data/malformed_runlevel
new file mode 100644
index 0000000..dd8810b
--- /dev/null
+++ b/test/util/data/malformed_runlevel
@@ -0,0 +1,21 @@
+Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
+Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:03:39.833 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:03:39.833 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:03:39.838 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:03:39.838 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:03:39.000 [notice] Bootstrapped 0%: Starting
+Apr 06 11:03:42.000 [notice] Bootstrapped 45%: Asking for relay descriptors
+Apr 06 11:03:43.000 [notice] Bootstrapped 50%: Loading relay descriptors
+Apr 06 11:03:49.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:03:51.000 [notice] Bootstrapped 55%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 63%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 69%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 74%: Loading relay descriptors
+Apr 06 11:03:52.000 [notice] Bootstrapped 80%: Connecting to the Tor network
+Apr 06 11:03:52.000 [unrecognized] Bootstrapped 90%: Establishing a Tor circuit
+Apr 06 11:03:53.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
+Apr 06 11:03:53.000 [notice] Bootstrapped 100%: Done
+Apr 06 11:03:55.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:53:46.000 [notice] Interrupt: exiting cleanly.
diff --git a/test/util/data/multiple_tor_instances b/test/util/data/multiple_tor_instances
new file mode 100644
index 0000000..1793ce5
--- /dev/null
+++ b/test/util/data/multiple_tor_instances
@@ -0,0 +1,33 @@
+Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
+Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:03:39.833 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:03:39.833 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:03:39.838 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:03:39.838 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:03:39.000 [notice] Bootstrapped 0%: Starting
+Apr 06 11:03:42.000 [notice] Bootstrapped 45%: Asking for relay descriptors
+Apr 06 11:03:43.000 [notice] Bootstrapped 50%: Loading relay descriptors
+Apr 06 11:03:49.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:03:51.000 [notice] Bootstrapped 55%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 63%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 69%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 74%: Loading relay descriptors
+Apr 06 11:03:52.000 [notice] Bootstrapped 80%: Connecting to the Tor network
+Apr 06 11:03:52.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
+Apr 06 11:03:53.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
+Apr 06 11:03:53.000 [notice] Bootstrapped 100%: Done
+Apr 06 11:03:55.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:53:46.000 [notice] Interrupt: exiting cleanly.
+Apr 06 11:53:54.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening log file.
+Apr 06 11:53:54.392 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:53:54.392 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:53:54.392 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:53:54.392 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:53:54.396 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:53:54.396 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:53:54.000 [warn] Your log may contain sensitive information - you're logging more than "notice". Don't log unless it serves an important reason. Overwrite the log afterwards.
+Apr 06 11:53:54.000 [debug] tor_disable_debugger_attach(): Attemping to disable debugger attachment to Tor for unprivileged users.
+Apr 06 11:53:54.000 [debug] tor_disable_debugger_attach(): Debugger attachment disabled for unprivileged users.
+Apr 06 11:53:54.000 [info] tor_lockfile_lock(): Locking "/home/atagar/.tor/lock"
+Apr 06 11:53:54.000 [debug] parse_dir_authority_line(): Trusted 100 dirserver at 128.31.0.39:9131 (9695)
diff --git a/test/util/data/tor_log b/test/util/data/tor_log
new file mode 100644
index 0000000..0a4464e
--- /dev/null
+++ b/test/util/data/tor_log
@@ -0,0 +1,21 @@
+Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
+Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
+Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
+Apr 06 11:03:39.833 [notice] This version is not a stable Tor release. Expect more bugs than usual.
+Apr 06 11:03:39.833 [notice] Read configuration file "/home/atagar/.tor/torrc".
+Apr 06 11:03:39.838 [notice] Opening Socks listener on 127.0.0.1:9050
+Apr 06 11:03:39.838 [notice] Opening Control listener on 127.0.0.1:9051
+Apr 06 11:03:39.000 [notice] Bootstrapped 0%: Starting
+Apr 06 11:03:42.000 [notice] Bootstrapped 45%: Asking for relay descriptors
+Apr 06 11:03:43.000 [notice] Bootstrapped 50%: Loading relay descriptors
+Apr 06 11:03:49.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:03:51.000 [notice] Bootstrapped 55%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 63%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 69%: Loading relay descriptors
+Apr 06 11:03:51.000 [notice] Bootstrapped 74%: Loading relay descriptors
+Apr 06 11:03:52.000 [notice] Bootstrapped 80%: Connecting to the Tor network
+Apr 06 11:03:52.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
+Apr 06 11:03:53.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
+Apr 06 11:03:53.000 [notice] Bootstrapped 100%: Done
+Apr 06 11:03:55.000 [notice] New control connection opened from 127.0.0.1.
+Apr 06 11:53:46.000 [notice] Interrupt: exiting cleanly.
diff --git a/test/util/read_tor_log.py b/test/util/read_tor_log.py
new file mode 100644
index 0000000..3b2ca01
--- /dev/null
+++ b/test/util/read_tor_log.py
@@ -0,0 +1,59 @@
+import os
+import unittest
+
+from nyx.util.log import LogEntry, read_tor_log
+
+
+def data_path(filename):
+  return os.path.join(os.path.dirname(__file__), 'data', filename)
+
+
+class TestReadTorLog(unittest.TestCase):
+  def test_general_log(self):
+    entries = list(read_tor_log(data_path('tor_log')))
+    self.assertEqual(21, len(entries))
+
+    self.assertEqual(LogEntry(1333738426, 'NOTICE', 'Interrupt: exiting cleanly.'), entries[0])
+    self.assertEqual(LogEntry(1333735419, 'NOTICE', 'Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.'), entries[-1])
+
+  def test_with_multiple_tor_instances(self):
+    entries = list(read_tor_log(data_path('multiple_tor_instances')))
+    self.assertEqual(12, len(entries))
+
+    self.assertEqual(LogEntry(1333738434, 'DEBUG', 'parse_dir_authority_line(): Trusted 100 dirserver at 128.31.0.39:9131 (9695)'), entries[0])
+    self.assertEqual(LogEntry(1333738434, 'INFO', 'tor_lockfile_lock(): Locking "/home/atagar/.tor/lock"'), entries[1])
+    self.assertEqual(LogEntry(1333738434, 'NOTICE', 'Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening log file.'), entries[-1])
+
+  def test_with_read_limit(self):
+    entries = list(read_tor_log(data_path('tor_log'), 5))
+    self.assertEqual(5, len(entries))
+    self.assertEqual('Interrupt: exiting cleanly.', entries[0].message)
+    self.assertEqual('Bootstrapped 90%: Establishing a Tor circuit', entries[-1].message)
+
+  def test_with_empty_file(self):
+    entries = list(read_tor_log(data_path('empty_file')))
+    self.assertEqual(0, len(entries))
+
+  def test_with_missing_path(self):
+    self.assertRaises(IOError, list, read_tor_log(data_path('no_such_path')))
+
+  def test_with_malformed_line(self):
+    try:
+      list(read_tor_log(data_path('malformed_line')))
+      self.fail("Malformed content should've raised a ValueError")
+    except ValueError as exc:
+      self.assertTrue("has a line that doesn't match the format we expect: Apr 06 11:03:53.000" in str(exc))
+
+  def test_with_malformed_runlevel(self):
+    try:
+      list(read_tor_log(data_path('malformed_runlevel')))
+      self.fail("Malformed content should've raised a ValueError")
+    except ValueError as exc:
+      self.assertTrue("has an unrecognized runlevel: [unrecognized]" in str(exc))
+
+  def test_with_malformed_date(self):
+    try:
+      list(read_tor_log(data_path('malformed_date')))
+      self.fail("Malformed content should've raised a ValueError")
+    except ValueError as exc:
+      self.assertTrue("has a timestamp we don't recognize: Zed 06 11:03:52.000" in str(exc))





More information about the tor-commits mailing list