Merge lp:~nuclearbob/utah/rsyslog-client into lp:utah

[Max Brustkern]

This branch adds syslog output on the LOCAL0 facility to the client. I'd like to add server-side code to use and process this output, but that's not done yet, and I'd like to get some other thoughts on the client-side design and implementation before I proceed.

[lp:~nuclearbob/utah/rsyslog-client]

862. By Max Brustkern on 2013-04-16

Merged iso squashfs validation update

[Andy Doan (doanac)]

On 04/15/2013 03:49 PM, Max Brustkern wrote:

> https://code.launchpad.net/~nuclearbob/utah/rsyslog-client/+merge/159015

> === modified file 'client.py'
> if not os.getuid() == 0:
> parser.print_usage()
> - sys.stderr.write('{}: UTAH client is expected '
> - 'to be executed as root user\n'
> - .format(parser.prog))
> + msg = ('{}: UTAH client is expected to be executed as root user\n'
> + .format(parser.prog))
> + sys.stderr.write(msg)
> + syslog.syslog(syslog.LOG_ERR, msg)

is the "\n" going to make the syslog stuff look/act weird?

> === modified file 'utah/client/common.py'
> --- utah/client/common.py 2013-04-08 19:16:05 +0000

> - p = subprocess.Popen("{} {}".format(cmd_prefix, command),
> - shell=True, cwd=cwd,
> - stdout=subprocess.PIPE, stderr=subprocess.PIPE)
> + p = subprocess.Popen(cmd, shell=True, cwd=cwd, stdout=subprocess.PIPE,
> + stderr=subprocess.PIPE)
>
> if timeout != 0:
> signal.signal(signal.SIGALRM, alarm_handler)
> signal.alarm(timeout)
>
> + stdout = []
> + stderr = []

This seems inefficient. Why not use cStringIO? Then you won't have to do
the '\n'.join(...) at the end of the function.

> try:
> - stdout, stderr = p.communicate()
> - stdout = _normalize_encoding(stdout)
> - stderr = _normalize_encoding(stderr)
> + while p.poll() is None:

Is this a safe way to deal with a process? The concern I have is that
stdout might be blocked, but there is data on stderr that needs to be
read and we sit blocked? I think we might want to make this a "select"
type look on stdout/stderr fd's.

> + stdout_tmp = _normalize_encoding(p.stdout.readline().strip())
> + stderr_tmp = _normalize_encoding(p.stderr.readline().strip())
> + syslog.syslog(stdout_tmp)
> + syslog.syslog(stderr_tmp)
> + stdout.append(stdout_tmp)
> + stderr.append(stderr_tmp)
>
> if timeout != 0:
> signal.alarm(0)

[Max Brustkern (nuclearbob)]

> On 04/15/2013 03:49 PM, Max Brustkern wrote:
>
> ...
>
> is the "\n" going to make the syslog stuff look/act weird?

Not sure, but I can check.

>
> ...
>
> This seems inefficient. Why not use cStringIO? Then you won't have to do
> the '\n'.join(...) at the end of the function.

The only time I tried to use cStringIO it turned into a horrible mess that didn't work, so I haven't really looked at it again since then. If you think it's a good fit for here, I think something better than what I've got would be nice. I can try that.

>
> > try:
> > - stdout, stderr = p.communicate()
> > - stdout = _normalize_encoding(stdout)
> > - stderr = _normalize_encoding(stderr)
> > + while p.poll() is None:
>
> Is this a safe way to deal with a process? The concern I have is that
> stdout might be blocked, but there is data on stderr that needs to be
> read and we sit blocked? I think we might want to make this a "select"
> type look on stdout/stderr fd's.

I should look up the "select" thing, since I'm not familiar with it. I'm learning lots of things today! We used to do basically this as part of the vm-tools integration, and it worked fine, but that's no guarantee it couldn't fail here.

[lp:~nuclearbob/utah/rsyslog-client]

863. By Javier Collado on 2013-04-17

Merged documentation string fixes

Source branch: lp:~javier.collado/utah/documentation_fixes

864. By Javier Collado on 2013-04-17

