Response payload is not completed when syncing AppStream (or at least a Very Big repo)

Thulium-Drake · October 23, 2023, 3:34pm

Problem: When syncing RH Appstream repos (or at least a Very Big repo) I’ve been seeing “Response payload is not completed” all the time.

Yes, I see this in Satellite, but opening a thread here might yield some more insights (I’m also reporting it to RH support, but I first wanted dig in a bit further).

Expected outcome: To not break

Foreman and Proxy versions:

Foreman: 3.5.1
Katello: 4.7.0
Satellite: 6.13.5

Distribution and version: RHEL 8.8

Other relevant data:

So it seems a bit weird to me, as this is a brand new installation with a really fast Internet connection (don’t know exactly, it’s a Hetzner hosted piece of iron in Falkenstein). When initially setting it up in my lab I downloaded:

RHEL 8 / 9
AAP
Postgres and some other small repos

Everything downloaded just fine ™, except Appstream 8 and 9 with the following message:

“Response payload is not completed”

I can restart the download (already did 20 times or so) and it will always download some extra packages, but it sometimes breaks after 1 minute, sometimes after 2 hours and it does not mention which package or what is breaking it.

And my persistence in pressing the sync button, in the end, is rewarded by Appstream 9 (which is considerably smaller then 8) eventually wrapping up and mentioning it added some 12k RPMs and a bunch of errata.

So, what do you think is causing it? I think the setup itself eliminates network issues (there’s a simple linux based NAT firewall in place, no other network shenanigans going on as far as I can see)

Thulium-Drake · October 23, 2023, 3:43pm

