commit c39e1f412ce8362db0832072f0b870646b1eb42d Author: Arturo Filastò arturo@filasto.net Date: Tue Oct 23 09:12:59 2012 +0000

Make logged work again * A good opportunity to refactor logging related code * Implement time related utilities * Start outlining configuration script * Move netalyzr test to nettest * XXX the new API tests are not working properly --- nettests/core/dnstamper.py | 23 +++- nettests/core/http_host.py | 15 +++ nettests/third_party/Makefile | 3 + nettests/third_party/README | 14 ++ nettests/third_party/netalyzr.py | 42 ++++++ .../ooni/plugins/netalyzr_plgoo.py | 30 ----- old-to-be-ported-code/third-party/Makefile | 3 - old-to-be-ported-code/third-party/README | 14 -- ooni/config.py | 7 + ooni/nettest.py | 11 ++- ooni/runner.py | 1 + ooni/utils/log.py | 132 ++++++------------- ooni/utils/otime.py | 43 +++++++ 13 files changed, 197 insertions(+), 141 deletions(-)

diff --git a/nettests/core/dnstamper.py b/nettests/core/dnstamper.py index 0f40c1c..1028291 100644 --- a/nettests/core/dnstamper.py +++ b/nettests/core/dnstamper.py @@ -27,7 +27,7 @@ class DNSTamperTest(nettest.TestCase): name = "DNS tamper"

description = "DNS censorship detection test" - version = '0.2' + version = "0.2"

lookupTimeout = [1]

@@ -38,8 +38,7 @@ class DNSTamperTest(nettest.TestCase): optParameters = [['controlresolver', 'c', '8.8.8.8', 'Known good DNS server'], ['testresolvers', 't', None, - 'file containing list of DNS resolvers to test against'] - ] + 'file containing list of DNS resolvers to test against']]

def setUp(self): self.report['test_lookups'] = {} @@ -130,6 +129,24 @@ class DNSTamperTest(nettest.TestCase): self.test_a_lookups[resolver] = None

def test_lookup(self): + """ + We perform an A lookup on the DNS test servers for the domains to be + tested and an A lookup on the known good DNS server. + + We then compare the results from test_resolvers and that from + control_resolver and see if the match up. + If they match up then no censorship is happening (tampering: false). + + If they do not we do a reverse lookup (PTR) on the test_resolvers and + the control resolver for every IP address we got back and check to see + if anyone of them matches the control ones. + + If they do then we take not of the fact that censorship is probably not + happening (tampering: reverse-match). + + If they do not match then censorship is probably going on (tampering: + true). + """ print "Doing the test lookups on %s" % self.input list_of_ds = [] hostname = self.input diff --git a/nettests/core/http_host.py b/nettests/core/http_host.py index 2228c52..62b50ca 100644 --- a/nettests/core/http_host.py +++ b/nettests/core/http_host.py @@ -12,6 +12,10 @@ from ooni.templates import httpt

class HTTPHost(httpt.HTTPTest): + """ + This test is aimed at detecting the presence of a transparent HTTP proxy + and enumerating the sites that are being censored by it. + """ name = "HTTP Host" author = "Arturo Filastò" version = 0.1 @@ -23,11 +27,22 @@ class HTTPHost(httpt.HTTPTest): inputFile = ['urls', 'f', None, 'Urls file']

def test_send_host_header(self): + """ + Stuffs the HTTP Host header field with the site to be tested for + censorship and does an HTTP request of this kind to our backend. + + We randomize the HTTP User Agent headers. + """ headers = {} headers["Host"] = [self.input] return self.doRequest(self.localOptions['backend'], headers=headers)

