Why is this a 2.8.0 blocker? Is there something more going on than just an unfortunate log message?

The sync task seemed to have been cancelled, but the log had errors. Subsequently trying to delete the repository, ended up in a waiting stage. I ended up having to restart services to be able to delete the repo.

On Sun, Feb 07, 2016 at 11:51:52PM +0100, Pulp wrote:

Why is this a 2.8.0 blocker? Is there something more going on than just an unfortunate log message?

Without investigation I do not believe it is obvious whether there is a
serious problem or not.

i think we have a regression here. the task cancellation is ignored. it still continues to download rpms, and then triggers publish. that's why Preethi was not able to remove the repo, because it still was syncing.

$ pulp-admin rpm repo sync run --repo-id f23

+----------------------------------------------------------------------+
                     Synchronizing Repository [f23]
+----------------------------------------------------------------------+

This command may be exited via ctrl+c without affecting the request.

Downloading metadata...
[/]
... completed

Downloading repository content...
[-]
[/]
[                                                  ] 0%
[                                                  ] 0%
RPMs:       23/2276 items
Delta RPMs: 0/0 items

[ipanova@ina pulp]$ pulp-admin tasks list

+----------------------------------------------------------------------+
                                 Tasks
+----------------------------------------------------------------------+

Operations:  sync
Resources:   f23 (repository)
State:       Running
Start Time:  2016-02-09T12:10:47Z
Finish Time: Incomplete
Task Id:     c8b48b51-fc81-4455-af67-bb1274245d96

[ipanova@ina pulp]$ pulp-admin tasks cancel --task-id c8b48b51-fc81-4455-af67-bb1274245d96

Task cancel is successfully initiated.
$ pulp-admin -vv tasks details --task-id c8b48b51-fc81-4455-af67-bb1274245d96

+----------------------------------------------------------------------+
                              Task Details
+----------------------------------------------------------------------+

Operations:       sync
Resources:        f23 (repository)
State:            Canceled
Start Time:       2016-02-09T12:10:47Z
Finish Time:      Incomplete
Result:           N/A
Task Id:          c8b48b51-fc81-4455-af67-bb1274245d96
Progress Report:  
  Yum Importer: 
    Comps:        
      State: NOT_STARTED
    Content:      
      Details:       
        Drpm Done:  0
        Drpm Total: 0
        Rpm Done:   240
        Rpm Total:  2276
      Error Details: 
      Items Left:    2036
      Items Total:   2276
      Size Left:     1541906014
      Size Total:    1704217426
      State:         CANCELLED
    Distribution: 
      Error Details: 
      Items Left:    0
      Items Total:   0
      State:         NOT_STARTED
    Errata:       
      State: NOT_STARTED
    Metadata:     
      State: FINISHED

[ipanova@ina pulp]$ pulp-admin -vv tasks details --task-id c8b48b51-fc81-4455-af67-bb1274245d96

+----------------------------------------------------------------------+
                              Task Details
+----------------------------------------------------------------------+

Operations:       sync
Resources:        f23 (repository)
State:            Canceled
Start Time:       2016-02-09T12:10:47Z
Finish Time:      Incomplete
Result:           N/A
Task Id:          c8b48b51-fc81-4455-af67-bb1274245d96
Progress Report:  
  Yum Importer: 
    Comps:        
      State: NOT_STARTED
    Content:      
      Details:       
        Drpm Done:  0
        Drpm Total: 0
        Rpm Done:   1648
        Rpm Total:  2276
      Error Details: 
      Items Left:    628
      Items Total:   2276
      Size Left:     342467234
      Size Total:    1704217426
      State:         CANCELLED
    Distribution: 
      Error Details: 
      Items Left:    0
      Items Total:   0
      State:         NOT_STARTED
    Errata:       
      State: NOT_STARTED
    Metadata:     
      State: FINISHED

Notice the RPM done counter

I trigger the repo deletion and it is in waiting state until sync finishes.
The prove that task cancelation is ignored is the publish is triggered.

$ pulp-admin -vv tasks details --task-id c8b48b51-fc81-4455-af67-bb1274245d96

+----------------------------------------------------------------------+
                              Task Details
+----------------------------------------------------------------------+

2016-02-09 13:16:15,169 - DEBUG - sending GET request to /pulp/api/v2/tasks/c8b48b51-fc81-4455-af67-bb1274245d96/
2016-02-09 13:16:15,419 - INFO - GET request to /pulp/api/v2/tasks/c8b48b51-fc81-4455-af67-bb1274245d96/ with parameters None
2016-02-09 13:16:15,419 - INFO - Response status : 200 

