ATOR-295 - Measure relays (#7)

docker/scanner/docker-entrypoint.sh

@@ -1,6 +1,6 @@
 mkdir -p /root/.sbws/log
 
-cd /root/.sbws && rm -rf datadir state.dat  state.dat.lockfile
+cd /root/.sbws && rm -rf state.dat  state.dat.lockfile
 
 crontab -l | { cat; echo "*/$INTERVAL_MINUTES * * * * export INTERVAL_MINUTES=$INTERVAL_MINUTES; /usr/local/bin/sbws -c /root/.sbws.ini generate >> /root/.sbws/log/generate.log  2>&1"; } | crontab -
 crontab -l | { cat; echo "35  0 * * * /usr/local/bin/sbws -c /root/.sbws.ini cleanup >> /root/.sbws/log/cleanup.log  2>&1"; } | crontab -

operations/deploy-live.hcl

@@ -128,8 +128,8 @@ ORPort {{ env `NOMAD_PORT_orport` }}
       }
 
       resources {
-        cpu    = 512
-        memory = 512
+        cpu    = 1000
+        memory = 1000
       }
 
       template {
@@ -183,7 +183,7 @@ external_control_port = {{ env `NOMAD_PORT_control_port` }}
 
       resources {
         cpu    = 128
-        memory = 1280
+        memory = 1500
       }
 
       service {

sbws/config.default.ini

@@ -19,7 +19,7 @@ data_period = 5
 # single float. Requests will use it both as the connect() timeout and the
 # timeout between bytes received from the server. See
 # http://docs.python-requests.org/en/master/user/advanced/#timeouts
-http_timeout = 10
+http_timeout = 60
 # Timeout in seconds for waiting on a circuit to be built. It MUST be an
 # **int**. We will use this both as the CircuitBuildTimeout and a timeout
 # to give to stem for waiting on a circuit to be built since

sbws/core/scanner.py

@@ -115,7 +115,7 @@ def timed_recv_from_server(session, dest, byte_range):
     # does not catch all the ssl exceptions and urllib3 doesn't seem to have
     # a base exception class.
     except Exception as e:
-        log.debug(e)
+        log.error(e)
         return False, e
     end_time = time.monotonic()
     return True, end_time - start_time
@@ -156,12 +156,12 @@ def measure_rtt_to_server(session, conf, dest, content_length):
     rtts = []
     size = conf.getint("scanner", "min_download_size")
     for _ in range(0, conf.getint("scanner", "num_rtts")):
-        log.debug("Measuring RTT to %s", dest.url)
+        log.info("Measuring RTT to %s", dest.url)
         random_range = get_random_range_string(content_length, size)
         success, data = timed_recv_from_server(session, dest, random_range)
         if not success:
             # data is an exception
-            log.debug(
+            log.warning(
                 "While measuring the RTT to %s we hit an exception "
                 "(does the webserver support Range requests?): %s",
                 dest.url,
@@ -195,7 +195,7 @@ def measure_bandwidth_to_server(session, conf, dest, content_length):
         success, data = timed_recv_from_server(session, dest, random_range)
         if not success:
             # data is an exception
-            log.debug(
+            log.warning(
                 "While measuring the bandwidth to %s we hit an "
                 "exception (does the webserver support Range "
                 "requests?): %s",
@@ -272,11 +272,11 @@ def upload_data(session, conf, dest, cont, circ_id):
         msg = "Could not connect to {} over circ {} {}: {}".format(
             dest.url, circ_id, stem_utils.circuit_str(cont, circ_id), e
         )
-        log.debug("%s: %s", msg, e)
+        log.error("%s: %s", msg, e)
         return None, msg
     except Exception as e:
         dest.add_failure()
-        log.debug(e)
+        log.error(e)
         return None, e
     finally:
         log.debug("Finished uploading data.")
@@ -287,7 +287,7 @@ def upload_data(session, conf, dest, cont, circ_id):
             "When sending HTTP POST to {}, we expected HTTP code {} "
             "not {}".format(dest.url, requests.codes.ok, response.status_code)
         )
-        log.debug(msg)
+        log.error(msg)
         return None, msg
 
     dest.add_success()
@@ -368,7 +368,7 @@ def _pick_ideal_second_hop(relay, rl, relay_as_entry, candidates):
 
 def error_no_helper(relay, dest, our_nick=""):
     reason = "Unable to select a second relay"
-    log.debug(
+    log.error(
         reason + " to help measure %s (%s)", relay.fingerprint, relay.nickname
     )
     return [
@@ -401,7 +401,7 @@ def create_path_relay(relay, dest, rl, relay_as_entry, candidates):
 
 
 def error_no_circuit(circ_fps, nicknames, reason, relay, dest, our_nick):
-    log.debug(
+    log.error(
         "Could not build circuit with path %s (%s): %s ",
         circ_fps,
         nicknames,
@@ -648,7 +648,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay):
         # would always fail when there's only one Web server.
 
         if not is_usable and not relay_as_entry:
-            log.debug(
+            log.warning(
                 "Exit %s (%s) that can't exit all ips, with exit policy %s, "
                 "failed to connect to %s via circuit %s (%s). Reason: %s. "
                 "Trying again with it as entry.",
@@ -671,7 +671,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay):
             circ_fps, nicknames, exit_policy = r
             circ_id, reason = cb.build_circuit(circ_fps)
             if not circ_id:
-                log.info(
+                log.warning(
                     "Exit %s (%s) that can't exit all ips, failed to create "
                     " circuit as entry: %s (%s).",
                     relay.fingerprint,
@@ -694,7 +694,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay):
                 dest, circ_id, s, cb.controller, dest._max_dl
             )
         if not is_usable:
-            log.debug(
+            log.error(
                 "Failed to connect to %s to measure %s (%s) via circuit "
                 "%s (%s). Exit policy: %s. Reason: %s.",
                 dest.url,
@@ -716,7 +716,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay):
             s, conf, dest, usable_data["content_length"]
         )
         if rtts is None:
-            log.debug(
+            log.warning(
                 "Unable to measure RTT for %s (%s) to %s via circuit "
                 "%s (%s): %s",
                 relay.fingerprint,
@@ -747,7 +747,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay):
     relay_update_xoff(relay, circ_id)
 
     if bw_results is None:
-        log.debug(
+        log.error(
             "Failed to measure %s (%s) via circuit %s (%s) to %s. Exit"
             " policy: %s. Reason: %s.",
             relay.fingerprint,
@@ -790,7 +790,7 @@ def dispatch_worker_thread(*a, **kw):
     # In case the arguments or the method change, catch the possible exceptions
     # but ignore here that there are not destinations.
     except (IndexError, TypeError):
-        log.debug("Wrong argument or attribute.")
+        log.error("Wrong argument or attribute.")
         functional_destinations = True
     if not functional_destinations or settings.end_event.is_set():
         return None
@@ -807,15 +807,15 @@ def _should_keep_result(did_request_maximum, result_time, download_times):
         and result_time >= download_times["min"]
         and result_time < download_times["max"]
     ):
-        log.debug(msg)
+        log.info(msg)
         return True
     # If we did request the maximum amount, we should keep the result as long
     # as it took less than the maximum amount of time
     if did_request_maximum and result_time < download_times["max"]:
-        log.debug(msg)
+        log.info(msg)
         return True
     # In all other cases, return false
-    log.debug(
+    log.info(
         "Not keeping result time %f.%s",
         result_time,
         ""

sbws/lib/circuitbuilder.py

@@ -51,7 +51,7 @@ def close_circuit(self, circ_id):
             self.controller.close_circuit(circ_id)
         # SocketClosed will be raised when stopping sbws
         except (InvalidArguments, InvalidRequest, SocketClosed) as e:
-            log.debug(e)
+            log.error(e)
         self.built_circuits.discard(circ_id)
 
     def _build_circuit_impl(self, path):

sbws/lib/resultdump.py

@@ -891,7 +891,7 @@ def handle_result(self, result):
         fp = result.fingerprint
         nick = result.nickname
         if isinstance(result, ResultError) and settings.end_event.is_set():
-            log.debug(
+            log.error(
                 "Ignoring %s for %s %s because we are shutting down",
                 type(result).__name__,
                 nick,

sbws/lib/v3bwfile.py

@@ -1499,7 +1499,7 @@ def read_number_consensus_relays(consensus_path):
         try:
             num = len(list(parse_file(consensus_path)))
         except (FileNotFoundError, AttributeError):
-            log.info(
+            log.warning(
                 "It is not possible to obtain statistics about the "
                 "percentage of measured relays because the cached "
                 "consensus file is not found."

sbws/util/fs.py

@@ -176,7 +176,7 @@ def is_low_space(conf):
     disk_required_mb = sbws_required_disk_space(conf)
     disk_avail_mb = df(conf.getpath("paths", "sbws_home"))
     if disk_avail_mb < disk_required_mb:
-        log.warn(
+        log.warning(
             "The space left on the device (%s MiB) is less than "
             "the minimum recommended to run sbws (%s MiB)."
             "Run sbws cleanup to delete old sbws generated files.",

sbws/util/stem.py

@@ -101,7 +101,7 @@ def closure_stream_event_listener(st):
                 InvalidRequest,
                 OperationFailed,
             ) as e:
-                log.debug(
+                log.error(
                     "Error attaching stream %s to circ %s: %s",
                     st.id,
                     circ_id,
@@ -129,7 +129,7 @@ def remove_event_listener(controller, func):
         controller.remove_event_listener(func)
     except SocketClosed as e:
         if not settings.end_event.is_set():
-            log.debug(e)
+            log.error(e)
         else:
             log.exception(e)
     except ProtocolError as e:
@@ -181,7 +181,7 @@ def _init_controller_socket(socket):
         # todo - extract password to config
         c.authenticate(password="password")
     except (IncorrectSocketType, SocketError):
-        log.debug("Error initting controller socket: socket error.")
+        log.error("Error initting controller socket: socket error.")
         return None
     except Exception as e:
         log.exception("Error initting controller socket: %s", e)
@@ -272,7 +272,7 @@ def set_torrc_options_can_fail(controller):
         try:
             controller.set_conf(k, v)
         except (InvalidArguments, InvalidRequest) as error:
-            log.debug(
+            log.error(
                 "Ignoring option not supported by this Tor version. %s", error
             )
         except ControllerError as e:
@@ -347,11 +347,11 @@ def get_socks_info(controller):
         return socks_ports[0]
     except SocketClosed as e:
         if not settings.end_event.is_set():
-            log.debug(e)
+            log.error(e)
     # This might need to return the exception if this happen in other cases
     # than when stopping the scanner.
     except ControllerError as e:
-        log.debug(e)
+        log.error(e)
 
 
 def only_relays_with_bandwidth(relays, min_bw=None, max_bw=None):
@@ -385,7 +385,7 @@ def circuit_str(controller, circ_id):
         return None
     # exceptions raised when stopping the scanner
     except (ControllerError, SocketClosed, socks.GeneralProxyError) as e:
-        log.debug(e)
+        log.error(e)
         return None
     return (
         "["