-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1

Hi,

I'm not very familiar with the source tree yet, but I notice one bit of low hanging fruit, one set of distinguishing hypothesis, and one concern. Responses inline:

On Sat, Jun 15, 2013 at 8:03 AM, Jacob Appelbaum jacob@appelbaum.net wrote:

Heya,

Greetings from #404Lab in Tunis, Tunisia!

I'm testing the ooniprobe in the censorship lab. I'm making a running list of issues and I'll outline them below.

When running the following test:

./bin/ooniprobe -l tunisia-404lab-netcache-000.log nettests/blocking/http_requests.py;

I find that the test hangs for ~10 minutes:

Log opened. [D] No test deck detected Starting Tor... [D] Setting control port as 9251 [D] Setting SOCKS port as 9250 [D] 10%: Finishing handshake with directory server [D] 15%: Establishing an encrypted directory connection [D] 20%: Asking for networkstatus consensus [D] 25%: Loading networkstatus consensus [D] 45%: Asking for relay descriptors [D] 80%: Connecting to the Tor network [D] 90%: Establishing a Tor circuit [D] 100%: Done [D] Building a TorState Successfully bootstrapped Tor [D] We now have the following circuits: [D] * <Circuit 1 BUILT [154.35.32.5] for GENERAL> [D] * <Circuit 2 BUILT [31.172.30.3] for GENERAL> [D] * <Circuit 3 BUILT [198.211.114.130] for GENERAL> [D] * <Circuit 5 BUILT [194.132.32.43] for GENERAL> [D] * <Circuit 6 BUILT [31.172.30.3 46.166.174.209 93.115.241.2] for GENERAL> [D] * <Circuit 7 EXTENDED [198.211.114.130 74.120.13.132] for GENERAL> [D] * <Circuit 8 EXTENDED [] for GENERAL> [D] * <Circuit 9 EXTENDED [] for GENERAL> [D] * <Circuit 10 EXTENDED [] for GENERAL> [D] * <Circuit 11 EXTENDED [] for GENERAL> [D] * <Circuit 12 EXTENDED [] for GENERAL> [D] * <Circuit 13 EXTENDED [] for GENERAL> [D] * <Circuit 14 EXTENDED [] for GENERAL> [D] * <Circuit 15 EXTENDED [] for GENERAL> [D] * <Circuit 16 EXTENDED [] for GENERAL> [D] Obtained our IP address from a Tor Relay None Found your IP via Tor 41.231.22.232 We will include some geo data in the report Your AS number is: AS2609 Reporting using collector: httpo://nkvphnp3p6agi5qq.onion [D] adding callback for startNetTest [D] Creating ./report-http_requests_test-2013-06-15T100736Z.yamloo [D] Writing report with YAML reporter [D] Created report with <ooni.reporter.YAMLReporter object at 0x334ca90> Reporting httpo://nkvphnp3p6agi5qq.onion/report [D] Sending {"software_name": "ooniprobe", "software_version": "0.0.11", "content": "---\noptions: []\nprobe_asn: AS2609\nprobe_cc: TN\nprobe_ip: 41.231.22.232\nsoftware_name: ooniprobe\nsoftware_version: 0.0.11\nstart_time: 1371290856.723735\ntest_name: http_requests_test\ntest_version: 0.2.3\n...\n", "test_version": "0.2.3", "test_name": "http_requests_test", "probe_asn": "AS2609"} Creating report with OONIB Reporter. Please be patient. This may take up to 1-2 minutes... [D] Created report with id 2013-06-15T100948Z_AS2609_UIsgF34hqK8qn2GaxQtaynMnlIQedKCNaH2fNVoY5voh1I4Kdw [D] Created report with <ooni.reporter.OONIBReporter object at 0x334cc90> [D] Starting this task <generator object generateMeasurements at 0x3c78870> [D] Running <class 'nettests.blocking.http_requests.HTTPRequestsTest'> test_get [D] Finished test setup

