October 2016 - tor-commits - lists.torproject.org

[ooni-probe/master] Add _failing_ scheduler test showing one of #612 deadlock reasons
by art＠torproject.org 15 Oct '16

15 Oct '16

commit c35b28365412b1a854865fad7b1ce500928c5093 Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Fri Oct 7 23:13:13 2016 +0300 Add _failing_ scheduler test showing one of #612 deadlock reasons If the lock has too many waiters then some stack overflow raises RuntimeError and scheduler fails altogether. --- ooni/tests/test_scheduler.py | 35 ++++++++++++++++++++++++++++++++++- 1 file changed, 34 insertions(+), 1 deletion(-) diff --git a/ooni/tests/test_scheduler.py b/ooni/tests/test_scheduler.py index a9501c0..c8eaf55 100644 --- a/ooni/tests/test_scheduler.py +++ b/ooni/tests/test_scheduler.py @@ -1,9 +1,10 @@ import os +import sys import shutil import random import tempfile -from twisted.internet import defer +from twisted.internet import reactor, task, defer from twisted.trial import unittest from ooni.agent.scheduler import ScheduledTask, DidNotRun, FileSystemlockAndMutex @@ -51,8 +52,40 @@ class TestScheduler(unittest.TestCase): self.assertEqual(len(in_file.readlines()), 1) self.assertEqual(dummy_st.should_run, False) + self.assertFalse(os.path.islink(os.path.join(scheduler_directory, identifier + '.lock'))) shutil.rmtree(scheduler_directory) + def test_thundering_herd(self): + lockno = int(os.getenv('TTH_LOCKNO', str(sys.getrecursionlimit() + 16))) + scheduler_directory = tempfile.mkdtemp() + counter = os.path.join(scheduler_directory, 'counter') + class DummyST(ScheduledTask): + @defer.inlineCallbacks + def task(subself): + self.assertTrue(os.path.islink(os.path.join(scheduler_directory, subself.identifier + '.lock'))) + with open(counter, 'w+') as fd: + data = fd.read() + fd.seek(0) + if not data: + fd.write('1') + yield task.deferLater(reactor, 1, lambda: 42) + else: + self.assertTrue(False) # should be unreachable due to schedule + identifier = "dummy" + dummy_st = DummyST(schedule='@daily', identifier=identifier, scheduler_directory=scheduler_directory) + dl = defer.DeferredList([dummy_st.run() for i in xrange(lockno)], consumeErrors=True) + @dl.addBoth + def so_what(results): + self.assertFalse(os.path.islink(os.path.join(scheduler_directory, identifier + '.lock'))) + self.assertEqual(results[0], (True, None)) # do not expect to get `42` here + for okflag, ex in results[1:]: + self.assertEqual(okflag, False) + ex.trap(DidNotRun) + self.assertEqual(dummy_st.should_run, False) + with open(counter, 'r') as fd: + self.assertEqual(fd.read(), '1') + shutil.rmtree(scheduler_directory) + return dl @defer.inlineCallbacks def test_filesystem_lock_and_mutex(self):

1 0

[ooni-probe/master] Fix one of the reasons of stuck scheduler lockfile for RunDeck task, see #612
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 877a2873a39641d2f0b6e56d8f40ead91c426e03 Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Fri Sep 30 15:02:30 2016 +0300 Fix one of the reasons of stuck scheduler lockfile for RunDeck task, see #612 --- ooni/nettest.py | 18 +++++++++++++----- ooni/nettests/blocking/web_connectivity.py | 5 ++++- 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/ooni/nettest.py b/ooni/nettest.py index d6784f4..7a2afc8 100644 --- a/ooni/nettest.py +++ b/ooni/nettest.py @@ -6,7 +6,7 @@ import sys from twisted.internet import defer from twisted.python.filepath import FilePath from twisted.trial.runner import filenameToModule -from twisted.python import usage, reflect +from twisted.python import failure, usage, reflect from ooni import __version__ as ooniprobe_version, errors from ooni import otime @@ -578,6 +578,9 @@ class NetTest(object): """ This is a generator that yields measurements and registers the callbacks for when a measurement is successful or has failed. + + FIXME: If this generator throws exception TaskManager scheduler is + irreversibly damaged. """ for test_class, test_methods in self.testCases: @@ -591,11 +594,16 @@ class NetTest(object): test_instance._setUp() test_instance.summary = self.summary for method in test_methods: + try: + measurement = self.makeMeasurement( + test_instance, + method, + test_input) + except Exception: + log.exception(failure.Failure()) + log.err('Failed to run %s %s %s' % (test_instance, method, test_input)) + continue # it's better to skip single measurement... log.debug("Running %s %s" % (test_instance, method)) - measurement = self.makeMeasurement( - test_instance, - method, - test_input) measurements.append(measurement.done) self.state.taskCreated() yield measurement diff --git a/ooni/nettests/blocking/web_connectivity.py b/ooni/nettests/blocking/web_connectivity.py index d8d539f..1d1b742 100644 --- a/ooni/nettests/blocking/web_connectivity.py +++ b/ooni/nettests/blocking/web_connectivity.py @@ -29,6 +29,9 @@ from ooni.common.http_utils import REQUEST_HEADERS class InvalidControlResponse(Exception): pass +class AbsentHostname(Exception): + pass + class UsageOptions(usage.Options): optParameters = [ ['url', 'u', None, 'Specify a single URL to test'], @@ -175,7 +178,7 @@ class WebConnectivityTest(httpt.HTTPTest, dnst.DNSTest): self.hostname = urlparse(self.input).netloc if not self.hostname: - raise Exception("Invalid input") + raise AbsentHostname('No hostname', self.input) self.control = { 'tcp_connect': {},

