Pulp

Pulp-only reproducer is needed to triage this bug.
Anyone, feel free to try to reproduce it.

cduryee, just in case you have time for it, that will be great :)

I was not able to reproduce it (with Pulp 2.12.2), see below what I did.
There is a note in the docs that it is not guaranteed that task will be in the canceled state. I am not sure if this is the case, I would expect task end up in error or finished state then. Any thoughts on this?

So far, task cancellation works for me:
- I created several consumer profiles, synced several repositories.
- Then triggered applicability regeneration with parallel=true to have a task group

$ curl -H "Accept: application/json" -X POST -d '{"repo_criteria": {"filters": {"id": {"$in": ["epel7", "epel7v2", "zooe1", "zoo", "upd_verizon"]}}}, "parallel": true}' -k -u admin:admin 'https://localhost/pulp/api/v2/repositories/actions/content/regenerate_applicability/'

{"group_id": "9f882286-8d8a-42a8-acb1-08127bcd2e8c", "_href": "/pulp/api/v2/task_groups/9f882286-8d8a-42a8-acb1-08127bcd2e8c/"}

- canceled several tasks via pulp-admin

$ pulp-admin tasks cancel --task-id f0799dde-0b5a-4e4c-8272-1b2b2d1761d4
Task cancel is successfully initiated.

$ pulp-admin tasks cancel --task-id d56d5b69-505a-4cd1-9c5d-639e9870b880
Task cancel is successfully initiated.

- requested state_summary and everything looks correct

$ curl -H "Accept: application/json" -k -u admin:admin 'https://localhost/pulp/api/v2/task_groups/9f882286-8d8a-42a8-acb1-08127bcd2e8c/state_summary/' | python -m json.tool
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   127  100   127    0     0    973      0 --:--:-- --:--:-- --:--:--   976
{
    "accepted": 0,
    "canceled": 2,
    "error": 0,
    "finished": 3,
    "running": 0,
    "skipped": 0,
    "suspended": 0,
    "total": 5,
    "waiting": 0
}

Same results for Pulp 2.8.7 upstream, I was not able to reproduce the issue.

cduryee will update this issue with more info.

Anyone who is going to work on this issue, feel free to ping me if you need help with step 1 of the reproducer (applicability task).

Btw, could this issue be related to #2835?

It could be similar to https://pulp.plan.io/issues/2861. I would not be surprised if fixing that fixes this as well.

I tried to reproduce this bug as suggested, but I never achieved the same result.

My steps:
1. Remove all repositories from pulp
2. Add centos repository

pulp-admin rpm repo create --repo-id=centos --feed=http://mirror.centos.org/centos/7/updates/x86_64/ --download-policy on_demand

3. Sync it

pulp-admin rpm repo sync run --repo-id centos

