Merge lp:~ltrager/maas/combined_script_output into lp:~maas-committers/maas/trunk

[Lee Trager]

Capture stdout, stderr, and the combined output of all scripts run.

maas-run-remote-scripts now captures stdout, stderr, and the combined output as three separate files. The metadataservice has been modified to allow uploading and storing all three files in the ScriptResult model. Uploaded files ending in .err will be stored as the ScriptResult's stderr output, files ending in .out will be stored as the ScriptResult's stdout output, all other files will be stored as the ScriptResult's combined output.

This also fixes 1664285 to return results base64 encoded and 1665478 to show the status as testing.

[Gavin Panella (allenap)]

All looks okay, but there needs to be a test that shows we're dealing with the problematic behaviour you saw with dhclient.

review: Needs Fixing

[Lee Trager (ltrager)]

Thanks for the review I've added a test which forks sleep for 20s and makes sure it doesn't block.

[Blake Rouse (blake-rouse)]

It might be a good idea to run a set of builtin scripts as tests as well. That way we are 100% sure our builtin tests dont regress.

[Gavin Panella (allenap)]

> finished_writing_pipes is needed for two reasons. First if the script
> doesn't output anything we never get a zero byte chunk so the loop
> never exists. Adding proc.poll() fixes that but I found the loop would
> often exit while data was still coming in. So all tests ran but the
> lshw result was incomplete. I've added a test which forks sleep and
> doesn't output anything which should test both conditions.
>
> I also tried the code you have above while commissioning but it causes
> 00-maas-01-cpuinfo to become defunct and never proceed.

Ah, okay, I think I understand.

I've put some code at lp:~allenap/maas/ltrager--combined_script_output.
This refactors the existing tests (it does not ultimately change their
behaviour) and adds three new. The only one that really matters is
test__captures_output_from_completed_process because c_s_o, at present,
will discard output from an already-completed process. The tests also
iterate 20 times to shake out additional failures: some of the other
tests fail for this same underlying reason.

This branch also has a version of capture_script_output that
consistently, over a few thousand iterations, passes these tests.

See the diff at https://code.launchpad.net/~allenap/maas/ltrager--combined_script_output/+merge/318096.

review: Needs Fixing

[Lee Trager (ltrager)]

Thanks for the review and reworking the tests. The updated capture_script_output definitely fixes some edge cases I was missing as shown by the new unit tests. When I testing the updated code in my test environment I noticed only about half of lshw's output was being captured. In the previous version the finished_writing_pipes dict was used to make sure capture_script_output waited until all output was written. I modified the code from your branch to do something similar. If any data has been written by the process capture_script_output waits until it detects EOF. This means any script which forks can't write to stdout or stderr. The only script we have which forks is 00-maas-06-dhcp-unconfigured-ifaces and that does not write to stdout or stderr. I added a new unit test for this, test__captures_all_output.

I was also wondering if we want to land reruning the tests 20 times or if that was just for testing?

[Gavin Panella (allenap)]

The new test, test__captures_all_output, fails on my machine 3 times in
4, because lshw reports a different frequency for my CPU each time
around.

However, lshw will produce XML with the -xml flag, and we can check that
the output is well-formed to be reasonably sure that we've captured
everything. Hence:

    def test__captures_all_output(self):
        proc = Popen(("lshw", "-xml"), stdout=PIPE, stderr=PIPE)
        returncode, stdout, stderr, combined = self.capture(proc)
        self.assertThat(returncode, Equals(0), stderr)
        # This is a complete XML document; we've captured all output.
        self.assertThat(etree.fromstring(stdout).tag, Equals("list"))

However, this hangs. Killing with ctrl-c always shows that it's hanging
at:

    chunk = key.fileobj.read(PIPE_BUF)

which, eventually, after some more reading and experimentation, made me
realise that we should be reading from the _raw_ file object. There's
more on why in the code.

It also occurred to me that we should make sure to read each pipe's
buffer in full each time. PIPE_BUF is only 4096, which is an outdated
figure: the default buffer size on Linux is now 65536 bytes; see
pipe(7). It can be adjusted up to 1048576 bytes, or even more by
privileged processes.

To get the size of a buffer we need to do fcntl(fd, F_GETPIPE_SZ), but
F_GETPIPE_SZ is not defined in Python so there's no "proper" way to find
out the size of a pipe's buffer from Python. I decided to assume that
we'll always be working with buffers of no more than 1048576 bytes. To
be honest, I expect that we will only ever work with 65536 byte buffers,
but I want this to be as defensively coded as I can make it.

The 1048576 figure is actually defined in /proc/sys/fs/pipe-max-size, so
that file is now read on import and the figure used by
_select_script_output for read() calls on raw file objects.

An updated diff can be see at https://code.launchpad.net/~allenap/maas/ltrager--combined_script_output/+merge/318235.

review: Needs Fixing

[Lee Trager (ltrager)]

Thanks again for the help. I do my development in a VM that doesn't do CPU scaling which is why the previous lshw test worked for me. I've merged your changed and verified commissioning works and captures everything in my test environment.

[Gavin Panella (allenap)]

Cool! After all the effort we put in I feel like bottling it and putting it somewhere safe.

review: Approve

[Mike Pontillo (mpontillo)]

I won't block this branch from landing, but I do have one question on this.

Some context: I was just looking at gathering information from `dmidecode` during commissioning. The `dmidecode` binary is chatty. At first I was thinking I should run several commissioning scripts: one to dump the data, and one to present it in various formats. But that's inconsistent with the other scripts.

Currently I have a single script with some different sections I can identify later when parsing the file, such as:

-----BEGIN FOO-----
stdout-0
stdout-1
-----END FOO-----

I started to worry, though: what if stderr output is unintentionally interspersed, such as:

-----BEGIN FOO-----
stdout-0
WARNING: could not look up hostname for unglamorous-rodents.maas
stdout-1
WARNING: could not look up hostname for unglamorous-rodents.maas
-----END FOO-----

That will mess up my parser if it happens, but the previous behavior would have been for the output to be safely hidden in the .err file, no?

[Andres Rodriguez (andreserl)]

Uhmmmm this brings a good point because there are major differences between what a commissioning script output vs a testing script output.

The goal of the commissioning output being stored, is in reality a *result* that can be processed by MAAS.

For example:

-------00-maas-07-block-devices---------

[
{
"RO": "1",
"ID_PATH": "/dev/disk/by-id/wwn-0x60000000000000000e00000000080001",
"MODEL": "VIRTUAL-DISK",
"RM": "0",
"PATH": "/dev/sdb",
"BLOCK_SIZE": "1024",
"SERIAL": "60000000000000000e00000000080001",
"SIZE": "187834368",
"ROTA": "1",
"NAME": "sdb"
},
]

---------00-maas-07-block-devices.err---------
sudo: unable to resolve host node01
sudo: unable to resolve host node01
sudo: unable to resolve host node01

Combining both of the above would obviously break processing of output, for example, this would be really wrong:

-------00-maas-07-block-devices---------
sudo: unable to resolve host node01
sudo: unable to resolve host node01
[
{
"RO": "1",
"ID_PATH": "/dev/disk/by-id/wwn-0x60000000000000000e00000000080001",
"MODEL": "VIRTUAL-DISK",
"RM": "0",
"PATH": "/dev/sdb",
"BLOCK_SIZE": "1024",
"SERIAL": "60000000000000000e00000000080001",
"SIZE": "187834368",
"ROTA": "1",
"NAME": "sdb"
},
]
sudo: unable to resolve host node01
---------------------------------------

So, I'd imagine that we care about two things:

1. The *result*
2. The script *log*

So, for commissioning we only care about the *result*, i.e:
* a list of block devices
* list of interfaces
* lshw output (the result of lshw)
* true/false/none
* etc.

For 'Testing' we care about the *result* & the script *output* as a **log**.

Result examples:
pass/fail (for testing scripts that we dont need to gather any data other than pass/fail)
<output> (which could be, say, the performance of disk writing/reading).

Output log:

-----smartctl-----
smartctl --XYZ
<output>
smartctl --ABC
<output>
------------------

------------------

review: Needs Information

[Lee Trager (ltrager)]

What this branch does is capture the combined output in addition to stdout and stderr. The combined output is what we give to the user by default. MAAS still runs the hooks on the pure stdout data[1]. So this change will not effect commissioning scripts.

