Project

Profile

Help

Issue #8692

closed

Repository sync will fail if Debian components are defined on the remote

Added by simon_t almost 3 years ago. Updated about 2 years ago.

Status:
CLOSED - DUPLICATE
Priority:
Normal
Assignee:
-
Sprint/Milestone:
-
Start date:
Due date:
Estimated time:
Severity:
2. Medium
Version - Debian:
Platform Release:
Target Release - Debian:
OS:
Triaged:
No
Groomed:
No
Sprint Candidate:
No
Tags:
Sprint:
Quarter:

Description

Ticket moved to GitHub: "pulp/pulp_deb/407":https://github.com/pulp/pulp_deb/issues/407


pulpcore version: 3.12.1

pulp_deb version: 2.11.1

Attempts to sync a repository with a remote that has Debian components defined consistently fail with the error "Response payload is not completed".

Failing remote config:

{
    "architectures": "amd64",
    "ca_cert": null,
    "client_cert": null,
    "components": "main contrib non-free",
    "connect_timeout": null,
    "distributions": "bullseye",
    "download_concurrency": 10,
    "gpgkey": null,
    "headers": null,
    "ignore_missing_package_indices": false,
    "name": "remote_debian_bullseye",
    "policy": "immediate",
    "proxy_url": null,
    "pulp_created": "2021-04-29T11:17:38.824675Z",
    "pulp_href": "/pulp/api/v3/remotes/deb/apt/18600e5b-4914-4bbd-ae2a-bc0488c30e07/",
    "pulp_labels": {},
    "pulp_last_updated": "2021-04-30T00:47:55.224174Z",
    "rate_limit": null,
    "sock_connect_timeout": null,
    "sock_read_timeout": null,
    "sync_installer": false,
    "sync_sources": false,
    "sync_udebs": false,
    "tls_validation": true,
    "total_timeout": null,
    "url": "http://ftp.au.debian.org/debian/"
}

Error reported to API:

{
            "child_tasks": [],
            "created_resources": [],
            "error": {
                "description": "Response payload is not completed",
                "traceback": "  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/worker.py\", line 1008, in perform_job\n    rv = job.perform()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py\", line 706, in perform\n    self._result = self._execute()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py\", line 729, in _execute\n    result = self.func(*self.args, **self.kwargs)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulp_deb/app/tasks/synchronizing.py\", line 122, in synchronize\n    DebDeclarativeVersion(first_stage, repository, mirror=mirror).create()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py\", line 149, in create\n    loop.run_until_complete(pipeline)\n  File \"/usr/lib/python3.6/asyncio/base_events.py\", line 484, in run_until_complete\n    return future.result()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py\", line 225, in create_pipeline\n    await asyncio.gather(*futures)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py\", line 43, in __call__\n    await self.run()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py\", line 174, in run\n    pb.done += task.result()  # download_count\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py\", line 200, in _handle_content_unit\n    await asyncio.gather(*downloaders_for_content)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/models.py\", line 89, in download\n    download_result = await downloader.run(extra_data=self.extra_data)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/base.py\", line 241, in run\n    return await self._run(extra_data=extra_data)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/backoff/_async.py\", line 133, in retry\n    ret = await target(*args, **kwargs)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py\", line 218, in _run\n    to_return = await self._handle_response(response)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py\", line 185, in _handle_response\n    chunk = await response.content.read(1048576)  # 1 megabyte\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py\", line 380, in read\n    await self._wait(\"read\")\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py\", line 306, in _wait\n    await waiter\n"
            },
            "finished_at": "2021-04-29T22:03:38.950771Z",
            "logging_cid": "2367609e386d4f3b8c94830deea2053e",
            "name": "pulp_deb.app.tasks.synchronizing.synchronize",
            "parent_task": null,
            "progress_reports": [
                {
                    "code": "update.release_file",
                    "done": 1,
                    "message": "Update ReleaseFile units",
                    "state": "canceled",
                    "suffix": null,
                    "total": null
                },
                {
                    "code": "update.packageindex",
                    "done": 3,
                    "message": "Update PackageIndex units",
                    "state": "canceled",
                    "suffix": null,
                    "total": null
                },
                {
                    "code": "associating.content",
                    "done": 10017,
                    "message": "Associating Content",
                    "state": "canceled",
                    "suffix": null,
                    "total": null
                },
                {
                    "code": "unassociating.content",
                    "done": 0,
                    "message": "Un-Associating Content",
                    "state": "canceled",
                    "suffix": null,
                    "total": null
                },
                {
                    "code": "sync.downloading.artifacts",
                    "done": 200,
                    "message": "Downloading Artifacts",
                    "state": "failed",
                    "suffix": null,
                    "total": null
                }
            ],
            "pulp_created": "2021-04-29T22:02:51.216445Z",
            "pulp_href": "/pulp/api/v3/tasks/c6ca7102-7b9a-4774-9455-5eb486b527b3/",
            "reserved_resources_record": [
                "/pulp/api/v3/remotes/deb/apt/2889a55e-8ece-40ae-a811-d39d89deda4e/",
                "/pulp/api/v3/repositories/deb/apt/35664f88-071a-4bec-a1be-b7e0befe369e/"
            ],
            "started_at": "2021-04-29T22:02:51.391384Z",
            "state": "failed",
            "task_group": null,
            "worker": "/pulp/api/v3/workers/ebece415-1026-44a0-8668-0de82c2ac9e9/"
        }

