- tor-commits - lists.torproject.org

[stem/master] Util for reading proc contents
by atagar＠torproject.org 09 Nov '11

09 Nov '11

commit 78de4e4cf1f442b50ec1b30733127f9b83a97fce Author: Damian Johnson <atagar(a)torproject.org> Date: Tue Nov 8 09:04:16 2011 -0800 Util for reading proc contents Rewrite of arm's utility for parsing proc contents, changes including better error handling and refacotring for stem's coding conventions and commenting. While writing the PROTOCOLINFO response handler I needed a system util for querying tor's pwd, which works best with proc information, so pulling it all in. For now most of this isn't being exercised, but will be later. --- stem/util/__init__.py | 2 +- stem/util/proc.py | 446 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 447 insertions(+), 1 deletions(-) diff --git a/stem/util/__init__.py b/stem/util/__init__.py index ef6730b..2e6b479 100644 --- a/stem/util/__init__.py +++ b/stem/util/__init__.py @@ -2,5 +2,5 @@ Utility functions used by the stem library. """ -__all__ = ["conf", "enum", "log", "system", "term"] +__all__ = ["conf", "enum", "log", "proc", "system", "term"] diff --git a/stem/util/proc.py b/stem/util/proc.py new file mode 100644 index 0000000..a5fc886 --- /dev/null +++ b/stem/util/proc.py @@ -0,0 +1,446 @@ +""" +Helper functions for querying process and system information from the /proc +contents. Fetching information this way provides huge performance benefits +over lookups via system utilities (ps, netstat, etc). For instance, resolving +connections this way cuts the runtime by around 90% verses the alternatives. +These functions may not work on all platforms (only Linux?). + +The method for reading these files (and a little code) are borrowed from +psutil: +https://code.google.com/p/psutil/ + +which was written by Jay Loden, Dave Daeschler, Giampaolo Rodola' and is under +the BSD license. +""" + +import os +import sys +import time +import socket +import base64 + +from stem.util import enum, log + +# cached system values +IS_PROC_AVAILABLE, SYS_START_TIME, SYS_PHYSICAL_MEMORY = None, None, None +CLOCK_TICKS = os.sysconf(os.sysconf_names["SC_CLK_TCK"]) +Stat = enum.Enum(("COMMAND", "command"), ("CPU_UTIME", "utime"), + ("CPU_STIME", "stime"), ("START_TIME", "start time")) + +def is_available(): + """ + Checks if proc information is available on this platform. + + Returns: + bool that's True if proc contents exist on this platform, False otherwise + """ + + global IS_PROC_AVAILABLE + + if IS_PROC_AVAILABLE == None: + if os.uname()[0] != "Linux": + IS_PROC_AVAILABLE = False + else: + # list of process independent proc paths we use + proc_paths = ("/proc/stat", "/proc/meminfo", "/proc/net/tcp", "/proc/net/udp") + proc_paths_exist = True + + for path in proc_paths: + if not os.path.exists(path): + proc_paths_exist = False + break + + IS_PROC_AVAILABLE = proc_paths_exist + + return IS_PROC_AVAILABLE + +def get_system_start_time(): + """ + Provides the unix time (seconds since epoch) when the system started. + + Returns: + float for the unix time of when the system started + + Raises: + IOError if it can't be determined + """ + + global SYS_START_TIME + if not SYS_START_TIME: + start_time, parameter = time.time(), "system start time" + btime_line = _get_line("/proc/stat", "btime", parameter) + + try: + SYS_START_TIME = float(btime_line.strip().split()[1]) + _log_runtime(parameter, "/proc/stat[btime]", start_time) + except: + exc = IOError("unable to parse the /proc/stat btime entry: %s" % btime_line) + _log_failure(parameter, exc) + raise exc + + return SYS_START_TIME + +def get_physical_memory(): + """ + Provides the total physical memory on the system in bytes. + + Returns: + int for the bytes of physical memory this system has + + Raises: + IOError if it can't be determined + """ + + global SYS_PHYSICAL_MEMORY + if not SYS_PHYSICAL_MEMORY: + start_time, parameter = time.time(), "system physical memory" + mem_total_line = _get_line("/proc/meminfo", "MemTotal:", parameter) + + try: + SYS_PHYSICAL_MEMORY = int(mem_total_line.split()[1]) * 1024 + _log_runtime(parameter, "/proc/meminfo[MemTotal]", start_time) + except: + exc = IOError("unable to parse the /proc/meminfo MemTotal entry: %s" % mem_total_line) + _log_failure(parameter, exc) + raise exc + + return SYS_PHYSICAL_MEMORY + +def get_pwd(pid): + """ + Provides the current working directory for the given process. + + Arguments: + pid (int) - process id of the process to be queried + + Returns: + str with the path of the workign direcctory for the process + + Raises: + IOError if it can't be determined + """ + + start_time, parameter = time.time(), "cwd" + proc_cwd_link = "/proc/%s/cwd" % pid + + if pid == 0: cwd = "" + else: + try: cwd = os.readlink(proc_cwd_link) + except OSError: + exc = IOError("unable to read %s" % proc_cwd_link) + _log_failure(parameter, exc) + raise exc + + _log_runtime(parameter, proc_cwd_link, start_time) + return cwd + +def get_uid(pid): + """ + Provides the user ID the given process is running under. + + Arguments: + pid (int) - process id of the process to be queried + + Returns: + int with the user id for the owner of the process + + Raises: + IOError if it can't be determined + """ + + start_time, parameter = time.time(), "uid" + status_path = "/proc/%s/status" % pid + uid_line = _get_line(status_path, "Uid:", parameter) + + try: + result = int(uid_line.split()[1]) + _log_runtime(parameter, "%s[Uid]" % status_path, start_time) + return result + except: + exc = IOError("unable to parse the %s Uid entry: %s" % (status_path, uid_line)) + _log_failure(parameter, exc) + raise exc + +def get_memory_usage(pid): + """ + Provides the memory usage in bytes for the given process. + + Arguments: + pid (int) - process id of the process to be queried + + Returns: + tuple of two ints with the memory usage of the process, of the form: + (residentSize, virtualSize) + + Raises: + IOError if it can't be determined + """ + + # checks if this is the kernel process + if pid == 0: return (0, 0) + + start_time, parameter = time.time(), "memory usage" + status_path = "/proc/%s/status" % pid + mem_lines = _get_lines(status_path, ("VmRSS:", "VmSize:"), parameter) + + try: + residentSize = int(mem_lines["VmRSS:"].split()[1]) * 1024 + virtualSize = int(mem_lines["VmSize:"].split()[1]) * 1024 + + _log_runtime(parameter, "%s[VmRSS|VmSize]" % status_path, start_time) + return (residentSize, virtualSize) + except: + exc = IOError("unable to parse the %s VmRSS and VmSize entries: %s" % (status_path, ", ".join(mem_lines))) + _log_failure(parameter, exc) + raise exc + +def get_stats(pid, *stat_types): + """ + Provides process specific information. Options are: + Stat.COMMAND command name under which the process is running + Stat.CPU_UTIME total user time spent on the process + Stat.CPU_STIME total system time spent on the process + Stat.START_TIME when this process began, in unix time + + Arguments: + pid (int) - process id of the process to be queried + stat_types (Stat) - information to be provided back + + Returns: + tuple with all of the requested statistics as strings + + Raises: + IOError if it can't be determined + """ + + start_time, parameter = time.time(), "process %s" % ", ".join(stat_types) + + # the stat file contains a single line, of the form... + # 8438 (tor) S 8407 8438 8407 34818 8438 4202496... + stat_path = "/proc/%s/stat" % pid + stat_line = _get_line(stat_path, str(pid), parameter) + + # breaks line into component values + stat_comp = [] + cmd_start, cmd_end = stat_line.find("("), stat_line.find(")") + + if cmd_start != -1 and cmd_end != -1: + stat_comp.append(stat_line[:cmd_start]) + stat_comp.append(stat_line[cmd_start + 1:cmd_end]) + stat_comp += stat_line[cmd_end + 1:].split() + + if len(stat_comp) != 44 and _is_float(stat_comp[13], stat_comp[14], stat_comp[21]): + exc = IOError("stat file had an unexpected format: %s" % stat_path) + _log_failure(parameter, exc) + raise exc + + results = [] + for stat_type in stat_types: + if stat_type == Stat.COMMAND: + if pid == 0: results.append("sched") + else: results.append(stat_comp[1]) + elif stat_type == Stat.CPU_UTIME: + if pid == 0: results.append("0") + else: results.append(str(float(stat_comp[13]) / CLOCK_TICKS)) + elif stat_type == Stat.CPU_STIME: + if pid == 0: results.append("0") + else: results.append(str(float(stat_comp[14]) / CLOCK_TICKS)) + elif stat_type == Stat.START_TIME: + if pid == 0: return get_system_start_time() + else: + # According to documentation, starttime is in field 21 and the unit is + # jiffies (clock ticks). We divide it for clock ticks, then add the + # uptime to get the seconds since the epoch. + p_start_time = float(stat_comp[21]) / CLOCK_TICKS + results.append(str(p_start_time + get_system_start_time())) + + _log_runtime(parameter, stat_path, start_time) + return tuple(results) + +def get_connections(pid): + """ + Queries connection related information from the proc contents. This provides + similar results to netstat, lsof, sockstat, and other connection resolution + utilities (though the lookup is far quicker). + + Arguments: + pid (int) - process id of the process to be queried + + Returns: + A listing of connection tuples of the form: + [(local_ipAddr1, local_port1, foreign_ipAddr1, foreign_port1), ...] + + IP addresses are strings and ports are ints. + + Raises: + IOError if it can't be determined + """ + + if pid == 0: return [] + + # fetches the inode numbers for socket file descriptors + start_time, parameter = time.time(), "process connections" + inodes = [] + for fd in os.listdir("/proc/%s/fd" % pid): + fd_path = "/proc/%s/fd/%s" % (pid, fd) + + try: + # File descriptor link, such as 'socket:[30899]' + fd_name = os.readlink(fd_path) + + if fd_name.startswith('socket:['): + inodes.append(fd_name[8:-1]) + except OSError: + # most likely couldn't be read due to permissions + exc = IOError("unable to determine file descriptor destination: %s" % fd_path) + _log_failure(parameter, exc) + raise exc + + if not inodes: + # unable to fetch any connections for this process + return [] + + # check for the connection information from the /proc/net contents + conn = [] + for proc_file_path in ("/proc/net/tcp", "/proc/net/udp"): + try: + proc_file = open(proc_file_path) + proc_file.readline() # skip the first line + + for line in proc_file: + _, l_addr, f_addr, status, _, _, _, _, _, inode = line.split()[:10] + + if inode in inodes: + # if a tcp connection, skip if it isn't yet established + if proc_file_path.endswith("/tcp") and status != "01": + continue + + local_ip, local_port = _decode_proc_address_encoding(l_addr) + foreign_ip, foreign_port = _decode_proc_address_encoding(f_addr) + conn.append((local_ip, local_port, foreign_ip, foreign_port)) + + proc_file.close() + except IOError, exc: + exc = IOError("unable to read '%s': %s" % (proc_file_path, exc)) + _log_failure(parameter, exc) + raise exc + except Exception, exc: + exc = IOError("unable to parse '%s': %s" % (proc_file_path, exc)) + _log_failure(parameter, exc) + raise exc + + _log_runtime(parameter, "/proc/net/[tcp|udp]", start_time) + return conn + +def _decode_proc_address_encoding(addr): + """ + Translates an address entry in the /proc/net/* contents to a human readable + form, for instance: + "0500000A:0016" -> ("10.0.0.5", 22) + + Reference: + http://linuxdevcenter.com/pub/a/linux/2000/11/16/LinuxAdmin.html + + Arguments: + addr (str) - proc address entry to be decoded + + Returns: + tuple of the form (addr, port), with addr as a string and port an int + """ + + ip, port = addr.split(':') + + # the port is represented as a two-byte hexadecimal number + port = int(port, 16) + + if sys.version_info >= (3,): + ip = ip.encode('ascii') + + # The IPv4 address portion is a little-endian four-byte hexadecimal number. + # That is, the least significant byte is listed first, so we need to reverse + # the order of the bytes to convert it to an IP address. + ip = socket.inet_ntop(socket.AF_INET, base64.b16decode(ip)[::-1]) + + return (ip, port) + +def _is_float(*value): + try: + for v in value: float(v) + return True + except ValueError: + return False + +def _get_line(file_path, line_prefix, parameter): + return _get_lines(file_path, (line_prefix, ), parameter)[line_prefix] + +def _get_lines(file_path, line_prefixes, parameter): + """ + Fetches lines with the given prefixes from a file. This only provides back + the first instance of each prefix. + + Arguments: + file_path (str) - path of the file to read + line_prefixes (tuple) - string prefixes of the lines to return + parameter (str) - description of the proc attribute being fetch + + Returns: + mapping of prefixes to the matching line + + Raises: + IOError if unable to read the file or can't find all of the prefixes + """ + + try: + remaining_prefixes = list(line_prefixes) + proc_file, results = open(file_path), {} + + for line in proc_file: + if not remaining_prefixes: break # found everything we're looking for + + for prefix in remaining_prefixes: + if line.startswith(prefix): + results[prefix] = line + remaining_prefixes.remove(prefix) + break + + proc_file.close() + + if remaining_prefixes: + if len(remaining_prefixes) == 1: + msg = "%s did not contain a %s entry" % (file_path, remaining_prefixes[0]) + else: + msg = "%s did not contain %s entries" % (file_path, ", ".join(remaining_prefixes)) + + raise IOError(msg) + else: + return results + except IOError, exc: + _log_failure(parameter, exc) + raise exc + +def _log_runtime(parameter, proc_location, start_time): + """ + Logs a message indicating a successful proc query. + + Arguments: + parameter (str) - description of the proc attribute being fetch + proc_location (str) - proc files we were querying + start_time (int) - unix time for when this query was started + """ + + runtime = time.time() - start_time + msg = "proc call (%s): %s (runtime: %0.4f)" % (parameter, proc_location, runtime) + log.log(log.DEBUG, msg) + +def _log_failure(parameter, exc): + """ + Logs a message indicating that the proc query failed. + + Arguments: + parameter (str) - description of the proc attribute being fetch + exc (Exception) - exception that we're raising + """ + + msg = "proc call failed (%s): %s" % (parameter, exc) + log.log(log.INFO, msg) +