2016-02-09 13:16:15,420 - INFO - Response body :
 {
  "exception": null, 
  "task_type": "pulp.server.managers.repo.sync.sync", 
  "_href": "/pulp/api/v2/tasks/c8b48b51-fc81-4455-af67-bb1274245d96/", 
  "task_id": "c8b48b51-fc81-4455-af67-bb1274245d96", 
  "tags": [
    "pulp:repository:f23", 
    "pulp:action:sync"
  ], 
  "finish_time": "2016-02-09T12:15:55Z", 
  "_ns": "task_status", 
  "start_time": "2016-02-09T12:10:47Z", 
  "traceback": null, 
  "spawned_tasks": [
    {
      "_href": "/pulp/api/v2/tasks/6298ea1c-0723-43d8-b7ed-d2a1e1e106a6/", 
      "task_id": "6298ea1c-0723-43d8-b7ed-d2a1e1e106a6"
    }
  ], 
  "progress_report": {
    "yum_importer": {
      "content": {
        "size_total": 1704217426, 
        "items_left": 0, 
        "items_total": 2276, 
        "state": "CANCELLED", 
        "size_left": 0, 
        "details": {
          "rpm_total": 2276, 
          "rpm_done": 2276, 
          "drpm_total": 0, 
          "drpm_done": 0
        }, 
        "error_details": []
      }, 
      "comps": {
        "state": "NOT_STARTED"
      }, 
      "distribution": {
        "items_total": 0, 
        "state": "NOT_STARTED", 
        "error_details": [], 
        "items_left": 0
      }, 
      "errata": {
        "state": "NOT_STARTED"
      }, 
      "metadata": {
        "state": "FINISHED"
      }
    }
  }, 
  "queue": "reserved_resource_worker-1@ina.usersys.redhat.com.dq", 
  "state": "canceled", 
  "worker_name": "reserved_resource_worker-1@ina.usersys.redhat.com", 
  "result": {
    "importer_type_id": "yum_importer", 
    "importer_id": {
      "$oid": "56b9d74345ef4815807d3c9a"
    }, 
    "exception": null, 
    "repo_id": "f23", 
    "started": "2016-02-09T12:10:47Z", 
    "_ns": "repo_sync_results", 
    "completed": "2016-02-09T12:15:55Z", 
    "traceback": null, 
    "error_message": null, 
    "summary": {
      "content": {
        "state": "CANCELLED"
      }, 
      "comps": {
        "state": "NOT_STARTED"
      }, 
      "distribution": {
        "state": "NOT_STARTED"
      }, 
      "errata": {
        "state": "NOT_STARTED"
      }, 
      "metadata": {
        "state": "FINISHED"
      }
    }, 
    "added_count": 2276, 
    "result": "canceled", 
    "updated_count": 0, 
    "details": {
      "content": {
        "size_total": 1704217426, 
        "items_left": 0, 
        "items_total": 2276, 
        "state": "CANCELLED", 
        "size_left": 0, 
        "details": {
          "rpm_total": 2276, 
          "rpm_done": 2276, 
          "drpm_total": 0, 
          "drpm_done": 0
        }, 
        "error_details": []
      }, 
      "comps": {
        "state": "NOT_STARTED"
      }, 
      "distribution": {
        "items_total": 0, 
        "state": "NOT_STARTED", 
        "error_details": [], 
        "items_left": 0
      }, 
      "errata": {
        "state": "NOT_STARTED"
      }, 
      "metadata": {
        "state": "FINISHED"
      }
    }, 
    "id": "56b9d87b45ef48708ae0a97d", 
    "removed_count": 0
  }, 
  "error": null, 
  "_id": {
    "$oid": "56b9d747556fc50fc87efaef"
  }, 
  "id": "56b9d747556fc50fc87efaef"
}

Operations:       sync
Resources:        f23 (repository)
State:            Canceled
Start Time:       2016-02-09T12:10:47Z
Finish Time:      2016-02-09T12:15:55Z
Result:           N/A
Task Id:          c8b48b51-fc81-4455-af67-bb1274245d96
Progress Report:  
  Yum Importer: 
    Comps:        
      State: NOT_STARTED
    Content:      
      Details:       
        Drpm Done:  0
        Drpm Total: 0
        Rpm Done:   2276
        Rpm Total:  2276
      Error Details: 
      Items Left:    0
      Items Total:   2276
      Size Left:     0
      Size Total:    1704217426
      State:         CANCELLED
    Distribution: 
      Error Details: 
      Items Left:    0
      Items Total:   0
      State:         NOT_STARTED
    Errata:       
      State: NOT_STARTED
    Metadata:     
      State: FINISHED

[ipanova@ina pulp]$ pulp-admin -vv tasks details --task-id 6298ea1c-0723-43d8-b7ed-d2a1e1e106a6

+----------------------------------------------------------------------+
                              Task Details
+----------------------------------------------------------------------+

2016-02-09 13:16:26,044 - DEBUG - sending GET request to /pulp/api/v2/tasks/6298ea1c-0723-43d8-b7ed-d2a1e1e106a6/
2016-02-09 13:16:26,153 - INFO - GET request to /pulp/api/v2/tasks/6298ea1c-0723-43d8-b7ed-d2a1e1e106a6/ with parameters None
2016-02-09 13:16:26,154 - INFO - Response status : 200 