When failing in this manner multiple attempts will progress the sync to a point beyond which it will not progress, in the example above that point was when the "associating.content" value was 10017.

As a further test the remote was recreated with a null value for "components":

{
    "architectures": "amd64",
    "ca_cert": null,
    "client_cert": null,
    "components": null,
    "connect_timeout": null,
    "distributions": "bullseye",
    "download_concurrency": 10,
    "gpgkey": null,
    "headers": null,
    "ignore_missing_package_indices": true,
    "name": "remote_debian_bullseye",
    "policy": "immediate",
    "proxy_url": null,
    "pulp_created": "2021-05-04T02:08:55.188864Z",
    "pulp_href": "/pulp/api/v3/remotes/deb/apt/3f95927d-b39c-4bda-a24e-f850d73f2095/",
    "pulp_labels": {},
    "pulp_last_updated": "2021-05-04T02:08:55.188881Z",
    "rate_limit": null,
    "sock_connect_timeout": null,
    "sock_read_timeout": null,
    "sync_installer": false,
    "sync_sources": false,
    "sync_udebs": false,
    "tls_validation": true,
    "total_timeout": null,
    "url": "http://ftp.au.debian.org/debian/"
}

While the sync attempts for this configuration still failed multiple times it is always with a "Server disconnected" error and the sync progressed further st each attempt until a complete sync was achieved.

{
   "child_tasks": [],
   "created_resources": [
       "/pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-0ddf62b92ebc/versions/4/"
   ],
   "error": null,
   "finished_at": "2021-05-04T06:24:54.428619Z",
   "logging_cid": "1121eb0f04d742aa80b0a1cb70b0cedb",
   "name": "pulp_deb.app.tasks.synchronizing.synchronize",
   "parent_task": null,
   "progress_reports": [
       {
           "code": "sync.downloading.artifacts",
           "done": 3157,
           "message": "Downloading Artifacts",
           "state": "completed",
           "suffix": null,
           "total": null
       },
       {
           "code": "update.release_file",
           "done": 1,
           "message": "Update ReleaseFile units",
           "state": "completed",
           "suffix": null,
           "total": null
       },
       {
           "code": "update.packageindex",
           "done": 3,
           "message": "Update PackageIndex units",
           "state": "completed",
           "suffix": null,
           "total": null
       },
       {
           "code": "associating.content",
           "done": 119400,
           "message": "Associating Content",
           "state": "completed",
           "suffix": null,
           "total": null
       },
       {
           "code": "unassociating.content",
           "done": 1,
           "message": "Un-Associating Content",
           "state": "completed",
           "suffix": null,
           "total": null
       }
   ],
   "pulp_created": "2021-05-04T06:09:38.553551Z",
   "pulp_href": "/pulp/api/v3/tasks/c9674fbd-5d30-4932-bbc1-1c50e8d6e595/",
   "reserved_resources_record": [
       "/pulp/api/v3/remotes/deb/apt/3f95927d-b39c-4bda-a24e-f850d73f2095/",
       "/pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-0ddf62b92ebc/"
   ],
   "started_at": "2021-05-04T06:09:38.704737Z",
   "state": "completed",
   "task_group": null,
   "worker": "/pulp/api/v3/workers/a25d6c8a-b4ea-4500-ab08-92104d08bca7/"
}