This is the output of ```journalctl -fu “pulpcore-worker@*” for the last sync run I did, there’s only 1 repo syncing

Oct 23 17:16:47 m-a03-01.rh.lab pulpcore-worker-3[368691]: pulp [4fdd0ae6-d41f-4b85-a753-8b74e49706a7]: pulpcore.tasking.pulpcore_worker:INFO: Task completed a6d1c89d-4284-4c72-be88-200253449943
Oct 23 17:16:51 m-a03-01.rh.lab pulpcore-worker-8[368701]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Starting task f9ccfc21-7ca4-4ccc-8dc7-1033a1817a73
Oct 23 17:16:51 m-a03-01.rh.lab pulpcore-worker-8[368701]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Task completed f9ccfc21-7ca4-4ccc-8dc7-1033a1817a73
Oct 23 17:16:51 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Starting task ed49c5e7-9e0b-47e1-8c91-77e759c053c4
Oct 23 17:16:51 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulp_rpm.app.tasks.synchronizing:INFO: Synchronizing: repository=Red_Hat_Enterprise_Linux_8_for_x86_64_-_AppStream_RPMs_8-44632 remote=Red_Hat_Enterprise_Linux_8_for_x86_64_-_AppStream_RPMs_8-49628
Oct 23 17:17:05 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulp_rpm.app.tasks.synchronizing:WARNING: The repository metadata being synced into Pulp is erroneous in a way that makes it ambiguous (duplicate PKGIDs). Yum, DNF and Pulp try to handle these problems, but unexpected things may happen.
Oct 23 17:17:05 m-a03-01.rh.lab pulpcore-worker-2[368706]: Please read https://github.com/pulp/pulp_rpm/issues/2402 for more details.
Oct 23 17:17:05 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulp_rpm.app.tasks.synchronizing:WARNING: The repository metadata being synced into Pulp is erroneous in a way that makes it ambiguous (duplicate NEVRAs). Yum, DNF and Pulp try to handle these problems, but unexpected things may happen.
Oct 23 17:17:05 m-a03-01.rh.lab pulpcore-worker-2[368706]: Please read https://github.com/pulp/pulp_rpm/issues/2402 for more details.
Oct 23 17:17:05 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulp_rpm.app.tasks.synchronizing:INFO: Excluding 6 packages (duplicates, outdated or skipping was requested e.g. 'skip_types')
Oct 23 17:36:16 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 1.0s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:36:16 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 1.0s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:36:16 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 0.8s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:36:16 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 0.8s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:36:17 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 1.0s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:36:17 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 1.0s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:36:25 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 3.9s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:36:25 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 3.9s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:38:43 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 0.2s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:38:43 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 0.2s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:23 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 0.7s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:23 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 0.7s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:29 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 1.6s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:29 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 1.6s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:35 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 1.5s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:35 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 1.5s (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:37 m-a03-01.rh.lab pulpcore-worker-2[368706]: Backing off download_wrapper(...) for 1.9s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:39:37 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:INFO: Backing off download_wrapper(...) for 1.9s (aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected)
Oct 23 17:39:39 m-a03-01.rh.lab pulpcore-worker-2[368706]: Giving up download_wrapper(...) after 5 tries (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:39 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: backoff:ERROR: Giving up download_wrapper(...) after 5 tries (aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed)
Oct 23 17:39:41 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: asyncio:ERROR: Task was destroyed but it is pending!
Oct 23 17:39:41 m-a03-01.rh.lab pulpcore-worker-2[368706]: task: <Task pending name='Task-32' coro=<Event.wait() running at /usr/lib64/python3.9/asyncio/locks.py:226> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f10b847d3a0>()]>>
Oct 23 17:39:41 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: asyncio:ERROR: Task was destroyed but it is pending!
Oct 23 17:39:41 m-a03-01.rh.lab pulpcore-worker-2[368706]: task: <Task pending name='Task-34' coro=<Event.wait() running at /usr/lib64/python3.9/asyncio/locks.py:226> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f10b92fc340>()]>>
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Task ed49c5e7-9e0b-47e1-8c91-77e759c053c4 failed (Response payload is not completed)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO:   File "/usr/lib/python3.9/site-packages/pulpcore/tasking/pulpcore_worker.py", line 458, in _perform_task
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     result = func(*args, **kwargs)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulp_rpm/app/tasks/synchronizing.py", line 577, in synchronize
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     repo_version = dv.create() or repo.latest_version()
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/declarative_version.py", line 161, in create
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     loop.run_until_complete(pipeline)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib64/python3.9/asyncio/base_events.py", line 647, in run_until_complete
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     return future.result()
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/api.py", line 225, in create_pipeline
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     await asyncio.gather(*futures)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/api.py", line 43, in __call__
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     await self.run()
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 183, in run
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     pb.done += task.result()  # download_count
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 209, in _handle_content_unit
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     await asyncio.gather(*downloaders_for_content)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/models.py", line 119, in download
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     raise e
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/plugin/stages/models.py", line 111, in download
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     download_result = await downloader.run(extra_data=self.extra_data)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/download/http.py", line 273, in run
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     return await download_wrapper()
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/backoff/_async.py", line 151, in retry
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     ret = await target(*args, **kwargs)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/download/http.py", line 258, in download_wrapper
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     return await self._run(extra_data=extra_data)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulp_rpm/app/downloaders.py", line 118, in _run
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     to_return = await self._handle_response(response)
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib/python3.9/site-packages/pulpcore/download/http.py", line 207, in _handle_response
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     chunk = await response.content.read(1048576)  # 1 megabyte
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib64/python3.9/site-packages/aiohttp/streams.py", line 385, in read
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     await self._wait("read")
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:   File "/usr/lib64/python3.9/site-packages/aiohttp/streams.py", line 304, in _wait
Oct 23 17:39:42 m-a03-01.rh.lab pulpcore-worker-2[368706]:     await waiter
Oct 23 17:39:55 m-a03-01.rh.lab pulpcore-worker-2[370742]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Starting task 308153ed-5af7-4cce-ba3d-f690c38d99d0
Oct 23 17:39:55 m-a03-01.rh.lab pulpcore-worker-2[370742]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Task completed 308153ed-5af7-4cce-ba3d-f690c38d99d0
Oct 23 17:39:55 m-a03-01.rh.lab pulpcore-worker-1[370750]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Starting task e715520f-c4ad-41fc-82fd-d11d3daccd0c
Oct 23 17:39:56 m-a03-01.rh.lab pulpcore-worker-1[370750]: pulp [b165bf52-951f-44fc-9324-d1b78a316e35]: pulpcore.tasking.pulpcore_worker:INFO: Task completed e715520f-c4ad-41fc-82fd-d11d3daccd0c

Those first messages are also interesting, but from what I found so far, shouldn’t really break the sync. But the rest is basically a stacktrace of the sync going bad

Ironman · March 28, 2024, 11:03pm

Have you had any success with synchronizing Appstream since? I am having issues with Appstream on Oracle R8 from Oracle Linux 8 (x86_64) AppStream | Oracle, Software. Hardware. Complete..
I am seeing this behind my work firewall but not on a different network without a firewall.
Is there anything on a cisco firewall that might be limiting an http(s) pull over a longer period of time (6+ hours)?