def processResponseBody(self, body): + """ + XXX this is to be filled in with either a domclass based classified or + with a rule that will allow to detect that the body of the result is + that of a censored site. + """ if 'not censored' in body: self.report['trans_http_proxy'] = False else: diff --git a/nettests/third_party/Makefile b/nettests/third_party/Makefile new file mode 100644 index 0000000..16adfe0 --- /dev/null +++ b/nettests/third_party/Makefile @@ -0,0 +1,3 @@ +fetch: + wget http://netalyzr.icsi.berkeley.edu/NetalyzrCLI.jar + chmod +x NetalyzrCLI.jar diff --git a/nettests/third_party/README b/nettests/third_party/README new file mode 100644 index 0000000..d9e435f --- /dev/null +++ b/nettests/third_party/README @@ -0,0 +1,14 @@ +There is no license for NetalyzrCLI.jar; so while we include it, it's just +for ease of use. + +We currently support interfacing with the ICSI Netalyzr system by wrapping +the NetalyzrCLI.jar client. It was downloaded on August 5th, 2011 from the +following URL: + http://netalyzr.icsi.berkeley.edu/NetalyzrCLI.jar + +More information about the client is available on the cli web page: + http://netalyzr.icsi.berkeley.edu/cli.html + +After looking at NetalyzrCLI.jar, I discovered that '-d' runs it in a +debugging mode that is quite useful for understanding their testing +framework as it runs. diff --git a/nettests/third_party/netalyzr.py b/nettests/third_party/netalyzr.py new file mode 100644 index 0000000..041c0be --- /dev/null +++ b/nettests/third_party/netalyzr.py @@ -0,0 +1,42 @@ +# -*- encoding: utf-8 -*- +# +# This is a wrapper around the Netalyzer Java command line client +# +# :authors: Jacob Appelbaum jacob@appelbaum.net +# Arturo "hellais" Filastò art@fuffa.org +# :licence: see LICENSE + +from ooni import nettest +from ooni.utils import log +import time +import os + +class NetalyzrWrapperTest(nettest.TestCase): + name = "NetalyzrWrapper" + type = "wrapper" + + def setUp(self): + cwd = os.path.join(os.path.abspath(__file__), '..') + + # XXX set the output directory to something more uniform + outputdir = os.path.join(cwd, '..', '..') + + program_path = os.path.join(cwd, 'NetalyzrCLI') + program = "java -jar %s " % program_path + + test_token = time.asctime(time.gmtime()).replace(" ", "_").strip() + + output_file = os.path.join(outputdir, + "NetalyzrCLI_" + test_token + ".out") + output_file.strip() + self.run_me = program + " 2>&1 >> " + output_file + + def test_run_netalyzr(self): + """ + This test simply wraps netalyzr and runs it from command line + """ + log.msg("running NetalyzrWrapper with command '%s'" % self.run_me) + os.system(self.run_me) + self.report['netalyzr_report'] = self.output_file + log.msg("finished running NetalzrWrapper") + diff --git a/old-to-be-ported-code/ooni/plugins/netalyzr_plgoo.py b/old-to-be-ported-code/ooni/plugins/netalyzr_plgoo.py deleted file mode 100644 index 05e0990..0000000 --- a/old-to-be-ported-code/ooni/plugins/netalyzr_plgoo.py +++ /dev/null @@ -1,30 +0,0 @@ -#!/usr/bin/python -# This is a wrapper around the Netalyzer Java command line client -# by Jacob Appelbaum jacob@appelbaum.net -# -from ooni.plugooni import Plugoo -import time -import os - -class NetalyzrPlugin(Plugoo): - def __init__(self): - self.name = "Netalyzr" - self.type = "wrapper" - self.paranoia = "low" - self.modules_to_import = ["os", "time"] - self.output_dir = "results/" - self.program = "java -jar third-party/NetalyzrCLI.jar " - self.test_token = time.asctime(time.gmtime()).replace(" ", "_").strip() - self.output_file = self.output_dir + "NetalyzrCLI_" + self.test_token + ".out" - self.output_file.strip() - self.run_me = self.program + " 2>&1 >> " + self.output_file - - def NetalzrWrapper(self): - return os.system(self.run_me) - - def ooni_main(self, cmd): - print "running NetalzrWrapper" - r = self.NetalzrWrapper() - print "finished running NetalzrWrapper" - return r - diff --git a/old-to-be-ported-code/third-party/Makefile b/old-to-be-ported-code/third-party/Makefile deleted file mode 100644 index 16adfe0..0000000 --- a/old-to-be-ported-code/third-party/Makefile +++ /dev/null @@ -1,3 +0,0 @@ -fetch: - wget http://netalyzr.icsi.berkeley.edu/NetalyzrCLI.jar - chmod +x NetalyzrCLI.jar diff --git a/old-to-be-ported-code/third-party/README b/old-to-be-ported-code/third-party/README deleted file mode 100644 index d9e435f..0000000 --- a/old-to-be-ported-code/third-party/README +++ /dev/null @@ -1,14 +0,0 @@ -There is no license for NetalyzrCLI.jar; so while we include it, it's just -for ease of use. - -We currently support interfacing with the ICSI Netalyzr system by wrapping -the NetalyzrCLI.jar client. It was downloaded on August 5th, 2011 from the -following URL: - http://netalyzr.icsi.berkeley.edu/NetalyzrCLI.jar - -More information about the client is available on the cli web page: - http://netalyzr.icsi.berkeley.edu/cli.html - -After looking at NetalyzrCLI.jar, I discovered that '-d' runs it in a -debugging mode that is quite useful for understanding their testing -framework as it runs. diff --git a/ooni/config.py b/ooni/config.py new file mode 100644 index 0000000..96a1ee0 --- /dev/null +++ b/ooni/config.py @@ -0,0 +1,7 @@ +from ooni.utils import Storage + +# XXX move this to an actual configuration file +basic = Storage() +advanced = Storage() + +advanced.debug = True diff --git a/ooni/nettest.py b/ooni/nettest.py index f1232c7..768833a 100644 --- a/ooni/nettest.py +++ b/ooni/nettest.py @@ -3,7 +3,7 @@ import os