1 0

[stem/master] Fully qualifying util paths
by atagar＠torproject.org 09 Nov '11

09 Nov '11

commit 7c7bd6adeca59e593635d6eb21c6a9a0e7cf585e Author: Damian Johnson <atagar(a)torproject.org> Date: Wed Nov 9 10:23:07 2011 -0800 Fully qualifying util paths Changing the conventional usage of util imports from "from stem.util import X" to simple imports (not pulling them into our namespace). There's some exceptions to fully qualified util usage where it hurts readability (often the case with stem.util.term), but explite paths will be the more common case. --- run_tests.py | 7 +++++-- stem/process.py | 5 ++--- stem/util/proc.py | 4 ++-- stem/util/term.py | 10 +++++----- test/integ/system.py | 4 ++-- test/runner.py | 6 +++--- 6 files changed, 19 insertions(+), 17 deletions(-) diff --git a/run_tests.py b/run_tests.py index cd84d3f..0b86706 100755 --- a/run_tests.py +++ b/run_tests.py @@ -10,6 +10,7 @@ import time import getopt import logging import unittest + import test.runner import test.unit.types.control_message import test.unit.types.control_line @@ -17,7 +18,8 @@ import test.unit.types.version import test.integ.message import test.integ.system -from stem.util import enum, term +import stem.util.enum +import stem.util.term as term OPT = "uic:t:h" OPT_EXPANDED = ["unit", "integ", "config=", "targets=", "help"] @@ -36,7 +38,8 @@ INTEG_TESTS = (("stem.types.ControlMessage", test.integ.message.TestMessageFunct # TODO: drop targets? # Configurations that the intergration tests can be ran with. Attributs are # tuples of the test runner and description. -TARGETS = enum.Enum(*[(v, v) for v in ("NONE", "NO_CONTROL", "NO_AUTH", "COOKIE", "PASSWORD", "SOCKET")]) +TARGETS = stem.util.enum.Enum(*[(v, v) for v in ("NONE", "NO_CONTROL", "NO_AUTH", "COOKIE", "PASSWORD", "SOCKET")]) + TARGET_ATTR = { TARGETS.NONE: (None, "No running tor instance."), TARGETS.NO_CONTROL: (None, "Basic client, no control port or socket."), diff --git a/stem/process.py b/stem/process.py index 4eaf1f7..2974989 100644 --- a/stem/process.py +++ b/stem/process.py @@ -12,8 +12,7 @@ import signal import subprocess import stem.types - -from stem.util import system +import stem.util.system # number of seconds before we time out our attempt to start a tor instance DEFAULT_INIT_TIMEOUT = 90 @@ -38,7 +37,7 @@ def get_tor_version(tor_cmd = "tor"): if not tor_cmd in VERSION_CACHE: try: version_cmd = "%s --version" % tor_cmd - version_output = system.call(version_cmd) + version_output = stem.util.system.call(version_cmd) except OSError, exc: raise IOError(exc) diff --git a/stem/util/proc.py b/stem/util/proc.py index 505a3d4..30fab6a 100644 --- a/stem/util/proc.py +++ b/stem/util/proc.py @@ -20,14 +20,14 @@ import socket import base64 import logging -from stem.util import enum +import stem.util.enum LOGGER = logging.getLogger("stem") # cached system values IS_PROC_AVAILABLE, SYS_START_TIME, SYS_PHYSICAL_MEMORY = None, None, None CLOCK_TICKS = os.sysconf(os.sysconf_names["SC_CLK_TCK"]) -Stat = enum.Enum(("COMMAND", "command"), ("CPU_UTIME", "utime"), +Stat = stem.util.enum.Enum(("COMMAND", "command"), ("CPU_UTIME", "utime"), ("CPU_STIME", "stime"), ("START_TIME", "start time")) def is_available(): diff --git a/stem/util/term.py b/stem/util/term.py index a2465a2..99c37fc 100644 --- a/stem/util/term.py +++ b/stem/util/term.py @@ -2,13 +2,13 @@ Utilities for working with the terminal. """ -from stem.util import enum +import stem.util.enum TERM_COLORS = ("BLACK", "RED", "GREEN", "YELLOW", "BLUE", "MAGENTA", "CYAN", "WHITE") -Color = enum.Enum(*TERM_COLORS) -BgColor = enum.Enum(*["BG_" + color for color in TERM_COLORS]) -Attr = enum.Enum("BOLD", "UNDERLINE", "HILIGHT") +Color = stem.util.enum.Enum(*TERM_COLORS) +BgColor = stem.util.enum.Enum(*["BG_" + color for color in TERM_COLORS]) +Attr = stem.util.enum.Enum("BOLD", "UNDERLINE", "HILIGHT") # mappings of terminal attribute enums to their ANSI escape encoding FG_ENCODING = dict([(Color.values()[i], str(30 + i)) for i in range(8)]) @@ -45,7 +45,7 @@ def format(msg, *attr): encodings = [] for text_attr in attr: - text_attr, encoding = enum.to_camel_case(text_attr), None + text_attr, encoding = stem.util.enum.to_camel_case(text_attr), None encoding = FG_ENCODING.get(text_attr, encoding) encoding = BG_ENCODING.get(text_attr, encoding) encoding = ATTR_ENCODING.get(text_attr, encoding) diff --git a/test/integ/system.py b/test/integ/system.py index 39e2d3e..dc5b24c 100644 --- a/test/integ/system.py +++ b/test/integ/system.py @@ -3,9 +3,9 @@ Unit tests for the util.system functions in the context of a tor process. """ import unittest -import test.runner -from stem.util import system +import test.runner +import stem.util.system as system class TestSystemFunctions(unittest.TestCase): """ diff --git a/test/runner.py b/test/runner.py index feb19fb..21cf1e5 100644 --- a/test/runner.py +++ b/test/runner.py @@ -25,8 +25,8 @@ import tempfile import threading import stem.process - -from stem.util import conf, term +import stem.util.conf +import stem.util.term as term DEFAULT_CONFIG = { "test.integ.test_directory": "./test/data", @@ -281,7 +281,7 @@ class Runner: _print_status(" loading test configuration... skipped\n", STATUS_ATTR, quiet) else: # loads custom testing configuration - test_config = conf.get_config("test") + test_config = stem.util.conf.get_config("test") config_path = os.path.abspath(config_path) try:

1 0

[stem/master] Replacing custom logging util with python builtin
by atagar＠torproject.org 09 Nov '11

09 Nov '11

commit 713eec7b70c06ab3361f22fb49f6eb6a8b9e82d3 Author: Damian Johnson <atagar(a)torproject.org> Date: Wed Nov 9 10:13:55 2011 -0800 Replacing custom logging util with python builtin Finally abandoning my custom logging implementation for the python builtin logging module. It's far more customizable, standardized, and what users would expect from a library like this. The only disadvantage is that it doesn't buffer past events so we lose anything prior to adding a handler. --- run_tests.py | 3 + stem/__init__.py | 2 + stem/types.py | 21 ++++--- stem/util/__init__.py | 11 ++++ stem/util/conf.py | 22 +++---- stem/util/log.py | 150 ------------------------------------------------- stem/util/proc.py | 9 ++- stem/util/system.py | 9 ++- test/integ/system.py | 2 +- test/runner.py | 30 ++++++++++ test/testrc.sample | 5 ++ 11 files changed, 84 insertions(+), 180 deletions(-) diff --git a/run_tests.py b/run_tests.py index 1228fcc..cd84d3f 100755 --- a/run_tests.py +++ b/run_tests.py @@ -8,6 +8,7 @@ import os import sys import time import getopt +import logging import unittest import test.runner import test.unit.types.control_message @@ -123,6 +124,7 @@ if __name__ == '__main__': print "%s\n%s\n%s\n" % (DIVIDER, "INTEGRATION TESTS".center(70), DIVIDER) integ_runner = test.runner.get_runner() + stem_logger = logging.getLogger("stem") try: # TODO: note unused config options afterward @@ -133,6 +135,7 @@ if __name__ == '__main__': for name, test_class in INTEG_TESTS: print "%s\n%s\n%s\n" % (DIVIDER, name, DIVIDER) + stem_logger.info("STARTING INTEGRATION TEST => %s" % name) suite = unittest.TestLoader().loadTestsFromTestCase(test_class) unittest.TextTestRunner(verbosity=2).run(suite) print diff --git a/stem/__init__.py b/stem/__init__.py index 5ac77ed..ac69776 100644 --- a/stem/__init__.py +++ b/stem/__init__.py @@ -2,5 +2,7 @@ Library for working with the tor process. """ +import stem.util # suppresses log handler warnings + __all__ = ["process", "types"] diff --git a/stem/types.py b/stem/types.py index 17d812c..e03698c 100644 --- a/stem/types.py +++ b/stem/types.py @@ -27,9 +27,10 @@ Version - Tor versioning information. import re import socket +import logging import threading -from stem.util import log +LOGGER = logging.getLogger("stem") KEY_ARG = re.compile("^(\S+)=") @@ -78,10 +79,10 @@ def read_message(control_file): # if the control_file has been closed then we will receive: # AttributeError: 'NoneType' object has no attribute 'recv' - log.log(log.WARN, "ControlSocketClosed: socket file has been closed") + LOGGER.warn("ControlSocketClosed: socket file has been closed") raise ControlSocketClosed("socket file has been closed") except socket.error, exc: - log.log(log.WARN, "ControlSocketClosed: received an exception (%s)" % exc) + LOGGER.warn("ControlSocketClosed: received an exception (%s)" % exc) raise ControlSocketClosed(exc) raw_content += line @@ -93,16 +94,16 @@ def read_message(control_file): # if the socket is disconnected then the readline() method will provide # empty content - log.log(log.WARN, "ControlSocketClosed: empty socket content") + LOGGER.warn("ControlSocketClosed: empty socket content") raise ControlSocketClosed("Received empty socket content.") elif len(line) < 4: - log.log(log.WARN, "ProtocolError: line too short (%s)" % line) + LOGGER.warn("ProtocolError: line too short (%s)" % line) raise ProtocolError("Badly formatted reply line: too short") elif not re.match(r'^[a-zA-Z0-9]{3}[-+ ]', line): - log.log(log.WARN, "ProtocolError: malformed status code/divider (%s)" % line) + LOGGER.warn("ProtocolError: malformed status code/divider (%s)" % line) raise ProtocolError("Badly formatted reply line: beginning is malformed") elif not line.endswith("\r\n"): - log.log(log.WARN, "ProtocolError: no CRLF linebreak (%s)" % line) + LOGGER.warn("ProtocolError: no CRLF linebreak (%s)" % line) raise ProtocolError("All lines should end with CRLF") line = line[:-2] # strips off the CRLF @@ -115,7 +116,7 @@ def read_message(control_file): # end of the message, return the message parsed_content.append((status_code, divider, content)) - log.log(log.DEBUG, "Received message:\n" + raw_content) + LOGGER.debug("Received message:\n" + raw_content) return ControlMessage(parsed_content, raw_content) elif divider == "+": @@ -129,7 +130,7 @@ def read_message(control_file): raw_content += line if not line.endswith("\r\n"): - log.log(log.WARN, "ProtocolError: no CRLF linebreak for data entry (%s)" % line) + LOGGER.warn("ProtocolError: no CRLF linebreak for data entry (%s)" % line) raise ProtocolError("All lines should end with CRLF") elif line == ".\r\n": break # data block termination @@ -150,7 +151,7 @@ def read_message(control_file): else: # this should never be reached due to the prefix regex, but might as well # be safe... - log.log(log.WARN, "ProtocolError: unrecognized divider type (%s)" % line) + LOGGER.warn("ProtocolError: unrecognized divider type (%s)" % line) raise ProtocolError("Unrecognized type '%s': %s" % (divider, line)) class ControlMessage: diff --git a/stem/util/__init__.py b/stem/util/__init__.py index 2e6b479..0391293 100644 --- a/stem/util/__init__.py +++ b/stem/util/__init__.py @@ -2,5 +2,16 @@ Utility functions used by the stem library. """ +# Adds a default nullhandler for the stem logger, suppressing the 'No handlers +# could be found for logger "stem"' warning as per... +# http://docs.python.org/release/3.1.3/library/logging.html#configuring-loggi… + +import logging + +class NullHandler(logging.Handler): + def emit(self, record): pass + +logging.getLogger("stem").addHandler(NullHandler()) + __all__ = ["conf", "enum", "log", "proc", "system", "term"] diff --git a/stem/util/conf.py b/stem/util/conf.py index 40cc956..7581a98 100644 --- a/stem/util/conf.py +++ b/stem/util/conf.py @@ -72,14 +72,12 @@ Example usage: user_config.update(ssh_config) """ +import logging import threading -from stem.util import log - +LOGGER = logging.getLogger("stem") CONFS = {} # mapping of identifier to singleton instances of configs -TYPE_ERROR_RUNLEVEL = log.NOTICE - # TODO: methods that will be needed if we want to allow for runtime # customization... # @@ -149,7 +147,7 @@ class Config(): self._requested_keys.add(key) else: msg = "config entry '%s' not found, defaulting to '%s'" % (key, default) - log.log(log.DEBUG, msg) + LOGGER.debug(msg) val = default self._contents_lock.release() @@ -205,19 +203,19 @@ class Config(): elif val.lower() == "false": val = False else: msg = "Config entry '%s' is expected to be a boolean, defaulting to '%s'" % (key, str(default)) - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) val = default elif isinstance(default, int): try: val = int(val) except ValueError: msg = "Config entry '%s' is expected to be an integer, defaulting to '%i'" % (key, default) - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) val = default elif isinstance(default, float): try: val = float(val) except ValueError: msg = "Config entry '%s' is expected to be a float, defaulting to '%f'" % (key, default) - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) val = default elif isinstance(default, list): pass # nothing special to do (already a list) @@ -231,7 +229,7 @@ class Config(): valMap[entryKey.strip()] = entryVal.strip() else: msg = "Ignoring invalid %s config entry (expected a mapping, but \"%s\" was missing \"=>\")" % (key, entry) - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) val = valMap elif key.startswith("log."): if val.upper() == "NONE": val = None @@ -239,7 +237,7 @@ class Config(): else: msg = "Config entry '%s' is expected to be a runlevel" % key if default != None: msg += ", defaulting to '%s'" % default - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) val = default return val @@ -271,7 +269,7 @@ class Config(): defaultStr = ", ".join([str(i) for i in default]) msg += ", defaulting to '%s'" % defaultStr - log.log(TYPE_ERROR_RUNLEVEL, msg) + LOGGER.info(msg) return default return conf_comp @@ -318,7 +316,7 @@ class Config(): break if error_msg: - log.log(TYPE_ERROR_RUNLEVEL, error_msg) + LOGGER.info(error_msg) return default else: return [int(val) for val in conf_comp] diff --git a/stem/util/log.py b/stem/util/log.py deleted file mode 100644 index 656052b..0000000 --- a/stem/util/log.py +++ /dev/null @@ -1,150 +0,0 @@ -""" -Tracks application events, both directing them to attached listeners and -keeping a record of them. A limited space is provided for old events, keeping -and trimming them on a per-runlevel basis (ie, too many DEBUG events will only -result in entries from that runlevel being dropped). All functions are thread -safe. -""" - -import time -from sys import maxint -from threading import RLock - -from stem.util import enum - -# Logging runlevels. These are *very* commonly used so including shorter -# aliases (so they can be referenced as log.DEBUG, log.WARN, etc). -Runlevel = enum.Enum(*[(v, v) for v in ("DEBUG", "INFO", "NOTICE", "WARN", "ERR")]) -DEBUG, INFO, NOTICE, WARN, ERR = Runlevel.values() - -LOG_LOCK = RLock() # provides thread safety for logging operations -MAX_LOG_SIZE = 1000 # maximum log entries per runlevel to be persisted - -# chronologically ordered records of events for each runlevel, stored as tuples -# consisting of: (time, message) -_backlog = dict([(level, []) for level in Runlevel.values()]) - -# mapping of runlevels to the listeners interested in receiving events from it -_listeners = dict([(level, []) for level in Runlevel.values()]) - -def log(level, msg, event_time = None): - """ - Registers an event, directing it to interested listeners and preserving it in - the backlog. - - Arguments: - level (Runlevel) - runlevel corresponding to the message severity - msg (str) - string associated with the message - event_time (int) - unix time at which the event occurred, current time if - undefined - """ - - # config attempts to disable log entries by using a runlevel of None - if not level: return - - if event_time == None: event_time = time.time() - - LOG_LOCK.acquire() - try: - new_event = (event_time, msg) - event_backlog = _backlog[level] - - # inserts the new event into the backlog - if not event_backlog or event_time >= event_backlog[-1][0]: - # newest event - append to end - event_backlog.append(new_event) - elif event_time <= event_backlog[0][0]: - # oldest event - insert at start - event_backlog.insert(0, new_event) - else: - # somewhere in the middle - start checking from the end - for i in range(len(event_backlog) - 1, -1, -1): - if event_backlog[i][0] <= event_time: - event_backlog.insert(i + 1, new_event) - break - - # truncates backlog if too long - to_delete = len(event_backlog) - MAX_LOG_SIZE - if to_delete > 0: del event_backlog[:to_delete] - - # notifies listeners - for callback in _listeners[level]: - callback(level, msg, event_time) - finally: - LOG_LOCK.release() - -def add_listener(levels, callback, dump_backlog = False): - """ - Directs future events to the given callback function. - - Arguments: - levels (list) - runlevels for the listener to be notified of - callback (functor) - functor to accept the events, of the form: - my_function(runlevel, msg, time) - dump_backlog (bool) - if true then this passes prior events to the callback - function (in chronological order) before returning - """ - - LOG_LOCK.acquire() - try: - for level in levels: - if not callback in _listeners[level]: - _listeners[level].append(callback) - - if dump_backlog: - for level, msg, event_time in _get_entries(levels): - callback(level, msg, event_time) - finally: - LOG_LOCK.release() - -def remove_listener(level, callback): - """ - Prevents a listener from being notified of further events. - - Arguments: - level (Runlevel) - runlevel for the listener to be removed from - callback (functor) - functor to be removed - - Returns: - True if a listener was removed, False otherwise - """ - - if callback in _listeners[level]: - _listeners[level].remove(callback) - return True - else: return False - -def _get_entries(levels): - """ - Generator for providing past events belonging to the given runlevels (in - chronological order). This should be used under the LOG_LOCK to prevent - concurrent modifications. - - Arguments: - levels (list) - runlevels for which events are provided - """ - - # drops any runlevels if there aren't entries in it - to_remove = [level for level in levels if not _backlog[level]] - for level in to_remove: levels.remove(level) - - # tracks where unprocessed entries start in the backlog - backlog_ptr = dict([(level, 0) for level in levels]) - - while levels: - earliest_level, earliest_msg, earliest_time = None, "", maxint - - # finds the earliest unprocessed event - for level in levels: - entry = _backlog[level][backlog_ptr[level]] - - if entry[0] < earliest_time: - earliest_level, earliest_msg, earliest_time = level, entry[1], entry[0] - - yield (earliest_level, earliest_msg, earliest_time) - - # removes runlevel if there aren't any more entries - backlog_ptr[earliest_level] += 1 - if len(_backlog[earliest_level]) <= backlog_ptr[earliest_level]: - levels.remove(earliest_level) - diff --git a/stem/util/proc.py b/stem/util/proc.py index a5fc886..505a3d4 100644 --- a/stem/util/proc.py +++ b/stem/util/proc.py @@ -18,8 +18,11 @@ import sys import time import socket import base64 +import logging -from stem.util import enum, log +from stem.util import enum + +LOGGER = logging.getLogger("stem") # cached system values IS_PROC_AVAILABLE, SYS_START_TIME, SYS_PHYSICAL_MEMORY = None, None, None @@ -430,7 +433,7 @@ def _log_runtime(parameter, proc_location, start_time): runtime = time.time() - start_time msg = "proc call (%s): %s (runtime: %0.4f)" % (parameter, proc_location, runtime) - log.log(log.DEBUG, msg) + LOGGER.debug(msg) def _log_failure(parameter, exc): """ @@ -442,5 +445,5 @@ def _log_failure(parameter, exc): """ msg = "proc call failed (%s): %s" % (parameter, exc) - log.log(log.INFO, msg) + LOGGER.debug(msg) diff --git a/stem/util/system.py b/stem/util/system.py index a27c265..b63974d 100644 --- a/stem/util/system.py +++ b/stem/util/system.py @@ -6,9 +6,10 @@ dependent, only working on linux, osx, and bsd. import re import os import time +import logging import subprocess -from stem.util import log +LOGGER = logging.getLogger("stem") # Mapping of commands to if they're available or not. This isn't always # reliable, failing for some special commands. For these the cache is @@ -265,7 +266,7 @@ def get_bsd_jail_id(pid): jid = ps_output[1].strip() if jid.isdigit(): return int(jid) - log.log(log.WARN, "Failed to figure out the FreeBSD jail id. Assuming 0.") + LOGGER.warn("Failed to figure out the FreeBSD jail id. Assuming 0.") return 0 def call(command, suppress_exc = True): @@ -295,13 +296,13 @@ def call(command, suppress_exc = True): msg = "system call: %s (runtime: %0.2f)" % (command, runtime) if stderr: msg += "\nstderr: %s" % stderr - log.log(log.DEBUG, msg) + LOGGER.debug(msg) if stdout: return stdout.split("\n") else: return [] except OSError, exc: msg = "system call (failed): %s (error: %s)" % (command, exc) - log.log(log.INFO, msg) + LOGGER.debug(msg) if suppress_exc: return None else: raise exc diff --git a/test/integ/system.py b/test/integ/system.py index 1fcb3d2..39e2d3e 100644 --- a/test/integ/system.py +++ b/test/integ/system.py @@ -47,5 +47,5 @@ class TestSystemFunctions(unittest.TestCase): properly). """ - self.assertEquals(0, system.get_bsd_jail_id("blarg_and_stuff")) + self.assertEquals(0, system.get_bsd_jail_id(99999)) diff --git a/test/runner.py b/test/runner.py index 6e2f998..feb19fb 100644 --- a/test/runner.py +++ b/test/runner.py @@ -20,6 +20,7 @@ import os import sys import time import shutil +import logging import tempfile import threading @@ -29,6 +30,7 @@ from stem.util import conf, term DEFAULT_CONFIG = { "test.integ.test_directory": "./test/data", + "test.integ.log": "./test/data/log", "test.integ.run.online": False, } @@ -327,6 +329,34 @@ class Runner: _print_status("failed (%s)\n" % exc, ERROR_ATTR, quiet) raise exc + # configures logging + logging_path = self._config["test.integ.log"] + + if logging_path: + # makes paths relative of stem's base directory + if logging_path.startswith("./"): + logging_path = STEM_BASE + logging_path[1:] + + _print_status(" configuring logger (%s)... " % logging_path, STATUS_ATTR, quiet) + + # delete the old log + if os.path.exists: os.remove(logging_path) + + logging.basicConfig( + filename = logging_path, + level = logging.DEBUG, + format = '%(asctime)s [%(levelname)s] %(message)s', + datefmt = '%D %H:%M:%S', + ) + + stem_logger = logging.getLogger("stem") + stem_logger.info("Logging opened for integration test run") + #datefmt='%m/%d/%Y %I:%M:%S %p', + + _print_status("done\n", STATUS_ATTR, quiet) + else: + _print_status(" configuring logger... skipped\n", STATUS_ATTR, quiet) + # writes our testing torrc torrc_dst = os.path.join(self._test_dir, "torrc") try: diff --git a/test/testrc.sample b/test/testrc.sample index cff8d13..47e3862 100644 --- a/test/testrc.sample +++ b/test/testrc.sample @@ -8,10 +8,15 @@ # have a faster startup and lower load on authorities). If set to an empty # value then this makes a fresh data directory for each test run. # +# test.integ.log +# Path runtime logs are placed. Relative paths are expanded in reference to +# 'run_tests.py'. Logging is disabled if set ot an empty value. +# # test.integ.run.online # Runs tests with network activity. If set then we'll wait for tor to fully # bootstrap when starting, which won't happen without a network connection. test.integ.test_directory ./test/data +test.integ.log ./test/data/log test.integ.run.online false

