Commit 52ac9c18 authored by Philipp Winter's avatar Philipp Winter
Browse files

Refactor logging and enable logging to file.

This commit adds the command line options "-o" and "--logfile" that
enable logging to file.  This functionality required minor restructuring
that led to a simplification of the logging code.  In particular:

- We get rid of log.py because it was never really necessary.

- We use named loggers, so it's easier to figure out what module logged
  a given message.

- We rename our logging object from "logger" to "log" to make the code
  more readable.

- The restructuring means that we now also get to see Stem's logging
  messages.
parent 07765506
2016-XX-XX: Changes in version YYYY.MM.DD:
2016-04-21: Changes in version 2016.04.21:
- Add command line option '-E' for file containing exit fingerprints.
- Add command line option '-n' for random delays between circuit creations.
- Add username to data directory, allowing multiple users on a single
......@@ -6,7 +6,10 @@
- Make dnspoison module populate its A records automatically.
- Add cloudflared module to check if a site is behind CloudFlare.
- Add rtt module to measure round-trip times from an exit to a destination.
Thanks to Zack Weinberg for the code.
- Add dnssec module to check if an exit relay validates DNSSEC.
- Improved logging now shows module names and Stem's log messages.
- Add command line option '-o' to log to file.
2015-08-23: Changes in version 2015.08.23:
- Exclude bad exits by default when selecting exit relays.
......
......@@ -25,13 +25,13 @@ import threading
import subprocess
import tempfile
import pprint
import logging
import log
import util
import torsocks
import error
logger = log.get_logger()
log = logging.getLogger(__name__)
def run_python_over_tor(queue, circ_id, socks_port):
......@@ -49,7 +49,7 @@ def run_python_over_tor(queue, circ_id, socks_port):
with torsocks.MonkeyPatchedSocket(queue, circ_id, socks_port):
func(*args)
except (error.SOCKSv5Error, socket.error) as err:
logger.info(err)
log.info(err)
return
return closure
......@@ -132,7 +132,7 @@ class Command(object):
with tempfile.NamedTemporaryFile(prefix="torsocks_") as fd:
logger.debug("Created temporary torsocks config file %s" % fd.name)
log.debug("Created temporary torsocks config file %s" % fd.name)
os.environ["TORSOCKS_CONF_FILE"] = fd.name
os.environ["TORSOCKS_LOG_LEVEL"] = "5"
......@@ -140,8 +140,8 @@ class Command(object):
fd.write("TorAddress 127.0.0.1\n")
fd.flush()
logger.debug("Invoking \"%s\" in environment:\n%s" %
(" ".join(command), pprint.pformat(dict(os.environ))))
log.debug("Invoking \"%s\" in environment:\n%s" %
(" ".join(command), pprint.pformat(dict(os.environ))))
thread = threading.Thread(target=self.invoke_process,
args=(command,))
......@@ -152,7 +152,7 @@ class Command(object):
# Attempt to kill the process if it did not finish in time.
if thread.is_alive():
logger.debug("Killing process after %d seconds." % timeout)
log.debug("Killing process after %d seconds." % timeout)
self.process.kill()
thread.join()
......
......@@ -24,6 +24,7 @@ import functools
import threading
import multiprocessing
import socket
import logging
import stem
from stem import StreamStatus
......@@ -31,9 +32,8 @@ from stem import CircStatus
import command
import util
import log
logger = log.get_logger()
log = logging.getLogger(__name__)
def get_relay_desc(controller, fpr):
......@@ -45,11 +45,11 @@ def get_relay_desc(controller, fpr):
try:
desc = controller.get_server_descriptor(relay=fpr)
except stem.DescriptorUnavailable as err:
logger.warning("Descriptor for %s not available: %s" % (fpr, err))
log.warning("Descriptor for %s not available: %s" % (fpr, err))
except stem.ControllerError as err:
logger.warning("Unable to query for %d: %s" % (fpr, err))
log.warning("Unable to query for %d: %s" % (fpr, err))
except ValueError:
logger.warning("%s is malformed. Is it a relay fingerprint?" % fpr)
log.warning("%s is malformed. Is it a relay fingerprint?" % fpr)
return desc
......@@ -105,20 +105,20 @@ class Attacher(object):
stream_id=stream_id)
self.unattached[port] = partially_attached
logger.debug("Pending attachers: %d." % len(self.unattached))
log.debug("Pending attachers: %d." % len(self.unattached))
def _attach(self, stream_id=None, circuit_id=None):
"""
Attach a stream to a circuit.
"""
logger.debug("Attempting to attach stream %s to circuit %s." %
(stream_id, circuit_id))
log.debug("Attempting to attach stream %s to circuit %s." %
(stream_id, circuit_id))
try:
self.controller.attach_stream(stream_id, circuit_id)
except stem.OperationFailed as err:
logger.warning("Failed to attach stream because: %s" % err)
log.warning("Failed to attach stream because: %s" % err)
def module_closure(queue, module, circ_id, *module_args, **module_kwargs):
......@@ -137,7 +137,7 @@ def module_closure(queue, module, circ_id, *module_args, **module_kwargs):
try:
module(*module_args, **module_kwargs)
logger.debug("Informing event handler that module finished.")
log.debug("Informing event handler that module finished.")
queue.put((circ_id, None))
except KeyboardInterrupt:
pass
......@@ -180,13 +180,13 @@ class EventHandler(object):
circuits.
"""
logger.debug("Starting thread to read from IPC queue.")
log.debug("Starting thread to read from IPC queue.")
while True:
try:
circ_id, sockname = self.queue.get()
except EOFError:
logger.debug("IPC queue terminated.")
log.debug("IPC queue terminated.")
break
# Over the queue, a module can either signal that it finished
......@@ -194,18 +194,17 @@ class EventHandler(object):
# its stream attached to a circuit (by sending (circ_id,sockname)).
if sockname is None:
logger.debug("Closing finished circuit %s." % circ_id)
log.debug("Closing finished circuit %s." % circ_id)
try:
self.controller.close_circuit(circ_id)
except stem.InvalidArguments as err:
logger.debug("Could not close circuit because: %s" % err)
log.debug("Could not close circuit because: %s" % err)
self.stats.finished_streams += 1
self.stats.print_progress()
self.check_finished()
else:
logger.debug("Read from queue: %s, %s" % (circ_id,
str(sockname)))
log.debug("Read from queue: %s, %s" % (circ_id, str(sockname)))
port = int(sockname[1])
self.attacher.prepare(port, circuit_id=circ_id)
self.check_finished()
......@@ -232,25 +231,24 @@ class EventHandler(object):
(self.stats.successful_circuits -
self.stats.failed_circuits))
logger.debug("failedCircs=%d, builtCircs=%d, totalCircs=%d, "
"finishedStreams=%d" % (
self.stats.failed_circuits,
self.stats.successful_circuits,
self.stats.total_circuits,
self.stats.finished_streams))
log.debug("failedCircs=%d, builtCircs=%d, totalCircs=%d, "
"finishedStreams=%d" % (self.stats.failed_circuits,
self.stats.successful_circuits,
self.stats.total_circuits,
self.stats.finished_streams))
if circs_done and streams_done:
self.already_finished = True
for proc in multiprocessing.active_children():
logger.debug("Terminating remaining PID %d." % proc.pid)
log.debug("Terminating remaining PID %d." % proc.pid)
proc.terminate()
if hasattr(self.module, "teardown"):
logger.debug("Calling module's teardown() function.")
log.debug("Calling module's teardown() function.")
self.module.teardown()
logger.info(self.stats)
log.info(self.stats)
sys.exit(0)
def new_circuit(self, circ_event):
......@@ -266,8 +264,8 @@ class EventHandler(object):
last_hop = circ_event.path[-1]
exit_fpr = last_hop[0]
logger.debug("Circuit for exit relay \"%s\" is built. "
"Now invoking probing module." % exit_fpr)
log.debug("Circuit for exit relay \"%s\" is built. "
"Now invoking probing module." % exit_fpr)
run_cmd_over_tor = command.Command(self.queue,
circ_event.id,
......@@ -305,11 +303,11 @@ class EventHandler(object):
port = util.get_source_port(str(stream_event))
if not port:
logger.warning("Couldn't extract source port from stream "
"event: %s" % str(stream_event))
log.warning("Couldn't extract source port from stream "
"event: %s" % str(stream_event))
return
logger.debug("Adding attacher for new stream %s." % stream_event.id)
log.debug("Adding attacher for new stream %s." % stream_event.id)
self.attacher.prepare(port, stream_id=stream_event.id)
self.check_finished()
......@@ -325,4 +323,4 @@ class EventHandler(object):
self.new_stream(event)
else:
logger.warning("Received unexpected event %s." % str(event))
log.warning("Received unexpected event %s." % str(event))
# Copyright 2013-2015 Philipp Winter <phw@nymity.ch>
# Copyright 2013-2016 Philipp Winter <phw@nymity.ch>
#
# This file is part of exitmap.
#
......@@ -39,7 +39,6 @@ import stem.descriptor
from stem.control import Controller, EventType
import modules
import log
import error
import util
import relayselector
......@@ -47,7 +46,7 @@ import relayselector
from eventhandler import EventHandler
from stats import Statistics
logger = log.get_logger()
log = logging.getLogger(__name__)
def bootstrap_tor(args):
......@@ -55,12 +54,12 @@ def bootstrap_tor(args):
Invoke a Tor process which is subsequently used by exitmap.
"""
logger.info("Attempting to invoke Tor process in directory \"%s\". This "
"might take a while." % args.tor_dir)
log.info("Attempting to invoke Tor process in directory \"%s\". This "
"might take a while." % args.tor_dir)
if not args.first_hop:
logger.info("No first hop given. Using randomly determined first "
"hops for circuits.")
log.info("No first hop given. Using randomly determined first "
"hops for circuits.")
ports = {}
partial_parse_log_lines = functools.partial(util.parse_log_lines, ports)
......@@ -85,9 +84,9 @@ def bootstrap_tor(args):
completion_percent=80,
init_msg_handler=partial_parse_log_lines,
)
logger.info("Successfully started Tor process (PID=%d)." % proc.pid)
log.info("Successfully started Tor process (PID=%d)." % proc.pid)
except OSError as err:
logger.error("Couldn't launch Tor: %s. Maybe try again?" % err)
log.error("Couldn't launch Tor: %s. Maybe try again?" % err)
sys.exit(1)
return ports["socks"], ports["control"]
......@@ -121,8 +120,8 @@ def parse_cmd_args():
try:
defaults = dict(config_parser.items("Defaults"))
except ConfigParser.NoSectionError as err:
logger.warning("Could not parse config file \"%s\": %s" %
(config_file, err))
log.warning("Could not parse config file \"%s\": %s" %
(config_file, err))
defaults = {}
else:
defaults = {}
......@@ -184,6 +183,10 @@ def parse_cmd_args():
"is used as first hop. This relay should be "
"under your control.")
parser.add_argument("-o", "--logfile", type=str, default=None,
help="Filename to which log output should be written "
"to.")
exits = parser.add_mutually_exclusive_group()
exits.add_argument("-b", "--bad-exits", action="store_true",
......@@ -230,9 +233,13 @@ def main():
if args.tor_dir and not os.path.exists(args.tor_dir):
os.makedirs(args.tor_dir)
logger.setLevel(logging.__dict__[args.verbosity.upper()])
logging.getLogger("stem").setLevel(logging.__dict__[args.verbosity.upper()])
log_format = "%(asctime)s %(name)s [%(levelname)s] %(message)s"
logging.basicConfig(format=log_format,
level=logging.__dict__[args.verbosity.upper()],
filename=args.logfile)
logger.debug("Command line arguments: %s" % str(args))
log.debug("Command line arguments: %s" % str(args))
socks_port, control_port = bootstrap_tor(args)
controller = Controller.from_port(port=control_port)
......@@ -241,7 +248,7 @@ def main():
# Redirect Tor's logging to work around the following problem:
# https://bugs.torproject.org/9862
logger.debug("Redirecting Tor's logging to /dev/null.")
log.debug("Redirecting Tor's logging to /dev/null.")
controller.set_conf("Log", "err file /dev/null")
# We already have the current consensus, so we don't need additional
......@@ -252,8 +259,8 @@ def main():
cached_consensus_path = os.path.join(args.tor_dir, "cached-consensus")
if args.first_hop and (not util.relay_in_consensus(args.first_hop,
cached_consensus_path)):
logger.critical("Given first hop \"%s\" not found in consensus. Is it"
" offline?" % args.first_hop)
log.critical("Given first hop \"%s\" not found in consensus. Is it"
" offline?" % args.first_hop)
return 1
for module_name in args.module:
......@@ -265,7 +272,7 @@ def main():
try:
run_module(module_name, args, controller, socks_port, stats)
except error.ExitSelectionError as err:
logger.error("Failed to run because : %s" % err)
log.error("Failed to run because : %s" % err)
return 0
def lookup_destinations(module):
......@@ -305,11 +312,10 @@ def select_exits(args, module):
try:
requested_exits = [line.strip() for line in open(args.exit_file)]
except OSError as err:
logger.error("Could not read %s: %s", args.exit_file,
err.strerror)
log.error("Could not read %s: %s", args.exit_file, err.strerror)
sys.exit(1)
except Exception as err:
logger.error("Could not read %s: %s", args.exit_file, err)
log.error("Could not read %s: %s", args.exit_file, err)
sys.exit(1)
else:
requested_exits = None
......@@ -322,8 +328,8 @@ def select_exits(args, module):
requested_exits = requested_exits,
destinations = destinations)
logger.debug("Successfully selected exit relays after %s." %
str(datetime.datetime.now() - before))
log.debug("Successfully selected exit relays after %s." %
str(datetime.datetime.now() - before))
return exit_destinations
......@@ -332,19 +338,19 @@ def run_module(module_name, args, controller, socks_port, stats):
Run an exitmap module over all available exit relays.
"""
logger.info("Running module '%s'." % module_name)
log.info("Running module '%s'." % module_name)
stats.modules_run += 1
try:
module = __import__("modules.%s" % module_name, fromlist=[module_name])
except ImportError as err:
logger.error("Failed to load module because: %s" % err)
log.error("Failed to load module because: %s" % err)
return
# Let module perform one-off setup tasks.
if hasattr(module, "setup"):
logger.debug("Calling module's setup() function.")
log.debug("Calling module's setup() function.")
module.setup()
exit_destinations = select_exits(args, module)
......@@ -366,10 +372,10 @@ def run_module(module_name, args, controller, socks_port, stats):
EventType.CIRC, EventType.STREAM)
duration = count * args.build_delay
logger.info("Scan is estimated to take around %s." %
datetime.timedelta(seconds=duration))
log.info("Scan is estimated to take around %s." %
datetime.timedelta(seconds=duration))
logger.info("Beginning to trigger %d circuit creation(s)." % count)
log.info("Beginning to trigger %d circuit creation(s)." % count)
iter_exit_relays(exit_relays, controller, stats, args)
......@@ -394,7 +400,7 @@ def sleep(delay, delay_noise):
if delay < 0:
delay = 0
logger.debug("Sleeping for %.1fs, then building next circuit." % delay)
log.debug("Sleeping for %.1fs, then building next circuit." % delay)
time.sleep(delay)
......@@ -420,7 +426,7 @@ def iter_exit_relays(exit_relays, controller, stats, args):
all_hops = list(fingerprints)
all_hops.remove(exit_relay)
first_hop = random.choice(all_hops)
logger.debug("Using random first hop %s for circuit." % first_hop)
log.debug("Using random first hop %s for circuit." % first_hop)
hops = [first_hop, exit_relay]
assert len(hops) > 1
......@@ -429,11 +435,11 @@ def iter_exit_relays(exit_relays, controller, stats, args):
controller.new_circuit(hops)
except stem.ControllerError as err:
stats.failed_circuits += 1
logger.debug("Circuit with exit relay \"%s\" could not be "
"created: %s" % (exit_relay, err))
log.debug("Circuit with exit relay \"%s\" could not be "
"created: %s" % (exit_relay, err))
if i != (count - 1):
sleep(args.build_delay, args.delay_noise)
logger.info("Done triggering circuit creations after %s." %
str(datetime.datetime.now() - before))
log.info("Done triggering circuit creations after %s." %
str(datetime.datetime.now() - before))
# Copyright 2013, 2014 Philipp Winter <phw@nymity.ch>
#
# This file is part of exitmap.
#
# exitmap is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# exitmap is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with exitmap. If not, see <http://www.gnu.org/licenses/>.
"""
Provides logging functionality.
"""
import logging
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter(fmt="%(asctime)s [%(levelname)s]: "
"%(message)s"))
logger = logging.getLogger("exitmap")
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
def get_logger():
"""
Returns a logger.
"""
return logger
......@@ -23,17 +23,17 @@ Module to detect false negatives for <https://check.torproject.org>.
import sys
import json
import logging
try:
import urllib2
except ImportError:
import urllib.request as urllib2
import log
from util import exiturl
import stem.descriptor.server_descriptor as descriptor
logger = log.get_logger()
log = logging.getLogger(__name__)
# exitmap needs this variable to figure out which relays can exit to the given
# destination(s).
......@@ -53,7 +53,7 @@ def fetch_page(exit_desc):
data = urllib2.urlopen("https://check.torproject.org/api/ip",
timeout=10).read()
except Exception as err:
logger.debug("urllib2.urlopen says: %s" % err)
log.debug("urllib2.urlopen says: %s" % err)
return
if not data:
......@@ -62,15 +62,15 @@ def fetch_page(exit_desc):
try:
check_answer = json.loads(data)
except ValueError as err:
logger.warning("Couldn't parse JSON over relay %s: %s" % (url, data))
log.warning("Couldn't parse JSON over relay %s: %s" % (url, data))
return
check_addr = check_answer["IP"].strip()
if not check_answer["IsTor"]:
logger.error("Found false negative for %s. Desc addr is %s and check "
"addr is %s." % (url, exit_desc.address, check_addr))
log.error("Found false negative for %s. Desc addr is %s and check "
"addr is %s." % (url, exit_desc.address, check_addr))
else:
logger.debug("Exit relay %s passed the check test." % url)
log.debug("Exit relay %s passed the check test." % url)
def probe(exit_desc, run_python_over_tor, run_cmd_over_tor, **kwargs):
......
......@@ -26,11 +26,11 @@ import StringIO
import gzip
import httplib
import collections
import logging
import log
import util
logger = log.get_logger()
log = logging.getLogger(__name__)
destinations = [("www.cloudflare.com", 443)]
DOMAIN, PORT = destinations[0]
......@@ -71,25 +71,25 @@ def is_cloudflared(exit_fpr):
"""
exit_url = util.exiturl(exit_fpr)
logger.debug("Probing exit relay \"%s\"." % exit_url)
log.debug("Probing exit relay \"%s\"." % exit_url)
conn = httplib.HTTPSConnection(DOMAIN, PORT, strict=False)
conn.request("GET", "/", headers=collections.OrderedDict(HTTP_HEADERS))
try:
response = conn.getresponse()
except Exception as err:
logger.warning("urlopen() over %s says: %s" % (exit_url, err))
log.warning("urlopen() over %s says: %s" % (exit_url, err))
return
data = decompress(response.read())
if not data:
logger.warning("Did not get any data over %s." % exit_url)
log.warning("Did not get any data over %s." % exit_url)
return
if data and (CAPTCHA_SIGN in data):
logger.info("Exit %s sees a CAPTCHA." % exit_url)
log.info("Exit %s sees a CAPTCHA." % exit_url)
else:
logger.info("Exit %s does not see a CAPTCHA." % exit_url)
log.info("Exit %s does not see a CAPTCHA." % exit_url)
def probe(exit_desc, run_python_over_tor, run_cmd_over_tor, **kwargs):
......
......@@ -21,7 +21,8 @@
Module to detect malfunctioning DNS resolution.
"""
import log
import logging
import torsocks
import socket
import error
......@@ -29,7 +30,7 @@ from util import exiturl
import dns.resolver
logger = log.get_logger()
log = logging.getLogger(__name__)
destinations = None
domains = {
......@@ -48,15 +49,15 @@ def setup():
Populate the `domains' dictionary by asking our system DNS resolver.
"""
logger.debug("Populating domain dictionary.")
log.debug("Populating domain dictionary.")
for domain in domains.iterkeys():
response = dns.resolver.query(domain)
for record in response:
logger.debug("Domain %s maps to %s." % (domain, record.address))
log.debug("Domain %s maps to %s." % (domain, record.address))
domains[domain].append(record.address)
logger.info("Domain whitelist: %s" % str(domains))
log.info("Domain whitelist: %s" % str(domains))
def resolve(exit_desc, domain, whitelist):
......@@ -75,22 +76,22 @@ def resolve(exit_desc, domain, whitelist):
try:
ipv4 = sock.resolve(domain)
except error.SOCKSv5Error as err:
logger.debug("Exit relay %s could not resolve IPv4 address for "
"\"%s\" because: %s" % (exit, domain, err))
log.debug("Exit relay %s could not resolve IPv4 address for "
"\"%s\" because: %s" % (exit, domain, err))
return
except socket.timeout as err:
logger.debug("Socket over exit relay %s timed out: %s" % (exit, err))
log.debug("Socket over exit relay %s timed out: %s" % (exit, err))