Handle the new format of vanilla_tor experiment

af/fastpath/debian/changelog

@@ -1,3 +1,9 @@
+fastpath (0.59) unstable; urgency=medium
+
+  * Fix vanilla_tor https://github.com/ooni/backend/issues/608
+
+ -- Federico Ceratto <federico@debian.org>  Mon, 15 Aug 2022 16:17:07 +0100
+
 fastpath (0.58) unstable; urgency=medium
 
   * Add DNS fingerprints for Iran

af/fastpath/fastpath/core.py

@@ -738,12 +738,12 @@ def score_http_invalid_request_line(msm):
 
 def get_http_header(resp, header_name, case_sensitive=False):
     """This function returns the HTTP header(s) matching the given
-       header_name from the headers. The returned value is a list
-       given that we may have multiple keys per header. If the new
-       headers_list field is present in the response, we'll use
-       that, otherwise we'll fallback to the headers map. We perform
-       case insensitive header names search by default. You can yet
-       optionally select case sensitive comparison."""
+    header_name from the headers. The returned value is a list
+    given that we may have multiple keys per header. If the new
+    headers_list field is present in the response, we'll use
+    that, otherwise we'll fallback to the headers map. We perform
+    case insensitive header names search by default. You can yet
+    optionally select case sensitive comparison."""
     if case_sensitive == False:
         header_name = header_name.lower()
 
@@ -753,7 +753,7 @@ def get_http_header(resp, header_name, case_sensitive=False):
     # header_list
     if "header_list" not in resp:
         headers = resp.get("headers", {})
-        header_list = [[h,v] for h,v in headers.items()]
+        header_list = [[h, v] for h, v in headers.items()]
     else:
         headers_list = resp.get("headers_list")  # TODO: unused
 
@@ -766,6 +766,7 @@ def get_http_header(resp, header_name, case_sensitive=False):
 
     return values
 
+
 @metrics.timer("score_measurement_whatsapp")
 def score_measurement_whatsapp(msm):
     """Calculate measurement scoring for Whatsapp.
@@ -902,18 +903,26 @@ def score_vanilla_tor(msm):
     if msm["software_name"] == "ooniprobe" and all_keys_none(tk, nks):
         if tk["tor_progress"] == 0:
             # client bug?
+            scores["accuracy"] = 0.0
             scores["msg"] = "Client bug"
             return scores
 
-    tor_log = tk.get("tor_log")
-    if tor_log is None:
+    tor_logs = []
+    # Handle incompatibility with legacy test:
+    # https://github.com/ooni/spec/blob/master/nettests/ts-016-vanilla-tor.md#incompatibility-with-ooniprobe-legacy
+    if tk.get("tor_logs"):
+        tor_logs = tk["tor_logs"]
+    elif tk.get("tor_log"):
+        tor_logs = tk["tor_log"].split("\n")
+
+    if len(tor_logs) == 0:
         # unknown bug
+        scores["accuracy"] = 0.0
         return scores
 
-    if (
-        "Bootstrapped 100%: Done" in tor_log
-        or "Bootstrapped 100% (done): Done" in tor_log
-    ):
+    done1 = "Bootstrapped 100%: Done"
+    done2 = "Bootstrapped 100% rdone): Done"
+    if any((done1 in x or done2 in x) for x in tor_logs):
         # Success
         return scores
 
@@ -1142,7 +1151,7 @@ def score_meek_fronted_requests_test(msm) -> dict:
         headers = resp.get("headers", {})
         # headers can be a list or a dict
         if isinstance(headers, list):
-            headers = {i[0]:i[1][0] for i in headers if i}
+            headers = {i[0]: i[1][0] for i in headers if i}
         server = headers.get("Server", "")
         if not server.startswith("ECAcc "):
             scores["blocking_general"] += 0.5

af/fastpath/fastpath/tests/data/vanilla_tor_bad_new.json