1 0

[ooni-probe/master] The correct name for cloudfront based backends is "cloudfront" (#620)
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 73b934ca05330d7c746e904f3f486e81b2ffcf12 Author: Arturo Filastò <arturo(a)filasto.net> Date: Tue Oct 11 13:05:28 2016 +0200 The correct name for cloudfront based backends is "cloudfront" (#620) --- ooni/ui/cli.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/ooni/ui/cli.py b/ooni/ui/cli.py index e7a0d88..c16173b 100644 --- a/ooni/ui/cli.py +++ b/ooni/ui/cli.py @@ -210,13 +210,13 @@ def initializeOoniprobe(global_options): include_country = False answer = raw_input('How would you like reports to be uploaded? (onion, ' - 'https, cloudfronted) ') + 'https, cloudfront) ') preferred_backend = 'onion' if answer.lower().startswith("https"): preferred_backend = 'https' - elif answer.lower().startswith("cloudfronted"): - preferred_backend = 'cloudfronted' + elif answer.lower().startswith("cloudfront"): + preferred_backend = 'cloudfront' config.create_config_file(include_ip=include_ip, include_asn=include_asn,

1 0

[ooni-probe/master] The https backend bouncer was still the testing one (#627)
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 9799f1d2e602cf29478c922447643b178ed47557 Author: Arturo Filastò <arturo(a)filasto.net> Date: Wed Oct 12 16:13:30 2016 +0200 The https backend bouncer was still the testing one (#627) :8 --- ooni/constants.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/ooni/constants.py b/ooni/constants.py index 38f85b4..6efa52e 100644 --- a/ooni/constants.py +++ b/ooni/constants.py @@ -1,7 +1,5 @@ CANONICAL_BOUNCER_ONION = 'httpo://nkvphnp3p6agi5qq.onion' -# XXX Change these two to the production ones once the release is made. -# CANONICAL_BOUNCER_HTTPS = 'https://bouncer.ooni.io' -CANONICAL_BOUNCER_HTTPS = 'https://bouncer.test.ooni.io' +CANONICAL_BOUNCER_HTTPS = 'https://bouncer.ooni.io' CANONICAL_BOUNCER_CLOUDFRONT = ( 'https://d3kr4emv7f56qa.cloudfront.net/', 'a0.awsstatic.com'

1 0

[ooni-probe/master] Replace 32 bit GPG keyids with full ids, see https://evil32.com/ for a reason
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 7e3401223fb7f838e576c8ba0b9f299477000c38 Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Thu Sep 29 12:39:48 2016 +0300 Replace 32 bit GPG keyids with full ids, see https://evil32.com/ for a reason Remember that old gnupg version did not use full id even when it was given full id: https://bugs.gnupg.org/gnupg/issue1579 --- Vagrantfile | 4 ++-- scripts/setup-dependencies.sh | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/Vagrantfile b/Vagrantfile index 71f7c7a..744246b 100644 --- a/Vagrantfile +++ b/Vagrantfile @@ -5,7 +5,7 @@ $setup_ooniprobe = <<SCRIPT echo "deb http://deb.torproject.org/torproject.org jessie main" >> /etc/apt/sources.list # Install deb.torproject.org key -gpg --keyserver keys.gnupg.net --recv 886DDD89 +gpg --keyserver keys.gnupg.net --recv A3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89 gpg --export A3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89 | apt-key add - apt-get update @@ -30,7 +30,7 @@ echo "Installing Tor..." echo "deb http://deb.torproject.org/torproject.org jessie main" >> /etc/apt/sources.list -gpg --keyserver keys.gnupg.net --recv 886DDD89 +gpg --keyserver keys.gnupg.net --recv A3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89 gpg --export A3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89 | apt-key add - apt-get update diff --git a/scripts/setup-dependencies.sh b/scripts/setup-dependencies.sh index d96f2cf..e5fdf84 100755 --- a/scripts/setup-dependencies.sh +++ b/scripts/setup-dependencies.sh @@ -882,7 +882,7 @@ case $DISTRO_VERSION in echo "${DSTUFFT_PUB_KEY}" > ${DSTUFFT_KEY_FILE} # Import the Tor public key - DO "sudo gpg --homedir /root --no-default-keyring --keyring $TMP_KEYRING --keyserver x-hkp://pool.sks-keyservers.net --recv-keys 0x886DDD89" "0" + DO "sudo gpg --homedir /root --no-default-keyring --keyring $TMP_KEYRING --keyserver x-hkp://pool.sks-keyservers.net --recv-keys 0xA3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89" "0" sudo gpg --homedir /root --no-default-keyring --keyring $TMP_KEYRING --export A3C4F0F979CAA22CDBA8F512EE8CBC9E886DDD89 | sudo apt-key add - HAVE_TOR_REPO="`grep deb.torproject.org/torproject.org /etc/apt/sources.list /etc/apt/sources.list.d/* 2>&1|grep torproject|head -n 1`";

1 0

[ooni-probe/master] Comment update
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 9c08df08a1a682f6a93826c3ca73045dfd2d5b32 Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Tue Oct 11 18:01:21 2016 +0300 Comment update --- ooni/agent/scheduler.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ooni/agent/scheduler.py b/ooni/agent/scheduler.py index 969602a..3e93d25 100644 --- a/ooni/agent/scheduler.py +++ b/ooni/agent/scheduler.py @@ -31,8 +31,8 @@ class FileSystemlockAndMutex(object): concurrently the mutex lock will block before the filesystem lock is acquired. - It's a way to support concurrent usage of the DeferredFilesystemLock - without races. + It's a way to support concurrent usage of the DeferredFilesystemLock from + different stacks (threads/fibers) within the same process without races. """ def __init__(self, file_path): self._fs_lock = defer.DeferredFilesystemLock(file_path)

1 0

[ooni-probe/master] Merge pull request #608 from TheTorProject/fix/606
by art＠torproject.org 15 Oct '16

15 Oct '16

commit ae465de52e18e084d465de3290c5888fd1a59e0a Merge: 4d79ff9 7f078c6 Author: Arturo Filastò <arturo(a)filasto.net> Date: Wed Sep 28 21:02:35 2016 +0200 Merge pull request #608 from TheTorProject/fix/606 On first run of the UpdateInputsAndResources task fetch the resources… ooni/__init__.py | 2 +- ooni/agent/scheduler.py | 11 +++++++++++ ooni/deck/store.py | 5 ++++- ooni/geoip.py | 1 + 4 files changed, 17 insertions(+), 2 deletions(-)

1 0

[ooni-probe/master] Fix #612 deadlock confirmed by TestScheduler.test_thundering_herd
by art＠torproject.org 15 Oct '16

15 Oct '16

commit 15bfb0312030a79c1985564dcbf7ee18101388b4 Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Mon Oct 10 23:06:50 2016 +0300 Fix #612 deadlock confirmed by TestScheduler.test_thundering_herd The trivial fix makes sense as current SchedulerService ticks every 30 seconds and imprecise scheduling is acceptable. --- ooni/agent/scheduler.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/ooni/agent/scheduler.py b/ooni/agent/scheduler.py index f6b52b7..969602a 100644 --- a/ooni/agent/scheduler.py +++ b/ooni/agent/scheduler.py @@ -61,6 +61,11 @@ class DidNotRun(Exception): class ScheduledTask(object): + """ + Two ScheduledTask instances with same identifier are not permited to run + concurrently. There should be no ScheduledTask queue waiting for the lock + as SchedulerService ticks quite often. + """ _time_format = "%Y-%m-%dT%H:%M:%SZ" schedule = None identifier = None @@ -117,6 +122,9 @@ class ScheduledTask(object): @defer.inlineCallbacks def run(self): + if self._last_run_lock.locked: + # do not allow the queue to grow forever + raise DidNotRun yield self._last_run_lock.acquire() if not self.should_run: self._last_run_lock.release()

1 0

[ooni-probe/master] Add some more debug level messages
by art＠torproject.org 15 Oct '16

15 Oct '16

commit ea311bbc6fd19700e6179e128a8e9abfd5fc84e2 Author: Arturo Filastò <arturo(a)filasto.net> Date: Thu Sep 22 16:07:52 2016 +0200 Add some more debug level messages --- ooni/agent/scheduler.py | 3 +++ ooni/deck/store.py | 4 +++- ooni/geoip.py | 1 + 3 files changed, 7 insertions(+), 1 deletion(-) diff --git a/ooni/agent/scheduler.py b/ooni/agent/scheduler.py index cc71ee4..f6b52b7 100644 --- a/ooni/agent/scheduler.py +++ b/ooni/agent/scheduler.py @@ -123,6 +123,7 @@ class ScheduledTask(object): raise DidNotRun try: if self.last_run == CANARY_DATE: + log.debug("Detected first run") yield defer.maybeDeferred(self.first_run) last_run_time = datetime.utcnow() yield self.task() @@ -149,6 +150,8 @@ class UpdateInputsAndResources(ScheduledTask): def task(self): log.debug("Updating the inputs") yield probe_ip.lookup() + log.debug("Updating the inputs for country %s" % + probe_ip.geodata['countrycode']) yield resources.check_for_update(probe_ip.geodata['countrycode']) yield input_store.update(probe_ip.geodata['countrycode']) yield probe_ip.resolveGeodata() diff --git a/ooni/deck/store.py b/ooni/deck/store.py index d88f5d5..1e4785e 100644 --- a/ooni/deck/store.py +++ b/ooni/deck/store.py @@ -6,7 +6,7 @@ from copy import deepcopy from twisted.internet import defer from twisted.python.filepath import FilePath -from ooni.utils import mkdir_p +from ooni.utils import mkdir_p, log from ooni.deck.deck import NGDeck from ooni.otime import timestampNowISO8601UTC from ooni.resources import check_for_update @@ -41,6 +41,8 @@ class InputStore(object): yield check_for_update(country_code) if not in_file.exists(): + log.msg("Could not find input for country " + "{0} in {1}".format(cc, in_file.path)) continue # XXX maybe move this to some utility function. diff --git a/ooni/geoip.py b/ooni/geoip.py index 5e6b275..9148e34 100644 --- a/ooni/geoip.py +++ b/ooni/geoip.py @@ -215,6 +215,7 @@ class ProbeIP(object): self.address = None if self.address: + self.resolveGeodata(include_ip, include_asn, include_country) defer.returnValue(self.address) else: self._state = IN_PROGRESS

1 0

[ooni-probe/master] Add microsecond-precise logging to have more info to debug timing issues
by art＠torproject.org 15 Oct '16

15 Oct '16

commit e00072738e08dd0fccd09b8b48a7ed38b7a094ae Author: Leonid Evdokimov <leon(a)darkk.net.ru> Date: Thu Sep 29 13:58:03 2016 +0300 Add microsecond-precise logging to have more info to debug timing issues --- ooni/utils/log.py | 34 ++++++++++++++++++++++++++++------ 1 file changed, 28 insertions(+), 6 deletions(-) diff --git a/ooni/utils/log.py b/ooni/utils/log.py index f20fdce..b4136be 100644 --- a/ooni/utils/log.py +++ b/ooni/utils/log.py @@ -3,6 +3,7 @@ import sys import errno import codecs import logging +from datetime import datetime from twisted.python import log as tw_log from twisted.python.logfile import DailyLogFile @@ -100,6 +101,27 @@ class StdoutStderrObserver(LogLevelObserver): self.write(text + "\n") self.flush() +class MsecLogObserver(tw_log.FileLogObserver): + def formatTime(self, when): + """ + Code from Twisted==16.4.1 modified to log microseconds. Although this + logging subsystem is legacy: http://twistedmatrix.com/trac/ticket/7596 + Also, `timeFormat` is not used as `%z` is broken. + """ + tzOffset = -self.getTimezoneOffset(when) + when = datetime.utcfromtimestamp(when + tzOffset) + tzHour = abs(int(tzOffset / 60 / 60)) + tzMin = abs(int(tzOffset / 60 % 60)) + if tzOffset < 0: + tzSign = '-' + else: + tzSign = '+' + return '%d-%02d-%02d %02d:%02d:%02d,%06d%s%02d%02d' % ( + when.year, when.month, when.day, + when.hour, when.minute, when.second, + when.microsecond, + tzSign, tzHour, tzMin) + class OONILogger(object): def msg(self, msg, *arg, **kw): text = log_encode(msg) @@ -152,18 +174,18 @@ class OONILogger(object): daily_logfile = DailyLogFile(log_filename, log_folder) - tw_log.msg("Starting %s on %s (%s UTC)" % (application_name, - otime.prettyDateNow(), - otime.prettyDateNowUTC())) - - self.fileObserver = LogLevelObserver(daily_logfile, - log_level=file_log_level) + self.fileObserver = MsecLogObserver(LogLevelObserver(daily_logfile, + log_level=file_log_level)) self.stdoutObserver = StdoutStderrObserver(sys.stdout, log_level=stdout_log_level) tw_log.startLoggingWithObserver(self.fileObserver.emit) tw_log.addObserver(self.stdoutObserver.emit) + tw_log.msg("Starting %s on %s (%s UTC)" % (application_name, + otime.prettyDateNow(), + otime.prettyDateNowUTC())) + def stop(self): self.stdoutObserver.stop() self.fileObserver.stop()

1 0