Logging improvements

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}