From 27e7dd40932d0248fd7dec948c88ee5c81df4937 Mon Sep 17 00:00:00 2001 From: Christopher Baines Date: Mon, 24 Mar 2014 00:38:52 +0000 Subject: Logging improvements --- lib/chutney/TorNet.py | 37 +++-- networks/hs-intro-fail | 368 ++++++++++++++++++++++++++--------------------- networks/hs-intro-scale | 2 +- torrc_templates/common.i | 1 + 4 files changed, 236 insertions(+), 172 deletions(-) diff --git a/lib/chutney/TorNet.py b/lib/chutney/TorNet.py index 28629ff..04af448 100644 --- a/lib/chutney/TorNet.py +++ b/lib/chutney/TorNet.py @@ -25,9 +25,6 @@ import random import stem.control -from twisted.web import server, resource -from twisted.internet import reactor - import StringIO import socket import urllib @@ -39,6 +36,8 @@ import Queue import chutney.Templating import chutney.Traffic +import logging + def mkdir_p(d, mode=0777): """Create directory 'd' and all of its parents as needed. Unlike os.makedirs, does not give an error if d already exists. @@ -750,15 +749,12 @@ def runConfigFile(verb, f): _GLOBALS = dict(_BASE_ENVIRON = _BASE_ENVIRON, Node=Node, EventType=stem.control.EventType, - server=server, - resource=resource, - reactor=reactor, time=time, thread=thread, Queue=Queue, random=random, threading=threading, - log=log, + logging=logging, stop=stop, _THE_NETWORK=_THE_NETWORK) @@ -779,8 +775,14 @@ def runConfigFile(verb, f): return getattr(network, verb)() -def log(string): - print(time.strftime("%b %d %H:%M:%S.000") + " " + str(string)) +def logold(string, show=True): + output = time.strftime("%b %d %H:%M:%S.000") + " " + str(string) + + f = open('log.log', 'w') + f.write(output) + + if show: + print(output) def signal_handler(signal, frame): _THE_NETWORK.stop() @@ -793,6 +795,23 @@ def main(): _BASE_ENVIRON = chutney.Templating.Environ(**DEFAULTS) _THE_NETWORK = Network(_BASE_ENVIRON) + logger = logging.getLogger() + logger.setLevel(logging.DEBUG) + + # create console handler and set level to info + handler = logging.StreamHandler() + handler.setLevel(logging.INFO) + formatter = logging.Formatter("%(asctime)s %(message)s", datefmt="%b %d %H:%M:%S.000") + handler.setFormatter(formatter) + logger.addHandler(handler) + + # create debug file handler and set level to debug + handler = logging.FileHandler(os.path.join(".", "chutney.log"), "w") + handler.setLevel(logging.DEBUG) + formatter = logging.Formatter("%(asctime)s %(message)s", datefmt="%b %d %H:%M:%S.000") + handler.setFormatter(formatter) + logger.addHandler(handler) + if len(sys.argv) < 3: print usage(_THE_NETWORK) print "Error: Not enough arguments given." diff --git a/networks/hs-intro-fail b/networks/hs-intro-fail index 2143a9d..8e5470a 100644 --- a/networks/hs-intro-fail +++ b/networks/hs-intro-fail @@ -1,46 +1,163 @@ -Authority = Node.create(3, { +authority_nodes = Node.create(3, { "tag": "a", "authority": 1, "relay": 1, "torrc": "authority.tmpl" }) -Relay = Node.create(10, { +# hidden service (hs) nodes +hs_nodes = [] + +hs_servers = [] + +port = 8081 + +from twisted.web import server, resource +from twisted.internet import reactor + +# Use twisted to create web servers in this script +class Site(resource.Resource): + isLeaf = True + numberRequests = 0 + + def __init__(self, siteNum): + self.siteNum = siteNum + + def render_GET(self, request): + self.numberRequests += 1 + request.setHeader("content-type", "text/plain") + return str(self.siteNum) + +base_port = 9080 +for i in range(2): + + port = base_port + i + + node = Node( + tag="h", + hiddenservice=1, + torrc="hidden-service.tmpl", + hiddenservicetarget="127.0.0.1:%i" % port + ) + hs_nodes.append(node) + + site = server.Site(Site(i)) + + s = reactor.listenTCP(port, site) + hs_servers.append(s) + + port += 1 + +client_nodes = Node.create(6, { + "tag": "c", + "torrc": "client.tmpl" +}) + +relay_nodes = Node.create(10, { "tag": "r", "relay": 1, "torrc": "intro.tmpl" }) -Client = Node.create(6, { - "tag": "c", - "torrc": "client.tmpl" -}) +thread.start_new_thread(reactor.run, (), {"installSignalHandlers": 0}) -initial_nodes = Authority + Relay + Client +initial_nodes = authority_nodes + relay_nodes + client_nodes + hs_nodes[:1] -# hidden service (hs) nodes +def start(): + if not all([ n.getController().start() for n in initial_nodes ]): + return False + + logging.info("All initial nodes running") + + for n in authority_nodes + relay_nodes: + fingerprint = n.getStemController().get_info("fingerprint") + nodes_by_fingerprint[fingerprint] = n -hs_node_1 = Node( - tag="h", - hiddenservice=1, - torrc="hidden-service.tmpl", - hiddenservicetarget="127.0.0.1:8081" -) + track_introduction_points(hs_nodes[0]) -initial_nodes.append(hs_node_1) + def hs_node_0_listener(logevent): + if "Successfully uploaded v2 rend descriptors" in logevent.message: + hs_nodes[0].getStemController().remove_event_listener(hs_node_0_listener) -hs_node_2 = Node( - tag="h", - hiddenservice=1, - torrc="hidden-service.tmpl", - hiddenservicetarget="127.0.0.1:8082" -) + hs_nodes[1].getController().start() -hs_nodes = (hs_node_1, hs_node_2) + track_introduction_points(hs_nodes[1]) -nodes_by_fingerprint = {} + def hs_node_1_listener(logevent): + if "Successfully uploaded v2 rend descriptors" in logevent.message: + hs_nodes[1].getStemController().remove_event_listener(hs_node_1_listener) -#{ nodenum: { circuit: "fingerprint", circuit: "fingerprint" } } + thread.start_new_thread(test_intro_failure, ()) + logging.info("out of node 1 listener") + + hs_nodes[1].getStemController().add_event_listener(hs_node_1_listener, EventType.INFO) + + hs_nodes[0].getStemController().add_event_listener(hs_node_0_listener, EventType.INFO) + +def test_intro_failure(): + connection_test() + + time.sleep(5) + + # Select a random node that is being used as an introduction point + nodenum = random.choice(node_intro_circuits.keys()) + fingerprint = random.choice(node_intro_circuits[nodenum].values()) + + node = nodes_by_fingerprint[fingerprint] + + logging.info("stopping " + node._env["nick"] + " (" + fingerprint + ")") + + node.getController().stop() + + logging.info("begining to watch for the establishment of new introduction points") + + changed = [False for n in hs_nodes] + + intro_points_before = [set(node_intro_circuits[n._env["nodenum"]].values()) for n in hs_nodes] + + time.sleep(90) + + intro_points_after = [set(node_intro_circuits[n._env["nodenum"]].values()) for n in hs_nodes] + + for i, node in enumerate(hs_nodes): + before = intro_points_before[i] + after = intro_points_after[i] + + if before != after: + changed[i] = True + + if all(changed): + logging.info("All changed") + else: + logging.info("All did not change") + + check_same_intro_points() + + connection_test() + + for server in hs_servers: + server.stopListening() + + reactor.stop() + logging.info("stopped the reactor") + + stop() + +def connection_test(): + logging.info("connecting to clients") + responses = {"0": 0, "1": 0} + + for c in client_nodes: + result = c.query("http://2oiifbe3wne4iaqb.onion/"); + + if result in responses: + responses[result] += 1 + else: + logging.info("Unknown response:") + + logging.info(str(responses)) + +## Utility Code # Introduction Point Tracking @@ -48,12 +165,13 @@ node_intro_circuits = {} node_intro_events = {} +# node_events + introduction_point_circuits = {} -from twisted.web import server, resource -from twisted.internet import reactor -from twisted.protocols import htb +nodes_by_fingerprint = {} +#{ nodenum: { circuit: "fingerprint", circuit: "fingerprint" } } def track_introduction_points(node): nodenum = node._env["nodenum"] @@ -73,13 +191,12 @@ def track_introduction_points(node): added_intro_node = nodes_by_fingerprint[fingerprint] - log("%s: added %s (%s)" % (nodenick, added_intro_node._env["nick"], fingerprint)) + logging.info("%s: added %s (%s)" % (nodenick, added_intro_node._env["nick"], fingerprint)) node_intro_events[nodenum].put(("added", fingerprint)) prefix = "rend_services_introduce(): Giving up on " if logevent.message.startswith(prefix) or "Giving up on" in logevent.message: - log(logevent.message) fingerprint = logevent.message[len(prefix):].split(" ")[0][1:41] for_deletion = [] @@ -90,21 +207,22 @@ def track_introduction_points(node): for_deletion.append(circuit) if len(for_deletion) == 0: - log("got log message " + logevent.message + " but not deleting an introduction point") + logging.info("got log message " + logevent.message + " but not deleting an introduction point") for circuit in for_deletion: fingerprint = node_intro_circuits[nodenum][circuit] removed_intro_node = nodes_by_fingerprint[fingerprint] - log("%s: removed %s (%s)" % (nodenick, removed_intro_node._env["nick"], fingerprint)) + logging.info("%s: removed %s (%s)" % (nodenick, removed_intro_node._env["nick"], fingerprint)) node_intro_events[nodenum].put(("removed", fingerprint)) del node_intro_circuits[nodenum][circuit] + logging.debug(nodenick + ": " + logevent.message) node.getStemController().add_event_listener(listener, EventType.INFO) - log("Tracking introduction points for " + node._env["nick"]) + logging.info("Tracking introduction points for " + node._env["nick"]) def track_introduction_point(node): nodenum = node._env["nodenum"] @@ -122,13 +240,13 @@ def track_introduction_point(node): added_intro_node = nodes_by_fingerprint[fingerprint] - log("%s: added %s (%s)" % (nodenick, added_intro_node._env["nick"], fingerprint)) + logging.info("%s: added %s (%s)" % (nodenick, added_intro_node._env["nick"], fingerprint)) node_intro_events[nodenum].put(("added", fingerprint)) prefix = "rend_services_introduce(): Giving up on " if logevent.message.startswith(prefix) or "Giving up on" in logevent.message: - log(logevent.message) + logging.info(logevent.message) fingerprint = logevent.message[len(prefix):].split(" ")[0][1:41] for_deletion = [] @@ -139,123 +257,85 @@ def track_introduction_point(node): for_deletion.append(circuit) if len(for_deletion) == 0: - log("got log message " + logevent.message + " but not deleting an introduction point") + logging.info("got log message " + logevent.message + " but not deleting an introduction point") for circuit in for_deletion: fingerprint = node_intro_circuits[nodenum][circuit] removed_intro_node = nodes_by_fingerprint[fingerprint] - log("%s: removed %s (%s)" % (nodenick, removed_intro_node._env["nick"], fingerprint)) + logging.info("%s: removed %s (%s)" % (nodenick, removed_intro_node._env["nick"], fingerprint)) node_intro_events[nodenum].put(("removed", fingerprint)) del node_intro_circuits[nodenum][circuit] node.getStemController().add_event_listener(listener, EventType.INFO) - log("Tracking introduction points for " + node._env["nick"]) - -# Use twisted to create web servers in this script -class Site(resource.Resource): - isLeaf = True - numberRequests = 0 - - def __init__(self, siteNum): - self.siteNum = siteNum - - def render_GET(self, request): - self.numberRequests += 1 - request.setHeader("content-type", "text/plain") - return str(self.siteNum) - -def start_test(): - log("Starting test") - - port8081 = reactor.listenTCP(8081, server.Site(Site(1))) - port8082 = reactor.listenTCP(8082, server.Site(Site(2))) - - def cleanup(): - port8081.stopListening() - log("stopped 8081") - port8082.stopListening() - log("stopped 8082") - reactor.stop() - log("stopped the reactor") + logging.info("Tracking introduction points for " + node._env["nick"]) - def watch_for_new_intro_points(): - log("begining to watch for the establishment of new introduction points") - changed = [False for n in hs_nodes] +def determine_max_load(service_url, clients): + request_queue = Queue.Queue(1000) + singlelock = threading.Lock() - intro_points_before = [set(node_intro_circuits[n._env["nodenum"]].values()) for n in hs_nodes] + responses = [] - time.sleep(60) + running = True - intro_points_after = [set(node_intro_circuits[n._env["nodenum"]].values()) for n in hs_nodes] + class worker(threading.Thread): + def __init__ (self, client): + super(worker, self).__init__() + self.client = client - for i, node in enumerate(hs_nodes): - before = intro_points_before[i] - after = intro_points_after[i] + def run(self): + while running: + try: + request = request_queue.get(True, 1) - if before != after: - changed[i] = True + print("making request") + result = self.client.query("http://2oiifbe3wne4iaqb.onion/"); - if all(changed): - log("All changed") - else: - log("All did not change") - - check_same_intro_points() - - connection_test() - - cleanup() - - stop() - - def connection_test(): - log("connecting to clients") - responses = {"1": 0, "2": 0} - - for c in Client: - result = c.query("http://2oiifbe3wne4iaqb.onion/"); - - if result in responses: - responses[result] += 1 - else: - log("Unknown response:") + singlelock.acquire() + responses.append((result, time.time())) + print("result " + str(result)) + singlelock.release() - log(responses) + # Let the queue know the job is finished. + request_queue.task_done() + except: + pass - def test(): - connection_test() + # Create worker threads + for client in clients: + worker(client).start() - time.sleep(5) + # Add elements to eueue at rate current_load + # Check size of queue, if above limit, return current_load - # Clear out the event queues such that the events are relevant - for node in hs_nodes: - nodenum = node._env["nodenum"] + while True: + # Determine Average Load + time_barrier = time.time() - 10.0 - log("replaced queue") - node_intro_events[nodenum] = Queue.Queue() + last_responses = [] - # Select a random node that is being used as an introduction point - nodenum = random.choice(node_intro_circuits.keys()) - fingerprint = random.choice(node_intro_circuits[nodenum].values()) + singlelock.acquire() + for response, response_time in reversed(responses): + if response_time < time_barrier: + break + last_responses.append(response) + singlelock.release() - node = nodes_by_fingerprint[fingerprint] + current_average_load = len(last_responses) / 10.0 + print("current average load %f" % current_average_load) - log("stopping " + node._env["nick"] + " (" + fingerprint + ")") + new_load = int(current_average_load) + 1 - node.getController().stop() + time_per_item = 1.0 / new_load - watch_for_new_intro_points() - - thread.start_new_thread(test, ()) - - log("running reactor") - - reactor.run(installSignalHandlers=0) + for i in range(new_load): + print("putting in item") + request_queue.put(1) + time.sleep(time_per_item) def check_same_intro_points(): intro_sets = [] @@ -263,52 +343,16 @@ def check_same_intro_points(): intro_sets.append(set(introduction_points.values())) if intro_sets[0].issubset(intro_sets[1]) and intro_sets[1].issubset(intro_sets[0]): - log("Same introduction points") + logging.info("Same introduction points") for fingerprint in node_intro_circuits.values()[0].values(): node = nodes_by_fingerprint[fingerprint] - log(" - " + node._env["nick"] + "(" + fingerprint + ")") + logging.info(" - " + node._env["nick"] + "(" + fingerprint + ")") return True else: - log("Not the same introduction points") + logging.info("Not the same introduction points") for num, circuits in node_intro_circuits.items(): - log("node %i" % num) + logging.info("node %i" % num) for fingerprint in circuits.values(): node = nodes_by_fingerprint[fingerprint] - log(" - " + node._env["nick"] + "(" + fingerprint + ")") - return False - -def start(): - log("Starting hidden service test") - - if not all([ n.getController().start() for n in initial_nodes ]): + logging.info(" - " + node._env["nick"] + "(" + fingerprint + ")") return False - - log("All initial nodes running") - - for n in Authority + Relay: - fingerprint = n.getStemController().get_info("fingerprint") - nodes_by_fingerprint[fingerprint] = n - - track_introduction_points(hs_node_1) - - def log_listener(logevent): - if "Successfully uploaded v2 rend descriptors" in logevent.message: - hs_node_1.getStemController().remove_event_listener(log_listener) - - def start_listener(logevent): - - # Probably after what needs waiting for - if "Successfully uploaded v2 rend descriptors" in logevent.message: - hs_node_2.getStemController().remove_event_listener(start_listener) - - if check_same_intro_points(): - thread.start_new_thread(start_test, ()) - log("finished running start_test in another thread") - - hs_node_2.getController().start() - - track_introduction_points(hs_node_2) - - hs_node_2.getStemController().add_event_listener(start_listener, EventType.INFO) - - hs_node_1.getStemController().add_event_listener(log_listener, EventType.INFO) diff --git a/networks/hs-intro-scale b/networks/hs-intro-scale index 50c5a37..2543b6d 100644 --- a/networks/hs-intro-scale +++ b/networks/hs-intro-scale @@ -134,7 +134,7 @@ node_intro_events = {} introduction_point_circuits = {} -nodes_by_fingerprint = {} +nodes_byefingerprint = {} #{ nodenum: { circuit: "fingerprint", circuit: "fingerprint" } } diff --git a/torrc_templates/common.i b/torrc_templates/common.i index 32fd0c6..c2d654d 100644 --- a/torrc_templates/common.i +++ b/torrc_templates/common.i @@ -7,6 +7,7 @@ ShutdownWaitLength 0 PidFile ${dir}/pid Log notice file ${dir}/notice.log Log info file ${dir}/info.log +Log debug file ${dir}/debug.log ProtocolWarnings 1 SafeLogging 0 ${authorities} -- cgit v1.2.3