1 0

[thandy/master] Add logCtrl for scripts that might fail from a thp
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit d2f814426fc5bae6315daea3feb8a3f8a2a9efd5 Author: Tomás Touceda <chiiph(a)torproject.org> Date: Sat Nov 5 14:54:57 2011 -0300 Add logCtrl for scripts that might fail from a thp --- lib/thandy/packagesys/ThpPackages.py | 5 +++++ 1 files changed, 5 insertions(+), 0 deletions(-) diff --git a/lib/thandy/packagesys/ThpPackages.py b/lib/thandy/packagesys/ThpPackages.py index f82415e..4745767 100644 --- a/lib/thandy/packagesys/ThpPackages.py +++ b/lib/thandy/packagesys/ThpPackages.py @@ -16,6 +16,8 @@ import thandy.formats import thandy.packagesys.PackageSystem as PS import thandy.packagesys.PackageDB as PDB +from thandy.util import logCtrl + json = thandy.util.importJSON() class ThpDB(object): @@ -184,15 +186,18 @@ class ThpTransaction(PS.Transaction): for pkg in order: if pkg.run('checkinst') != 0: logging.info("Check inst failed for %s" % pkg) + logCtrl("ERROR", SCRIPT="checkinst") sys.exit(1) for pkg in order: logging.info("Starting installation using %s" % pkg) if pkg.run('preinst') != 0: logging.info("Preinst script for %s failed" % pkg) + logCtrl("ERROR", SCRIPT="preinst") sys.exit(1) pkg.install() if pkg.run('postinst') != 0: logging.info("postinst script failed") + logCtrl("ERROR", SCRIPT="postinst") except AlreadyLocked: print "You can't run more than one instance of Thandy" except LockFailed:

