Actions

Copy link

#1

Updated by pthomas@redhat.com about 8 years ago

Project changed from Pulp to RPM Support

Actions

Copy link

#2

Updated by jortel@redhat.com about 8 years ago

Severity changed from 2. Medium to 3. High
Platform Release set to 2.8.0
Triaged changed from No to Yes

Actions

Copy link

#3

Updated by mhrivnak about 8 years ago

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

Actions

Copy link

#4

Updated by pthomas@redhat.com about 8 years ago

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.

Actions

Copy link

#5

Updated by rbarlow about 8 years ago

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.

Actions

Copy link

#6

Updated by ipanova@redhat.com about 8 years ago

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

Actions

Copy link

#7

Updated by dkliban@redhat.com about 8 years ago

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

Actions

Copy link

#8

Updated by dkliban@redhat.com about 8 years ago

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

Actions

Copy link

#9

Updated by jortel@redhat.com about 8 years ago

Status changed from NEW to ASSIGNED
Assignee set to jortel@redhat.com

Actions

Copy link

#10

Updated by jortel@redhat.com about 8 years ago

Status changed from ASSIGNED to NEW
Assignee deleted (~~jortel@redhat.com~~)

The Plan¶

Rather than add cancel back to content sources, the plan is to remove the YumImporter.cancel_repo_sync() method. This will allow the base class implementation to call sys.exit() instead. This method is deprecated and doing this is aligned with our long term plans for cancel. Removing this method will leave dead (cancel) code sprinkled throughout the importer that should also be removed.

A know side effect of no longer calling into the cancel code in the plugin is that the DownloadConfig.finalize() will no longer be called. Calling finalize() is necessary to clean up temporary files written into /tmp by Nectar. The config object writes these files when it's handed certificates by value instead of a path to them on the filesystem. One approach to resolving this would be for the plugin to write certificates into the working directory and pass the paths to Nectar instead.

Actions

Copy link

#11

Updated by ipanova@redhat.com about 8 years ago

Status changed from NEW to ASSIGNED
Assignee set to ipanova@redhat.com

Actions

Copy link

#12

Updated by ipanova@redhat.com about 8 years ago

Status changed from ASSIGNED to POST

https://github.com/pulp/pulp/pull/2431
https://github.com/pulp/pulp_rpm/pull/810
https://github.com/pulp/nectar/pull/44

Actions

Copy link

#13

Updated by ipanova@redhat.com about 8 years ago

Status changed from POST to MODIFIED
% Done changed from 0 to 100

Applied in changeset nectar:78334d22c941f96191430ab2ca5dbcb7cb5aa351.

Actions

Copy link

#14

Updated by dkliban@redhat.com about 8 years ago

Status changed from MODIFIED to 5

Actions

Copy link

#15

Updated by pthomas@redhat.com about 8 years ago

Status changed from 5 to 6

verified

[root@mgmt5 ~]# pulp-admin rpm repo create --repo-id f23 --feed http://mirrors.mit.edu/fedora/linux/releases/23/Everything/x86_64/os/
Successfully created repository [f23]

[root@mgmt5 ~]#
[root@mgmt5 ~]#
[root@mgmt5 ~]# 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...
[/]
[= ] 3%
RPMs: 786/46074 items
Delta RPMs: 0/0 items

^C[root@mgmt5 ~]# pulp-admin tasks list
~~--------------------------------------------------------------------~~
Tasks
~~--------------------------------------------------------------------~~

Operations: sync
Resources: rhel5-ks (repository)
State: Waiting
Start Time: Unstarted
Finish Time: Incomplete
Task Id: 63918636-c17c-450f-b231-ae539c2434cb

Operations: sync
Resources: f23 (repository)
State: Running
Start Time: 2016-03-14T17:26:44Z
Finish Time: Incomplete
Task Id: bd2515f1-1c79-46bc-bbcf-55b444e72efd

[root@mgmt5 ~]# pulp-admin rpm repo sync run --repo-id f23 ~~--------------------------------------------------------------------~~
Synchronizing Repository [f23]
~~--------------------------------------------------------------------~~

A sync task is already in progress for this repository. Its progress will be
tracked below.

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

Downloading metadata...
[-]
... completed

Downloading repository content...
[== ] 5%
RPMs: 1131/46074 items
Delta RPMs: 0/0 items

Task Canceled

[root@mgmt5 ~]# pulp-admin rpm repo delete --repo-id f23
This command may be exited via ctrl+c without affecting the request.

[|]
Running...

Repository [f23] successfully deleted

[root@mgmt5 ~]#

Actions

Copy link

#16

Updated by dkliban@redhat.com about 8 years ago

Status changed from 6 to CLOSED - CURRENTRELEASE

Actions

Copy link

#18

Updated by bmbouter about 5 years ago

Tags Pulp 2 added

Project

Profile

Help

RPM Support

Agile boards

Custom queries

Issue #1626

Error in the log when trying to cancel a running repo sync task

Updated by pthomas@redhat.com about 8 years ago

Updated by jortel@redhat.com about 8 years ago

Updated by mhrivnak about 8 years ago

Updated by pthomas@redhat.com about 8 years ago

Updated by rbarlow about 8 years ago

Updated by ipanova@redhat.com about 8 years ago

Updated by dkliban@redhat.com about 8 years ago

Updated by dkliban@redhat.com about 8 years ago

Updated by jortel@redhat.com about 8 years ago

Updated by jortel@redhat.com about 8 years ago

The Plan¶

Updated by ipanova@redhat.com about 8 years ago

Added by ipanova@redhat.com about 8 years ago

Updated by ipanova@redhat.com about 8 years ago

Updated by ipanova@redhat.com about 8 years ago

Added by ipanova@redhat.com about 8 years ago

Added by ipanova@redhat.com about 8 years ago

Added by ipanova@redhat.com about 8 years ago

Updated by dkliban@redhat.com about 8 years ago

Updated by pthomas@redhat.com about 8 years ago

Updated by dkliban@redhat.com about 8 years ago

Updated by bmbouter about 5 years ago