December 2018 - tor-commits - lists.torproject.org

[sbws/master] scanner: lower log level
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit a7ccb09bb1d55b8a7c66d1223107c0cc8875ad62 Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 09:12:59 2018 +0000 scanner: lower log level Warnings can make think the operator that sbws is not working, while it's normal that some measurements fail. Resultdump already logs at info level what succcess and what fails. Keep these logs at debug level. --- sbws/core/scanner.py | 34 +++++++++++++++++----------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/sbws/core/scanner.py b/sbws/core/scanner.py index 5406a74..bcde389 100644 --- a/sbws/core/scanner.py +++ b/sbws/core/scanner.py @@ -84,9 +84,9 @@ def measure_rtt_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.warning('While measuring the RTT to %s we hit an exception ' - '(does the webserver support Range requests?): %s', - dest.url, data) + log.debug('While measuring the RTT to %s we hit an exception ' + '(does the webserver support Range requests?): %s', + dest.url, data) return None assert success # data is an RTT @@ -114,9 +114,9 @@ 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.warning('While measuring the bandwidth to %s we hit an ' - 'exception (does the webserver support Range ' - 'requests?): %s', dest.url, data) + log.debug('While measuring the bandwidth to %s we hit an ' + 'exception (does the webserver support Range ' + 'requests?): %s', dest.url, data) return None assert success # data is a download time @@ -170,8 +170,8 @@ def measure_relay(args, conf, destinations, cb, rl, relay): # Pick a destionation dest = destinations.next() if not dest: - log.warning('Unable to get destination to measure %s %s', - relay.nickname, relay.fingerprint[0:8]) + log.debug('Unable to get destination to measure %s %s', + relay.nickname, relay.fingerprint[0:8]) return None # Pick a relay to help us measure the given relay. If the given relay is an # exit, then pick a non-exit. Otherwise pick an exit. @@ -189,7 +189,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay): circ_fps = [relay.fingerprint, helper.fingerprint] if not helper: # TODO: Return ResultError of some sort - log.warning('Unable to pick a 2nd hop to help measure %s %s', + log.debug('Unable to pick a 2nd hop to help measure %s %s', relay.nickname, relay.fingerprint[0:8]) return None assert helper @@ -198,7 +198,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay): our_nick = conf['scanner']['nickname'] circ_id, reason = cb.build_circuit(circ_fps) if not circ_id: - log.warning('Could not build circuit involving %s', relay.nickname) + log.debug('Could not build circuit involving %s', relay.nickname) msg = 'Unable to complete circuit' return [ ResultErrorCircuit(relay, circ_fps, dest.url, our_nick, msg=msg), @@ -210,9 +210,9 @@ def measure_relay(args, conf, destinations, cb, rl, relay): # still help us measure is_usable, usable_data = dest.is_usable(circ_id, s, cb.controller) if not is_usable: - log.warning('When measuring %s %s the destination seemed to have ' - 'stopped being usable: %s', relay.nickname, - relay.fingerprint[0:8], usable_data) + log.debug('When measuring %s %s the destination seemed to have ' + 'stopped being usable: %s', relay.nickname, + relay.fingerprint[0:8], usable_data) cb.close_circuit(circ_id) # TODO: Return a different/new type of ResultError? msg = 'The destination seemed to have stopped being usable' @@ -224,8 +224,8 @@ def measure_relay(args, conf, destinations, cb, rl, relay): # FIRST: measure RTT rtts = measure_rtt_to_server(s, conf, dest, usable_data['content_length']) if rtts is None: - log.warning('Unable to measure RTT to %s via relay %s %s', - dest.url, relay.nickname, relay.fingerprint[0:8]) + log.debug('Unable to measure RTT to %s via relay %s %s', + dest.url, relay.nickname, relay.fingerprint[0:8]) cb.close_circuit(circ_id) # TODO: Return a different/new type of ResultError? msg = 'Something bad happened while measuring RTTs' @@ -236,8 +236,8 @@ def measure_relay(args, conf, destinations, cb, rl, relay): bw_results = measure_bandwidth_to_server( s, conf, dest, usable_data['content_length']) if bw_results is None: - log.warning('Unable to measure bandwidth to %s via relay %s %s', - dest.url, relay.nickname, relay.fingerprint[0:8]) + log.debug('Unable to measure bandwidth to %s via relay %s %s', + dest.url, relay.nickname, relay.fingerprint[0:8]) cb.close_circuit(circ_id) # TODO: Return a different/new type of ResultError? msg = 'Something bad happened while measuring bandwidth'