1 0

[thandy/master] Don't exit when trying to create a directory for an installed package
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit 849bfc07585efc8ca0cc056022af0ef5246b7ad1 Author: Tomás Touceda <chiiph(a)torproject.org> Date: Sat Nov 5 16:55:40 2011 -0300 Don't exit when trying to create a directory for an installed package --- lib/thandy/packagesys/ThpPackages.py | 7 ++++++- 1 files changed, 6 insertions(+), 1 deletions(-) diff --git a/lib/thandy/packagesys/ThpPackages.py b/lib/thandy/packagesys/ThpPackages.py index 4745767..17c0791 100644 --- a/lib/thandy/packagesys/ThpPackages.py +++ b/lib/thandy/packagesys/ThpPackages.py @@ -8,6 +8,7 @@ import time import shutil import subprocess import sys +import errno from lockfile import LockFile, AlreadyLocked, LockFailed @@ -261,7 +262,11 @@ class ThpInstaller(PS.Installer): pass if "/" in file["name"]: - os.makedirs("/".join([destPath] + file["name"].split("/")[:-1])) + try: + os.makedirs(os.path.join(*([destPath] + file["name"].split("/")[:-1]))) + except OSError, e: + if e.errno != errno.EEXIST: + raise e shutil.copy(os.path.join(self._pkg.getTmpPath(), "content", file['name']), os.path.join(destPath, file['name']));