2016-02-09 13:16:26,154 - INFO - Response body :
 {
  "exception": null, 
  "task_type": "pulp.server.managers.repo.publish.publish", 
  "_href": "/pulp/api/v2/tasks/6298ea1c-0723-43d8-b7ed-d2a1e1e106a6/", 
  "task_id": "6298ea1c-0723-43d8-b7ed-d2a1e1e106a6", 
  "tags": [
    "pulp:repository:f23", 
    "pulp:action:publish"
  ], 
  "finish_time": "2016-02-09T12:15:56Z", 
  "_ns": "task_status", 
  "start_time": "2016-02-09T12:15:56Z", 
  "traceback": "Traceback (most recent call last):\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 240, in trace_task\n    R = retval = fun(*args, **kwargs)\n  File \"/home/ipanova/pulp_development/pulp/server/pulp/server/async/tasks.py\", line 473, in __call__\n    return super(Task, self).__call__(*args, **kwargs)\n  File \"/home/ipanova/pulp_development/pulp/server/pulp/server/async/tasks.py\", line 103, in __call__\n    return super(PulpTask, self).__call__(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 437, in __protected_call__\n    return self.run(*args, **kwargs)\n  File \"/home/ipanova/pulp_development/pulp/server/pulp/server/controllers/repository.py\", line 914, in publish\n    repo_obj = model.Repository.objects.get_repo_or_missing_resource(repo_id)\n  File \"/home/ipanova/pulp_development/pulp/server/pulp/server/db/querysets.py\", line 139, in get_repo_or_missing_resource\n    raise pulp_exceptions.MissingResource(repository=repo_id)\nMissingResource: Missing resource(s): repository=f23\n", 
  "spawned_tasks": [], 
  "progress_report": {}, 
  "queue": "reserved_resource_worker-1@ina.usersys.redhat.com.dq", 
  "state": "error", 
  "worker_name": "reserved_resource_worker-1@ina.usersys.redhat.com", 
  "result": null, 
  "error": {
    "code": "PLP0009", 
    "data": {
      "resources": {
        "repository": "f23"
      }
    }, 
    "description": "Missing resource(s): repository=f23", 
    "sub_errors": []
  }, 
  "_id": {
    "$oid": "56b9d87b556fc50fc87f03d5"
  }, 
  "id": "56b9d87b556fc50fc87f03d5"
}

Operations:       publish
Resources:        f23 (repository)
State:            Failed
Start Time:       2016-02-09T12:15:56Z
Finish Time:      2016-02-09T12:15:56Z
Result:           N/A
Task Id:          6298ea1c-0723-43d8-b7ed-d2a1e1e106a6
Progress Report:  
Traceback:        Traceback (most recent call last):   File
                  "/usr/lib/python2.7/site-packages/celery/app/trace.py", line
                  240, in trace_task     R = retval = fun(*args, **kwargs)  
                  File
                  "/home/ipanova/pulp_development/pulp/server/pulp/server/async/
                  tasks.py", line 473, in __call__     return super(Task,
                  self).__call__(*args, **kwargs)   File
                  "/home/ipanova/pulp_development/pulp/server/pulp/server/async/
                  tasks.py", line 103, in __call__     return super(PulpTask,
                  self).__call__(*args, **kwargs)   File
                  "/usr/lib/python2.7/site-packages/celery/app/trace.py", line
                  437, in __protected_call__     return self.run(*args,
                  **kwargs)   File
                  "/home/ipanova/pulp_development/pulp/server/pulp/server/contro
                  llers/repository.py", line 914, in publish     repo_obj =
                  model.Repository.objects.get_repo_or_missing_resource(repo_id)
                  File
                  "/home/ipanova/pulp_development/pulp/server/pulp/server/db/que
                  rysets.py", line 139, in get_repo_or_missing_resource    
                  raise pulp_exceptions.MissingResource(repository=repo_id)
                  MissingResource: Missing resource(s): repository=f23 

After investigating this issue I have determined that a user can experience different behaviors when canceling a sync operation. If the cancel occurs while repo metadata is being downloaded, the cancel works fine. However, if it occurs while RPMs are being downloaded the sync task gets marked as CANCELLED in the database, but the worker continues to execute. While debugging the problem I determined that when the task is canceled during download of RPMs, this[0] code path is always hit. As a result the downloader doesn't receive the cancel signal. This code has not changed in a long time. This is not a regression.

[0] https://github.com/pulp/pulp_rpm/blob/master/plugins/pulp_rpm/plugins/importers/yum/sync.py#L740

After some discussion with other developers, I take my last comment back. This is a regression. The cancel() method was removed in this[0] commit. That commit came after this[1] commit removed the cancel from the alternate content source container as part of lazy download work[2].

[0] https://github.com/pulp/pulp_rpm/commit/a8c1dcbd24835b01c3947a36a3a2879646a5677c
[1] https://github.com/pulp/pulp/commit/e5640ba82f091dc61108fb55b00d7b89b8c85b2f
[2] https://pulp.plan.io/issues/1208