Merge lp:~julian-edwards/maas/log-celery-exceptions-bug-1184589 into lp:~maas-committers/maas/trunk

[Julian Edwards]

Make sure failing celery jobs log the exception text

I make no apologies for this hideous hack, but when you're dealing with stupidity, you sometimes have to fight with more stupid.

The comment I added at the top of the code will suffice to explain:

# The tasks catch bare exceptions in an attempt to circumvent Celery's
# bizarre exception handling which prints a stack trace but not the
# error message contained in the exception itself! The message is
# printed and then the exception re-raised so that it marks the task as
# failed - in doing so it logs the stack trace, which is why the code
# does not do a simple logger.exception(exc).

[Gavin Panella (allenap)]

Fight Fire With Fire!

review: Approve

[Raphaël Badin (rvb)]

Arg, I had a much simpler idea to fix this :/

[Julian Edwards (julian-edwards)]

On Sunday 02 Mar 2014 01:56:34 you wrote:
> Arg, I had a much simpler idea to fix this :/

And there endeth the lesson of writing your thoughts down on the bug :)

[Raphaël Badin (rvb)]

Here is the idea I had on how to fix the bug:

Celery messes with the error a bit but it still propagates the full original traceback. What I mean is that if you change the value of error_msg from "Task %(name)s[%(id)s] %(description)s: %(exc)s" to "Task %(name)s[%(id)s] %(description)s: %(traceback)s" in /usr/lib/python2.7/dist-packages/celery/worker/job.py:Request you'll see the full error message when a task fails.

We could do this by either monkey patching celery or registering a new log handler.

=== modified file 'src/provisioningserver/tasks.py'
--- src/provisioningserver/tasks.py	2014-02-27 02:33:54 +0000
+++ src/provisioningserver/tasks.py	2014-02-28 04:15:21 +0000
@@ -26,6 +26,7 @@
     'write_full_dns_config',
     ]
 
+from functools import wraps
 from logging import getLogger
 import os
 from subprocess import CalledProcessError
@@ -77,7 +78,27 @@
 logger = getLogger(__name__)
 
 
+# The tasks catch bare exceptions in an attempt to circumvent Celery's
+# bizarre exception handling which prints a stack trace but not the
+# error message contained in the exception itself!  The message is
+# printed and then the exception re-raised so that it marks the task as
+# failed - in doing so it logs the stack trace, which is why the code
+# does not do a simple logger.exception(exc).
+def log_exception_text(func):
+    """Wrap a function and log any exception text raised."""
+    @wraps(func)
+    def wrapper(*args, **kwargs):
+        try:
+            func(*args, **kwargs)
+        except Exception as e:
+            logger.error("%s: %s", func.__name__, unicode(e))
+            raise
+    return wrapper
+
+
+
 @task
+@log_exception_text
 def refresh_secrets(**kwargs):
     """Update the worker's knowledge of various secrets it needs.
 
@@ -152,12 +173,14 @@
 
 
 @task
+@log_exception_text
 def power_on(power_type, **kwargs):
     """Turn a node on."""
     issue_power_action(power_type, 'on', **kwargs)
 
 
 @task
+@log_exception_text
 def power_off(power_type, **kwargs):
     """Turn a node off."""
     issue_power_action(power_type, 'off', **kwargs)
@@ -175,6 +198,7 @@
 
 
 @task(max_retries=RNDC_COMMAND_MAX_RETRY, queue=celery_config.WORKER_QUEUE_DNS)
+@log_exception_text
 def rndc_command(arguments, retry=False, callback=None):
     """Use rndc to execute a command.
     :param arguments: Argument list passed down to the rndc command.
@@ -186,17 +210,19 @@
     """
     try:
         execute_rndc_command(arguments)
-    except CalledProcessError, exc:
+    except CalledProcessError as exc:
         if retry:
             return rndc_command.retry(
                 exc=exc, countdown=RNDC_COMMAND_RETRY_DELAY)
         else:
+            logger.error("rndc_command failed: %s", unicode(exc))
             raise
     if callback is not None:
         callback.delay()
 
 
 @task(queue=celery_config.WORKER_QUEUE_DNS)
+@log_exception_text
 def write_full_dns_config(zones=None, callback=None, **kwargs):
     """Write out the DNS configuration files: the main configuration
     file and the zone files.
