restructure project slightly

testing.log

@@ -1,30 +0,0 @@
-2013-07-25 16:21:35,001 [stdout] PING localhost (127.0.0.1) 56(84) bytes of data.
-2013-07-25 16:21:35,001 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=1 ttl=64 time=0.017 ms
-2013-07-25 16:21:36,000 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=2 ttl=64 time=0.018 ms
-2013-07-25 16:21:37,000 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=3 ttl=64 time=0.019 ms
-2013-07-25 16:21:38,000 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=4 ttl=64 time=0.022 ms
-2013-07-25 16:21:38,000 [stdout] --- localhost ping statistics ---
-2013-07-25 16:21:38,000 [stdout] 4 packets transmitted, 4 received, 0% packet loss, time 2998ms
-2013-07-25 16:21:38,000 [stdout] rtt min/avg/max/mdev = 0.017/0.019/0.022/0.002 ms
-2013-07-25 16:22:41,579 [stdout] PING localhost (127.0.0.1) 56(84) bytes of data.
-2013-07-25 16:22:41,579 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=1 ttl=64 time=0.018 ms
-2013-07-25 16:22:42,578 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=2 ttl=64 time=0.015 ms
-2013-07-25 16:22:43,577 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=3 ttl=64 time=0.026 ms
-2013-07-25 16:22:44,577 [stdout] 64 bytes from localhost (127.0.0.1): icmp_req=4 ttl=64 time=0.026 ms
-2013-07-25 16:22:44,577 [stdout] --- localhost ping statistics ---
-2013-07-25 16:22:44,577 [stdout] 4 packets transmitted, 4 received, 0% packet loss, time 2998ms
-2013-07-25 16:22:44,577 [stdout] rtt min/avg/max/mdev = 0.015/0.021/0.026/0.005 ms
-2013-07-25 16:23:14,577 [heartbeat]
-2013-07-25 16:25:04,155 [stderr] Usage: ping [-LRUbdfnqrvVaAD] [-c count] [-i interval] [-w deadline]
-2013-07-25 16:25:04,155 [stderr]             [-p pattern] [-s packetsize] [-t ttl] [-I interface]
-2013-07-25 16:25:04,155 [stderr]             [-M pmtudisc-hint] [-m mark] [-S sndbuf]
-2013-07-25 16:25:04,155 [stderr]             [-T tstamp-options] [-Q tos] [hop1 ...] destination
-2013-07-25 16:38:37,987 [stderr] Usage: ping [-LRUbdfnqrvVaAD] [-c count] [-i interval] [-w deadline]
-2013-07-25 16:38:37,987 [stderr]             [-p pattern] [-s packetsize] [-t ttl] [-I interface]
-2013-07-25 16:38:37,987 [stderr]             [-M pmtudisc-hint] [-m mark] [-S sndbuf]
-2013-07-25 16:38:37,987 [stderr]             [-T tstamp-options] [-Q tos] [hop1 ...] destination
-2013-07-25 16:43:17,558 [stderr] Usage: ping [-LRUbdfnqrvVaAD] [-c count] [-i interval] [-w deadline]
-2013-07-25 16:43:17,558 [stderr]             [-p pattern] [-s packetsize] [-t ttl] [-I interface]
-2013-07-25 16:43:17,558 [stderr]             [-M pmtudisc-hint] [-m mark] [-S sndbuf]
-2013-07-25 16:43:17,558 [stderr]             [-T tstamp-options] [-Q tos] [hop1 ...] destination
-2013-07-25 16:43:17,558 [script exit code = 2]

turbo_hipster/lib/utils.py

@@ -97,7 +97,8 @@ def execute_to_log(cmd, logfile, timeout=-1,
         os.lseek(fd, 0, os.SEEK_END)
         descriptors[fd] = dict(
             name=watch_file[0],
-            poll=select.POLLIN
+            poll=select.POLLIN,
+            lines=''
         )
 
     cmd += ' 2>&1'
@@ -106,11 +107,7 @@ def execute_to_log(cmd, logfile, timeout=-1,
         cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
 
     descriptors[p.stdout.fileno()] = dict(
-        name='[stdout]',
+        name='[output]',
-        poll=(select.POLLIN | select.POLLHUP)
-    )
-    descriptors[p.stderr.fileno()] = dict(
-        name='[stderr]',
         poll=(select.POLLIN | select.POLLHUP)
     )
 
@@ -120,6 +117,21 @@ def execute_to_log(cmd, logfile, timeout=-1,
 
     last_heartbeat = time.time()
 
+    def process(fd):
+        """ Write the fd to log """
+        descriptors[fd]['lines'] += os.read(fd, 1024 * 1024)
+        # Avoid partial lines by only processing input with breaks
+        if lines[fd].find('\n') != -1:
+            elems = descriptors[fd]['lines'].split('\n')
+            # Take all but the partial line
+            for l in elems[:-1]:
+                if len(l) > 0:
+                    l = '%s %s' % (descriptors[fd]['name'], l)
+                    logger.info(l)
+                    last_heartbeat = time.time()
+            # Place the partial line back into lines to be processed
+            descriptors[fd]['lines'] = elems[-1]
+
     while p.poll() is None:
         if timeout > 0 and time.time() - start_time > timeout:
             # Append to logfile
@@ -127,16 +139,15 @@ def execute_to_log(cmd, logfile, timeout=-1,
             os.kill(p.pid, 9)
 
         for fd, flag in poll_obj.poll(0):
-            lines = os.read(fd, 1024 * 1024)
+            process(fd)
-            for l in lines.split('\n'):
-                if len(l) > 0:
-                    l = '%s %s' % (descriptors[fd]['name'], l)
-                    logger.info(l)
-                    last_heartbeat = time.time()
 
         if time.time() - last_heartbeat > 30:
             # Append to logfile
             logger.info("[heartbeat]")
             last_heartbeat = time.time()
 
+    # Do one last write to get the remaining lines
+    for fd, flag in poll_obj.poll(0):
+        process(fd)
+
     logger.info('[script exit code = %d]' % p.returncode)