Full log of a sync failing with the "Response payload is not completed" error:

Apr 30 00:29:19 pulphost.domain.local gunicorn[1381]: pulp [28ac6dceafad4e07933ddfbeead891e7]:  - admin [30/Apr/2021:00:29:19 +0000] "POST /pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-
0ddf62b92ebc/sync/ HTTP/1.0" 202 67 "-" "HTTPie/0.9.8"
Apr 30 00:29:19 pulphost.domain.local rq[1374]: pulp [None]: rq.worker:INFO: 1374@pulphost.domain.local: 69878f8d-7e56-4322-8f4c-5687c9ae7aeb
Apr 30 00:29:19 pulphost.domain.local rq[1383]: pulp [28ac6dceafad4e07933ddfbeead891e7]: rq.worker:INFO: resource-manager: Job OK (46efd531-9651-48db-8aa3-73521c79de42)
Apr 30 00:29:19 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Downloading Release file for distribution: "bullseye"
Apr 30 00:29:20 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Parsing Release file at distribution="bullseye"
Apr 30 00:29:20 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Downloading: contrib/binary-amd64/Packages
Apr 30 00:29:20 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Downloading: non-free/binary-amd64/Packages
Apr 30 00:29:20 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Downloading: main/binary-amd64/Packages
Apr 30 00:29:25 pulphost.domain.local rq[1374]: /usr/local/lib/pulp/lib/python3.6/site-packages/debian/deb822.py:740: UserWarning: Parsing of Deb822 data with python3-apt's apt_pkg was requested bu
t this package is not importable. Is python3-apt installed?
Apr 30 00:29:25 pulphost.domain.local rq[1374]:   warnings.warn(msg)
Apr 30 00:29:25 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Artifact digest not matched. Ignored
<snip>
Apr 30 00:29:28 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: pulp_deb.app.tasks.synchronizing:INFO: Artifact digest not matched. Ignored
Apr 30 00:29:30 pulphost.domain.local gunicorn[1381]: pulp [953559dc9eb149849798a84899c1fa04]:  - admin [30/Apr/2021:00:29:30 +0000] "GET /pulp/api/v3/tasks/cb2c2cb4-c3ca-4758-be66-faa930487dad/ HT
TP/1.0" 200 1391 "-" "HTTPie/0.9.8"
Apr 30 00:30:03 pulphost.domain.local gunicorn[1381]: pulp [c2c1187c01de41d3bd0ea2ca6ff96079]:  - admin [30/Apr/2021:00:30:03 +0000] "GET /pulp/api/v3/tasks/8f2574c3-56f4-40f3-b0c3-31227bef42fd/ HT
TP/1.0" 200 602 "-" "HTTPie/0.9.8"
Apr 30 00:30:37 pulphost.domain.local rq[1388]: pulp [None]: rq.worker:INFO: Cleaning registries for queue: 1388@pulphost.domain.local
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b8558>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.6/asyncio/tasks.py:380]>
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b8498>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.6/asyncio/tasks.py:380]>
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b83d8>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.6/asyncio/tasks.py:380]>
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b8318>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.6/asyncio/tasks.py:380]>
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b8138>()]>>
Apr 30 00:30:47 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: asyncio:ERROR: Task was destroyed but it is pending!
Apr 30 00:30:47 pulphost.domain.local rq[1374]: task: <Task pending coro=<Event.wait() running at /usr/lib/python3.6/asyncio/locks.py:283> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object
 at 0x7d07428b8258>()]> cb=[_wait.<locals>._on_completion() at /usr/lib/python3.6/asyncio/tasks.py:380]>
