Mark abandoned tasks as "failed" #1649

mdellweg · 2021-09-27T12:48:42Z

fixes #9247

pulpbot · 2021-09-27T12:49:09Z

Attached issue: https://pulp.plan.io/issues/9247

dralley · 2021-09-27T14:26:33Z

When I trigger a failure, the task status is correct, but in the logs it looks like it's "failing" when it tries to save a null state.

Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/home/vagrant/devel/pulpcore/pulpcore/tasking/entrypoint.py", line 46, in worker
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     NewPulpWorker().run_forever()
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/home/vagrant/devel/pulpcore/pulpcore/tasking/pulpcore_worker.py", line 308, in run_forever
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290187]: pulp [None]: pulpcore.tasking.pulpcore_worker:INFO: Cleaning up and canceling Task 5faa90e3-8c9a-483a-9467-3ab894a8b82d
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     self.supervise_task(task)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/home/vagrant/devel/pulpcore/pulpcore/tasking/pulpcore_worker.py", line 297, in supervise_task
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     self.cancel_abandoned_task(task, cancel_state)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/home/vagrant/devel/pulpcore/pulpcore/tasking/pulpcore_worker.py", line 150, in cancel_abandoned_task
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     Task.objects.filter(pk=task.pk, state=TASK_STATES.CANCELING).update(state=final_state)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/models/query.py", line 783, in update
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     rows = query.get_compiler(self.db).execute_sql(CURSOR)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 1559, in execute_sql
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     cursor = super().execute_sql(result_type)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/models/sql/compiler.py", line 1175, in execute_sql
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     cursor.execute(sql, params)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/backends/utils.py", line 66, in execute
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     return executor(sql, params, many, context)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     return self.cursor.execute(sql, params)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/utils.py", line 90, in __exit__
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     raise dj_exc_value.with_traceback(traceback) from exc_value
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:   File "/usr/local/lib/pulp/lib64/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]:     return self.cursor.execute(sql, params)
Sep 27 14:24:29 pulp3-source-fedora34.localhost.example.com pulpcore-worker[290186]: django.db.utils.IntegrityError: null value in column "state" of relation "core_task" violates not-null constraint

mdellweg · 2021-09-27T15:07:53Z

When I trigger a failure, the task status is correct, but in the logs it looks like it's "failing" when it tries to save a null state.

Yeah, i can see, where that is coming from.

dralley · 2021-09-27T15:19:16Z

It works now, but the logs are still a bit misleading. When the task aborts / disappears, it still prints "Cleaning up and canceling Task ..." when it should say that it's moving to failed.

mdellweg · 2021-09-27T15:21:38Z

@dralley how about that?

dralley · 2021-09-27T15:25:49Z

pulpcore/tasking/pulpcore_worker.py

        Task.objects.filter(pk=task.pk, state=TASK_STATES.RUNNING).update(
            state=TASK_STATES.CANCELING
        )
        task.refresh_from_db()
        if task.state == TASK_STATES.CANCELING:
+            _logger.info(_("Cleaning up Task %s and marking as %s"), task.pk, final_state)


Can we make the capitalization of Task consistent with the other messages?

dralley

Manually tested with:

SIGABRT from within task (os.abort())
SIGKILL (sudo kill -9 $pid)
Python exception from within task
Task cancellation

It works and logs appropriate messages in all situations, thank you

dralley · 2021-09-27T16:12:29Z

I think we're still missing a small piece of functionality that had been discussed earlier. It logs "Cleaning up X and marking as failed" but there is no message to call out that the worker process disappeared

https://pulp.plan.io/issues/9247#note-3

mdellweg · 2021-09-28T08:35:33Z

I now see the following:

[
  {
    "pulp_href": "/pulp/api/v3/tasks/0d01973a-56b1-472d-9347-b4b7ecad05d6/",
    "pulp_created": "2021-09-28T08:33:27.907425Z",
    "state": "canceled",
    "name": "pulp_herminig.app.tasks.benchmark.test_task",
    "logging_cid": "8825c817a34d4406b79e0e739044cd63",
    "started_at": "2021-09-28T08:33:27.940186Z",
    "finished_at": "2021-09-28T08:33:47.087975Z",
    "error": null,
    "worker": "/pulp/api/v3/workers/e69b0e8b-9776-4ce9-a3b4-942f0648654f/",
    "parent_task": null,
    "child_tasks": [],
    "task_group": "/pulp/api/v3/task-groups/809b3b41-e269-4cab-9efc-032c06ecb299/",
    "progress_reports": [],
    "created_resources": [],
    "reserved_resources_record": []
  },
  {
    "pulp_href": "/pulp/api/v3/tasks/d9d0b347-30db-4874-9409-e018b05cb33f/",
    "pulp_created": "2021-09-28T08:31:43.734470Z",
    "state": "failed",
    "name": "pulp_herminig.app.tasks.benchmark.test_task",
    "logging_cid": "01129c8ff3cd4670ab8c52fb67787676",
    "started_at": "2021-09-28T08:31:49.073222Z",
    "finished_at": "2021-09-28T08:31:55.766986Z",
    "error": {
      "reason": "Worker has gone missing."
    },
    "worker": "/pulp/api/v3/workers/52c0900b-0297-4a5a-976c-bdf2195446f6/",
    "parent_task": null,
    "child_tasks": [],
    "task_group": "/pulp/api/v3/task-groups/45239142-7dce-46f5-8b11-a3d38c862ba1/",
    "progress_reports": [],
    "created_resources": [],
    "reserved_resources_record": []
  },
  {
    "pulp_href": "/pulp/api/v3/tasks/d4fc9f51-cbe1-4dfd-bfe2-b81a32ca7b74/",
    "pulp_created": "2021-09-28T08:30:34.706707Z",
    "state": "failed",
    "name": "pulp_herminig.app.tasks.benchmark.test_task",
    "logging_cid": "3310ff88568e474d9f1141535c879220",
    "started_at": "2021-09-28T08:30:34.754476Z",
    "finished_at": "2021-09-28T08:30:59.025217Z",
    "error": {
      "reason": "Aborted during worker shutdown."
    },
    "worker": null,
    "parent_task": null,
    "child_tasks": [],
    "task_group": "/pulp/api/v3/task-groups/a8ab99cc-6de5-409d-a76f-5ec217e17779/",
    "progress_reports": [],
    "created_resources": [],
    "reserved_resources_record": []
  }
]

dralley · 2021-09-28T13:46:33Z

pulpcore/tasking/pulpcore_worker.py

        Task.objects.filter(pk=task.pk, state=TASK_STATES.RUNNING).update(
            state=TASK_STATES.CANCELING
        )
        task.refresh_from_db()
        if task.state == TASK_STATES.CANCELING:
+            _logger.info(_("Cleaning up task %s and marking as %s"), task.pk, final_state)


In the event of failed task (or code-wise perhaps if reason), could we have this message print {...} marking as failed. reason: Worker has gone missing.

Something like