[1] See src/metadataserver/models/scriptresult.py:147

[Mike Pontillo (mpontillo)]

Thanks for the clarification. Sounds good to me!

review: Approve

[Andres Rodriguez (andreserl)]

On the API, what's the output the "data" field? Is this the combined output? If so, this is a regression for commissioning as we would be changing the output.

That said, this makes me realize that while "data" for a commissioning script is the *result* for a testing script would be random output... this feels like testing should have :

1. Result of a test, like passed/failed or the for example performance values
2. Log of the script run and the whole output of what's running (similar to our Jenkins log)

review: Needs Information

[Lee Trager (ltrager)]

API and websocket have been updated to show both stdout and stderr.

[Andres Rodriguez (andreserl)]

I'm good with this now!

review: Approve

[MAAS Lander (maas-lander)]

The attempt to merge lp:~ltrager/maas/combined_script_output into lp:maas failed. Below is the output from the failed tests.

Hit:1 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial InRelease
Get:2 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates InRelease [102 kB]
Get:3 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-backports InRelease [102 kB]
Get:4 http://security.ubuntu.com/ubuntu xenial-security InRelease [102 kB]
Fetched 306 kB in 0s (640 kB/s)
Reading package lists...
sudo DEBIAN_FRONTEND=noninteractive apt-get -y \
    --no-install-recommends install apache2 archdetect-deb authbind avahi-utils bash bind9 bind9utils build-essential bzr bzr-builddeb chromium-browser chromium-chromedriver curl daemontools debhelper dh-apport dh-systemd distro-info dnsutils firefox freeipmi-tools git gjs ipython isc-dhcp-common isc-dhcp-server libjs-angularjs libjs-jquery libjs-jquery-hotkeys libjs-yui3-full libjs-yui3-min libnss-wrapper libpq-dev make nodejs-legacy npm postgresql psmisc pxelinux python3-all python3-apt python3-attr python3-bson python3-convoy python3-crochet python3-cssselect python3-curtin python3-dev python3-distro-info python3-django python3-django-nose python3-django-piston3 python3-dnspython python3-docutils python3-formencode python3-hivex python3-httplib2 python3-jinja2 python3-jsonschema python3-lxml python3-netaddr python3-netifaces python3-novaclient python3-oauth python3-oauthlib python3-openssl python3-paramiko python3-petname python3-pexpect python3-psycopg2 python3-pyinotify python3-pyparsing python3-pyvmomi python3-requests python3-seamicroclient python3-setuptools python3-simplestreams python3-sphinx python3-tempita python3-twisted python3-txtftp python3-tz python3-yaml python3-zope.interface python-bson python-crochet python-django python-django-piston python-djorm-ext-pgarray python-formencode python-lxml python-netaddr python-netifaces python-pocket-lint python-psycopg2 python-simplejson python-tempita python-twisted python-yaml socat syslinux-common tgt ubuntu-cloudimage-keyring wget xvfb
Reading package lists...
Building dependency tree...
Reading state information...
authbind is already the newest version (2.1.1+nmu1).
avahi-utils is already the newest version (0.6.32~rc+dfsg-1ubuntu2).
build-essential is already the newest version (12.1ubuntu2).
debhelper is already the newest version (9.20160115ubuntu3).
distro-info is already the newest version (0.14build1).
git is already the newest version (1:2.7.4-0ubuntu1).
libjs-angularjs is already the newest version (1.2.28-1ubuntu2).
libjs-jquery is already the newest version (1.11.3+dfsg-4).
libjs-yui3-full is already the newest version (3.5.1-1ubuntu3).
libjs-yui3-min is already the newest version (3.5.1-1ubuntu3).
make is already the newest version (4.1-6).
postgresql is already the newest version (9.5+173).
psmisc is already the newest version (22.21-2.1build1).
pxelinux is already the newest version (3:6.03+dfsg-11ubuntu1).
python-formencode is already the newest version (1.3.0-0ubuntu5).
python-lxml is already the newest version (3.5.0-1build1).
python-netaddr is already the newest version (0.7.18-1).
python-neti...

[MAAS Lander (maas-lander)]

The attempt to merge lp:~ltrager/maas/combined_script_output into lp:maas failed. Below is the output from the failed tests.

Hit:1 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial InRelease
Get:2 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates InRelease [102 kB]
Get:3 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-backports InRelease [102 kB]
Get:4 http://security.ubuntu.com/ubuntu xenial-security InRelease [102 kB]
Fetched 306 kB in 0s (593 kB/s)
Reading package lists...
sudo DEBIAN_FRONTEND=noninteractive apt-get -y \
    --no-install-recommends install apache2 archdetect-deb authbind avahi-utils bash bind9 bind9utils build-essential bzr bzr-builddeb chromium-browser chromium-chromedriver curl daemontools debhelper dh-apport dh-systemd distro-info dnsutils firefox freeipmi-tools git gjs ipython isc-dhcp-common isc-dhcp-server libjs-angularjs libjs-jquery libjs-jquery-hotkeys libjs-yui3-full libjs-yui3-min libnss-wrapper libpq-dev make nodejs-legacy npm postgresql psmisc pxelinux python3-all python3-apt python3-attr python3-bson python3-convoy python3-crochet python3-cssselect python3-curtin python3-dev python3-distro-info python3-django python3-django-nose python3-django-piston3 python3-dnspython python3-docutils python3-formencode python3-hivex python3-httplib2 python3-jinja2 python3-jsonschema python3-lxml python3-netaddr python3-netifaces python3-novaclient python3-oauth python3-oauthlib python3-openssl python3-paramiko python3-petname python3-pexpect python3-psycopg2 python3-pyinotify python3-pyparsing python3-pyvmomi python3-requests python3-seamicroclient python3-setuptools python3-simplestreams python3-sphinx python3-tempita python3-twisted python3-txtftp python3-tz python3-yaml python3-zope.interface python-bson python-crochet python-django python-django-piston python-djorm-ext-pgarray python-formencode python-lxml python-netaddr python-netifaces python-pocket-lint python-psycopg2 python-simplejson python-tempita python-twisted python-yaml socat syslinux-common tgt ubuntu-cloudimage-keyring wget xvfb
Reading package lists...
Building dependency tree...
Reading state information...
authbind is already the newest version (2.1.1+nmu1).
avahi-utils is already the newest version (0.6.32~rc+dfsg-1ubuntu2).
build-essential is already the newest version (12.1ubuntu2).
debhelper is already the newest version (9.20160115ubuntu3).
distro-info is already the newest version (0.14build1).
git is already the newest version (1:2.7.4-0ubuntu1).
libjs-angularjs is already the newest version (1.2.28-1ubuntu2).
libjs-jquery is already the newest version (1.11.3+dfsg-4).
libjs-yui3-full is already the newest version (3.5.1-1ubuntu3).
libjs-yui3-min is already the newest version (3.5.1-1ubuntu3).
make is already the newest version (4.1-6).
postgresql is already the newest version (9.5+173).
psmisc is already the newest version (22.21-2.1build1).
pxelinux is already the newest version (3:6.03+dfsg-11ubuntu1).
python-formencode is already the newest version (1.3.0-0ubuntu5).
python-lxml is already the newest version (3.5.0-1build1).
python-netaddr is already the newest version (0.7.18-1).
python-neti...

[MAAS Lander (maas-lander)]

The attempt to merge lp:~ltrager/maas/combined_script_output into lp:maas failed. Below is the output from the failed tests.