...

I'm not clear what will happen next - it just hangs. I killed it after around ten minutes.

Some categorical distinctions of the cause:

Here are my intuitions about how to distinguish different causes of this ten minute "hang": First, the actual network behavior may have been such that "correct" code would have taken longer than ten minutes to complete. Second, there may have been an event handled in a silent, non-progressing manner (more below). Third, there may have been a non-terminating process (more below).

If the actual networking events added up to more than ten minutes, then perhaps more fine grained logging of the events would help the operator distinguish a hang versus a slow network. (Also, slowness could be network interference!)

A common case of "silent, non-progressing" processing in twisted applications is unhandled Failures in a deferred chain. Deferreds are designed such that they cannot predict if new callbacks will be added someday, so if there's a failure that reaches the end of the chain, Deferred will silently hang onto it assuming some code will later add an errback. Aside from scouring the code looking for missing errbacks (which is difficult), you might try asking in freenode's #twisted, #tahoe-lafs, or #leastauthority, to ask for a general solution to detecting/debugging this.

As for non-termination, in twisted this can be hard to spot because the loop may be spread throughout deferred callbacks. (For example, an infinite retry sequence could happen by design or if there is a bug in the retry limiting.) I recommend logging at all retry decision points to detect common cases.

My Concern: The test name includes "blocking".

I overheard a bit of conversation that sounds like the only source of blocking networking currently has to do with accessing SSL certificate details around the time of a handshake. I believe it's possible to access certificate details in a somewhat twisted-friendly manner by using custom verify callbacks. Here's an example I wrote:

This hooks up the verifier to a twisted SSL listener:

https://bitbucket.org/0x0000/saturnalia/src/00c286319033711059d63ee81ba177b7...

The "tlsContextFactory" (constructed a few lines above) is what implements a custom verifier. It's definitions is here:

https://bitbucket.org/0x0000/saturnalia/src/00c286319033711059d63ee81ba177b7...

Several strong caveats:

1. I don't know if I understand the SSL / blocking IO issue well enough to know if the example linked above is useful.

2. I have low confidence in this custom verifier: there may either be validation logic errors, or API misuse bugs, so please minimize your security assumptions about this example.

3. I don't know if this is "The Right Way" to get details about a certificate / certificate chain from python's SSL wrapper. It's *a* way which occurs prior to the twisted Protocol layer, during the handshake.

4. The python SSL bindings here are super sketch. I have a vague memory of calling something like a signature verification method on a cert only to have a core dump. (Tantalizing...)

5. I *assume* that the verify callback runs on the reactor's thread, so if it blocks, the entire reactor thread blocks, but it is (hopefully) safe to twiddle any python variables (owned on the reactor thread). Also, the return value is used for SSL validation, so it is not possible to use twisted deferreds to make a validation decision.

6. There's an obnoxious layering violation gotcha that stems from the lower SSL abstraction, which gets reified in twisted. I don't remember the exact details, but it's something like "connectionMade" is called *prior* to certificate validation, but some other event handlers are called after. Be careful and double check any authentication assumptions in each event handler separately.

7. The codebase I pointed to uses a different event management framework (called task) that is then mashed together with twisted, so please don't emulate the larger code structure there without understanding it. The two points I linked to are the useful bits.

I recommend verifying any code you write with #twisted. There will be folks there who have much more expertise on this than I do.

(I can repeat these details in a ticket if someone points me to it.)

I followed up with the following test:

./bin/ooniprobe -l tunisia-404lab-netcache-000.log nettests/manipulation/http_invalid_request_line.py;

It worked without issues.

The following test goes on for a while:

./bin/ooniprobe -l tunisia-404lab-netcache-000.log nettests/blocking/http_requests.py -f inputs/top-1000.txt