if reason: msg = _("Cleaning up task %s and marking as %s. Reason: %s") args = (task.pk, final_state, reason) else: msg = _("Cleaning up task %s and marking as %s.) args = (task.pk, final_state) _logger.info(msg, *args)

A clearer log message would be nice.

fixes #9247

bmbouter · 2021-09-28T14:09:36Z

pulpcore/tasking/pulpcore_worker.py

@@ -129,26 +129,39 @@ def beat(self):
    def notify_workers(self):
        self.cursor.execute("NOTIFY pulp_worker_wakeup")

-    def cancel_abandoned_task(self, task):
+    def cancel_abandoned_task(self, task, final_state, reason=None):


Can this method get args and kwargs docs?

bmbouter · 2021-09-28T14:10:02Z

pulpcore/tasking/pulpcore_worker.py

        """Cancel and clean up an abandoned task.

-        This function must only be called while holding the lock for that task.
+        This function must only be called while holding the lock for that task. It is a no-op if
+        the task is neither in "running" nor "canceling" state.

        Return ``True`` if the task was actually canceled, ``False`` otherwise.


This could also follow the napolean docstring format.

bmbouter

I hand tested this and it worked well. I saw Cleaning up Task b087bd6f-dc8c-45e3-9984-e70b598159f1 and marking as failed in my logs and the task state was at failed. Thanks @mdellweg !

salman8328 · 2023-05-19T14:21:11Z

hey !,
when the worker goes missing, the task is shown as failed, but the task list shows a few sub-tasks are still running, as shown below:

{
"pulp_href": "/pulp/api/v3/tasks/9f53c6f6-bc00-4da0-b2e7-67175486b7ba/",
"pulp_created": "2023-05-17T13:30:42.169868Z",
"state": "failed",
"name": "pulp_rpm.app.tasks.synchronizing.synchronize",
"logging_cid": "9dd033c5e9234b0aa9d4ad95ff90867f",
"started_at": "2023-05-17T13:30:42.220159Z",
"finished_at": "2023-05-19T05:35:58.765626Z",
"error": {
"reason": "Worker has gone missing."
},
"worker": null,
"parent_task": null,
"child_tasks": [],
"task_group": null,
"progress_reports": [
{
"message": "Downloading Artifacts",
"code": "sync.downloading.artifacts",
"state": "running",
"total": null,
"done": 7872,
"suffix": null
},
{
"message": "Parsed Advisories",
"code": "sync.parsing.advisories",
"state": "completed",
"total": 986,
"done": 986,
"suffix": null
},
{
"message": "Parsed Modulemd",
"code": "sync.parsing.modulemds",
"state": "completed",
"total": 45,
"done": 45,
"suffix": null
},
{
"message": "Parsed Modulemd-defaults",
"code": "sync.parsing.modulemd_defaults",
"state": "completed",
"total": 7,
"done": 7,
"suffix": null
},
{
"message": "Parsed Modulemd Obsolete",
"code": "sync.parsing.modulemd_obsoletes",
"state": "completed",
"total": 0,
"done": 0,
"suffix": null
},
{
"message": "Skipping Packages",
"code": "sync.skipped.packages",
"state": "completed",
"total": 0,
"done": 0,
"suffix": null
},
{
"message": "Parsed Packages",
"code": "sync.parsing.packages",
"state": "completed",
"total": 8267,
"done": 8267,
"suffix": null
},
{
"message": "Downloading Metadata Files",
"code": "sync.downloading.metadata",
"state": "completed",
"total": null,
"done": 6,
"suffix": null
},
{
"message": "Associating Content",
"code": "associating.content",
"state": "running",
"total": null,
"done": 9005,
"suffix": null
}
],
"created_resources": [],
"reserved_resources_record": [
"/pulp/api/v3/repositories/rpm/rpm/dbf41fe8-c225-453a-9f5f-b339715b263c/",
"shared:/pulp/api/v3/remotes/rpm/rpm/7bd62f03-318e-417a-ae03-00d64d16e5df/"
]
},

this could be just a display issue but it is really confusing to see, running there.

and after the worker goes missing, the pulp worker list endpoint still shows the state=missing workers in worker list, which is pretty weird.

will these workers be deleted later on ? or will pulp still try to wait for those workers to be online indefinetly?

@dralley, thank you !

dralley · 2023-05-19T14:36:19Z

They're not subtasks, just progress reports. Issue is filed here #3609

I think the workers do get cleaned up automatically after a week or so.

mdellweg force-pushed the fail_abandoned_tasks branch from 319fc7d to a62f01a Compare September 27, 2021 15:09

mdellweg force-pushed the fail_abandoned_tasks branch from a62f01a to 8535242 Compare September 27, 2021 15:21

dralley reviewed Sep 27, 2021

View reviewed changes

dralley approved these changes Sep 27, 2021

View reviewed changes

mdellweg force-pushed the fail_abandoned_tasks branch from 8535242 to 8297aa6 Compare September 28, 2021 08:34

dralley reviewed Sep 28, 2021

View reviewed changes

dkliban requested a review from bmbouter September 28, 2021 13:51

Mark abandoned tasks as "failed"

6da67a5

fixes #9247

mdellweg force-pushed the fail_abandoned_tasks branch from 8297aa6 to 6da67a5 Compare September 28, 2021 14:08

bmbouter reviewed Sep 28, 2021

View reviewed changes

dralley approved these changes Sep 28, 2021

View reviewed changes

bmbouter approved these changes Sep 28, 2021

View reviewed changes

bmbouter merged commit 6fb9109 into pulp:master Sep 28, 2021

mdellweg deleted the fail_abandoned_tasks branch September 28, 2021 20:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Mark abandoned tasks as "failed" #1649

Mark abandoned tasks as "failed" #1649

mdellweg commented Sep 27, 2021

pulpbot commented Sep 27, 2021

dralley commented Sep 27, 2021

mdellweg commented Sep 27, 2021

dralley commented Sep 27, 2021

mdellweg commented Sep 27, 2021

dralley Sep 27, 2021

dralley left a comment •

edited

Loading

dralley commented Sep 27, 2021 •

edited

Loading

mdellweg commented Sep 28, 2021

dralley Sep 28, 2021 •

edited

Loading

dralley Sep 28, 2021 •

edited

Loading

bmbouter Sep 28, 2021

bmbouter Sep 28, 2021

bmbouter Sep 28, 2021

bmbouter left a comment

salman8328 commented May 19, 2023 •

edited

Loading

dralley commented May 19, 2023

Mark abandoned tasks as "failed" #1649

Mark abandoned tasks as "failed" #1649

Conversation

mdellweg commented Sep 27, 2021

pulpbot commented Sep 27, 2021

dralley commented Sep 27, 2021

mdellweg commented Sep 27, 2021

dralley commented Sep 27, 2021

mdellweg commented Sep 27, 2021

dralley Sep 27, 2021

Choose a reason for hiding this comment

dralley left a comment • edited Loading

Choose a reason for hiding this comment

dralley commented Sep 27, 2021 • edited Loading

mdellweg commented Sep 28, 2021

dralley Sep 28, 2021 • edited Loading

Choose a reason for hiding this comment

dralley Sep 28, 2021 • edited Loading

Choose a reason for hiding this comment

bmbouter Sep 28, 2021

Choose a reason for hiding this comment

bmbouter Sep 28, 2021

Choose a reason for hiding this comment

bmbouter Sep 28, 2021

Choose a reason for hiding this comment

bmbouter left a comment

Choose a reason for hiding this comment

salman8328 commented May 19, 2023 • edited Loading

dralley commented May 19, 2023

dralley left a comment •

edited

Loading

dralley commented Sep 27, 2021 •

edited

Loading

dralley Sep 28, 2021 •

edited

Loading

dralley Sep 28, 2021 •

edited

Loading

salman8328 commented May 19, 2023 •

edited

Loading