@@ -0,0 +1 @@
+{"annotations":{"architecture":"arm64","engine_name":"ooniprobe-engine","engine_version":"3.15.2","flavor":"stableFdroid","network_type":"wifi","origin":"autorun","platform":"android"},"data_format_version":"0.2.0","input":null,"measurement_start_time":"2022-08-02 21:55:29","probe_asn":"AS17623","probe_cc":"CN","probe_ip":"127.0.0.1","probe_network_name":"China Unicom Shenzen network","report_id":"20220802T215209Z_vanillator_CN_17623_n1_LXFdyo7ao2kE7sQj","resolver_asn":"AS17623","resolver_ip":"27.40.22.154","resolver_network_name":"China Unicom Shenzen network","software_name":"ooniprobe-android-unattended","software_version":"3.7.0","test_keys":{"bootstrap_time":0,"error":"timeout-reached","failure":"generic_timeout_error","success":false,"timeout":200,"tor_logs":["Aug 03 05:52:09.000 [notice] Bootstrapped 0% (starting): Starting","Aug 03 05:52:09.000 [notice] Bootstrapped 5% (conn): Connecting to a relay"],"tor_progress":5,"tor_progress_tag":"conn","tor_progress_summary":"Connecting to a relay","tor_version":"0.4.6.10-dev","transport_name":"vanilla"},"test_name":"vanilla_tor","test_runtime":200.02608409,"test_start_time":"2022-08-02 21:52:07","test_version":"0.2.0"}

af/fastpath/fastpath/tests/data/vanilla_tor_bad_old.json

@@ -0,0 +1 @@
+{"test_keys": {"transport_name": "vanilla", "success": false, "tor_log": "Oct 07 07:33:17.000 [notice] Tor 0.2.9.10 (git-e28303bcf90b842d) opening new log file.\nOct 07 07:33:17.346 [notice] Tor 0.2.9.10 (git-e28303bcf90b842d) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.1t and Zlib 1.2.8.\nOct 07 07:33:17.346 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning\nOct 07 07:33:17.347 [notice] Configuration file \"/non-existant\" not present, using reasonable defaults.\nOct 07 07:33:17.378 [notice] Opening Socks listener on 127.0.0.1:27178\nOct 07 07:33:17.378 [notice] Opening Control listener on 127.0.0.1:58496\nOct 07 07:33:17.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip.\nOct 07 07:33:19.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6.\nOct 07 07:33:20.000 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.\nOct 07 07:33:23.000 [notice] Bootstrapped 0%: Starting\nOct 07 07:33:23.000 [notice] Bootstrapped 5%: Connecting to directory server\nOct 07 07:33:23.000 [notice] New control connection opened from 127.0.0.1.\nOct 07 07:33:23.000 [notice] Tor 0.2.9.10 (git-e28303bcf90b842d) opening log file.\nOct 07 07:38:15.000 [notice] Catching signal TERM, exiting cleanly.\n", "tor_progress_tag": "conn_dir", "tor_progress": 5, "timeout": 300, "error": "timeout-reached", "tor_version": "0.2.9.10", "tor_progress_summary": "Connecting to directory server"}, "software_version": "2.2.0", "test_runtime": 300.17800116539, "test_start_time": "2017-10-07 07:33:08", "input_hashes": [], "software_name": "ooniprobe", "options": [], "data_format_version": "0.2.0", "measurement_start_time": "2017-10-07 07:33:15", "test_version": "0.1.0", "probe_city": null, "test_name": "vanilla_tor", "id": "14632cd4-1469-4e36-98ed-b1da0c52e740", "input": null, "probe_ip": "127.0.0.1", "probe_cc": "CN", "probe_asn": "AS56040", "annotations": {"platform": "lepidopter"}, "test_helpers": {}, "report_id": "20171007T073314Z_AS56040_re2Zb27c4u8wWG2YfuXUAmUW6eXCrrotLnUmjBtlZx66JjNYmq", "measurement_uid": "0120171007df235919e72f85cee42cc424b5461d"}

af/fastpath/fastpath/tests/data/vanilla_tor_good_new.json