Apr 30 00:30:48 pulphost.domain.local rq[1374]: pulp [28ac6dceafad4e07933ddfbeead891e7]: rq.worker:ERROR: Traceback (most recent call last):
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/worker.py", line 1008, in perform_job
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     rv = job.perform()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py", line 706, in perform
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     self._result = self._execute()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py", line 729, in _execute
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     result = self.func(*self.args, **self.kwargs)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulp_deb/app/tasks/synchronizing.py", line 122, in synchronize
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     DebDeclarativeVersion(first_stage, repository, mirror=mirror).create()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py", line 149, in create
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     loop.run_until_complete(pipeline)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     return future.result()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 225, in create_pipeline
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await asyncio.gather(*futures)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 43, in __call__
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await self.run()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 174, in run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     pb.done += task.result()  # download_count
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 200, in _handle_content_unit
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await asyncio.gather(*downloaders_for_content)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/models.py", line 89, in download
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     download_result = await downloader.run(extra_data=self.extra_data)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/base.py", line 241, in run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     return await self._run(extra_data=extra_data)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/backoff/_async.py", line 133, in retry
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     ret = await target(*args, **kwargs)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py", line 218, in _run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     to_return = await self._handle_response(response)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py", line 185, in _handle_response
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     chunk = await response.content.read(1048576)  # 1 megabyte
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py", line 380, in read
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await self._wait("read")
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py", line 306, in _wait
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await waiter
Apr 30 00:30:48 pulphost.domain.local rq[1374]: aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed
Apr 30 00:30:48 pulphost.domain.local rq[1374]: Traceback (most recent call last):
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/worker.py", line 1008, in perform_job
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     rv = job.perform()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py", line 706, in perform
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     self._result = self._execute()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py", line 729, in _execute
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     result = self.func(*self.args, **self.kwargs)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulp_deb/app/tasks/synchronizing.py", line 122, in synchronize
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     DebDeclarativeVersion(first_stage, repository, mirror=mirror).create()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py", line 149, in create
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     loop.run_until_complete(pipeline)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     return future.result()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 225, in create_pipeline
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await asyncio.gather(*futures)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 43, in __call__
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await self.run()
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 174, in run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     pb.done += task.result()  # download_count
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 200, in _handle_content_unit
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await asyncio.gather(*downloaders_for_content)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/models.py", line 89, in download
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     download_result = await downloader.run(extra_data=self.extra_data)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/base.py", line 241, in run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     return await self._run(extra_data=extra_data)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/backoff/_async.py", line 133, in retry
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     ret = await target(*args, **kwargs)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py", line 218, in _run
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     to_return = await self._handle_response(response)
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py", line 185, in _handle_response
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     chunk = await response.content.read(1048576)  # 1 megabyte
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py", line 380, in read
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await self._wait("read")
Apr 30 00:30:48 pulphost.domain.local rq[1374]:   File "/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py", line 306, in _wait
Apr 30 00:30:48 pulphost.domain.local rq[1374]:     await waiter
Apr 30 00:30:48 pulphost.domain.local rq[1374]: aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed
Actions #1

Updated by quba42 almost 3 years ago

Apparently other plugins have experienced similar problems in the past: https://pulp.plan.io/issues/6945

It looks like this issue might not be reliably reproducible. I have just had this same issue with a completely different repo.

I also have my doubt that this is in any way related to whether or not any components are defined.

My suspicion is that it might be caused by random network hiccups during download.

For now, my advice is to simply try repeatedly rerunning affected syncs, to see if they then succeed.

If the sync fails multiple times, check the sync tasks if the number of steps that were successfully completed before the failure differs from sync to sync.

Until there is some way to reliably reproduce the root cause there isn't much I can do about this.

Actions #2

Updated by simon_t almost 3 years ago

mcorr tried unsuccessfully to reproduce this too although I am unsure if he was using a value for "components" in his settings.

In my testing the syncs were consistently failing over multiple tests (at least 20) with the "Response payload is not completed" error on two remote/repo pairs (debian bullseye and debian bullseye-security) with components set. In both instances recreating the remotes with null values for "components" immediately caused syncs to progress and complete after several attempts.

At the moment we are stuck on https://pulp.plan.io/issues/8671 so I cannot test further myself.

Actions #3

Updated by quba42 almost 3 years ago

I will leave this issue open for now, in order to keep an eye on it. I don't have any immediate ideas how to continue narrowing it down.