1 0

[tor/master] Include HiddenServiceDir in some warning messages
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit 565463243c4e019bfd8dff965582f02a2aa05e14 Author: Robert Ransom <rransom.8774(a)gmail.com> Date: Mon Nov 7 17:02:50 2011 -0800 Include HiddenServiceDir in some warning messages --- changes/bug4426 | 8 ++++++++ src/or/rendservice.c | 9 ++++++--- 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/changes/bug4426 b/changes/bug4426 new file mode 100644 index 0000000..1322243 --- /dev/null +++ b/changes/bug4426 @@ -0,0 +1,8 @@ + o Minor features: + + - When Tor ignores a hidden service specified in its + configuration, include the hidden service's directory in the + warning message. Previously, we would only tell the user that + some hidden service was ignored. Bugfix on 0.0.6; fixes bug + 4426. + diff --git a/src/or/rendservice.c b/src/or/rendservice.c index 0f57319..25695c5 100644 --- a/src/or/rendservice.c +++ b/src/or/rendservice.c @@ -171,14 +171,17 @@ rend_add_service(rend_service_t *service) if (service->auth_type != REND_NO_AUTH && smartlist_len(service->clients) == 0) { - log_warn(LD_CONFIG, "Hidden service with client authorization but no " - "clients; ignoring."); + log_warn(LD_CONFIG, "Hidden service (%s) with client authorization but no " + "clients; ignoring.", + esc_for_log(service->directory)); rend_service_free(service); return; } if (!smartlist_len(service->ports)) { - log_warn(LD_CONFIG, "Hidden service with no ports configured; ignoring."); + log_warn(LD_CONFIG, "Hidden service (%s) with no ports configured; " + "ignoring.", + esc_for_log(service->directory)); rend_service_free(service); } else { int dupe = 0;