@@ -0,0 +1 @@
+{"annotations":{"architecture":"arm64","engine_name":"ooniprobe-engine","engine_version":"3.15.2","flavor":"stableFull","network_type":"wifi","origin":"autorun","platform":"android"},"data_format_version":"0.2.0","input":null,"measurement_start_time":"2022-08-12 11:52:56","probe_asn":"AS7922","probe_cc":"US","probe_ip":"127.0.0.1","probe_network_name":"Comcast Cable Communications, LLC","report_id":"20220812T115246Z_vanillator_US_7922_n1_v8yNHvllkZNG3TVo","resolver_asn":"AS7922","resolver_ip":"76.96.24.39","resolver_network_name":"Comcast Cable Communications, LLC","software_name":"ooniprobe-android-unattended","software_version":"3.7.0","test_keys":{"bootstrap_time":10.083362131,"error":null,"failure":null,"success":true,"timeout":200,"tor_logs":["Aug 12 06:52:46.000 [notice] Bootstrapped 0% (starting): Starting","Aug 12 06:52:46.000 [notice] Bootstrapped 5% (conn): Connecting to a relay","Aug 12 06:52:46.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay","Aug 12 06:52:46.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay","Aug 12 06:52:47.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done","Aug 12 06:52:47.000 [notice] Bootstrapped 20% (onehop_create): Establishing an encrypted directory connection","Aug 12 06:52:47.000 [notice] Bootstrapped 25% (requesting_status): Asking for networkstatus consensus","Aug 12 06:52:47.000 [notice] Bootstrapped 30% (loading_status): Loading networkstatus consensus","Aug 12 06:52:49.000 [notice] Bootstrapped 40% (loading_keys): Loading authority key certs","Aug 12 06:52:49.000 [notice] Bootstrapped 45% (requesting_descriptors): Asking for relay descriptors","Aug 12 06:52:50.000 [notice] Bootstrapped 50% (loading_descriptors): Loading relay descriptors","Aug 12 06:52:51.000 [notice] Bootstrapped 55% (loading_descriptors): Loading relay descriptors","Aug 12 06:52:53.000 [notice] Bootstrapped 63% (loading_descriptors): Loading relay descriptors","Aug 12 06:52:53.000 [notice] Bootstrapped 68% (loading_descriptors): Loading relay descriptors","Aug 12 06:52:53.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits","Aug 12 06:52:53.000 [notice] Bootstrapped 80% (ap_conn): Connecting to a relay to build circuits","Aug 12 06:52:53.000 [notice] Bootstrapped 85% (ap_conn_done): Connected to a relay to build circuits","Aug 12 06:52:53.000 [notice] Bootstrapped 89% (ap_handshake): Finishing handshake with a relay to build circuits","Aug 12 06:52:53.000 [notice] Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits","Aug 12 06:52:53.000 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit","Aug 12 06:52:56.000 [notice] Bootstrapped 100% (done): Done"],"tor_progress":100,"tor_progress_tag":"done","tor_progress_summary":"Done","tor_version":"0.4.6.10-dev","transport_name":"vanilla"},"test_name":"vanilla_tor","test_runtime":10.359145881,"test_start_time":"2022-08-12 11:52:45","test_version":"0.2.0"}

af/fastpath/fastpath/tests/data/vanilla_tor_good_old.json