from twisted.python import log, usage from twisted.trial import unittest, itrial -from twisted.internet import defer +from twisted.internet import defer, utils

pyunit = __import__('unittest')

@@ -79,6 +79,15 @@ class TestCase(unittest.TestCase):

optParameters = None

+ def _run(self, methodName, result): + from twisted.internet import reactor + method = getattr(self, methodName) + d = defer.maybeDeferred( + utils.runWithWarningsSuppressed, self._getSuppress(), method) + d.addBoth(lambda x : call.active() and call.cancel() or x) + return d + + def deferSetUp(self, ignored, result): """ If we have the reporterFactory set we need to write the header. If such diff --git a/ooni/runner.py b/ooni/runner.py index 7aa8676..1fbc4fe 100644 --- a/ooni/runner.py +++ b/ooni/runner.py @@ -238,6 +238,7 @@ class ORunner(object): result.done()

def run(self): + log.start() self.reporterFactory.options = self.options for inputUnit in InputUnitFactory(self.inputs): self.runWithInputUnit(inputUnit) diff --git a/ooni/utils/log.py b/ooni/utils/log.py index eef50d8..2b5c1ac 100644 --- a/ooni/utils/log.py +++ b/ooni/utils/log.py @@ -1,98 +1,50 @@ -""" -OONI logging facility. -""" -from sys import stderr, stdout - -from twisted.python import log, util -from twisted.python.failure import Failure - -def _get_log_level(level): - english = ['debug', 'info', 'warn', 'err', 'crit'] - - levels = dict(zip(range(len(english)), english)) - number = dict(zip(english, range(len(english)))) - - if not level: - return number['info'] +# -*- encoding: utf-8 -*- +# +# :authors: Arturo Filastò +# :licence: see LICENSE + +import sys +import os +import logging + +from twisted.python import log as txlog +from twisted.python.logfile import DailyLogFile + +from ooni.utils import otime +from ooni import config + +# XXX make this a config option +log_file = "/tmp/ooniprobe.log" + +log_folder = os.path.join('/', *log_file.split('/')[:-1]) +log_filename = log_file.split('/')[-1] +daily_logfile = DailyLogFile(log_filename, log_folder) + +def start(): + txlog.msg("Starting OONI on %s (%s UTC)" % (otime.prettyDateNow(), + otime.utcPrettyDateNow())) + logging.basicConfig() + python_logging = txlog.PythonLoggingObserver() + if config.advanced.debug: + python_logging.logger.setLevel(logging.DEBUG) else: - ve = "Unknown log level: %s\n" % level - ve += "Allowed levels: %s\n" % [word for word in english] - - if type(level) is int: - if 0 <= level <= 4: - return level - elif type(level) is str: - if number.has_key(level.lower()): - return number[level] - else: - raise ValueError, ve - else: - raise ValueError, ve - -class OONITestFailure(Failure): - """ - For handling Exceptions asynchronously. - - Can be given an Exception as an argument, else will use the - most recent Exception from the current stack frame. - """ - def __init__(self, exception=None, _type=None, - _traceback=None, _capture=False): - Failure.__init__(self, exc_type=_type, - exc_tb=_traceback, captureVars=_capture) - -class OONILogObserver(log.FileLogObserver): - """ - Supports logging level verbosity. - """ - def __init__(self, logfile, verb=None): - log.FileLogObserver.__init__(self, logfile) - self.level = _get_log_level(verb) if verb is not None else 1 - assert type(self.level) is int - - def emit(self, eventDict): - if 'logLevel' in eventDict: - msgLvl = _get_log_level(eventDict['logLevel']) - assert type(msgLvl) is int - ## only log our level and higher - if self.level <= msgLvl: - text = log.textFromEventDict(eventDict) - else: - text = None - else: - text = log.textFromEventDict(eventDict) - - if text is None: - return - - timeStr = self.formatTime(eventDict['time']) - fmtDict = {'system': eventDict['system'], - 'text': text.replace('\n','\n\t')} - msgStr = log._safeFormat("[%(system)s] %(text)s\n", fmtDict) - - util.untilConcludes(self.write, timeStr + " " + msgStr) - util.untilConcludes(self.flush) + python_logging.logger.setLevel(logging.INFO)

-def start(logfile=None, verbosity=None): - if log.defaultObserver: - verbosity = _get_log_level(verbosity) + txlog.startLoggingWithObserver(python_logging.emit)

- ## Always log to file, keep level at info - file = open(logfile, 'a') if logfile else stderr - OONILogObserver(file, "info").start() + txlog.addObserver(txlog.FileLogObserver(daily_logfile).emit)

- log.msg("Starting OONI...") +def stop(): + txlog.msg("Stopping OONI")

-def debug(message, level="debug", **kw): - print "[%s] %s" % (level, message) - ## If we want debug messages in the logfile: - #log.msg(message, logLevel=level, **kw) +def msg(msg, *arg, **kw): + txlog.msg(msg, logLevel=logging.INFO, *arg, **kw)

-def msg(message, level="info", **kw): - log.msg(message, logLevel=level, **kw) +def debug(msg, *arg, **kw): + txlog.msg(msg, logLevel=logging.DEBUG, *arg, **kw)

-def err(message, level="err", **kw): - log.err(logLevel=level, **kw) +def err(msg, *arg, **kw): + txlog.err(msg, logLevel=logging.ERROR, *arg, **kw)

-def fail(message, exception, level="crit", **kw): - log.failure(message, OONITestFailure(exception, **kw), logLevel=level) +def exception(*msg): + logging.exception(msg) diff --git a/ooni/utils/otime.py b/ooni/utils/otime.py new file mode 100644 index 0000000..11f7be1 --- /dev/null +++ b/ooni/utils/otime.py @@ -0,0 +1,43 @@ +# -*- encoding: utf-8 -*- +# +# :authors: Arturo Filastò +# :licence: see LICENSE + +""" +Here is the location for all time and date related utility functions. +""" +import time +from datetime import datetime + +def utcDateNow(): + """ + Returns the datetime object of the current UTC time. + """ + return datetime.utcnow() + +def utcTimeNow(): + """ + Returns seconds since epoch in UTC time, it's of type float. + """ + return time.mktime(time.gmtime()) + +def dateToTime(date): + """ + Takes as input a datetime object and outputs the seconds since epoch. + """ + return time.mktime(date.timetuple()) + +def prettyDateNow(): + """ + Returns a good looking string for the local time. + """ + return datetime.now().ctime() + +def utcPrettyDateNow(): + """ + Returns a good looking string for utc time. + """ + return datetime.utcnow().ctime() + +def timeToPrettyDate(time_val): + return time.ctime(time_val)