storyboard: add logging and log retrieval

5 files changed, 156 insertions, 87 deletions

diff --git a/examples/example.py b/examples/example.py
index 8d17ff2..a26ab3b 100755
--- a/examples/example.py
+++ b/examples/example.py
@@ -30,26 +30,55 @@ n1.add_policy("security-manager", "passwd")
 e1 = ShimEthDIF("e1")
 
 a = Node("a",
-         difs = [n1, e1],
-         dif_registrations = {n1 : [e1]})
+         difs=[n1, e1],
+         dif_registrations={n1: [e1]})
 
 b = Node("b",
-         difs = [e1, n1],
-         dif_registrations = {n1 : [e1]})
+         difs=[e1, n1],
+         dif_registrations={n1: [e1]})
 
-tb = jfed.Testbed(exp_name = "example1",
-                  username = "user1",
-                  cert_file = "/home/user1/cert.pem")
+tb = jfed.Testbed(exp_name="example1",
+                  username="user1",
+                  cert_file="/home/user1/cert.pem")
+
+exp = rl.Experiment(tb, nodes=[a, b])
+
+print(exp)
+
+# General setup (can be reused in other scripts as-is)
+storyboard = StoryBoard(duration=30)
+
+# Clients can be applications that just keep running, and will be
+# stopped by a SIGINT...
+client1 = Client("rinaperf",
+                 options="-t perf -s 1000 -c 0")
+
+# ... or a custom shutdown method can be provided.
+client2 = Client("rinaperf",
+                 options="-t perf -s 1000 -D <duration>",
+                 shutdown="")
+
+server = Server("rinaperf", options="-l", arrival_rate=0.5,
+                mean_duration=5, clients=[client1, client2])
+
+
+# Experiment-specific configuration:
+# (This can be done anytime before storyboard.start())
+
+storyboard.set_experiment(exp)
+storyboard.add_server((server, a))
+client1.add_node(b)
+client2.add_node(b)
 
-exp = rl.Experiment(tb, nodes = [a, b])
 
 print(exp)
 
 with ExperimentManager(exp):
     exp.swap_in()
+    exp.install_prototype()
     exp.bootstrap_prototype()
-    c1 = Client("rinaperf", options ="-t perf -s 1000 -c 0", nodes=[b])
-    s1 = Server("rinaperf", arrival_rate=2, mean_duration=5,
-                options = "-l", nodes = [a], clients = [c1])
-    sb = StoryBoard(duration=3600, experiment=exp, servers=[s1])
-    sb.start()
+    storyboard.start()
+
+    # Fetch the client/server logs from the nodes
+    # and put them in the cwd.
+    storyboard.fetch_logs()
diff --git a/examples/rinaperf_sb-usage.py b/examples/rinaperf_sb-usage.py
deleted file mode 100644
index 0e7ca72..0000000
--- a/examples/rinaperf_sb-usage.py
+++ /dev/null
@@ -1,58 +0,0 @@
-#!/usr/bin/env python
-
-from rumba.model import *
-from rumba.storyboard import *
-import rumba.testbeds.qemu as qemu
-import rumba.prototypes.irati as irati
-import rumba.log as log
-from rumba.utils import ExperimentManager
-
-log.set_logging_level('DEBUG')
-
-
-n1 = NormalDIF("n1")
-
-n1.add_policy("rmt.pff", "lfa")
-n1.add_policy("security-manager", "passwd")
-
-e1 = ShimEthDIF("e1")
-
-a = Node("a",
-         difs=[n1, e1],
-         dif_registrations={n1: [e1]})
-
-b = Node("b",
-         difs=[e1, n1],
-         dif_registrations={n1: [e1]})
-
-tb = qemu.Testbed(exp_name="example1",
-                  username="root",
-                  password="root")
-
-exp = irati.Experiment(tb, nodes=[a, b])
-
-
-# General setup (can be reused in other scripts as-is)
-storyboard = StoryBoard(duration=30)
-client = Client("rinaperf",
-                options="-t perf -s 1000 -D <duration>",
-                shutdown="")
-server = Server("rinaperf", options="-l", arrival_rate=0.5,
-                mean_duration=5, clients=[client])
-
-
-# Experiment-specific configuration:
-# (This can be done anytime before storyboard.start())
-
-storyboard.set_experiment(exp)
-storyboard.add_server((server, a))
-client.add_node(b)
-
-
-print(exp)
-
-with ExperimentManager(exp):
-    exp.swap_in()
-    exp.bootstrap_prototype()
-    storyboard.start()
-    input('ENTER')
diff --git a/rumba/model.py b/rumba/model.py
index 7a68459..7573df2 100644
--- a/rumba/model.py
+++ b/rumba/model.py
@@ -370,12 +370,20 @@ class Node:
             destination
         )
 