@@ -0,0 +1 @@
+{"test_keys": {"transport_name": "vanilla", "success": true, "tor_log": "Aug 13 01:20:13.000 [notice] Tor 0.3.4.9 (git-074ca2e0054fded1) opening new log file.\nAug 13 01:20:13.198 [warn] OpenSSL version from headers does not match the version we're running with. If you get weird crashes, that might be why. (Compiled with 1000106f: OpenSSL 1.0.1f 6 Jan 2014; running with 1000207f: OpenSSL 1.0.2g  1 Mar 2016).\nAug 13 01:20:13.231 [notice] Tor 0.3.4.9 (git-074ca2e0054fded1) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.2g, Zlib 1.2.8, Liblzma N/A, and Libzstd N/A.\nAug 13 01:20:13.231 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning\nAug 13 01:20:13.231 [notice] Configuration file \"/non-existant\" not present, using reasonable defaults.\nAug 13 01:20:13.234 [notice] Scheduler type KIST has been enabled.\nAug 13 01:20:13.234 [notice] Opening Socks listener on 127.0.0.1:2280\nAug 13 01:20:13.235 [notice] Opening Control listener on 127.0.0.1:10163\nAug 13 01:20:13.000 [notice] Bootstrapped 0%: Starting\nAug 13 01:20:13.000 [notice] Starting with guard context \"default\"\nAug 13 01:20:13.000 [notice] New control connection opened from 127.0.0.1.\nAug 13 01:20:13.000 [notice] Tor 0.3.4.9 (git-074ca2e0054fded1) opening log file.\nAug 13 01:20:13.000 [notice] Bootstrapped 5%: Connecting to directory server\nAug 13 01:20:13.000 [notice] Bootstrapped 10%: Finishing handshake with directory server\nAug 13 01:20:13.000 [notice] Bootstrapped 15%: Establishing an encrypted directory connection\nAug 13 01:20:14.000 [notice] Bootstrapped 20%: Asking for networkstatus consensus\nAug 13 01:20:14.000 [notice] Bootstrapped 25%: Loading networkstatus consensus\nAug 13 01:20:15.000 [notice] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.\nAug 13 01:20:15.000 [notice] Bootstrapped 40%: Loading authority key certs\nAug 13 01:20:16.000 [notice] The current consensus has no exit nodes. Tor can only build internal paths, such as paths to onion services.\nAug 13 01:20:16.000 [notice] Bootstrapped 45%: Asking for relay descriptors for internal paths\nAug 13 01:20:16.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 0/6704, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 100% of end bw (no exits in consensus) = 0% of path bw.)\nAug 13 01:20:16.000 [notice] Bootstrapped 50%: Loading relay descriptors for internal paths\nAug 13 01:20:16.000 [notice] The current consensus contains exit nodes. Tor can build exit and internal paths.\nAug 13 01:20:16.000 [notice] Bootstrapped 55%: Loading relay descriptors\nAug 13 01:20:16.000 [notice] Bootstrapped 62%: Loading relay descriptors\nAug 13 01:20:17.000 [notice] Bootstrapped 72%: Loading relay descriptors\nAug 13 01:20:17.000 [notice] Bootstrapped 80%: Connecting to the Tor network\nAug 13 01:20:17.000 [notice] Bootstrapped 85%: Finishing handshake with first hop\nAug 13 01:20:17.000 [notice] Bootstrapped 90%: Establishing a Tor circuit\nAug 13 01:20:17.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.\nAug 13 01:20:17.000 [notice] Bootstrapped 100%: Done\nAug 13 01:20:17.000 [notice] Catching signal TERM, exiting cleanly.\n", "tor_progress_tag": "done", "tor_progress": 100, "timeout": 300, "error": null, "tor_version": "0.3.4.9", "tor_progress_summary": "Done"}, "software_version": "2.0.2", "test_runtime": 4.391853094100952, "test_start_time": "2020-08-13 00:00:27", "input_hashes": [], "software_name": "ooniprobe", "options": [], "data_format_version": "0.2.0", "measurement_start_time": "2020-08-13 00:20:13", "test_version": "0.1.0", "probe_city": null, "test_name": "vanilla_tor", "id": "33de92f6-e03d-4e72-b554-e27ceb6ad8e8", "input": null, "probe_ip": "127.0.0.1", "probe_cc": "IE", "probe_asn": "AS6830", "annotations": {"platform": "linux"}, "test_helpers": {}, "report_id": "20200813T000028Z_AS6830_vdHRv7BWyejAP2Gj1INiRb9qHArwaEMdxcfTvH1q8pjD24pU2G", "measurement_uid": "0120200813e619f7d08ae11ff487ebda33a984d5"}

af/fastpath/fastpath/tests/test_unit.py

@@ -484,6 +484,24 @@ def test_score_torsf2():
     }
 
 
+def test_score_vanilla_tor():
+    msm = loadj("vanilla_tor_bad_new")
+    scores = fp.score_measurement(msm)
+    assert scores["blocking_general"] > 0
+
+    msm = loadj("vanilla_tor_bad_old")
+    scores = fp.score_measurement(msm)
+    assert scores["blocking_general"] > 0
+
+    msm = loadj("vanilla_tor_good_new")
+    scores = fp.score_measurement(msm)
+    assert scores["blocking_general"] == 0
+
+    msm = loadj("vanilla_tor_good_old")
+    scores = fp.score_measurement(msm)
+    assert scores["blocking_general"] == 0
+
+
 # # Bug tests