I now have a quick fix for https://pulp.plan.io/issues/8671 which will hopefully be released soon. Perhaps once that is done it will be easier to try and find a set of circumstances to reliably reproduce this issue.

Actions #4

Updated by simon_t almost 3 years ago

I'm seeing this behaviour again on new repos synced with remotes with components configured.

Testing individual remote/repository pairs for each Debian component.

Remotes:

{
    "count": 7,
    "next": null,
    "previous": null,
    "results": [
        {
            "architectures": "amd64",
            "ca_cert": null,
            "client_cert": null,
            "components": "non-free",
            "connect_timeout": null,
            "distributions": "bullseye",
            "download_concurrency": 10,
            "gpgkey": null,
            "headers": null,
            "ignore_missing_package_indices": true,
            "name": "remote_debian_bullseye_non-free",
            "policy": "immediate",
            "proxy_url": null,
            "pulp_created": "2021-05-27T00:22:33.126681Z",
            "pulp_href": "/pulp/api/v3/remotes/deb/apt/76066d07-476d-453b-b41e-0910ed154a5e/",
            "pulp_labels": {},
            "pulp_last_updated": "2021-05-27T00:22:33.126700Z",
            "rate_limit": null,
            "sock_connect_timeout": null,
            "sock_read_timeout": null,
            "sync_installer": false,
            "sync_sources": false,
            "sync_udebs": false,
            "tls_validation": true,
            "total_timeout": null,
            "url": "http://ftp.au.debian.org/debian/"
        },
        {
            "architectures": "amd64",
            "ca_cert": null,
            "client_cert": null,
            "components": "contrib",
            "connect_timeout": null,
            "distributions": "bullseye",
            "download_concurrency": 10,
            "gpgkey": null,
            "headers": null,
            "ignore_missing_package_indices": true,
            "name": "remote_debian_bullseye_contrib",
            "policy": "immediate",
            "proxy_url": null,
            "pulp_created": "2021-05-27T00:20:39.645508Z",
            "pulp_href": "/pulp/api/v3/remotes/deb/apt/ffb8c1f5-2ac1-488a-be46-e6d951af6d25/",
            "pulp_labels": {},
            "pulp_last_updated": "2021-05-27T00:20:39.645527Z",
            "rate_limit": null,
            "sock_connect_timeout": null,
            "sock_read_timeout": null,
            "sync_installer": false,
            "sync_sources": false,
            "sync_udebs": false,
            "tls_validation": true,
            "total_timeout": null,
            "url": "http://ftp.au.debian.org/debian/"
        },
        {
            "architectures": "amd64",
            "ca_cert": null,
            "client_cert": null,
            "components": "main",
            "connect_timeout": null,
            "distributions": "bullseye",
            "download_concurrency": 10,
            "gpgkey": null,
            "headers": null,
            "ignore_missing_package_indices": true,
            "name": "remote_debian_bullseye_main",
            "policy": "immediate",
            "proxy_url": null,
            "pulp_created": "2021-05-27T00:18:28.333232Z",
            "pulp_href": "/pulp/api/v3/remotes/deb/apt/03515213-1edf-4f96-81b4-298845684034/",
            "pulp_labels": {},
            "pulp_last_updated": "2021-05-27T00:18:28.333248Z",
            "rate_limit": null,
            "sock_connect_timeout": null,
            "sock_read_timeout": null,
            "sync_installer": false,
            "sync_sources": false,
            "sync_udebs": false,
            "tls_validation": true,
            "total_timeout": null,
            "url": "http://ftp.au.debian.org/debian/"
        }
    ]
}

Repositories:

{
    "count": 6,
    "next": null,
    "previous": null,
    "results": [
        {
            "description": null,
            "latest_version_href": "/pulp/api/v3/repositories/deb/apt/b6d04104-1982-430a-8634-6df0f78c97a6/versions/1/",
            "name": "debian_bullseye_non-free",
            "pulp_created": "2021-05-27T00:31:16.258161Z",
            "pulp_href": "/pulp/api/v3/repositories/deb/apt/b6d04104-1982-430a-8634-6df0f78c97a6/",
            "pulp_labels": {},
            "remote": "/pulp/api/v3/remotes/deb/apt/76066d07-476d-453b-b41e-0910ed154a5e/",
            "versions_href": "/pulp/api/v3/repositories/deb/apt/b6d04104-1982-430a-8634-6df0f78c97a6/versions/"
        },
        {
            "description": null,
            "latest_version_href": "/pulp/api/v3/repositories/deb/apt/d033805a-4944-4a1b-bcdd-c6e896946bf5/versions/1/",
            "name": "debian_bullseye_contrib",
            "pulp_created": "2021-05-27T00:29:46.285836Z",
            "pulp_href": "/pulp/api/v3/repositories/deb/apt/d033805a-4944-4a1b-bcdd-c6e896946bf5/",
            "pulp_labels": {},
            "remote": "/pulp/api/v3/remotes/deb/apt/ffb8c1f5-2ac1-488a-be46-e6d951af6d25/",
            "versions_href": "/pulp/api/v3/repositories/deb/apt/d033805a-4944-4a1b-bcdd-c6e896946bf5/versions/"
        },
        {
            "description": null,
            "latest_version_href": "/pulp/api/v3/repositories/deb/apt/5818633d-9746-46ca-a512-58f6d1c4b93d/versions/0/",
            "name": "debian_bullsyeye_main",
            "pulp_created": "2021-05-27T00:28:42.200459Z",
            "pulp_href": "/pulp/api/v3/repositories/deb/apt/5818633d-9746-46ca-a512-58f6d1c4b93d/",
            "pulp_labels": {},
            "remote": "/pulp/api/v3/remotes/deb/apt/03515213-1edf-4f96-81b4-298845684034/",
            "versions_href": "/pulp/api/v3/repositories/deb/apt/5818633d-9746-46ca-a512-58f6d1c4b93d/versions/"
        }
    ]
}

Syncs of the debian_bullseye_contrib and debian_bullseye_non-free repositories completed successfully almost immediately. Neither of these repos have much content.

Syncs of the debian_bullseye_main repo are failing consistently at the same point with the "Response payload is not completed" error:

{
    "child_tasks": [],
    "created_resources": [],
    "error": {
        "description": "Response payload is not completed",
        "traceback": "  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/worker.py\", line 1008, in perform_job\n    rv = job.perform()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py\", line 706, in perform\n    self._result = self._execute()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/rq/job.py\", line 729, in _execute\n    result = self.func(*self.args, **self.kwargs)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulp_deb/app/tasks/synchronizing.py\", line 122, in synchronize\n    DebDeclarativeVersion(first_stage, repository, mirror=mirror).create()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py\", line 149, in create\n    loop.run_until_complete(pipeline)\n  File \"/usr/lib/python3.6/asyncio/base_events.py\", line 484, in run_until_complete\n    return future.result()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py\", line 225, in create_pipeline\n    await asyncio.gather(*futures)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/api.py\", line 43, in __call__\n    await self.run()\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py\", line 174, in run\n    pb.done += task.result()  # download_count\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py\", line 200, in _handle_content_unit\n    await asyncio.gather(*downloaders_for_content)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/plugin/stages/models.py\", line 89, in download\n    download_result = await downloader.run(extra_data=self.extra_data)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/base.py\", line 241, in run\n    return await self._run(extra_data=extra_data)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/backoff/_async.py\", line 133, in retry\n    ret = await target(*args, **kwargs)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py\", line 218, in _run\n    to_return = await self._handle_response(response)\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/pulpcore/download/http.py\", line 185, in _handle_response\n    chunk = await response.content.read(1048576)  # 1 megabyte\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py\", line 380, in read\n    await self._wait(\"read\")\n  File \"/usr/local/lib/pulp/lib/python3.6/site-packages/aiohttp/streams.py\", line 306, in _wait\n    await waiter\n"
    },
    "finished_at": "2021-05-27T00:59:50.698059Z",
    "logging_cid": "db70dfb90bbd4f4cb4156af490a42953",
    "name": "pulp_deb.app.tasks.synchronizing.synchronize",
    "parent_task": null,
    "progress_reports": [
        {
            "code": "sync.downloading.artifacts",
            "done": 9,
            "message": "Downloading Artifacts",
            "state": "failed",
            "suffix": null,
            "total": null
        },
        {
            "code": "update.release_file",
            "done": 1,
            "message": "Update ReleaseFile units",
            "state": "canceled",
            "suffix": null,
            "total": null
        },
        {
            "code": "update.packageindex",
            "done": 1,
            "message": "Update PackageIndex units",
            "state": "canceled",
            "suffix": null,
            "total": null
        },
        {
            "code": "associating.content",
            "done": 8005,
            "message": "Associating Content",
            "state": "canceled",
            "suffix": null,
            "total": null
        }
    ],
    "pulp_created": "2021-05-27T00:59:13.952000Z",
    "pulp_href": "/pulp/api/v3/tasks/60557da7-9a43-470d-bc20-2db9bd8afaef/",
    "reserved_resources_record": [
        "/pulp/api/v3/repositories/deb/apt/5818633d-9746-46ca-a512-58f6d1c4b93d/",
        "/pulp/api/v3/remotes/deb/apt/03515213-1edf-4f96-81b4-298845684034/"
    ],
    "started_at": "2021-05-27T00:59:14.118586Z",
    "state": "failed",
    "task_group": null,
    "worker": "/pulp/api/v3/workers/ac7b3d07-6828-4c4f-8ea2-61d653105b62/"
}