Hit:1 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial InRelease
Get:2 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-updates InRelease [102 kB]
Get:3 http://prodstack-zone-2.clouds.archive.ubuntu.com/ubuntu xenial-backports InRelease [102 kB]
Get:4 http://security.ubuntu.com/ubuntu xenial-security InRelease [102 kB]
Fetched 306 kB in 0s (617 kB/s)
Reading package lists...
sudo DEBIAN_FRONTEND=noninteractive apt-get -y \
    --no-install-recommends install apache2 archdetect-deb authbind avahi-utils bash bind9 bind9utils build-essential bzr bzr-builddeb chromium-browser chromium-chromedriver curl daemontools debhelper dh-apport dh-systemd distro-info dnsutils firefox freeipmi-tools git gjs ipython isc-dhcp-common isc-dhcp-server libjs-angularjs libjs-jquery libjs-jquery-hotkeys libjs-yui3-full libjs-yui3-min libnss-wrapper libpq-dev make nodejs-legacy npm postgresql psmisc pxelinux python3-all python3-apt python3-attr python3-bson python3-convoy python3-crochet python3-cssselect python3-curtin python3-dev python3-distro-info python3-django python3-django-nose python3-django-piston3 python3-dnspython python3-docutils python3-formencode python3-hivex python3-httplib2 python3-jinja2 python3-jsonschema python3-lxml python3-netaddr python3-netifaces python3-novaclient python3-oauth python3-oauthlib python3-openssl python3-paramiko python3-petname python3-pexpect python3-psycopg2 python3-pyinotify python3-pyparsing python3-pyvmomi python3-requests python3-seamicroclient python3-setuptools python3-simplestreams python3-sphinx python3-tempita python3-twisted python3-txtftp python3-tz python3-yaml python3-zope.interface python-bson python-crochet python-django python-django-piston python-djorm-ext-pgarray python-formencode python-lxml python-netaddr python-netifaces python-pocket-lint python-psycopg2 python-simplejson python-tempita python-twisted python-yaml socat syslinux-common tgt ubuntu-cloudimage-keyring wget xvfb
Reading package lists...
Building dependency tree...
Reading state information...
authbind is already the newest version (2.1.1+nmu1).
avahi-utils is already the newest version (0.6.32~rc+dfsg-1ubuntu2).
build-essential is already the newest version (12.1ubuntu2).
debhelper is already the newest version (9.20160115ubuntu3).
distro-info is already the newest version (0.14build1).
git is already the newest version (1:2.7.4-0ubuntu1).
libjs-angularjs is already the newest version (1.2.28-1ubuntu2).
libjs-jquery is already the newest version (1.11.3+dfsg-4).
libjs-yui3-full is already the newest version (3.5.1-1ubuntu3).
libjs-yui3-min is already the newest version (3.5.1-1ubuntu3).
make is already the newest version (4.1-6).
postgresql is already the newest version (9.5+173).
psmisc is already the newest version (22.21-2.1build1).
pxelinux is already the newest version (3:6.03+dfsg-11ubuntu1).
python-formencode is already the newest version (1.3.0-0ubuntu5).
python-lxml is already the newest version (3.5.0-1build1).
python-netaddr is already the newest version (0.7.18-1).
python-neti...

=== modified file 'src/maasserver/api/results.py'
--- src/maasserver/api/results.py	2017-02-17 14:23:04 +0000
+++ src/maasserver/api/results.py	2017-02-28 23:55:43 +0000
@@ -7,6 +7,9 @@
     'NodeResultsHandler',
     ]
 
