commit b20b60df25a5f99f32b0f347173083883e6fb409 Author: Damian Johnson <atagar@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 ( )] -@uses_settings +@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))