Merge pull request #130 from pricingassistant/traceback_histories

Traceback histories

Author: sylvinus

mrq/config.py

@@ -419,6 +419,7 @@ def get_config(
                 from_args[k] = v
 
     # If we were given another config file, use it
+
     if file_path is not None:
         config_file = file_path
     elif from_args.get("config"):

mrq/dashboard/app.py

@@ -286,15 +286,27 @@ def api_job_result(job_id):
 @app.route('/api/job/<job_id>/traceback')
 @requires_auth
 def api_job_traceback(job_id):
-    collection = connections.mongodb_jobs.mrq_jobs
+    collection = connections.mongodb_jobs.mrq_jobss
+    if get_current_config().get("save_traceback_history"):
+
+        field_sent = "traceback_history"
+    else:
+        field_sent = "traceback"
+
     job_data = collection.find_one(
-        {"_id": ObjectId(job_id)}, projection=["traceback"])
+        {"_id": ObjectId(job_id)}, projection=[field_sent])
 
     if not job_data:
-        job_data = {}
+        # If a job has no traceback history, we fallback onto traceback
+        if field_sent == "traceback_history":
+            field_sent = "traceback"
+            job_data = collection.find_one(
+                {"_id": ObjectId(job_id)}, projection=[field_sent])
+        if not job_data:
+            job_data = {}
 
     return jsonify({
-        "traceback": job_data.get("traceback", "No exception raised")
+        field_sent: job_data.get(field_sent, "No exception raised")
     })
 
 

mrq/dashboard/static/js/views/jobs.js

