When an external command fails, the log doesn't give a clue about what went wrong.

[Raphaël Badin]

We added ExternalProcessError (src/provisioningserver/utils.py) to have more details in the logs about failed commands but it turns out it's not working as expected:

I manually broke the DHCP restart task in /usr/lib/python2.7/dist-packages/provisioningserver/tasks.py and then restarted celery.
@task
def restart_dhcp_server():
    """Restart the DHCP server."""
    call_and_check(['sudo', '-n', 'service', 'maas-dhcp-server', 'restart-boo'])

The log show this:
[2014-01-31 10:04:52,031: ERROR/MainProcess] Task provisioningserver.tasks.restart_dhcp_server[bd099d8e-0a40-4f5b-92ab-16a34bed2564] raised unexpected: ExternalProcessError()
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/celery/app/trace.py", line 218, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/celery/app/trace.py", line 398, in __protected_call__
    return self.run(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/provisioningserver/tasks.py", line 343, in restart_dhcp_server
    call_and_check(['sudo', '-n', 'service', 'maas-dhcp-server', 'restart-boo'])
  File "/usr/lib/python2.7/dist-packages/provisioningserver/utils.py", line 119, in call_and_check
    return subprocess.check_call(command, *args, **kwargs)
  File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
    raise CalledProcessError(retcode, cmd)
ExternalProcessError

No trace of the command run or the return code.

[Raphaël Badin (rvb)]

Marking this bug 'High' because this makes debugging failed external command particularly hard.

[Julian Edwards (julian-edwards)]

This is really a dupe of https://bugs.launchpad.net/maas/+bug/1184589 which is marked fixed but apparently it's not. :)

[Julian Edwards (julian-edwards)]

If you agree, please dupe.

[Graham Binns (gmb)]

Yeah, there's a clear mixup here w.r.t QA'ing that previous bug fix.
It's fixed for all cases where we didn't get enough feedback except
for the case when the lack of feedback came from a process run by
celery... which is exactly what the bug says is the problem. Clearly a
dupe. Sorry.