1 0

[sbws/master] resultdump: format the main success/error msg
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 738dc1812221e75378c565fc534765decc26ed3d Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 08:23:50 2018 +0000 resultdump: format the main success/error msg that would be shown at info level. --- sbws/lib/resultdump.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/sbws/lib/resultdump.py b/sbws/lib/resultdump.py index 3756f6f..3dce6fa 100644 --- a/sbws/lib/resultdump.py +++ b/sbws/lib/resultdump.py @@ -567,8 +567,17 @@ class ResultDump: return self.store_result(result) write_result_to_datadir(result, self.datadir) - log.info('%s %s finished measurement with %s', nick, fp[0:8], - type(result).__name__) + if result.type == "success": + msg = "Success measuring {} ({}) via circuit {} and " \ + "destination {}".format( + result.fingerprint, result.nickname, result.circ, + result.dest_url) + else: + msg = "Error measuring {} ({}) via circuit {} and " \ + "destination {}: {}".format( + result.fingerprint, result.nickname, result.circ, + result.dest_url, result.msg) + log.info(msg) def enter(self): ''' Main loop for the ResultDump thread '''

1 0

[sbws/master] relayprioritizer: low logging levels.
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit e268c3909b074dc972343f1666011f890850bfd1 Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 08:14:29 2018 +0000 relayprioritizer: low logging levels. The time it took to run prioritize function is not relevant for the operator. After several days, prioritiy would be adjusted for many relays, so don't log it. We can have different debug verbose levels in the future. --- sbws/lib/relayprioritizer.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/sbws/lib/relayprioritizer.py b/sbws/lib/relayprioritizer.py index 3a635f0..8d3b0c5 100644 --- a/sbws/lib/relayprioritizer.py +++ b/sbws/lib/relayprioritizer.py @@ -69,10 +69,11 @@ class RelayPrioritizer: # will come back to them sooner to try again. assert result.freshness_reduction_factor >= 0.0 assert result.freshness_reduction_factor <= 1.0 - log.debug('Cutting freshness for a %s result by %d%% for ' - '%s', result.type.value, - result.freshness_reduction_factor * 100, - relay.nickname) + # After several days, these would log many relays. + # log.debug('Cutting freshness for a %s result by %d%% for' + # ' %s', result.type.value, + # result.freshness_reduction_factor * 100, + # relay.nickname) freshness *= max(1.0-result.freshness_reduction_factor, 0) priority += freshness relay.priority = priority @@ -83,7 +84,7 @@ class RelayPrioritizer: self.min_to_return) fn_tstop = Decimal(time.time()) fn_tdelta = (fn_tstop - fn_tstart) * 1000 - log.info('Spent %f msecs calculating relay best priority', fn_tdelta) + log.debug('Spent %f msecs calculating relay best priority', fn_tdelta) # Finally, slowly return the relays to the caller (after removing the # priority member we polluted the variable with ...) for relay in relays[0:cutoff]:

1 0