The above sync has been attempted eight times now and each time fails when the "associating.content" counter reaches 8005.

Syncs of the remote/repo pair below, without components configured on the remote, proceed normally and eventually complete.

{
    "architectures": "amd64",
    "ca_cert": null,
    "client_cert": null,
    "components": null,
    "connect_timeout": null,
    "distributions": "bullseye",
    "download_concurrency": 10,
    "gpgkey": null,
    "headers": null,
    "ignore_missing_package_indices": true,
    "name": "remote_debian_bullseye",
    "policy": "immediate",
    "proxy_url": null,
    "pulp_created": "2021-05-04T02:08:55.188864Z",
    "pulp_href": "/pulp/api/v3/remotes/deb/apt/3f95927d-b39c-4bda-a24e-f850d73f2095/",
    "pulp_labels": {},
    "pulp_last_updated": "2021-05-10T11:11:36.716679Z",
    "rate_limit": null,
    "sock_connect_timeout": null,
    "sock_read_timeout": null,
    "sync_installer": false,
    "sync_sources": false,
    "sync_udebs": false,
    "tls_validation": true,
    "total_timeout": null,
    "url": "http://ftp.au.debian.org/debian/"
}
{
    "description": "Debian Bullseye base repository.",
    "latest_version_href": "/pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-0ddf62b92ebc/versions/5/",
    "name": "debian_bullseye",
    "pulp_created": "2021-04-29T11:18:30.132385Z",
    "pulp_href": "/pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-0ddf62b92ebc/",
    "pulp_labels": {},
    "remote": "/pulp/api/v3/remotes/deb/apt/3f95927d-b39c-4bda-a24e-f850d73f2095/",
    "versions_href": "/pulp/api/v3/repositories/deb/apt/dbd1bbf7-a5ef-46b6-922a-0ddf62b92ebc/versions/"
}
Actions #5

Updated by quba42 almost 3 years ago

Thanks for the extensive testing around this bug. That is certainly a big help. I still don't have any immediate ideas what might be causing this, but this does give us a basis to start brain storming.

Actions #6

Updated by quba42 almost 3 years ago

  • Sprint/Milestone set to Katello
Actions #7

Updated by quba42 over 2 years ago

I cannot reproduce this with latest pulpcore and pulp_deb.

Since there has been some work both on Download logic in pulpcore, as well as the components filtering in pulp_deb, it is certainly possible this was fixed along with something else.

If anyone can still reproduce this error please post your remote, the pulpcore, and the pulp_deb version, and I will have another go at trying to reproduce this.

Actions #8

Updated by quba42 over 2 years ago

  • Sprint/Milestone deleted (Katello)
Actions #9

Updated by pulpbot about 2 years ago

  • Description updated (diff)
  • Status changed from NEW to CLOSED - DUPLICATE

Also available in: Atom PDF