-    def setup_vlan(self, vlan_id, int_name):
-        ssh_support.setup_vlan(
+    def fetch_files(self, paths, destination):
+        ssh_support.copy_files_from_testbed(
             self.ssh_config,
             self.ssh_config,
-            vlan_id,
-            int_name
+            paths,
+            destination
+        )
+
+    def fetch_file(self, path, destination):
+        ssh_support.copy_file_from_testbed(
+            self.ssh_config,
+            self.ssh_config,
+            path,
+            destination
         )
 
 
diff --git a/rumba/ssh_support.py b/rumba/ssh_support.py
index fbe68c8..1a065c6 100644
--- a/rumba/ssh_support.py
+++ b/rumba/ssh_support.py
@@ -26,6 +26,7 @@
 
 import os
 import paramiko
+import re
 import time
 
 import rumba.log as log
@@ -53,12 +54,15 @@ def get_ssh_client():
 def _print_stream(stream):
         o = str(stream.read()).strip('b')
         o = o.strip('\'\"')
-        o = o.replace('\\n', '')
+        o = o.rstrip()
+        o = re.sub(r'(\\n)*$', '', o)
         if o != "":
             o_array = o.split('\\n')
             for oi in o_array:
                 logger.debug(oi)
-        return o.rstrip()
+        else:
+            o_array = []
+        return '\n'.join(o_array)
 
 def ssh_connect(hostname, port, username, password, time_out, proxy_server):
     logger.debug('Trying to open a connection towards node %s.' % hostname)
@@ -300,6 +304,55 @@ def copy_file_to_testbed(testbed, ssh_config, path, destination):
     copy_files_to_testbed(testbed, ssh_config, [path], destination)
 
 
+def copy_files_from_testbed(testbed, ssh_config, paths, destination):
+    """
+    Copies local files to a remote node.
+
+    @param testbed: testbed info
+    @param ssh_config: ssh config of the node
+    @param paths: source paths (remote) as an iterable
+    @param destination: destination folder name (local)
+    """
+    if destination is not '' and not destination.endswith('/'):
+        destination = destination + '/'
+
+    if ssh_config.client is None:
+        client, proxy_client = ssh_connect(ssh_config.hostname, ssh_config.port,
+                                           testbed.username, testbed.password,
+                                           None, ssh_config.proxy_server)
+        ssh_config.client = client
+        ssh_config.proxy_client = proxy_client
+
+    try:
+        sftp_client = ssh_config.client.open_sftp()
+
+        for path in paths:
+            file_name = os.path.basename(path)
+            dest_file = destination + file_name
+            logger.debug("Copying %s to %s@%s:%s path %s" % (
+                path,
+                testbed.username,
+                ssh_config.hostname,
+                ssh_config.port,
+                dest_file))
+            sftp_client.get(path, dest_file)
+
+    except Exception as e:
+        raise SSHException('Failed to copy files from testbed', e)
+
+
+def copy_file_from_testbed(testbed, ssh_config, path, destination):
+    """
+    Copies a local file to a remote node.
+
+    @param testbed: testbed info
+    @param ssh_config: ssh config of the node
+    @param path: source path (remote)
+    @param destination: destination folder name (local)
+    """
+    copy_files_from_testbed(testbed, ssh_config, [path], destination)
+
+
 def setup_vlans(testbed, node, vlans):
     """
     Gets the interface (ethx) to link mapping
diff --git a/rumba/storyboard.py b/rumba/storyboard.py
index 52bd875..4a09ac8 100644
--- a/rumba/storyboard.py
+++ b/rumba/storyboard.py
@@ -5,6 +5,7 @@
 #    Copyright (C) 2017 imec
 #
 #    Sander Vrijders   <sander.vrijders@ugent.be>
+#    Dimitri Staessens <dimitri.staessens@ugent.be>
 #    Vincenzo Maffione <v.maffione@nextworks.it>
 #    Marco Capitani    <m.capitani@nextworks.it>
 #
@@ -23,11 +24,12 @@
 # Foundation, Inc., http://www.fsf.org/about/contact/.
 #
 
-# Base class for client programs
+# Base class for client apps
 #
 # @ap: Application Process binary
 # @options: Options to pass to the binary
 #
+import os
 import random
 import time
 
@@ -50,6 +52,14 @@ except ImportError:
     logger.debug("Falling back to simple implementations.")
     # PROBLEM! These logs will almost never be printed... But we might not care
 
+current_id = -1
+
+
+def get_id():
+    global current_id
+    current_id += 1
+    return current_id
+
 
 class Client(object):
     def __init__(self, ap, nodes=None, options=None, shutdown="kill <pid>"):
@@ -69,7 +79,7 @@ class Client(object):
 
     def process(self, duration):
         node = random.choice(self.nodes) if len(self.nodes) > 0 else None
-        return ClientProcess(self.ap, self.startup, duration, node, self.shutdown)
+        return ClientProcess(get_id(), self.ap, self.startup, duration, node, self.shutdown)
 
 
 # Base class for client processes
@@ -80,8 +90,9 @@ class Client(object):
 # @options: Options to pass to the binary
 #
 class ClientProcess(object):
-    def __init__(self, ap, startup, duration,
+    def __init__(self, client_id, ap, startup, duration,
                  node=None, shutdown="<kill <pid>"):
+        self.id = client_id
         self.ap = ap
         self.startup = startup
         self.duration = duration
@@ -103,7 +114,9 @@ class ClientProcess(object):
             self.ap, self.node.name, self.duration
         )
 
-        start_cmd = "./startup.sh %s" % (
+        start_cmd = "./startup.sh %s_%s %s" % (
+            self.ap,
+            self.id,
             self.startup.replace("<duration>", str(self.duration)),
         )
         self.running = True
@@ -209,11 +222,11 @@ class Server:
     def run(self):
         for node in self.nodes:
             logfile = "%s_server.log" % self.ap
-            script = r'nohup "$@" > %s & echo "$!"' % (logfile,)
+            script = r'nohup "$@" > %s 2>&1 & echo "$!"' % (logfile,)
             run_cmd = self.ap + (
                 (" " + self.options) if self.options is not None else ""
             )
-            cmd_1 = "echo '%s' > startup.sh && chmod a+x startup.sh && cat startup.sh" \
+            cmd_1 = "echo '%s' > startup.sh && chmod a+x startup.sh" \
                     % (script,)
             cmd_2 = "./startup.sh %s" % (run_cmd,)
             logger.debug(
@@ -223,7 +236,6 @@ class Server:
             try:
                 node.execute_command(cmd_1)
                 self.pids[node] = (node.execute_command(cmd_2))
-                node.execute_command("cat startup.sh")
             except ssh_support.SSHException:
                 logger.warn('Could not start server %s on node %s.',
                             self.ap, node.name)
@@ -269,7 +281,8 @@ class StoryBoard:
                              "setting the experiment.")
         if hasattr(s, '__len__') and len(s) == 2:
             server, node = s
-            if not isinstance(server, Server) or not isinstance(node, model.Node):
+            if not isinstance(server, Server) \
+                    or not isinstance(node, model.Node):
                 raise TypeError('First element must be of "Server" type, '
                                 'second must be of "Node" type.')
             server.add_node(node)
@@ -297,13 +310,15 @@ class StoryBoard:
 
     def start(self):
         self.start_time = time.time()
-        script = r'nohup "$@" > /tmp/$1 & echo "$!"'
+        script = r'logname="$1"; shift; nohup "${@}" ' \
+                 r'> /tmp/${logname}.rumba.log 2>&1  & echo "$!"'
         logger.debug("Writing utility startup script on client nodes.")
         for server in self.servers:
             for client in server.clients:
                 for node in client.nodes:
                     node.execute_command(
-                        "echo '%s' > startup.sh && chmod a+x startup.sh" % (script,)
+                        "echo '%s' > startup.sh && chmod a+x startup.sh"
+                        % (script,)
                     )
         try:
             for server in self.servers:
@@ -325,3 +340,25 @@ class StoryBoard:
                 client.stop()
             for server in self.servers:
                 server.stop()
+
+    def fetch_logs(self, local_dir='.'):
+        if not os.path.isdir(local_dir):
+            raise Exception('"%s" is not a directory. Cannot fetch logs.'
+                            % local_dir)
+        server_nodes = set()
+        client_nodes = set()
+        for server in self.servers:
+            for node in server.nodes:
+                server_nodes.add(node)
+            for client in server.clients:
+                for node in client.nodes:
+                    client_nodes.add(node)
+        for node in server_nodes:
+            logs_list = node.execute_command('ls *_server.log')
+            logger.info('Log list is:\n%s', logs_list)
+            node.fetch_files(logs_list.split('\n'), local_dir)
+        for node in client_nodes:
+            logs_list = node.execute_command('ls /tmp/*.rumba.log '
+                                             '|| echo ""')
+            logger.info('Log list is:\n%s', logs_list)
+            node.fetch_files(logs_list.split('\n'), local_dir)