It starts throwing the following errors: Performing GET request to google.com.ar [D] Performing request google.com.ar GET {'User-Agent': ['Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.2) Gecko/20100115 Firefox/3.6']} [!] Unsupported scheme: '' [!] Task <ooni.tasks.Measurement object at 0x3302d90> has failed 6 times Traceback (most recent call last): File "/ooni-probe/ooni/managers.py", line 59, in _fillSlots self._run(task) File "/ooni-probe/ooni/managers.py", line 70, in _run d = task.start() File "/ooni-probe/ooni/tasks.py", line 91, in start return BaseTask.start(self) File "/ooni-probe/ooni/tasks.py", line 38, in start self._running = defer.maybeDeferred(self.run) --- <exception caught here> --- File "/ooniprobe/lib/python2.7/site-packages/twisted/internet/defer.py", line 138, in maybeDeferred result = f(*args, **kw) File "/ooni-probe/ooni/tasks.py", line 129, in run d = self.netTestMethod() File "/ooni-probe/nettests/blocking/http_requests.py", line 117, in test_get headers=headers) File "/ooni-probe/ooni/templates/httpt.py", line 313, in doRequest body_producer) File "/ooni-probe/ooni/utils/txagentwithsocks.py", line 179, in request return client.Agent.request(self, method, uri, headers, bodyProducer) File "/lib/python2.7/site-packages/twisted/web/client.py", line 1218, in request parsedURI.port) File "/ooni-probe/ooni/utils/txagentwithsocks.py", line 199, in _getEndpoint raise SchemeNotSupported("Unsupported xxx scheme: %r" % (scheme,)) exceptions.NameError: global name 'SchemeNotSupported' is not defined

Here's the Low Hanging Fruit:

Run pyflakes on the ooni codebase. Require pyflakes in your official merge process. Require it in your official release candidate process. Require it during package building it. Run pyflakes on all python code you ever touch. Configure your editor to run pyflakes as soon as you save a python file. Add pre-commit hooks that abort your commits if pyflakes fails. Run pyflakes in your sleep. Eat pyflakes for breakfast.

Then, after you've sprinkled pyflakes everywhere you possibly can, take a moment of silence and ponder the tragedy of total time lost due to the fact that python doesn't simply run the pyflakes checks every time it ever imports any module.

[!] Permanent failure for <ooni.tasks.Measurement object at 0x3302d90> Failed doing measurement: <ooni.tasks.Measurement object at 0x3302d90> [D] Starting this task <ooni.tasks.ReportEntry object at 0xbf0c950> [D] Starting this task <ooni.tasks.ReportEntry object at 0xbf0ca50>

It then hangs like so:

[D] Checking all tasks for completion 102 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xc1405d0> [D] None [D] Checking all tasks for completion 103 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xc1408d0> [D] None

I killed it - I'm not sure why it hangs. The host list is just the top alexa hosts.

% ./bin/ooniprobe -l tunisia-404lab-netcache-000.log nettests/blocking/tcpconnect.py -f inputs/top-1000-port80.txt

This worked without issue.

I tried:

% ./bin/ooniprobe -l tunisia-404lab-netcache-000.log nettests/blocking/http_requests.py -f inputs/top-1000.txt

I had similar hangs - so the tests never finished:

[D] Checking all tasks for completion 100 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xcc7d190> [D] None [D] Checking all tasks for completion 101 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xcc7d490> [D] None [D] Checking all tasks for completion 102 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xcc7d790> [D] None [D] Checking all tasks for completion 103 == 133 [D] Successfully performed report <ooni.tasks.ReportEntry object at 0xcc7da90> [D] None

Thoughts?

I have little understanding of this log format, but the "None" entries seem suspicious. Could there be a function missing a "return" statement, that implicitly returns None?

All the best, Jake _______________________________________________ ooni-dev mailing list ooni-dev@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/ooni-dev

- -- Nathan Wilcox Least Authoritarian

GPG id: CBA48BDD GPG fingerprint: 9309 EB72 87D4 192F 0D7E 0F16 1191 AF31 CBA4 8BDD