When external commands, issued by MAAS, fail, the log output does not give any information about the failure.

When a command fails, the logs should contain:
- the exact command that was run (because, very often, one will be able to re-launch that same command plus debugging enabled to understand what the problem is).
- the error returned by the command

Note that this was done for the power commands (but only for them) in src/provisioningserver/power/poweraction.py:PowerActionFail.

I think this should be generalized and applied to every single call we make to subprocess.check_output and the likes.

Setting this back to "Triaged::High" since it's not actually been fixed for the celery case, which was kind of the point of it.

I can confirm this bug is still alive and kicking: I manually broke the restart_dhcp_server task by changing the name of the restarted service (in /usr/lib/python2.7/dist-packages/provisioningserver/tasks.py) and this is what gets written to /var/log/maas/celery.log when the task runs (and fails) http://paste.ubuntu.com/6919457/

I've been doing this:

CloudFive:/usr/lib/python2.7/dist-packages/provisioningserver/power$ diff -U5 poweraction.py.old poweraction.py
--- poweraction.py.old 2014-02-26 17:33:18.318719677 +0200
+++ poweraction.py 2014-02-26 17:26:50.478738789 +0200
@@ -116,11 +116,14 @@
         # to the individual scripts.
         try:
             output = subprocess.check_output(
                 commands, shell=True, stderr=subprocess.STDOUT, close_fds=True)
         except subprocess.CalledProcessError as e:
- raise PowerActionFail(self, e)
+ paf = PowerActionFail(self, e)
+ with open('/tmp/paf', 'w') as out:
+ out.write(str(paf))
+ raise paf
         # This output is only examined in tests, execute just ignores it
         return output

     def execute(self, **kwargs):
         """Execute the template.

followed by a:

 sudo service maas-cluster-celery restart

which will at least let you see the script and its output.

Of course launchpad seems to eat diffs, but you get the idea :-)

Yay! The rndc failure happened again, but this time I'm seeing the output we need—

«warning: /tmp/tmp7Xz17g/named.conf.rndc.maas:7: couldn't add command channel 127.0.0.1#56314: address in use»

Filing separate bug about that.