4. Run consumer generating script (https://pulp.plan.io/attachments/319/gen_test_data.py)

python gen_test_data.py

5. Regenerate consumer applicability and wait

curl -H "Accept: application/json" -X POST -d '{"consumer_criteria": {}}' -k -u admin:admin 'https://localhost/pulp/api/v2/consumers/actions/content/regenerate_applicability/'

6. Upload rpm to trigger repo change

pulp-admin rpm repo uploads --repo-id=centos --file=kangaroo-0.2-1.noarch.rpm

7. Generate repository aplicalibity

curl -H "Accept: application/json" -X POST -d '{"repo_criteria": {"filters": {"id": {"$in": ["centos"]}}}, "parallel": true}' -k -u admin:admin 'https://localhost/pulp/api/v2/repositories/actions/content/regenerate_applicability/'

8. Get task group status

curl -H "Accept: application/json" -X GET  -k -u admin:admin 'https://localhost/pulp/api/v2/task_groups/<ID>/state_summary/'

9. Kill and stop all services

pkill celery; pstop

10. start all services

pstart

11. Observe task group status

curl -H "Accept: application/json" -X GET  -k -u admin:admin 'https://localhost/pulp/api/v2/task_groups/<ID>/state_summary/'

The waiting will be getting lower and lower and WILL reach 0. But 4 running tasks never finish.

Before restart:
{"accepted": 0, "finished": 4, "running": 4, "canceled": 0, "waiting": 42, "skipped": 0, "suspended": 0, "error": 0, "total": 50}
After restart:
{"accepted": 0, "finished": 15, "running": 5, "canceled": 0, "waiting": 30, "skipped": 0, "suspended": 0, "error": 0, "total": 50}
Stucked state:
{"accepted": 0, "finished": 46, "running": 4, "canceled": 0, "waiting": 0, "skipped": 0, "suspended": 0, "error": 0, "total": 50}

One of the running tasks details:

$ pulp-admin -vv tasks details --task-id 1be03945-479a-4712-b698-3133a0b3d0b9
+----------------------------------------------------------------------+
                              Task Details
+----------------------------------------------------------------------+

2017-08-02 14:20:43,205 - DEBUG - sending GET request to /pulp/api/v2/tasks/1be03945-479a-4712-b698-3133a0b3d0b9/
2017-08-02 14:20:43,237 - INFO - GET request to /pulp/api/v2/tasks/1be03945-479a-4712-b698-3133a0b3d0b9/ with parameters None
2017-08-02 14:20:43,237 - INFO - Response status : 200 

2017-08-02 14:20:43,237 - INFO - Response body :
 {
  "exception": null, 
  "task_type": "pulp.server.managers.consumer.applicability.batch_regenerate_applicability", 
  "_href": "/pulp/api/v2/tasks/1be03945-479a-4712-b698-3133a0b3d0b9/", 
  "task_id": "1be03945-479a-4712-b698-3133a0b3d0b9", 
  "tags": [], 
  "finish_time": null, 
  "_ns": "task_status", 
  "start_time": "2017-08-02T13:38:29Z", 
  "traceback": null, 
  "spawned_tasks": [], 
  "progress_report": {}, 
  "queue": "celery.dq", 
  "state": "running", 
  "worker_name": "celery", 
  "result": null, 
  "error": null, 
  "_id": {
    "$oid": "5981d5b58bb3cb1f7e15dc81"
  }, 
  "id": "5981d5b58bb3cb1f7e15dc81"
}

Operations:       
Resources:        
State:            Running
Start Time:       2017-08-02T13:38:29Z
Finish Time:      Incomplete
Result:           Incomplete
Task Id:          1be03945-479a-4712-b698-3133a0b3d0b9
Progress Report:  

I experienced the same behaviour on 2.13-release as on pulp-2.8.7-1

This bug has two parts:

1. A bug in Katello - I asked one of the devs from Katello for help, during that I found out that there is a slight misunderstanding of our API. Katello marks the task as running till the number of tasks marked as finished is not equal to the total number of tasks in a group. But in our API field 'finished' marks only tasks that have finished successfully. (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/webservices/views/task_groups.py#L66-L84 and https://github.com/pulp/pulp/blob/2.8-dev/common/pulp/common/constants.py#L26-L42). This is why the reproducer in the description is not reproducible with plain pulp. Even when part two is solved this has to be fixed. Because I believe that when running task is killed it should be marked as 'failed' and therefore Katello would be waiting forever again.

2. A bug in pulp - Most of the tasks that pulp handles are tasks with reservation called via apply_async_with_reservation (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L352) this causes the task to go through _queue_reserved_task Task (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L107-L160) in this function crucial thing happens a worker is selected and a new apply_async task is spawned with worker name as parameter (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L159) However generate applicability is called with apply_async (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/managers/consumer/applicability.py#L168) and therefore no worker is selected for such task and default routing key is saved to database instead. (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L440 and https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L430-L431). This leads to the fact that when the worker goes missing and then reappears the task won't get cancelled because it's not associated with Worker (https://github.com/pulp/pulp/blob/2.8-dev/server/pulp/server/async/tasks.py#L255-L258)

@Tanya, you should be aware that the fix for this (which is completely correct and proper) makes this vulnerable to a separate, and more serious problem in the tasking cleanup code. https://pulp.plan.io/issues/2835

That's entirely expected because prior to the fix it wasn't cleaning up those tasks properly, and now it is, so that code is being called...

There's a fix for 2835, but it definitely will not apply cleanly backwards. I'm trying to figure out a more straightforward and less involved way to fix it on pre-2.13 pulp for the sake of downstream.

I verified that 2835 only affects versions of pulp >= 2.13 so my last comment can be disregarded with respect to downstream.

Applied in changeset pulp|fc9b02084241f9d3a1db1025f2c71cf1af0bcd8e.

Followed the steps from comment#15 to verify this in pulp 2.13.4