+from base64 import b64encode
+
+from django.core.urlresolvers import reverse
 from formencode.validators import Int
 from maasserver.api.support import OperationsHandler
 from maasserver.api.utils import (
@@ -27,7 +30,7 @@
     model = ScriptResult
     fields = (
         'name', 'script_result', 'result_type', 'updated', 'created',
-        'node', 'data')
+        'node', 'data', 'resource_uri')
 
     def read(self, request):
         """List NodeResult visible to the user, optionally filtered.
@@ -63,6 +66,8 @@
             # Convert to a set; it's used for membership testing.
             names = set(names)
 
+        resource_uri = reverse('commissioning_scripts_handler')
+
         results = []
         for script_set in script_sets:
             if (result_type is not None and
@@ -74,6 +79,17 @@
                         SCRIPT_STATUS.TIMEOUT, SCRIPT_STATUS.ABORTED)):
                 if names is not None and script_result.name not in names:
                     continue
+                # MAAS stores stdout, stderr, and the combined output. The
+                # metadata API determine which field uploaded data should go
+                # into based on the extention of the uploaded file. .out goes
+                # to stdout, .err goes to stderr, otherwise its assumed the
+                # data is combined. Curtin uploads the installation log as
+                # install.log so its stored as a combined result. This ensures
+                # a result is always returned.
+                if script_result.stdout != b'':
+                    data = b64encode(script_result.stdout)
+                else:
+                    data = b64encode(script_result.output)
                 results.append({
                     'created': script_result.created,
                     'updated': script_result.updated,
@@ -82,7 +98,8 @@
                     'script_result': script_result.exit_status,
                     'result_type': script_set.result_type,
                     'node': {'system_id': script_set.node.system_id},
-                    'data': script_result.stdout.decode('utf-8'),
+                    'data': data,
+                    'resource_uri': resource_uri,
                 })
                 if script_result.stderr != b'':
                     results.append({
@@ -93,7 +110,8 @@
                         'script_result': script_result.exit_status,
                         'result_type': script_set.result_type,
                         'node': {'system_id': script_set.node.system_id},
-                        'data': script_result.stderr.decode('utf-8'),
+                        'data': b64encode(script_result.stderr),
+                        'resource_uri': resource_uri,
                     })
 
         return results

=== modified file 'src/maasserver/api/tests/test_commissioning.py'
--- src/maasserver/api/tests/test_commissioning.py	2017-02-17 14:23:04 +0000
+++ src/maasserver/api/tests/test_commissioning.py	2017-02-28 23:55:43 +0000
@@ -5,7 +5,10 @@
 
 __all__ = []
 
-from base64 import b64encode
+from base64 import (
+    b64decode,
+    b64encode,
+)
 import http.client
 from itertools import chain
 import random
@@ -153,9 +156,11 @@
 class NodeCommissionResultHandlerAPITest(APITestCase.ForUser):
 
     def store_result(
-            self, script_result, stdout=None, stderr=None,
+            self, script_result, output=None, stdout=None, stderr=None,
             **kwargs):
         # Create a test store_result which doesn't run the script hooks.
+        if output is not None:
+            script_result.output = Bin(output.encode('utf-8'))
         if stdout is not None:
             script_result.stdout = Bin(stdout.encode('utf-8'))
         if stderr is not None:
@@ -195,7 +200,7 @@
             len(parsed_results))
         self.assertItemsEqual([
             'created', 'updated', 'id', 'name', 'script_result', 'result_type',
-            'node', 'data'], parsed_result.keys())
+            'node', 'data', 'resource_uri'], parsed_result.keys())
         self.assertEquals(script_result.id, parsed_result['id'])
         self.assertEquals(script_result.name, parsed_result['name'])
         self.assertEquals(
@@ -205,7 +210,7 @@
             {'system_id': script_set.node.system_id},
             parsed_result['node'])
         self.assertEquals(
-            script_result.stdout.decode('utf-8'), parsed_result['data'])
+            script_result.stdout, b64decode(parsed_result['data']))
 
     def test_list_returns_with_multiple_empty_data(self):
         node = factory.make_Node(with_empty_script_sets=True)
@@ -253,6 +258,29 @@
             ],
             [parsed_result['data'] for parsed_result in parsed_results])
 
+    def test_list_returns_output_if_stdout_empty(self):
+        node = factory.make_Node(with_empty_script_sets=True)
+        for script_result in chain(
+                node.current_commissioning_script_set,
+                node.current_testing_script_set,
+                node.current_installation_script_set):
+            self.store_result(
+                script_result, exit_status=0, output=factory.make_string())
+
+        url = reverse('node_results_handler')
+        response = self.client.get(url, {'system_id': [node.system_id]})
+        self.assertThat(response, HasStatusCode(http.client.OK))
+        parsed_results = json_load_bytes(response.content)
+        self.assertItemsEqual(
+            [
+                b64encode(script_result.output).decode()
+                for script_result in chain(
+                    node.current_commissioning_script_set,
+                    node.current_testing_script_set,
+                    node.current_installation_script_set)
+            ],
+            [parsed_result['data'] for parsed_result in parsed_results])
+
     def test_list_shows_all_latest_results(self):
         # XXX ltrager 2017-01-23 - Needed until builtin tests are added.
         factory.make_Script(script_type=SCRIPT_TYPE.TESTING)

=== modified file 'src/maasserver/enum.py'
--- src/maasserver/enum.py	2017-02-17 21:27:46 +0000
+++ src/maasserver/enum.py	2017-02-28 23:55:43 +0000
@@ -126,8 +126,8 @@
     (NODE_STATUS.FAILED_ENTERING_RESCUE_MODE, "Failed to enter rescue mode"),
     (NODE_STATUS.EXITING_RESCUE_MODE, "Exiting rescue mode"),
     (NODE_STATUS.FAILED_EXITING_RESCUE_MODE, "Failed to exit rescue mode"),
-    (NODE_STATUS.TESTING, "Testing node"),
-    (NODE_STATUS.FAILED_TESTING, "Tests failed on node"),
+    (NODE_STATUS.TESTING, "Testing"),
+    (NODE_STATUS.FAILED_TESTING, "Failed testing"),
 )
 
 

=== modified file 'src/maasserver/migrations/builtin/maasserver/0106_testing_status.py'
--- src/maasserver/migrations/builtin/maasserver/0106_testing_status.py	2017-01-09 02:12:00 +0000
+++ src/maasserver/migrations/builtin/maasserver/0106_testing_status.py	2017-02-28 23:55:43 +0000
@@ -17,11 +17,11 @@
         migrations.AlterField(
             model_name='node',
             name='previous_status',
-            field=models.IntegerField(editable=False, default=0, choices=[(0, 'New'), (1, 'Commissioning'), (2, 'Failed commissioning'), (3, 'Missing'), (4, 'Ready'), (5, 'Reserved'), (10, 'Allocated'), (9, 'Deploying'), (6, 'Deployed'), (7, 'Retired'), (8, 'Broken'), (11, 'Failed deployment'), (12, 'Releasing'), (13, 'Releasing failed'), (14, 'Disk erasing'), (15, 'Failed disk erasing'), (16, 'Rescue mode'), (17, 'Entering rescue mode'), (18, 'Failed to enter rescue mode'), (19, 'Exiting rescue mode'), (20, 'Failed to exit rescue mode'), (21, 'Testing node'), (22, 'Tests failed on node')]),
+            field=models.IntegerField(editable=False, default=0, choices=[(0, 'New'), (1, 'Commissioning'), (2, 'Failed commissioning'), (3, 'Missing'), (4, 'Ready'), (5, 'Reserved'), (10, 'Allocated'), (9, 'Deploying'), (6, 'Deployed'), (7, 'Retired'), (8, 'Broken'), (11, 'Failed deployment'), (12, 'Releasing'), (13, 'Releasing failed'), (14, 'Disk erasing'), (15, 'Failed disk erasing'), (16, 'Rescue mode'), (17, 'Entering rescue mode'), (18, 'Failed to enter rescue mode'), (19, 'Exiting rescue mode'), (20, 'Failed to exit rescue mode'), (21, 'Testing'), (22, 'Failed testing')]),
         ),
         migrations.AlterField(
             model_name='node',
             name='status',
-            field=models.IntegerField(editable=False, default=0, choices=[(0, 'New'), (1, 'Commissioning'), (2, 'Failed commissioning'), (3, 'Missing'), (4, 'Ready'), (5, 'Reserved'), (10, 'Allocated'), (9, 'Deploying'), (6, 'Deployed'), (7, 'Retired'), (8, 'Broken'), (11, 'Failed deployment'), (12, 'Releasing'), (13, 'Releasing failed'), (14, 'Disk erasing'), (15, 'Failed disk erasing'), (16, 'Rescue mode'), (17, 'Entering rescue mode'), (18, 'Failed to enter rescue mode'), (19, 'Exiting rescue mode'), (20, 'Failed to exit rescue mode'), (21, 'Testing node'), (22, 'Tests failed on node')]),
+            field=models.IntegerField(editable=False, default=0, choices=[(0, 'New'), (1, 'Commissioning'), (2, 'Failed commissioning'), (3, 'Missing'), (4, 'Ready'), (5, 'Reserved'), (10, 'Allocated'), (9, 'Deploying'), (6, 'Deployed'), (7, 'Retired'), (8, 'Broken'), (11, 'Failed deployment'), (12, 'Releasing'), (13, 'Releasing failed'), (14, 'Disk erasing'), (15, 'Failed disk erasing'), (16, 'Rescue mode'), (17, 'Entering rescue mode'), (18, 'Failed to enter rescue mode'), (19, 'Exiting rescue mode'), (20, 'Failed to exit rescue mode'), (21, 'Testing'), (22, 'Failed testing')]),
         ),
     ]

=== modified file 'src/maasserver/testing/factory.py'
--- src/maasserver/testing/factory.py	2017-02-17 21:27:46 +0000
+++ src/maasserver/testing/factory.py	2017-02-28 23:55:43 +0000
@@ -675,8 +675,8 @@
 
     def make_ScriptResult(
             self, script_set=None, script=None, script_version=None,
-            status=None, exit_status=None, script_name=None, stdout=None,
-            stderr=None, result=None):
+            status=None, exit_status=None, script_name=None, output=None,
+            stdout=None, stderr=None, result=None):
         if script_set is None:
             script_set = self.make_ScriptSet()
         if script is None and script_name is None:
@@ -685,6 +685,8 @@
             status = self.pick_choice(SCRIPT_STATUS_CHOICES)
         if status in (SCRIPT_STATUS.PENDING, SCRIPT_STATUS.RUNNING):
             # Pending and running script results shouldn't have results stored.
+            if output is None:
+                output = b''
             if stdout is None:
                 stdout = b''
             if stderr is None:
@@ -694,6 +696,8 @@
         else:
             if exit_status is None:
                 exit_status = random.randint(0, 255)
+            if output is None:
+                output = self.make_string().encode('utf-8')
             if stdout is None:
                 stdout = self.make_string().encode('utf-8')
             if stderr is None:
@@ -706,7 +710,8 @@
             script_set=script_set, script=script,
             script_version=script_version, status=status,
             exit_status=exit_status, script_name=script_name,
-            stdout=Bin(stdout), stderr=Bin(stderr), result=result)
+            output=Bin(output), stdout=Bin(stdout), stderr=Bin(stderr),
+            result=result)
 
     def make_MAC(self):
         """Generate a random MAC address, in the form of a MAC object."""

=== modified file 'src/maasserver/websockets/handlers/node.py'
--- src/maasserver/websockets/handlers/node.py	2017-02-17 14:23:04 +0000
+++ src/maasserver/websockets/handlers/node.py	2017-02-28 23:55:43 +0000
@@ -423,12 +423,23 @@
         # updated when the UI has an understanding of script_sets and
         # script_results.
         for script_result in script_set:
+            # MAAS stores stdout, stderr, and the combined output. The
+            # metadata API determine which field uploaded data should go
+            # into based on the extention of the uploaded file. .out goes
+            # to stdout, .err goes to stderr, otherwise its assumed the
+            # data is combined. Curtin uploads the installation log as
+            # install.log so its stored as a combined result. This ensures
+            # a result is always returned.
+            if script_result.stdout != b'':
+                data = script_result.stdout
+            else:
+                data = script_result.output
             ret.append({
                 'id': script_result.id,
                 'result': script_result.exit_status,
                 'name': script_result.name,
-                'data': script_result.stdout,
-                'line_count': len(script_result.stdout.splitlines()),
+                'data': data,
+                'line_count': len(data.splitlines()),
                 'created': dehydrate_datetime(script_result.updated),
             })
             if script_result.stderr != b'':

=== modified file 'src/maasserver/websockets/handlers/tests/test_machine.py'
--- src/maasserver/websockets/handlers/tests/test_machine.py	2017-02-17 14:23:04 +0000
+++ src/maasserver/websockets/handlers/tests/test_machine.py	2017-02-28 23:55:43 +0000
@@ -784,6 +784,22 @@
                 'created': dehydrate_datetime(script_result.updated),
             }], handler.dehydrate_script_set(script_result.script_set))
 
+    def test_dehydrate_script_set_returns_output_if_stdout_empty(self):
+        owner = factory.make_User()
+        handler = MachineHandler(owner, {})
+        script_result = factory.make_ScriptResult(
+            status=SCRIPT_STATUS.PASSED, stdout=''.encode(),
+            stderr=''.encode(), output=factory.make_string().encode())
+        self.assertDictEqual(
+            {
+                'id': script_result.id,
+                'result': script_result.exit_status,
+                'name': script_result.name,
+                'data': script_result.output,
+                'line_count': len(script_result.output.splitlines()),
+                'created': dehydrate_datetime(script_result.updated),
+            }, handler.dehydrate_script_set(script_result.script_set)[0])
+
     def test_dehydrate_events_only_includes_lastest_50(self):
         owner = factory.make_User()
         node = factory.make_Node(owner=owner)

=== modified file 'src/maasserver/websockets/tests/test_protocol.py'
--- src/maasserver/websockets/tests/test_protocol.py	2017-02-24 19:08:57 +0000
+++ src/maasserver/websockets/tests/test_protocol.py	2017-02-28 23:55:43 +0000
@@ -495,7 +495,7 @@
         script_set = node.current_commissioning_script_set
         script_result = script_set.find_script_result(
             script_name=LSHW_OUTPUT_NAME)
-        script_result.store_result(exit_status=0, stdout=fake_lshw)
+        script_result.store_result(exit_status=0, output=fake_lshw)
         return node
 
     @wait_for_reactor

=== modified file 'src/metadataserver/api.py'
--- src/metadataserver/api.py	2017-02-28 21:20:49 +0000
+++ src/metadataserver/api.py	2017-02-28 23:55:43 +0000
@@ -215,15 +215,18 @@
     script_result_id = get_optional_param(
         request, 'script_result_id', None, Int)
 
-    # The .err indicates this should be stored in the STDERR column of the
-    # ScriptResult. When finding or creating a ScriptResult don't include the
-    # .err in the name. If given, we look up by script_result_id along with
-    # the name to allow .err in the name.
-    if script_name.endswith('.err'):
+    # The .out or .err indicates this should be stored in the stdout or stderr
+    # column of ScriptResult. If neither are given put it in the combined
+    # output column. If given, we look up by script_result_id along with the
+    # name to allow .out or .err in the name.
+    if script_name.endswith('.out'):
+        script_name = script_name[0:-4]
+        key = 'stdout'
+    elif script_name.endswith('.err'):
         script_name = script_name[0:-4]
         key = 'stderr'
     else:
-        key = 'stdout'
+        key = 'output'
 
     try:
         script_result = script_set.scriptresult_set.get(id=script_result_id)

=== added file 'src/metadataserver/migrations/builtin/0006_scriptresult_combined_output.py'
--- src/metadataserver/migrations/builtin/0006_scriptresult_combined_output.py	1970-01-01 00:00:00 +0000
+++ src/metadataserver/migrations/builtin/0006_scriptresult_combined_output.py	2017-02-28 23:55:43 +0000
@@ -0,0 +1,23 @@
+# -*- coding: utf-8 -*-
+from __future__ import unicode_literals
+
+from django.db import (
+    migrations,
+    models,
+)
+import metadataserver.fields
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ('metadataserver', '0005_store_powerstate_on_scriptset_creation'),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name='scriptresult',
+            name='output',
+            field=metadataserver.fields.BinaryField(blank=True, default=b'', max_length=1048576),
+        ),
+    ]

=== modified file 'src/metadataserver/models/scriptresult.py'
--- src/metadataserver/models/scriptresult.py	2017-01-24 08:38:40 +0000
+++ src/metadataserver/models/scriptresult.py	2017-02-28 23:55:43 +0000
@@ -62,6 +62,8 @@
     script_name = CharField(
         max_length=255, unique=False, editable=False, null=True)
 
+    output = BinaryField(max_length=1024 * 1024, blank=True, default=b'')
+
     stdout = BinaryField(max_length=1024 * 1024, blank=True, default=b'')
 
     stderr = BinaryField(max_length=1024 * 1024, blank=True, default=b'')
@@ -82,8 +84,8 @@
         return "%s/%s" % (self.script_set.node.system_id, self.name)
 
     def store_result(
-            self, exit_status, stdout=None, stderr=None, result=None,
-            script_version_id=None):
+            self, exit_status, output=None, stdout=None, stderr=None,
+            result=None, script_version_id=None):
         # Don't allow ScriptResults to be overwritten unless the node is a
         # controller. Controllers are allowed to overwrite their results to
         # prevent new ScriptSets being created everytime a controller starts.
@@ -94,6 +96,7 @@
             # inform MAAS the Script was being run, it just uploaded results.
             assert self.status in (
                 SCRIPT_STATUS.PENDING, SCRIPT_STATUS.RUNNING)
+            assert self.output == b''
             assert self.stdout == b''
             assert self.stderr == b''
             assert self.result == ''
@@ -104,6 +107,8 @@
             self.status = SCRIPT_STATUS.PASSED
         else:
             self.status = SCRIPT_STATUS.FAILED
+        if output is not None:
+            self.output = Bin(output)
         if stdout is not None:
             self.stdout = Bin(stdout)
         if stderr is not None:

=== modified file 'src/metadataserver/models/tests/test_scriptresult.py'
--- src/metadataserver/models/tests/test_scriptresult.py	2017-01-24 08:22:16 +0000
+++ src/metadataserver/models/tests/test_scriptresult.py	2017-02-28 23:55:43 +0000
@@ -53,6 +53,12 @@
         self.assertRaises(
             AssertionError, script_result.store_result, random.randint(0, 255))
 
+    def test_store_result_only_allows_when_output_is_blank(self):
+        script_result = factory.make_ScriptResult(
+            status=SCRIPT_STATUS.RUNNING, output=factory.make_bytes())
+        self.assertRaises(
+            AssertionError, script_result.store_result, random.randint(0, 255))
+
     def test_store_result_only_allows_when_stdout_is_blank(self):
         script_result = factory.make_ScriptResult(
             status=SCRIPT_STATUS.RUNNING, stdout=factory.make_bytes())
@@ -79,16 +85,18 @@
         script_result = factory.make_ScriptResult(
             script_set=script_set, status=SCRIPT_STATUS.PASSED)
         exit_status = random.randint(0, 255)
+        output = factory.make_bytes()
         stdout = factory.make_bytes()
         stderr = factory.make_bytes()
         result = factory.make_string()
 
         script_result.store_result(
             random.randint(0, 255), factory.make_bytes(), factory.make_bytes(),
-            factory.make_string())
-        script_result.store_result(exit_status, stdout, stderr, result)
+            factory.make_bytes(), factory.make_string())
+        script_result.store_result(exit_status, output, stdout, stderr, result)
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(output, script_result.output)
         self.assertEquals(stdout, script_result.stdout)
         self.assertEquals(stderr, script_result.stderr)
         self.assertEquals(result, script_result.result)
@@ -98,6 +106,7 @@
         script_result.store_result(0)
         self.assertEquals(SCRIPT_STATUS.PASSED, script_result.status)
         self.assertEquals(0, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEquals('', script_result.result)
@@ -110,6 +119,22 @@
         script_result.store_result(exit_status)
         self.assertEquals(SCRIPT_STATUS.FAILED, script_result.status)
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
+        self.assertEquals(b'', script_result.stdout)
+        self.assertEquals(b'', script_result.stderr)
+        self.assertEquals('', script_result.result)
+        self.assertEquals(
+            script_result.script.script, script_result.script_version)
+
+    def test_store_result_stores_output(self):
+        script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
+        exit_status = random.randint(0, 255)
+        output = factory.make_bytes()
+
+        script_result.store_result(exit_status, output=output)
+
+        self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(output, script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEquals('', script_result.result)
@@ -124,6 +149,7 @@
         script_result.store_result(exit_status, stdout=stdout)
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(stdout, script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEquals('', script_result.result)
@@ -138,6 +164,7 @@
         script_result.store_result(exit_status, stderr=stderr)
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(stderr, script_result.stderr)
         self.assertEquals('', script_result.result)
@@ -152,6 +179,7 @@
         script_result.store_result(exit_status, result=json.dumps(result))
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEqual(result, script_result.result)
@@ -171,6 +199,7 @@
             exit_status, script_version_id=old_version.id)
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEquals('', script_result.result)
@@ -185,6 +214,7 @@
         script_result.store_result(exit_status)
 
         self.assertEquals(exit_status, script_result.exit_status)
+        self.assertEquals(b'', script_result.output)
         self.assertEquals(b'', script_result.stdout)
         self.assertEquals(b'', script_result.stderr)
         self.assertEquals('', script_result.result)

=== modified file 'src/metadataserver/tests/test_api.py'
--- src/metadataserver/tests/test_api.py	2017-02-17 14:23:04 +0000
+++ src/metadataserver/tests/test_api.py	2017-02-28 23:55:43 +0000
@@ -235,6 +235,50 @@
         self.assertEqual(
             EVENT_TYPES.REQUEST_CONTROLLER_REFRESH, event.type.name)
 
+    def test_process_file_creates_new_entry_for_output(self):
+        results = {}
+        script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
+        output = factory.make_string()
+        request = {'exit_status': random.randint(0, 255)}
+
+        process_file(
+            results, script_result.script_set, script_result.name, output,
+            request)
+
+        self.assertDictEqual(
+            {
+                'exit_status': request['exit_status'],
+                'output': output,
+            },
+            results[script_result])
+
+    def test_process_file_creates_adds_field_for_output(self):
+        results = {}
+        script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
+        output = factory.make_string()
+        stdout = factory.make_string()
+        stderr = factory.make_string()
+        request = {'exit_status': random.randint(0, 255)}
+
+        process_file(
+            results, script_result.script_set, '%s.out' % script_result.name,
+            stdout, request)
+        process_file(
+            results, script_result.script_set, '%s.err' % script_result.name,
+            stderr, request)
+        process_file(
+            results, script_result.script_set, script_result.name, output,
+            request)
+
+        self.assertDictEqual(
+            {
+                'exit_status': request['exit_status'],
+                'output': output,
+                'stdout': stdout,
+                'stderr': stderr,
+            },
+            results[script_result])
+
     def test_process_file_creates_new_entry_for_stdout(self):
         results = {}
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
@@ -242,8 +286,8 @@
         request = {'exit_status': random.randint(0, 255)}
 
         process_file(
-            results, script_result.script_set, script_result.name, stdout,
-            request)
+            results, script_result.script_set, '%s.out' % script_result.name,
+            stdout, request)
 
         self.assertDictEqual(
             {
@@ -255,20 +299,25 @@
     def test_process_file_creates_adds_field_for_stdout(self):
         results = {}
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
+        output = factory.make_string()
         stdout = factory.make_string()
         stderr = factory.make_string()
         request = {'exit_status': random.randint(0, 255)}
 
         process_file(
+            results, script_result.script_set, script_result.name, output,
+            request)
+        process_file(
             results, script_result.script_set, '%s.err' % script_result.name,
             stderr, request)
         process_file(
-            results, script_result.script_set, script_result.name, stdout,
-            request)
+            results, script_result.script_set, '%s.out' % script_result.name,
+            stdout, request)
 
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
+                'output': output,
                 'stdout': stdout,
                 'stderr': stderr,
             },
@@ -294,20 +343,25 @@
     def test_process_file_creates_adds_field_for_stderr(self):
         results = {}
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
+        output = factory.make_string()
         stdout = factory.make_string()
         stderr = factory.make_string()
         request = {'exit_status': random.randint(0, 255)}
 
         process_file(
-            results, script_result.script_set, script_result.name, stdout,
+            results, script_result.script_set, script_result.name, output,
             request)
         process_file(
+            results, script_result.script_set, '%s.out' % script_result.name,
+            stdout, request)
+        process_file(
             results, script_result.script_set, '%s.err' % script_result.name,
             stderr, request)
 
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
+                'output': output,
                 'stdout': stdout,
                 'stderr': stderr,
             },
@@ -316,7 +370,7 @@
     def test_process_file_finds_script_result_by_id(self):
         results = {}
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
-        stdout = factory.make_string()
+        output = factory.make_string()
         request = {
             'exit_status': random.randint(0, 255),
             'script_result_id': script_result.id,
@@ -324,19 +378,19 @@
 
         process_file(
             results, script_result.script_set,
-            factory.make_name('script_name'), stdout, request)
+            factory.make_name('script_name'), output, request)
 
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
-                'stdout': stdout,
+                'output': output,
             },
             results[script_result])
 
     def test_process_file_adds_script_version_id(self):
         results = {}
         script_result = factory.make_ScriptResult(status=SCRIPT_STATUS.RUNNING)
-        stdout = factory.make_string()
+        output = factory.make_string()
         request = {
             'exit_status': random.randint(0, 255),
             'script_result_id': script_result.id,
@@ -345,12 +399,12 @@
 
         process_file(
             results, script_result.script_set,
-            factory.make_name('script_name'), stdout, request)
+            factory.make_name('script_name'), output, request)
 
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
-                'stdout': stdout,
+                'output': output,
                 'script_version_id': script_result.script.script_id,
             },
             results[script_result])
@@ -359,10 +413,10 @@
         results = {}
         script_name = factory.make_name('script_name')
         script_set = factory.make_ScriptSet()
-        stdout = factory.make_string()
+        output = factory.make_string()
         request = {'exit_status': random.randint(0, 255)}
 
-        process_file(results, script_set, script_name, stdout, request)
+        process_file(results, script_set, script_name, output, request)
         script_result, value = list(results.items())[0]
 
         self.assertEquals(script_name, script_result.name)
@@ -370,7 +424,7 @@
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
-                'stdout': stdout,
+                'output': output,
             },
             value)
 
@@ -380,13 +434,13 @@
         script = factory.make_Script()
         script.script = script.script.update(factory.make_string())
         script_set = factory.make_ScriptSet()
-        stdout = factory.make_string()
+        output = factory.make_string()
         request = {
             'exit_status': random.randint(0, 255),
             'script_version_id': script.script.id,
         }
 
-        process_file(results, script_set, script_name, stdout, request)
+        process_file(results, script_set, script_name, output, request)
 
         script_result, value = list(results.items())[0]
 
@@ -394,7 +448,7 @@
         self.assertDictEqual(
             {
                 'exit_status': request['exit_status'],
-                'stdout': stdout,
+                'output': output,
                 'script_version_id': script.script.id,
             },
             value)
@@ -1308,7 +1362,7 @@
             http.client.OK, response.status_code, response.content)
         script_result = reload_object(script_result)
         self.assertEqual(exit_status, script_result.exit_status)
-        self.assertEqual(output, script_result.stdout.decode('utf-8'))
+        self.assertEqual(output, script_result.output.decode('utf-8'))
 
     def test_signaling_accepts_WORKING_status(self):
         node = factory.make_Node(
@@ -1487,7 +1541,7 @@
             files={script_result.name: text})
         script_result = reload_object(script_result)
         self.assertEqual(http.client.OK, response.status_code)
-        self.assertEqual(text, script_result.stdout)
+        self.assertEqual(text, script_result.output)
 
     def test_signal_stores_binary(self):
         unicode_text = '<\u2621>'
@@ -1504,7 +1558,7 @@
             files={script_result.name: unicode_text.encode('utf-8')})
         script_result = reload_object(script_result)
         self.assertEqual(http.client.OK, response.status_code)
-        self.assertEqual(unicode_text.encode("utf-8"), script_result.stdout)
+        self.assertEqual(unicode_text.encode("utf-8"), script_result.output)
 
     def test_signal_stores_multiple_files(self):
         node = factory.make_Node(
@@ -1528,7 +1582,7 @@
         self.assertEqual(
             contents,
             {
-                script_result.name: reload_object(script_result).stdout
+                script_result.name: reload_object(script_result).output
                 for script_result in script_results
             })
 
@@ -1551,7 +1605,7 @@
             files={script_result.name: contents.encode('utf-8')})
         script_result = reload_object(script_result)
         self.assertEqual(http.client.OK, response.status_code)
-        self.assertEqual(size_limit, len(script_result.stdout))
+        self.assertEqual(size_limit, len(script_result.output))
 
     def test_signal_stores_virtual_tag_on_node_if_virtual(self):
         node = factory.make_Node(
@@ -1560,7 +1614,7 @@
         content = 'qemu'.encode('utf-8')
         response = call_signal(
             client, script_result=0,
-            files={'00-maas-02-virtuality': content})
+            files={'00-maas-02-virtuality.out': content})
         self.assertEqual(http.client.OK, response.status_code)
         node = reload_object(node)
         self.assertEqual(
@@ -1575,7 +1629,7 @@
         content = 'none'.encode('utf-8')
         response = call_signal(
             client, script_result=0,
-            files={'00-maas-02-virtuality': content})
+            files={'00-maas-02-virtuality.out': content})
         self.assertEqual(http.client.OK, response.status_code)
         node = reload_object(node)
         self.assertEqual(
@@ -1588,7 +1642,7 @@
         content = 'none'.encode('utf-8')
         response = call_signal(
             client, script_result=0,
-            files={'00-maas-02-virtuality': content})
+            files={'00-maas-02-virtuality.out': content})
         self.assertEqual(http.client.OK, response.status_code)
         node = reload_object(node)
         self.assertEqual(0, len(node.tags.all()))

=== modified file 'src/metadataserver/tests/test_api_status.py'
--- src/metadataserver/tests/test_api_status.py	2017-02-17 14:23:04 +0000
+++ src/metadataserver/tests/test_api_status.py	2017-02-28 23:55:43 +0000
@@ -391,7 +391,7 @@
         }
         response = call_status(client, node, payload)
         self.assertEqual(http.client.OK, response.status_code)
-        self.assertEqual(contents, reload_object(script_result).stdout)
+        self.assertEqual(contents, reload_object(script_result).output)
 
     def test_status_with_file_invalid_statuses_fails(self):
         """Adding files should fail for every status that's neither