@@ -219,6 +245,7 @@
 
 
 @task(queue=celery_config.WORKER_QUEUE_DNS)
+@log_exception_text
 def write_dns_config(zones=(), callback=None, **kwargs):
     """Write out the DNS configuration file.
 
@@ -236,6 +263,7 @@
 
 
 @task(queue=celery_config.WORKER_QUEUE_DNS)
+@log_exception_text
 def write_dns_zone_config(zones, callback=None, **kwargs):
     """Write out DNS zones.
 
@@ -252,6 +280,7 @@
 
 
 @task(queue=celery_config.WORKER_QUEUE_DNS)
+@log_exception_text
 def setup_rndc_configuration(callback=None):
     """Write out the two rndc configuration files (rndc.conf and
     named.conf.rndc).
@@ -270,6 +299,7 @@
 
 
 @task
+@log_exception_text
 def upload_dhcp_leases():
     """Upload DHCP leases.
 
@@ -280,6 +310,7 @@
 
 
 @task
+@log_exception_text
 def add_new_dhcp_host_map(mappings, server_address, shared_key):
     """Add address mappings to the DHCP server.
 
@@ -295,15 +326,17 @@
     try:
         for ip_address, mac_address in mappings.items():
             omshell.create(ip_address, mac_address)
-    except CalledProcessError:
+    except CalledProcessError as e:
         # TODO signal to webapp that the job failed.
 
         # Re-raise, so the job is marked as failed.  Only currently
         # useful for tests.
+        logger.error("add_new_dhcp_host_map failed: %s", unicode(e))
         raise
 
 
 @task
+@log_exception_text
 def remove_dhcp_host_map(ip_address, server_address, omapi_key):
     """Remove an IP to MAC mapping in the DHCP server.
 
@@ -317,15 +350,17 @@
     omshell = Omshell(server_address, omapi_key)
     try:
         omshell.remove(ip_address)
-    except CalledProcessError:
+    except CalledProcessError as e:
         # TODO signal to webapp that the job failed.
 
         # Re-raise, so the job is marked as failed.  Only currently
         # useful for tests.
+        logger.error("remove_dhcp_host_map failed: %s", unicode(e))
         raise
 
 
 @task
+@log_exception_text
 def write_dhcp_config(callback=None, **kwargs):
     """Write out the DHCP configuration file and restart the DHCP server.
 
@@ -342,18 +377,21 @@
 
 
 @task
+@log_exception_text
 def restart_dhcp_server():
     """Restart the DHCP server."""
     call_and_check(['sudo', '-n', 'service', 'maas-dhcp-server', 'restart'])
 
 
 @task
+@log_exception_text
 def stop_dhcp_server():
     """Stop a DHCP server."""
     call_and_check(['sudo', '-n', 'service', 'maas-dhcp-server', 'stop'])
 
 
 @task
+@log_exception_text
 def periodic_probe_dhcp():
     """Probe for foreign DHCP servers."""
     detect.periodic_probe_task()
@@ -365,6 +403,7 @@
 
 
 @task
+@log_exception_text
 def report_boot_images():
     """For master worker only: report available netboot images."""
     boot_images.report_to_server()
@@ -383,6 +422,7 @@
 
 
 @task(max_retries=UPDATE_NODE_TAGS_MAX_RETRY)
+@log_exception_text
 def update_node_tags(tag_name, tag_definition, tag_nsmap, retry=True):
     """Update the nodes for a new/changed tag definition.
 
@@ -405,6 +445,7 @@
 # =====================================================================
 
 @task
+@log_exception_text
 def import_boot_images(http_proxy=None, main_archive=None, ports_archive=None,
                        cloud_images_archive=None):
     env = dict(os.environ)
@@ -425,6 +466,7 @@
 # =====================================================================
 
 @task
+@log_exception_text
 def add_seamicro15k(mac, username, password):
     """ See `maasserver.api.NodeGroupsHandler.add_seamicro15k`. """
     ip = find_ip_via_arp(mac)