[task] Fix verification log

While fix for bug #1562713 changed the way how to save verification log in
case of some issues at CLI layer, it did not fixed old saved logs. Also, it
produced one more bug - IOError trace was saved as list instead of string.

This patch fixes the way of storage IOError and add migration to fix old data

Also, we change format of verification_log to dict here
Change-Id: Iffcf066e7033acd48f1446baebe0b2e9a334449f
Related-Bug: #1562713

rally/cli/commands/task.py

@@ -138,7 +138,7 @@ class TaskCommands(object):
             if task_instance:
                 task_instance.set_failed(err.__class__.__name__,
                                          str(err),
-                                         json.dumps(traceback.format_stack()))
+                                         json.dumps(traceback.format_exc()))
             raise
         api.Task.validate(deployment, input_task, task_instance)
         print(_("Task config is valid :)"))
@@ -325,11 +325,11 @@ class TaskCommands(object):
             print("-" * 80)
             verification = yaml.safe_load(task["verification_log"])
             if logging.is_debug():
-                print(yaml.safe_load(verification[2]))
+                print(yaml.safe_load(verification["trace"]))
             else:
-                print(verification[0])
-                print(verification[1])
-                print(_("\nFor more details run:\nrally -vd task detailed %s")
+                print(verification["etype"])
+                print(verification["msg"])
+                print(_("\nFor more details run:\nrally -d task detailed %s")
                       % task["uuid"])
             return 0
         elif task["status"] not in [consts.TaskStatus.FINISHED,

rally/common/db/sqlalchemy/migrations/script.py.mako

@@ -1,3 +1,17 @@
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
 """${message}
 
 Revision ID: ${up_revision}
@@ -16,9 +30,12 @@ from alembic import op
 import sqlalchemy as sa
 ${imports if imports else ""}
 
+${"from rally import exceptions" if not downgrades else ""}
+
+
 def upgrade():
     ${upgrades if upgrades else "pass"}
 
 
 def downgrade():
-    ${downgrades if downgrades else "pass"}
+    ${downgrades if downgrades else "raise exceptions.DowngradeNotSupported()"}

rally/common/db/sqlalchemy/migrations/versions/08e1515a576c_fix_invalid_verification_logs.py

@@ -0,0 +1,112 @@
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+"""fix invalid verification logs
+
+Revision ID: 08e1515a576c
+Revises: 54e844ebfbc3
+Create Date: 2016-09-12 15:47:11.279610
+
+"""
+
+# revision identifiers, used by Alembic.
+revision = "08e1515a576c"
+down_revision = "54e844ebfbc3"
+branch_labels = None
+depends_on = None
+
+
+import json
+import uuid
+
+from alembic import op
+import sqlalchemy as sa
+
+from rally import consts
+from rally import exceptions
+
+
+def UUID():
+    return str(uuid.uuid4())
+
+
+task_helper = sa.Table(
+    "tasks",
+    sa.MetaData(),
+    sa.Column("id", sa.Integer, primary_key=True, autoincrement=True),
+    sa.Column("uuid", sa.String(36), default=UUID, nullable=False),
+    sa.Column("status", sa.Enum(*list(consts.TaskStatus),
+                                name="enum_tasks_status"),
+              default=consts.TaskStatus.INIT, nullable=False),
+    sa.Column("verification_log", sa.Text, default=""),
+    sa.Column("tag", sa.String(64), default=""),
+    sa.Column("deployment_uuid", sa.String(36), nullable=False)
+)
+
+
+def _make_trace(etype, emsg, raw_trace=None):
+    trace = "Traceback (most recent call last):\n"
+    if raw_trace is None:
+        trace += "\n\t\t...n/a..\n\n"
+    else:
+        trace += "".join(json.loads(raw_trace))
+
+    trace += "%s: %s" % (etype, emsg)
+    return trace
+
+
+def upgrade():
+    connection = op.get_bind()
+    for task in connection.execute(task_helper.select()):
+        verification_log = task.verification_log
+
+        if not verification_log:
+            continue
+
+        new_value = None
+
+        verification_log = json.loads(verification_log)
+        if isinstance(verification_log, list):
+            new_value = {"etype": verification_log[0],
+                         "msg": verification_log[1],
+                         "trace": verification_log[2]}
+            if new_value["trace"].startswith("["):
+                # NOTE(andreykurilin): For several cases traceback was
+                #   transmitted as list instead of string.
+                new_value["trace"] = _make_trace(*verification_log)
+        else:
+            if verification_log.startswith("No such file"):
+                new_value = {"etype": IOError.__name__,
+                             "msg": verification_log}
+                new_value["trace"] = _make_trace(new_value["etype"],
+                                                 new_value["msg"])
+            elif verification_log.startswith("Task config is invalid"):
+                new_value = {"etype": exceptions.InvalidTaskException.__name__,
+                             "msg": verification_log}
+                new_value["trace"] = _make_trace(new_value["etype"],
+                                                 new_value["msg"])
+            elif verification_log.startswith("Failed to load task"):
+                new_value = {"etype": "FailedToLoadTask",
+                             "msg": verification_log}
+                new_value["trace"] = _make_trace(new_value["etype"],
+                                                 new_value["msg"])
+
+        if new_value:
+            connection.execute(task_helper.update().where(
+                task_helper.c.id == task.id).values(
+                verification_log=json.dumps(new_value)))
+
+
+def downgrade():
+    raise exceptions.DowngradeNotSupported()

rally/common/objects/task.py

@@ -350,10 +350,8 @@ class Task(object):
 
     def set_failed(self, etype, msg, etraceback):
         self._update({"status": consts.TaskStatus.FAILED,
-                      "verification_log": json.dumps([etype,
-                                                      msg,
-                                                      etraceback
-                                                      ])})
+                      "verification_log": json.dumps(
+                          {"etype": etype, "msg": msg, "trace": etraceback})})
 
     def get_results(self):
         return db.task_result_get_all_by_uuid(self.task["uuid"])

tests/unit/cli/commands/test_task.py

@@ -324,8 +324,9 @@ class TaskCommandsTestCase(test.TestCase):
             "uuid": test_uuid,
             "status": consts.TaskStatus.FAILED,
             "results": [],
-            "verification_log": json.dumps(["error_type", "error_message",
-                                            "error_traceback"])
+            "verification_log": json.dumps({"etype": "error_type",
+                                            "msg": "error_message",
+                                            "trace": "error_traceback"})
         }
         mock_task.get_detailed = mock.MagicMock(return_value=value)
 
@@ -334,14 +335,14 @@ class TaskCommandsTestCase(test.TestCase):
         verification = yaml.safe_load(value["verification_log"])
         if debug:
             expected_calls = [mock.call("Task test_task_id: failed"),
-                              mock.call("%s" % verification[2])]
+                              mock.call("%s" % verification["trace"])]
             mock_stdout.write.assert_has_calls(expected_calls, any_order=True)
         else:
             expected_calls = [mock.call("Task test_task_id: failed"),
-                              mock.call("%s" % verification[0]),
-                              mock.call("%s" % verification[1]),
+                              mock.call("%s" % verification["etype"]),
+                              mock.call("%s" % verification["msg"]),
                               mock.call("\nFor more details run:\nrally "
-                                        "-vd task detailed %s" % test_uuid)]
+                                        "-d task detailed %s" % test_uuid)]
             mock_stdout.write.assert_has_calls(expected_calls, any_order=True)
 
     @mock.patch("rally.cli.commands.task.api.Task")

tests/unit/common/db/test_migrations.py

@@ -383,3 +383,76 @@ class MigrationWalkTestCase(rtest.DBTestCase,
                     deployment_table.delete().where(
                         deployment_table.c.uuid == deployment.uuid)
                 )
+
+    def _pre_upgrade_08e1515a576c(self, engine):
+        self._08e1515a576c_logs = [
+            {"pre": "No such file name",
+             "post": {"etype": IOError.__name__, "msg": "No such file name"}},
+            {"pre": "Task config is invalid: bla",
+             "post": {"etype": "InvalidTaskException",
+                      "msg": "Task config is invalid: bla"}},
+            {"pre": "Failed to load task foo",
+             "post": {"etype": "FailedToLoadTask",
+                      "msg": "Failed to load task foo"}},
+            {"pre": ["SomeCls", "msg", json.dumps(
+                ["File some1.py, line ...\n",
+                 "File some2.py, line ...\n"])],
+             "post": {"etype": "SomeCls",
+                      "msg": "msg",
+                      "trace": "Traceback (most recent call last):\n"
+                               "File some1.py, line ...\n"
+                               "File some2.py, line ...\nSomeCls: msg"}},
+        ]
+
+        deployment_table = db_utils.get_table(engine, "deployments")
+        task_table = db_utils.get_table(engine, "tasks")
+
+        self._08e1515a576c_deployment_uuid = "08e1515a576c-uuuu-uuuu-iiii-dddd"
+        with engine.connect() as conn:
+            conn.execute(
+                deployment_table.insert(),
+                [{"uuid": self._08e1515a576c_deployment_uuid,
+                  "name": self._08e1515a576c_deployment_uuid,
+                  "config": six.b("{}"),
+                  "enum_deployments_status":
+                      consts.DeployStatus.DEPLOY_FINISHED,
+                  "credentials": six.b(json.dumps([])),
+                  "users": six.b(json.dumps([]))
+                  }])
+            for i in range(0, len(self._08e1515a576c_logs)):
+                log = json.dumps(self._08e1515a576c_logs[i]["pre"])
+                conn.execute(
+                    task_table.insert(),
+                    [{"uuid": i,
+                      "verification_log": log,
+                      "status": consts.TaskStatus.FAILED,
+                      "enum_tasks_status": consts.TaskStatus.FAILED,
+                      "deployment_uuid": self._08e1515a576c_deployment_uuid
+                      }])
+
+    def _check_08e1515a576c(self, engine, data):
+        self.assertEqual("08e1515a576c",
+                         api.get_backend().schema_revision(engine=engine))
+
+        tasks = self._08e1515a576c_logs
+
+        deployment_table = db_utils.get_table(engine, "deployments")
+        task_table = db_utils.get_table(engine, "tasks")
+
+        with engine.connect() as conn:
+            tasks_found = conn.execute(task_table.select()).fetchall()
+            for task in tasks_found:
+                actual_log = json.loads(task.verification_log)
+                self.assertIsInstance(actual_log, dict)
+                expected = tasks[int(task.uuid)]["post"]
+                for key in expected:
+                    self.assertEqual(expected[key], actual_log[key])
+
+                conn.execute(
+                    task_table.delete().where(task_table.c.uuid == task.uuid))
+
+            deployment_uuid = self._08e1515a576c_deployment_uuid
+            conn.execute(
+                deployment_table.delete().where(
+                    deployment_table.c.uuid == deployment_uuid)
+            )

tests/unit/common/objects/test_task.py

@@ -249,8 +249,9 @@ class TaskTestCase(test.TestCase):
         mock_task_update.assert_called_once_with(
             self.task["uuid"],
             {"status": consts.TaskStatus.FAILED,
-             "verification_log": "[\"foo_type\", \"foo_error_message\", "
-                                 "\"foo_trace\"]"},
+             "verification_log": json.dumps({"etype": "foo_type",
+                                             "msg": "foo_error_message",
+                                             "trace": "foo_trace"})},
         )
 
     @ddt.data(