@@ -476,7 +476,7 @@
             self.assertEqual(
                 target_status, reload_object(node).status)
             # Check the node result.
-            self.assertEqual(contents, reload_object(script_result).stdout)
+            self.assertEqual(contents, reload_object(script_result).output)
 
     def test_status_with_results_succeeds(self):
         """Adding a script result should succeed"""
@@ -509,7 +509,7 @@
         response = call_status(client, node, payload)
         self.assertEqual(http.client.OK, response.status_code)
         script_result = reload_object(script_result)
-        self.assertEqual(contents, script_result.stdout)
+        self.assertEqual(contents, script_result.output)
         self.assertEqual(-42, script_result.exit_status)
 
     def test_status_with_results_no_exit_status_defaults_to_zero(self):
@@ -617,7 +617,7 @@
             'description': 'Commissioning',
             'files': [
                 {
-                    "path": "00-maas-02-virtuality",
+                    "path": "00-maas-02-virtuality.out",
                     "encoding": "base64",
                     "content": encode_as_base64(content),
                 }
@@ -648,7 +648,7 @@
             'description': 'Commissioning',
             'files': [
                 {
-                    "path": "00-maas-02-virtuality",
+                    "path": "00-maas-02-virtuality.out",
                     "encoding": "base64",
                     "content": encode_as_base64(content),
                 }

=== modified file 'src/metadataserver/tests/test_api_twisted.py'
--- src/metadataserver/tests/test_api_twisted.py	2017-02-28 19:23:48 +0000
+++ src/metadataserver/tests/test_api_twisted.py	2017-02-28 23:55:43 +0000
@@ -532,7 +532,7 @@
             ]
         }
         self.processMessage(node, payload)