Merged changes to validate master runlist before provisioning (LP: #1082087)

Source branch: lp:~javier.collado/utah/bug1082087

[Max Brustkern (nuclearbob)]

> On 04/15/2013 03:49 PM, Max Brustkern wrote:
>
> > https://code.launchpad.net/~nuclearbob/utah/rsyslog-client/+merge/159015
>
> > === modified file 'client.py'
> > if not os.getuid() == 0:
> > parser.print_usage()
> > - sys.stderr.write('{}: UTAH client is expected '
> > - 'to be executed as root user\n'
> > - .format(parser.prog))
> > + msg = ('{}: UTAH client is expected to be executed as root user\n'
> > + .format(parser.prog))
> > + sys.stderr.write(msg)
> > + syslog.syslog(syslog.LOG_ERR, msg)
>
> is the "\n" going to make the syslog stuff look/act weird?
>
It looks okay to me:
Apr 17 09:09:42 eden utah: client.py: UTAH client is expected to be executed as root user
Apr 17 09:09:48 eden utah: client.py: UTAH client is expected to be executed as root user
Apr 17 09:10:04 eden utah: Fetching testsuite: utah_tests_sample

I'm going to work on the other things.

[Max Brustkern (nuclearbob)]

I switched to StringIO and pushed that. As for subprocess stuff, what do you think about something like this:
http://stackoverflow.com/questions/375427/non-blocking-read-on-a-subprocess-pipe-in-python

[Andy Doan (doanac)]

On 04/17/2013 12:45 PM, Max Brustkern wrote:
> As for subprocess stuff, what do you think about something like this:
> http://stackoverflow.com/questions/375427/non-blocking-read-on-a-subprocess-pipe-in-python

that stinks. in C a pipe is normal FD and you can do select stuff. I
guess threads are the way to go.

[lp:~nuclearbob/utah/rsyslog-client]

865. By Javier Collado on 2013-04-18

Fix broken build

The package build is broken because a weird exception:
RuntimeError: sys.path must be a list of directory names

Looking in python source code I see this change:
http://hg.python.org/cpython/rev/c9bb16b7d148

that indeed changes what it was an ImportError to a RuntimeError. However, it's
not clear why PyList_Check(path) is failing because I'm pretty sure that
sys.path is a list (I even tried to filter it with os.path.isdir). Hence, I
guess that path in that code isn't really sys.path under some circumstances.

Anyway, catching that exception and handling it the same way as ImportError
works fine.

[Max Brustkern (nuclearbob)]

I implemented the thread and queue method and tested it. The script I use always sends stdout before stderr, but in the output if this, sometimes the stderr comes before the stdout. I don't know how big of a problem that is, or whether there's a reasonable thing to do about it that doesn't potentially allow one buffer to fill up while waiting on the other one. The stdout and stderr in the yaml at the end do come out right.

review: Needs Resubmitting

[lp:~nuclearbob/utah/rsyslog-client]

875. By Max Brustkern on 2013-04-17

Using StringIO instead of arrays

876. By Max Brustkern on 2013-04-18

Using threads and queues to read process output; this seems like something we could use a generalized function, but I don't see anywhere else we need it right now

[Andy Doan (doanac)]

review: Approve

=== modified file 'client.py'
--- client.py	2013-04-04 13:13:34 +0000
+++ client.py	2013-04-18 18:26:24 +0000
@@ -21,6 +21,7 @@
 import logging
 import platform
 import sys
+import syslog
 import os
 
 from utah.url import url_argument
@@ -88,6 +89,8 @@
 
 
 def main():
+    syslog.openlog('utah', 0, syslog.LOG_LOCAL0)
+
     """Interpret command line arguments and run tests."""
     # TODO: write <2.7 optparse version and set based on version of python
     #       being used.
@@ -96,9 +99,10 @@
 
     if not os.getuid() == 0:
         parser.print_usage()
-        sys.stderr.write('{}: UTAH client is expected '
-                         'to be executed as root user\n'
-                         .format(parser.prog))
+        msg = ('{}: UTAH client is expected to be executed as root user\n'
+               .format(parser.prog))
+        sys.stderr.write(msg)
+        syslog.syslog(syslog.LOG_ERR, msg)
         sys.exit(ReturnCodes.INVALID_USER)
 
     setup_logging(args.debug)
@@ -131,6 +135,7 @@
             sys.stdout = open(output, open_flags)
         except IOError as e:
             sys.stderr.write(str(e))
+            syslog.syslog(syslog.LOG_ERR, str(e))
             sys.exit(ReturnCodes.EXCEPTION_ERROR)
     if args.format == 'text':
         result_class = Result
@@ -152,6 +157,7 @@
 
     except UTAHClientError as e:
         sys.stderr.write(str(e))
+        syslog.syslog(syslog.LOG_ERR, str(e))
         sys.exit(ReturnCodes.EXCEPTION_ERROR)
 
     sys.exit(returncode)

=== modified file 'debian/changelog'
--- debian/changelog	2013-04-17 08:26:37 +0000
+++ debian/changelog	2013-04-18 18:26:24 +0000
@@ -4,6 +4,9 @@
   * Check squashfs on the server images as well during ISO static
     validation.
 
+  [ Max Brustkern ]
+  * Added syslog output (including real time test output) to client
+
  -- Max Brustkern <[e-mail]>  Tue, 16 Apr 2013 09:21:19 -0400
 
 utah (0.10ubuntu1) UNRELEASED; urgency=low

=== modified file 'utah/client/common.py'
--- utah/client/common.py	2013-04-08 19:16:05 +0000
+++ utah/client/common.py	2013-04-18 18:26:24 +0000
@@ -24,8 +24,13 @@
 import re
 import signal
 import subprocess
+import syslog
 import time
 
+from Queue import Queue, Empty
+from StringIO import StringIO
+from threading import Thread
+
 import jsonschema
 import yaml
 
@@ -108,6 +113,14 @@
     """
 
 
+# Process queue stuff inspired by:
+# http://stackoverflow.com/a/4896288
+def enqueue_output(out, queue):
+    for line in iter(out.readline, b''):
+        queue.put(line)
+    out.close()
+
+
 # Inspired by:
 # http://stackoverflow.com/a/3326559
 def run_cmd(command, cwd=None, timeout=0, cmd_type=CMD_TC_TEST, run_as=None,
@@ -166,19 +179,43 @@
     if battery_measurements:
         start_battery = battery.get_data()
 
+    cmd = '{} {}'.format(cmd_prefix, command)
+    syslog.syslog('Running command: {}'.format(cmd))
+
+    stdout = StringIO()
+    stderr = StringIO()
+    outq = Queue()
+    errq = Queue()
+
     start_time = datetime.datetime.now()
-    p = subprocess.Popen("{} {}".format(cmd_prefix, command),
-                         shell=True, cwd=cwd,
-                         stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+    p = subprocess.Popen(cmd, shell=True, cwd=cwd, stdout=subprocess.PIPE,
+                         stderr=subprocess.PIPE)
 
     if timeout != 0:
         signal.signal(signal.SIGALRM, alarm_handler)
         signal.alarm(timeout)
 
+    outt = Thread(target=enqueue_output, args=(p.stdout, outq))
+    outt.daemon = True
+    outt.start()
+    errt = Thread(target=enqueue_output, args=(p.stderr, errq))
+    errt.daemon = True
+    errt.start()
+
     try:
-        stdout, stderr = p.communicate()
-        stdout = _normalize_encoding(stdout)
-        stderr = _normalize_encoding(stderr)
+        while p.poll() is None:
+            try:
+                stdout_tmp = _normalize_encoding(outq.get_nowait())
+                syslog.syslog(stdout_tmp)
+                stdout.write(stdout_tmp)
+            except Empty:
+                pass
+            try:
+                stderr_tmp = _normalize_encoding(errq.get_nowait())
+                syslog.syslog(stderr_tmp)
+                stderr.write(stderr_tmp)
+            except Empty:
+                pass
 
         if timeout != 0:
             signal.alarm(0)
@@ -209,10 +246,15 @@
 
     time_delta = datetime.datetime.now() - start_time
 
+    if p.returncode:
+        syslog.syslog(syslog.LOG_ERR,
+                      'Process exited with non-zero return code: {}'
+                      .format(p.returncode))
+
     kwargs = {'command': command,
               'retcode': p.returncode,
-              'stdout': stdout,
-              'stderr': stderr,
+              'stdout': stdout.getvalue(),
+              'stderr': stderr.getvalue(),
               'start_time': start_time.strftime(DATE_FORMAT),
               'time_delta': str(time_delta),
               'cmd_type': cmd_type,

=== modified file 'utah/client/runner.py'
--- utah/client/runner.py	2013-04-04 15:04:43 +0000
+++ utah/client/runner.py	2013-04-18 18:26:24 +0000
@@ -22,6 +22,7 @@
 import shutil
 import stat
 import subprocess
+import syslog
 import urllib
 
 from utah.client import exceptions
@@ -308,6 +309,7 @@
                     # Return success despite of the results
                     # to let server know that it has to check the state file
                     # to know the final result after the reboot
+                    syslog.syslog('REBOOT: Test case requested reboot')
                     return ReturnCodes.REBOOT
 
             self.errors += suite.errors
@@ -530,6 +532,7 @@
                 return result
 
             if name not in self.fetched_suites:
+                syslog.syslog('Fetching testsuite: {}'.format(name))
                 # Retry bzr export on http errors for 60 seconds
                 res = timeout(60, retry, vcs_get_retriable)
                 self.result.add_result(res)
@@ -623,8 +626,12 @@
     def returncode(self):
         """Provide return code based on test status."""
         if self.errors > 0 or self.fetch_errors > 0:
+            syslog.syslog(syslog.LOG_ERR,
+                          'ERROR: Errors encountered during testing')
             return ReturnCodes.ERROR
         elif self.failures > 0:
+            syslog.syslog(syslog.LOG_ERR, 'FAIL: Not all tests passed')
             return ReturnCodes.FAIL
         else:
+            syslog.syslog('PASS: All tests passed')
             return ReturnCodes.PASS

=== modified file 'utah/client/testcase.py'
--- utah/client/testcase.py	2013-04-08 19:12:25 +0000
+++ utah/client/testcase.py	2013-04-18 18:26:24 +0000
@@ -17,6 +17,7 @@
 
 
 import os
+import syslog
 
 import jsonschema
 
@@ -170,6 +171,7 @@
         """Run build, but only if we haven't started a run yet."""
         if self.status == 'NOTRUN':
             self.set_status('BUILD')
+            syslog.syslog('Testcase {} build'.format(self.name))
             cmd_result = run_cmd(
                 self.build_cmd,
                 cwd=self.working_dir,
@@ -181,6 +183,7 @@
         """Run tc_setup, but only if build() has just passed."""
         if self.status == 'BUILD' and result.status == 'PASS':
             self.set_status('SETUP')
+            syslog.syslog('Testcase {} setup'.format(self.name))
             cmd_result = run_cmd(
                 self.tc_setup,
                 cwd=self.working_dir,
@@ -192,6 +195,7 @@
         """Run tc_cleanup after a run."""
         if self.status == 'RUN':
             self.set_status('CLEANUP')
+            syslog.syslog('Testcase {} cleanup'.format(self.name))
             cmd_result = run_cmd(
                 self.tc_cleanup,
                 cwd=self.working_dir,
@@ -256,6 +260,7 @@
                 'action': self.action,
                 'expected_results': self.expected_results,
             }
+            syslog.syslog('Testcase {} run'.format(self.name))
             cmd_result = run_cmd(
                 self.command,
                 timeout=timeout,

=== modified file 'utah/client/testsuite.py'
--- utah/client/testsuite.py	2013-04-04 15:09:51 +0000
+++ utah/client/testsuite.py	2013-04-18 18:26:24 +0000
@@ -18,6 +18,7 @@
 
 import jsonschema
 import os
+import syslog
 import yaml
 
 from utah.client import exceptions
@@ -204,6 +205,7 @@
         """Run build, but only if we haven't started a run yet."""
         if self.status == 'NOTRUN':
             self.set_status('BUILD')
+            syslog.syslog('Testsuite {} build'.format(self.name))
             cmd_result = run_cmd(
                 self.build_cmd,
                 cwd=self.name,
@@ -215,6 +217,7 @@
         """Run ts_setup, but only if build() has just passed."""
         if self.status == 'BUILD' and result.status == 'PASS':
             self.set_status('SETUP')
+            syslog.syslog('Testsuite {} setup'.format(self.name))
             cmd_result = run_cmd(
                 self.ts_setup,
                 cwd=self.name,
@@ -226,6 +229,7 @@
         """Run ts_cleanup after a run."""
         if self.status == 'INPROGRESS':
             self.set_status('CLEANUP')
+            syslog.syslog('Testsuite {} cleanup'.format(self.name))
             cmd_result = run_cmd(
                 self.ts_cleanup,
                 cwd=self.name,