@@ -56,8 +56,14 @@ define(["jquery", "underscore", "views/generic/datatablepage", "models"],functio
       $.ajax("/api/job/"+jobId+"/traceback", {
         "type": "GET",
         "success": function(data) {
-          var stack = self.format_traceback(data["traceback"]);
-          self.$(".js-jobs-modal .js-jobs-modal-content").html(stack);
+          if (data["traceback"]) {
+            var stack = self.format_traceback(data["traceback"]);
+            self.$(".js-jobs-modal .js-jobs-modal-content").html(stack);
+          }
+          else {
+            var stack = self.format_traceback_history(data["traceback_history"]);
+            self.$(".js-jobs-modal .js-jobs-modal-content").html(stack);
+          }
           self.$(".js-jobs-modal h4").html("Stack Trace");
           self.$(".js-jobs-modal").modal({});
         },
@@ -129,7 +135,21 @@ define(["jquery", "underscore", "views/generic/datatablepage", "models"],functio
 
       return stack;
     },
-
+    format_traceback_history: function(stacks) {
+      var self = this;
+      var full_history = "";
+      _.each(stacks, function(stack) {
+        full_history += "<br/><b>" + stack["date"] + "</b><br/>";
+        if (stack["original_traceback"]) {
+          full_history += "<b>Original trace</b>";
+          full_history += self.format_traceback(stack["original_traceback"] || "");
+        }
+        full_history += "<b>Trace</b>" + "<br/>";
+        full_history += self.format_traceback(stack["traceback"] || "");
+        full_history += "---------------------------------------------------------------------" + "<br/>";
+      });
+      return full_history;
+    },
     row_jobaction:function(evt) {
       evt.preventDefault();
       evt.stopPropagation();

mrq/job.py

@@ -203,7 +203,7 @@ def insert(cls, jobs_data, queue=None, statuses_no_storage=None, return_jobs=Tru
 
     def _attach_original_exception(self, exc):
         """ Often, a retry will be raised inside an "except" block.
-            This Keep track of the first exception for debugging purposes. """
+            This Keep track of the first exception for debugging purposes """
 
         original_exception = sys.exc_info()
         if original_exception[0] is not None:
@@ -350,6 +350,27 @@ def save_retry(self, retry_exc):
 
             self._save_status("retry", updates, exception=True)
 
+    def _save_traceback_history(self, status, trace, job_exc):
+        """ Create traceback history or add a new traceback to history. """
+        failure_date = datetime.datetime.utcnow()
+
+        new_history = {
+            "date": failure_date,
+            "status": status,
+            "exceptiontype": job_exc.__name__
+        }
+
+        traces = trace.split("---- Original exception: -----")
+        if len(traces) > 1:
+            new_history["original_traceback"] = traces[1]
+        worker = context.get_current_worker()
+        if worker:
+            new_history["worker"] = worker.id
+        new_history["traceback"] = traces[0]
+        self.collection.update({
+            "_id": self.id
+        }, {"$push": {"traceback_history": new_history}})
+
     def save_success(self, result=None):
 
         dateexpires = datetime.datetime.utcnow() + datetime.timedelta(seconds=self.result_ttl)
@@ -413,7 +434,12 @@ def _save_status(self, status, updates=None, exception=False, w=None, j=None):
             trace = traceback.format_exc()
             context.log.error(trace)
             db_updates["traceback"] = trace
-            db_updates["exceptiontype"] = sys.exc_info()[0].__name__
+            exc = sys.exc_info()[0]
+            db_updates["exceptiontype"] = exc.__name__
+
+            if context.get_current_config().get("save_traceback_history"):
+
+                self._save_traceback_history(status, trace, exc)
 
         # In the most common case, we allow an optimization on Mongo writes
         if status == "success":

tests/fixtures/config-tracebackhistory.py

@@ -0,0 +1 @@
+SAVE_TRACEBACK_HISTORY = True

tests/tasks/general.py

@@ -12,7 +12,6 @@
 class Add(Task):
 
     def run(self, params):
-
         log.info("adding", params)
         res = params.get("a", 0) + params.get("b", 0)
 
@@ -86,6 +85,30 @@ def run(self, params):
         raise Exception("Should not be reached")
 
 
+class InRetryException(BaseException):
+    pass
+
+
+class RetryOnFailed(Task):
+
+    def run(self, params):
+
+        log.info("Retrying in %s on %s" %
+                 (params.get("delay"), params.get("queue")))
+
+        connections.mongodb_jobs.tests_inserts.insert(params)
+        try:
+            raise InRetryException
+        except InRetryException:
+            retry_current_job(
+                queue=params.get("queue"),
+                delay=params.get("delay"),
+                max_retries=params.get("max_retries")
+            )
+
+        raise Exception("Should not be reached")
+
+
 class WaitForFlag(Task):
 
     def run(self, params):

tests/test_retry.py

@@ -159,3 +159,36 @@ def test_retry_max_retries_zero(worker):
 
     job = Job(job_id).fetch()
     assert job.data["status"] == "maxretries"
+
+
+def test_retry_traceback_history(worker):
+
+    worker.start(flags="--config tests/fixtures/config-tracebackhistory.py")
+    # delay = 0 should requeue right away.
+
+    worker.send_task(
+        "tests.tasks.general.Retry", {"queue": "noexec", "delay": 60}, block=True, accept_statuses=["retry"]
+    )
+
+    job = worker.mongodb_jobs.mrq_jobs.find()[0]
+
+    assert len(job["traceback_history"]) == 1
+    assert not job["traceback_history"][0].get("original_traceback")
+
+    worker.send_task(
+        "tests.tasks.general.RetryOnFailed", {"queue": "default", "delay": 1}, block=True, accept_statuses=["retry"]
+    )
+
+    job = worker.mongodb_jobs.mrq_jobs.find({
+        "path": "tests.tasks.general.RetryOnFailed"})[0]
+
+    assert len(job["traceback_history"]) == 1
+    assert "InRetryException" in job["traceback_history"][0].get("original_traceback")
+    time.sleep(2)
+    worker.send_task("mrq.basetasks.cleaning.RequeueRetryJobs", {}, block=True)
+    time.sleep(2)
+    job = worker.mongodb_jobs.mrq_jobs.find({
+        "path": "tests.tasks.general.RetryOnFailed"})[0]
+
+    assert len(job["traceback_history"]) == 2
+    assert job["traceback_history"][0]["date"] < job["traceback_history"][1]["date"]