[sbws/master] scanner: stop logging rtt when is not perform
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit f9c5a9dc29b9d3bb3f92315664384451951242bf Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 08:50:14 2018 +0000 scanner: stop logging rtt when is not perform If rtt is configured to 0, the rtt measurements are not run, but it was being logged that they're run --- sbws/core/scanner.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sbws/core/scanner.py b/sbws/core/scanner.py index 80251ec..a9b4959 100644 --- a/sbws/core/scanner.py +++ b/sbws/core/scanner.py @@ -78,8 +78,8 @@ def measure_rtt_to_server(session, conf, dest, content_length): be made, return None. Otherwise return a list of the RTTs (in seconds). ''' rtts = [] size = conf.getint('scanner', 'min_download_size') - log.debug('Measuring RTT to %s', dest.url) for _ in range(0, conf.getint('scanner', 'num_rtts')): + log.debug('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:

1 0

[sbws/master] resuldump: inform when previous results are loaded
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 294581ec101ee3d0d0e83c67abeec55d5f83e88c Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 09:44:47 2018 +0000 resuldump: inform when previous results are loaded since it takes some seconds and the operator would not see any progress at the beginning, until relays start to be measured. --- sbws/lib/resultdump.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sbws/lib/resultdump.py b/sbws/lib/resultdump.py index 3dce6fa..52a0b7c 100644 --- a/sbws/lib/resultdump.py +++ b/sbws/lib/resultdump.py @@ -133,6 +133,8 @@ def load_recent_results_in_datadir(fresh_days, datadir, success_only=False, Results as a list ''' assert isinstance(fresh_days, int) assert os.path.isdir(datadir) + # Inform the results are being loaded, since it takes some seconds. + log.info("Reading and processing previous measurements.") results = {} today = datetime.utcfromtimestamp(time.time()) data_period = fresh_days + 2

1 0

[sbws/master] destination: log the reason why can't build circuit
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 0b63d3dee4f644bcf38dee8daa01d9384a619613 Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 11:03:39 2018 +0000 destination: log the reason why can't build circuit --- sbws/lib/destination.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sbws/lib/destination.py b/sbws/lib/destination.py index c081f89..0b27f39 100644 --- a/sbws/lib/destination.py +++ b/sbws/lib/destination.py @@ -200,7 +200,7 @@ class DestinationList: break if not circ_id: log.warning('Unable to build a circuit to test the usability ' - 'of %s. Assuming it isn\'t usable.', dest.url) + 'of %s, %s', dest.url, reason) continue log.debug('Built circ %s %s to test usability of %s', circ_id, stem_utils.circuit_str(cont, circ_id), dest.url)

1 0

[sbws/master] scanner: inform about the progress of the measurements
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit b13f58805474f33e80f78e42c24f6d2499288c79 Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 09:39:26 2018 +0000 scanner: inform about the progress of the measurements When a new loop starts and when it ends, with the number of relays measured and the time it took. --- sbws/core/scanner.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sbws/core/scanner.py b/sbws/core/scanner.py index bcde389..96b9b90 100644 --- a/sbws/core/scanner.py +++ b/sbws/core/scanner.py @@ -345,6 +345,7 @@ def run_speedtest(args, conf): while True: num_relays = 0 loop_tstart = time.time() + log.info("Starting a new loop to measure relays.") for target in rp.best_priority(): num_relays += 1 log.debug('Measuring %s %s', target.nickname, @@ -364,7 +365,7 @@ def run_speedtest(args, conf): pending_results = [r for r in pending_results if not r.ready()] loop_tstop = time.time() loop_tdelta = (loop_tstop - loop_tstart) / 60 - log.debug("Measured %s relays in %s minutes", num_relays, loop_tdelta) + log.info("Measured %s relays in %s minutes", num_relays, loop_tdelta) def gen_parser(sub):

1 0

[sbws/master] stem: inform Tor is being launched
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 491ded05374df48d774d212b7bd967b73c8e9936 Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 09:57:42 2018 +0000 stem: inform Tor is being launched since it takes some seconds. --- sbws/util/stem.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sbws/util/stem.py b/sbws/util/stem.py index c3fffd1..39c99e4 100644 --- a/sbws/util/stem.py +++ b/sbws/util/stem.py @@ -119,6 +119,8 @@ def _init_controller_socket(socket): def launch_tor(conf): assert isinstance(conf, ConfigParser) + # Inform Tor is being launched, since it takes some seconds. + log.info("Launching Tor...") os.makedirs(conf.getpath('tor', 'datadir'), mode=0o700, exist_ok=True) os.makedirs(conf.getpath('tor', 'log'), exist_ok=True) os.makedirs(conf.getpath('tor', 'run_dpath'), mode=0o700, exist_ok=True)

1 0

[sbws/master] config: format log as usual loggers
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 8d961e831b36394e9f9a90523779fc2f291b8ead Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 10:45:35 2018 +0000 config: format log as usual loggers --- sbws/config.default.ini | 2 +- sbws/config.log.default.ini | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/sbws/config.default.ini b/sbws/config.default.ini index 8abee3d..be8660b 100644 --- a/sbws/config.default.ini +++ b/sbws/config.default.ini @@ -112,7 +112,7 @@ to_file_level = ${level} to_stdout_level = ${level} to_syslog_level = ${level} # Format string to use when logging -format = [%(asctime)s] [%(name)s] [%(levelname)s] %(message)s +format = %(asctime)s %(module)s[%(process)s]: <%(levelname)s> %(message)s to_file_format = ${format} to_stdout_format = ${format} to_syslog_format = %(module)s[%(process)s]: <%(levelname)s> %(message)s diff --git a/sbws/config.log.default.ini b/sbws/config.log.default.ini index deb6275..58d9157 100644 --- a/sbws/config.log.default.ini +++ b/sbws/config.log.default.ini @@ -34,7 +34,10 @@ formatter=to_syslog args = ('/dev/log',) [formatter_to_stdout] +# format date as syslog and journal +datefmt = %b %d %H:%M:%S [formatter_to_file] +datefmt = %b %d %H:%M:%S [formatter_to_syslog]

1 0

[sbws/master] scanner: return the error when measuring
by juga＠torproject.org 20 Dec '18

20 Dec '18

commit 2e0c2da522dc560eeaafff73b890efaca5b4ff0a Author: juga0 <juga(a)riseup.net> Date: Sun Dec 9 11:21:28 2018 +0000 scanner: return the error when measuring bandwidth or rtt, so that it can be used to be stored and logged. --- sbws/core/scanner.py | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-) diff --git a/sbws/core/scanner.py b/sbws/core/scanner.py index 96b9b90..ecc6934 100644 --- a/sbws/core/scanner.py +++ b/sbws/core/scanner.py @@ -75,7 +75,12 @@ def measure_rtt_to_server(session, conf, dest, content_length): ''' Make multiple end-to-end RTT measurements by making small HTTP requests over a circuit + stream that should already exist, persist, and not need rebuilding. If something goes wrong and not all of the RTT measurements can - be made, return None. Otherwise return a list of the RTTs (in seconds). ''' + be made, return None. Otherwise return a list of the RTTs (in seconds). + + :returns tuple: results or None if the if the measurement fail. + None or exception if the measurement fail. + + ''' rtts = [] size = conf.getint('scanner', 'min_download_size') for _ in range(0, conf.getint('scanner', 'num_rtts')): @@ -87,15 +92,20 @@ def measure_rtt_to_server(session, conf, dest, content_length): log.debug('While measuring the RTT to %s we hit an exception ' '(does the webserver support Range requests?): %s', dest.url, data) - return None + return None, data assert success # data is an RTT assert isinstance(data, float) or isinstance(data, int) rtts.append(data) - return rtts + return rtts, None def measure_bandwidth_to_server(session, conf, dest, content_length): + """ + :returns tuple: results or None if the if the measurement fail. + None or exception if the measurement fail. + + """ results = [] num_downloads = conf.getint('scanner', 'num_downloads') expected_amount = conf.getint('scanner', 'initial_read_request') @@ -117,7 +127,7 @@ def measure_bandwidth_to_server(session, conf, dest, content_length): log.debug('While measuring the bandwidth to %s we hit an ' 'exception (does the webserver support Range ' 'requests?): %s', dest.url, data) - return None + return None, data assert success # data is a download time assert isinstance(data, float) or isinstance(data, int) @@ -127,7 +137,7 @@ def measure_bandwidth_to_server(session, conf, dest, content_length): 'duration': data, 'amount': expected_amount}) expected_amount = _next_expected_amount( expected_amount, data, download_times, min_dl, max_dl) - return results + return results, None def _pick_ideal_second_hop(relay, dest, rl, cont, is_exit): @@ -222,7 +232,8 @@ def measure_relay(args, conf, destinations, cb, rl, relay): assert is_usable assert 'content_length' in usable_data # FIRST: measure RTT - rtts = measure_rtt_to_server(s, conf, dest, usable_data['content_length']) + rtts, reason = measure_rtt_to_server(s, conf, dest, + usable_data['content_length']) if rtts is None: log.debug('Unable to measure RTT to %s via relay %s %s', dest.url, relay.nickname, relay.fingerprint[0:8]) @@ -233,7 +244,7 @@ def measure_relay(args, conf, destinations, cb, rl, relay): ResultErrorStream(relay, circ_fps, dest.url, our_nick, msg=msg), ] # SECOND: measure bandwidth - bw_results = measure_bandwidth_to_server( + bw_results, reason = measure_bandwidth_to_server( s, conf, dest, usable_data['content_length']) if bw_results is None: log.debug('Unable to measure bandwidth to %s via relay %s %s',

1 0