1 0

[tor/master] Merge remote-tracking branch 'rransom-tor/bug4426' into maint-0.2.2
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit 8adec8705014ef7e788a1dcf5d3a4a2d85a328ed Merge: 0cc7a63 56546324 Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed Nov 9 11:03:20 2011 -0500 Merge remote-tracking branch 'rransom-tor/bug4426' into maint-0.2.2 changes/bug4426 | 8 ++++++++ src/or/rendservice.c | 9 ++++++--- 2 files changed, 14 insertions(+), 3 deletions(-)

1 0

[tor/master] Merge remote-tracking branch 'origin/maint-0.2.2'
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit f0589da0e3270e627ac6fd249976234a4c085d3f Merge: 9452b65 8adec87 Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed Nov 9 11:04:40 2011 -0500 Merge remote-tracking branch 'origin/maint-0.2.2' changes/bug4426 | 8 ++++++++ src/or/rendservice.c | 9 ++++++--- 2 files changed, 14 insertions(+), 3 deletions(-)

1 0

[tor/maint-0.2.2] Include HiddenServiceDir in some warning messages
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit 565463243c4e019bfd8dff965582f02a2aa05e14 Author: Robert Ransom <rransom.8774(a)gmail.com> Date: Mon Nov 7 17:02:50 2011 -0800 Include HiddenServiceDir in some warning messages --- changes/bug4426 | 8 ++++++++ src/or/rendservice.c | 9 ++++++--- 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/changes/bug4426 b/changes/bug4426 new file mode 100644 index 0000000..1322243 --- /dev/null +++ b/changes/bug4426 @@ -0,0 +1,8 @@ + o Minor features: + + - When Tor ignores a hidden service specified in its + configuration, include the hidden service's directory in the + warning message. Previously, we would only tell the user that + some hidden service was ignored. Bugfix on 0.0.6; fixes bug + 4426. + diff --git a/src/or/rendservice.c b/src/or/rendservice.c index 0f57319..25695c5 100644 --- a/src/or/rendservice.c +++ b/src/or/rendservice.c @@ -171,14 +171,17 @@ rend_add_service(rend_service_t *service) if (service->auth_type != REND_NO_AUTH && smartlist_len(service->clients) == 0) { - log_warn(LD_CONFIG, "Hidden service with client authorization but no " - "clients; ignoring."); + log_warn(LD_CONFIG, "Hidden service (%s) with client authorization but no " + "clients; ignoring.", + esc_for_log(service->directory)); rend_service_free(service); return; } if (!smartlist_len(service->ports)) { - log_warn(LD_CONFIG, "Hidden service with no ports configured; ignoring."); + log_warn(LD_CONFIG, "Hidden service (%s) with no ports configured; " + "ignoring.", + esc_for_log(service->directory)); rend_service_free(service); } else { int dupe = 0;

1 0

[tor/maint-0.2.2] Merge remote-tracking branch 'rransom-tor/bug4426' into maint-0.2.2
by nickm＠torproject.org 09 Nov '11

09 Nov '11

commit 8adec8705014ef7e788a1dcf5d3a4a2d85a328ed Merge: 0cc7a63 56546324 Author: Nick Mathewson <nickm(a)torproject.org> Date: Wed Nov 9 11:03:20 2011 -0500 Merge remote-tracking branch 'rransom-tor/bug4426' into maint-0.2.2 changes/bug4426 | 8 ++++++++ src/or/rendservice.c | 9 ++++++--- 2 files changed, 14 insertions(+), 3 deletions(-)

1 0