-        self.assertEqual(contents, reload_object(script_result).stdout)
+        self.assertEqual(contents, reload_object(script_result).output)
 
     def test_status_with_file_invalid_statuses_fails(self):
         """Adding files should fail for every status that's neither
@@ -613,7 +613,7 @@
             self.assertEqual(
                 target_status, reload_object(node).status)
             # Check the node result.
-            self.assertEqual(contents, reload_object(script_result).stdout)
+            self.assertEqual(contents, reload_object(script_result).output)
 
     def test_status_with_results_succeeds(self):
         """Adding a script result should succeed"""
@@ -645,7 +645,7 @@
         }
         self.processMessage(node, payload)
         script_result = reload_object(script_result)
-        self.assertEqual(contents, script_result.stdout)
+        self.assertEqual(contents, script_result.output)
         self.assertEqual(-42, script_result.exit_status)
 
     def test_status_with_results_no_exit_status_defaults_to_zero(self):
@@ -692,7 +692,7 @@
             'timestamp': datetime.utcnow(),
             'files': [
                 {
-                    "path": "00-maas-02-virtuality",
+                    "path": "00-maas-02-virtuality.out",
                     "encoding": "base64",
                     "content": encode_as_base64(content),
                 }
@@ -722,7 +722,7 @@
             'timestamp': datetime.utcnow(),
             'files': [
                 {
-                    "path": "00-maas-02-virtuality",
+                    "path": "00-maas-02-virtuality.out",
                     "encoding": "base64",
                     "content": encode_as_base64(content),
                 }

=== modified file 'src/metadataserver/user_data/templates/snippets/maas_run_remote_scripts.py'
--- src/metadataserver/user_data/templates/snippets/maas_run_remote_scripts.py	2017-02-17 14:23:04 +0000
+++ src/metadataserver/user_data/templates/snippets/maas_run_remote_scripts.py	2017-02-28 23:55:43 +0000
@@ -4,7 +4,11 @@
 from io import BytesIO
 import json
 import os
-from subprocess import run
+import selectors
+from subprocess import (
+    PIPE,
+    Popen,
+)
 import sys
 import tarfile
 from threading import (
@@ -13,6 +17,11 @@
 )
 import time
 
+# See fcntl(2), re. F_SETPIPE_SZ. By requesting this many bytes from a pipe on
+# each read we can be sure that we are always draining its buffer completely.
+with open("/proc/sys/fs/pipe-max-size") as _pms:
+    PIPE_MAX_SIZE = int(_pms.read())
+
 
 try:
     from maas_api_helper import (
@@ -57,6 +66,51 @@
         tar.extractall(scripts_dir)
 
 
+def capture_script_output(proc, combined_path, stdout_path, stderr_path):
+    """Capture stdout and stderr from `proc`.
+
+    Standard output is written to a file named by `stdout_path`, and standard
+    error is written to a file named by `stderr_path`. Both are also written
+    to a file named by `combined_path`.
+
+    If the given subprocess forks additional processes, and these write to the
+    same stdout and stderr, their output will be captured only as long as
+    `proc` is running.
+
+    :return: The exit code of `proc`.
+    """
+    with open(stdout_path, 'wb') as out, open(stderr_path, 'wb') as err:
+        with open(combined_path, 'wb') as combined:
+            with selectors.DefaultSelector() as selector:
+                selector.register(proc.stdout, selectors.EVENT_READ, out)
+                selector.register(proc.stderr, selectors.EVENT_READ, err)
+                while selector.get_map() and proc.poll() is None:
+                    # Select with a short timeout so that we don't tight loop.
+                    _select_script_output(selector, combined, 0.1)
+                else:
+                    # Process has finished or has closed stdout and stderr.
+                    # Process anything still sitting in the latter's buffers.
+                    _select_script_output(selector, combined, 0.0)
+
+    # Always wait for the process to finish.
+    return proc.wait()
+
+
+def _select_script_output(selector, combined, timeout):
+    """Helper for `capture_script_output`."""
+    for key, event in selector.select(timeout):
+        if event & selectors.EVENT_READ:
+            # Read from the _raw_ file. Ordinarily Python blocks until a
+            # read(n) returns n bytes or the stream reaches end-of-file,
+            # but here we only want to get what's there without blocking.
+            chunk = key.fileobj.raw.read(PIPE_MAX_SIZE)
+            if len(chunk) == 0:  # EOF
+                selector.unregister(key.fileobj)
+            else:
+                key.data.write(chunk)
+                combined.write(chunk)
+
+
 def run_scripts(url, creds, scripts_dir, out_dir, scripts):
     """Run and report results for the given scripts."""
     fail_count = 0
@@ -82,17 +136,21 @@
         # and capture the output to the filesystem to avoid that and help with
         # debugging.
         script_path = os.path.join(scripts_dir, script['path'])
-        stdout_path = os.path.join(out_dir, script['name'])
+        combined_path = os.path.join(out_dir, script['name'])
+        stdout_name = '%s.out' % script['name']
+        stdout_path = os.path.join(out_dir, stdout_name)
         stderr_name = '%s.err' % script['name']
         stderr_path = os.path.join(out_dir, stderr_name)
-        proc = run(
-            "%s > %s 2> %s" % (script_path, stdout_path, stderr_path),
-            shell=True)
+
+        proc = Popen(script_path, stdout=PIPE, stderr=PIPE)
+        capture_script_output(proc, combined_path, stdout_path, stderr_path)
+
         if proc.returncode != 0:
             fail_count += 1
         args['exit_status'] = proc.returncode
         args['files'] = {
-            script['name']: open(stdout_path, 'rb').read(),
+            script['name']: open(combined_path, 'rb').read(),
+            stdout_name: open(stdout_path, 'rb').read(),
             stderr_name: open(stderr_path, 'rb').read(),
         }
 

=== modified file 'src/metadataserver/user_data/templates/snippets/maas_wedge_autodetect.sh' (properties changed: +x to -x)
=== modified file 'src/metadataserver/user_data/templates/snippets/tests/test_maas_run_remote_scripts.py'
--- src/metadataserver/user_data/templates/snippets/tests/test_maas_run_remote_scripts.py	2017-02-17 14:23:04 +0000
+++ src/metadataserver/user_data/templates/snippets/tests/test_maas_run_remote_scripts.py	2017-02-28 23:55:43 +0000
@@ -8,10 +8,17 @@
 from io import BytesIO
 import json
 import os
+from pathlib import Path
 import random
+from subprocess import (
+    PIPE,
+    Popen,
+)
 import tarfile
+import time
 from unittest.mock import ANY
 
+from lxml import etree
 from maastesting.factory import factory
 from maastesting.fixtures import TempDirectory
 from maastesting.matchers import (
@@ -22,10 +29,16 @@
 from maastesting.testcase import MAASTestCase
 from snippets import maas_run_remote_scripts
 from snippets.maas_run_remote_scripts import (
+    capture_script_output,
     download_and_extract_tar,
     run_scripts,
     run_scripts_from_metadata,
 )
+from testtools.matchers import (
+    Equals,
+    MatchesAny,
+    MatchesListwise,
+)
 
 
 class TestMaasRunRemoteScripts(MAASTestCase):
@@ -44,12 +57,16 @@
 
     def make_script_output(self, scripts, scripts_dir):
         for script in scripts:
+            output = factory.make_string()
             stdout = factory.make_string()
             stderr = factory.make_string()
+            script['output'] = output.encode()
             script['stdout'] = stdout.encode()
             script['stderr'] = stderr.encode()
-            stdout_path = os.path.join(scripts_dir, script['name'])
+            output_path = os.path.join(scripts_dir, script['name'])
+            stdout_path = os.path.join(scripts_dir, '%s.out' % script['name'])
             stderr_path = os.path.join(scripts_dir, '%s.err' % script['name'])
+            open(output_path, 'w').write(output)
             open(stdout_path, 'w').write(stdout)
             open(stderr_path, 'w').write(stderr)
 
@@ -127,7 +144,9 @@
     def test_run_scripts(self):
         scripts_dir = self.useFixture(TempDirectory()).path
         mock_signal = self.patch(maas_run_remote_scripts, 'signal')
-        mock_run = self.patch(maas_run_remote_scripts, 'run')
+        mock_popen = self.patch(maas_run_remote_scripts, 'Popen')
+        mock_capture_script_output = self.patch(
+            maas_run_remote_scripts, 'capture_script_output')
         scripts = self.make_scripts()
         self.make_script_output(scripts, scripts_dir)
 
@@ -146,11 +165,13 @@
             'error': 'Starting %s [1/1]' % scripts[0]['name'],
         }
         self.assertThat(mock_signal, MockAnyCall(**args))
-        self.assertThat(mock_run, MockCalledOnce())
+        self.assertThat(mock_popen, MockCalledOnce())
+        self.assertThat(mock_capture_script_output, MockCalledOnce())
         # This is a MagicMock
         args['exit_status'] = ANY
         args['files'] = {
-            scripts[0]['name']: scripts[0]['stdout'],
+            scripts[0]['name']: scripts[0]['output'],
+            '%s.out' % scripts[0]['name']: scripts[0]['stdout'],
             '%s.err' % scripts[0]['name']: scripts[0]['stderr'],
         }
         args['error'] = 'Finished %s [1/1]: 1' % scripts[0]['name']
@@ -159,7 +180,8 @@
     def test_run_scripts_signals_failure(self):
         scripts_dir = self.useFixture(TempDirectory()).path
         mock_signal = self.patch(maas_run_remote_scripts, 'signal')
-        self.patch(maas_run_remote_scripts, 'run')
+        self.patch(maas_run_remote_scripts, 'Popen')
+        self.patch(maas_run_remote_scripts, 'capture_script_output')
         scripts = self.make_scripts()
         self.make_script_output(scripts, scripts_dir)
 
@@ -175,3 +197,105 @@
             mock_signal,
             MockAnyCall(
                 None, None, 'FAILED', '1 scripts failed to run'))
+
+
+class TestCaptureScriptOutput(MAASTestCase):
+
+    # Iterate multiple times to shake out spurious failures.
+    scenarios = [
+        ("iteration %d" % iteration, {})
+        for iteration in range(1, 21)
+    ]
+
+    def capture(self, proc):
+        scripts_dir = Path(self.useFixture(TempDirectory()).path)
+        combined_path = scripts_dir.joinpath("combined")
+        stdout_path = scripts_dir.joinpath("stdout")
+        stderr_path = scripts_dir.joinpath("stderr")
+
+        returncode = capture_script_output(
+            proc, str(combined_path), str(stdout_path), str(stderr_path))
+
+        return (
+            returncode,
+            stdout_path.read_text(),
+            stderr_path.read_text(),
+            combined_path.read_text(),
+        )
+
+    def test__captures_script_output(self):
+        proc = Popen(
+            'echo "stdout"; echo "stderr" 1>&2', stdout=PIPE, stderr=PIPE,
+            shell=True)
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("stdout\n"), Equals("stderr\n"),
+                # The writes to stdout and stderr occur so close in time that
+                # they may be received in any order.
+                MatchesAny(
+                    Equals("stdout\nstderr\n"),
+                    Equals("stderr\nstdout\n"),
+                ),
+            )))
+
+    def test__does_not_wait_for_forked_process(self):
+        start_time = time.time()
+        proc = Popen('sleep 6 &', stdout=PIPE, stderr=PIPE, shell=True)
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals(""), Equals(""), Equals(""),
+            )))
+        # A forked process should continue running after capture_script_output
+        # returns. capture_script_output should not block on the forked call.
+        self.assertLess(time.time() - start_time, 3)
+
+    def test__captures_output_from_completed_process(self):
+        # Write to both stdout and stderr.
+        proc = Popen(
+            'echo -n foo >&1 && echo -n bar >&2',
+            stdout=PIPE, stderr=PIPE, shell=True)
+        # Wait for it to finish before capturing.
+        self.assertEquals(0, proc.wait())
+        # Capturing now still gets foo and bar.
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("foo"), Equals("bar"),
+                # The writes to stdout and stderr occur so close in time that
+                # they may be received in any order.
+                MatchesAny(Equals("foobar"), Equals("barfoo")),
+            )))
+
+    def test__captures_stderr_after_stdout_closes(self):
+        # Write to stdout, close stdout, then write to stderr.
+        proc = Popen(
+            'echo -n foo >&1 && exec 1>&- && echo -n bar >&2',
+            stdout=PIPE, stderr=PIPE, shell=True)
+        # Capturing gets the bar even after stdout is closed.
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("foo"), Equals("bar"),
+                # The writes to stdout and stderr occur so close in time that
+                # they may be received in any order.
+                MatchesAny(Equals("foobar"), Equals("barfoo")),
+            )))
+
+    def test__captures_stdout_after_stderr_closes(self):
+        # Write to stderr, close stderr, then write to stdout.
+        proc = Popen(
+            'echo -n bar >&2 && exec 2>&- && echo -n foo >&1',
+            stdout=PIPE, stderr=PIPE, shell=True)
+        # Capturing gets the foo even after stderr is closed.
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("foo"), Equals("bar"),
+                # The writes to stdout and stderr occur so close in time that
+                # they may be received in any order.
+                MatchesAny(Equals("foobar"), Equals("barfoo")),
+            )))
+
+    def test__captures_all_output(self):
+        proc = Popen(("lshw", "-xml"), stdout=PIPE, stderr=PIPE)
+        returncode, stdout, stderr, combined = self.capture(proc)
+        self.assertThat(returncode, Equals(0), stderr)
+        # This is a complete XML document; we've captured all output.
+        self.assertThat(etree.fromstring(stdout).tag, Equals("list"))