Python Plugin No Longer Automatically Creating Publications

[razorbladex401]

Version
I'm using the all-in-one docker container. It contains the below versions.
pulpcore: 3.21.3
pulp_python: 3.7.3

Describe the bug
I noticed when going from pulpcore 3.21.0 with pulp_python 3.7.2 that publications are no longer being auto generated after syncing, even when autopublish is set on the repository.

To Reproduce
Steps to reproduce the behavior:
Create a new python remote/repository using pulpcore 3.21.2 with pulp_python plugin 3.7.3 and set the repository to autopublish.
Execute a sync.

Expected behavior
A publication to be created when a new repository is sync'd or a new version be create when the repository is updated.

Additional context
Logs from pulpcore 3.21.3 with pulp_python 3.7.3:
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: 127.0.0.1 - admin [07/Dec/2022:19:18:29 +0000] "POST /pulp/api/v3/repositories/python/python/aaa0a1ec-093a-4661-bfdb-9ab733d3d9a6/sync/ HTTP/1.0" 202 67 "-" "Pulp-CLI/0.15.0"
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: pulpcore.tasking.pulpcore_worker:INFO: Starting task 75c609dc-ac87-498c-89a2-41cbaa1d132d
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [3eb502dd5bb544f98a430c8e20b05a5a]: 127.0.0.1 - admin [07/Dec/2022:19:18:29 +0000] "GET /pulp/api/v3/tasks/75c609dc-ac87-498c-89a2-41cbaa1d132d/ HTTP/1.0" 200 665 "-" "Pulp-CLI/0.15.0"
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch:INFO: Initialized project plugin allowlist_project, filtering ['pip']
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch:INFO: Initialized release plugin allowlist_release, filtering [<Requirement('pip')>]
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch:INFO: Initialized release plugin blocklist_release, filtering []
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch:INFO: Initialized latest releases plugin with keep=15
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch:INFO: Initialized prerelease plugin with [re.compile('.+rc\d+$'), re.compile('.+a(lpha)?\d+$'), re.compile('.+b(eta)?\d+$'), re.compile('.+dev\d+$')]
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch.mirror:INFO: Syncing with https://pypi.org.
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch.mirror:INFO: No metadata filters are enabled. Skipping metadata filtering
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch.mirror:INFO: No release file filters are enabled. Skipping release file filtering
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: bandersnatch.package:INFO: Fetching metadata for package: pip (serial 0)
Dec 7 14:18:29 us01vlpulp100 6e9dc4b764ed[1499]: pulp [e18d39f2fc5f4c7aac5d8937a5880527]: pulpcore.tasking.pulpcore_worker:INFO: Task completed 75c609dc-ac87-498c-89a2-41cbaa1d132d
Dec 7 14:18:30 us01vlpulp100 6e9dc4b764ed[1499]: pulp [007cf461811e464dba0359353ab8256c]: 127.0.0.1 - - [07/Dec/2022:19:18:30 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"
Dec 7 14:18:30 us01vlpulp100 6e9dc4b764ed[1499]: pulp [f348a461cbc047fc89b504581683ff41]: 127.0.0.1 - - [07/Dec/2022:19:18:30 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"
Dec 7 14:18:30 us01vlpulp100 6e9dc4b764ed[1499]: Already migrated!
Dec 7 14:18:30 us01vlpulp100 6e9dc4b764ed[1499]: pulp [f899a1e26bce41eebcfe044a80c12979]: 127.0.0.1 - admin [07/Dec/2022:19:18:30 +0000] "GET /pulp/api/v3/tasks/75c609dc-ac87-498c-89a2-41cbaa1d132d/ HTTP/1.0" 200 1061 "-" "Pulp-CLI/0.15.0"
Dec 7 14:18:31 us01vlpulp100 6e9dc4b764ed[1499]: Already migrated!
Dec 7 14:18:32 us01vlpulp100 6e9dc4b764ed[1499]: pulp [3e246bea85104b2a99169f0ac21f66b0]: 127.0.0.1 - - [07/Dec/2022:19:18:32 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"
Dec 7 14:18:32 us01vlpulp100 6e9dc4b764ed[1499]: pulp [27c967828f664588a90a023d37290ec2]: 127.0.0.1 - - [07/Dec/2022:19:18:32 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"
Dec 7 14:18:32 us01vlpulp100 6e9dc4b764ed[1499]: Already migrated!
Dec 7 14:18:33 us01vlpulp100 6e9dc4b764ed[1499]: Already migrated!

Logs from pulpcore 3.21.0 with pulp_python 3.7.2:
Dec 7 14:21:58 us01vlpulp100 db9da661835d[1499]: pulp [6c219c68d8a84147bc121096b0e263ff]: 127.0.0.1 - - [07/Dec/2022:19:21:58 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [ffe43f56b5af44edb2eb7b60e0555100]: 127.0.0.1 - admin [07/Dec/2022:19:21:59 +0000] "GET /pulp/api/v3/repositories/python/python/?name=pip&offset=0&limit=1 HTTP/1.0" 200 608 "-" "Pulp-CLI/0.15.0"
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: 127.0.0.1 - admin [07/Dec/2022:19:21:59 +0000] "POST /pulp/api/v3/repositories/python/python/aaa0a1ec-093a-4661-bfdb-9ab733d3d9a6/sync/ HTTP/1.0" 202 67 "-" "Pulp-CLI/0.15.0"
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: Already migrated!
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: pulpcore.tasking.pulpcore_worker:INFO: Starting task e856a43c-3af6-4466-914a-b98910cf0c26
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch:INFO: Initialized project plugin allowlist_project, filtering ['pip']
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch:INFO: Initialized release plugin allowlist_release, filtering [<Requirement('pip')>]
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch:INFO: Initialized release plugin blocklist_release, filtering []
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch:INFO: Initialized latest releases plugin with keep=15
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch:INFO: Initialized prerelease plugin with [re.compile('.+rc\d+$'), re.compile('.+a(lpha)?\d+$'), re.compile('.+b(eta)?\d+$'), re.compile('.+dev\d+$')]
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [09ed6d2937614e04b535df102dd7aace]: 127.0.0.1 - admin [07/Dec/2022:19:21:59 +0000] "GET /pulp/api/v3/tasks/e856a43c-3af6-4466-914a-b98910cf0c26/ HTTP/1.0" 200 1032 "-" "Pulp-CLI/0.15.0"
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch.mirror:INFO: Syncing with https://pypi.org.
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch.mirror:INFO: No metadata filters are enabled. Skipping metadata filtering
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch.mirror:INFO: No release file filters are enabled. Skipping release file filtering
Dec 7 14:21:59 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: bandersnatch.package:INFO: Fetching metadata for package: pip (serial 0)
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: Already migrated!
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: pulp_python.app.tasks.publish:INFO: Publishing: repository=pip, version=1
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: pulp_python.app.tasks.publish:INFO: Publication: 1beb3c77-e97e-4d8a-99bc-0dd63bb2b330 created
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: pulp [a9ef3adb0d9f424e9ac33e9e0d2a3ff0]: pulpcore.tasking.pulpcore_worker:INFO: Task completed e856a43c-3af6-4466-914a-b98910cf0c26
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: pulp [ff0c412084b74b93a6f6f095d275cb4d]: 127.0.0.1 - admin [07/Dec/2022:19:22:00 +0000] "GET /pulp/api/v3/tasks/e856a43c-3af6-4466-914a-b98910cf0c26/ HTTP/1.0" 200 1230 "-" "Pulp-CLI/0.15.0"
Dec 7 14:22:00 us01vlpulp100 db9da661835d[1499]: pulp [bed41df7ac1a4335b36dbc2d77a27583]: 127.0.0.1 - - [07/Dec/2022:19:22:00 +0000] "HEAD /pulp/api/v3/status/ HTTP/1.0" 200 2649 "-" "-"

[gerrod3]

@razorbladex401 Can you check the task output of the sync? In created_resources there should be a new repository version, and with auto-publish, a new publication. If no new repository version was created (possibly because no new content was synced) then there wouldn't be a new publication created either.

[razorbladex401]

@gerrod3 so this is happening on multiple instances that I have. I've run it on a different server and same thing happens. If it's helpful here is the output from the task.

{
"pulp_href": "/pulp/api/v3/tasks/3524f18f-1d1f-487f-b232-044c335969fa/",
"pulp_created": "2022-12-15T20:57:49.435257Z",
"state": "completed",
"name": "pulp_python.app.tasks.sync.sync",
"logging_cid": "a1cd1d353f774380b2a5e874c9a2ee67",
"started_at": "2022-12-15T20:57:49.549579Z",
"finished_at": "2022-12-15T20:57:57.923204Z",
"error": null,
"worker": "/pulp/api/v3/workers/4397f356-94f0-4089-8d05-c6ecda3b12c3/",
"parent_task": null,
"child_tasks": [],
"task_group": null,
"progress_reports": [
{
"message": "Fetching Project Metadata",
"code": "sync.fetching.project",
"state": "completed",
"total": null,
"done": 0,
"suffix": null
},
{
"message": "Downloading Artifacts",
"code": "sync.downloading.artifacts",
"state": "completed",
"total": null,
"done": 0,
"suffix": null
},
{
"message": "Associating Content",
"code": "associating.content",
"state": "completed",
"total": null,
"done": 0,
"suffix": null
}
],
"created_resources": [],
"reserved_resources_record": [
"/pulp/api/v3/repositories/python/python/200ac92f-b598-4030-b8ef-4020e8862393/",
"shared:/pulp/api/v3/remotes/python/python/51f15308-3751-4aae-874f-e9891b11c785/"
]
}

I'm using the pulp-cli and if I do pulp python content list, I get nothing back.

This is what the configuration looks like for the remote:
[
{
"pulp_href": "/pulp/api/v3/remotes/python/python/51f15308-3751-4aae-874f-e9891b11c785/",
"pulp_created": "2022-11-29T16:12:30.712773Z",
"name": "pulp",
"url": "https://pypi.org/",
"ca_cert": null,
"client_cert": null,
"tls_validation": true,
"proxy_url": "http://someproxyserver:3128",
"pulp_labels": {
"repo_type": "python"
},
"pulp_last_updated": "2022-12-15T09:04:51.314693Z",
"download_concurrency": null,
"max_retries": 3,
"policy": "immediate",
"total_timeout": null,
"connect_timeout": null,
"sock_connect_timeout": null,
"sock_read_timeout": null,
"headers": null,
"rate_limit": null,
"includes": [
"pulp-python",
"pulp-rpm",
"pulp-cli",
"pulp-file",
"pulp-npm",
"pulp-ostree",
"pulp-maven",
"pulp-cookbook",
"pulp-deb",
"pulp-ansible",
"pulpcore"
],
"excludes": [],
"prereleases": false,
"package_types": [],
"keep_latest_packages": 15,
"exclude_platforms": []
}
]

This is the repository configuration:
{
"pulp_href": "/pulp/api/v3/repositories/python/python/200ac92f-b598-4030-b8ef-4020e8862393/",
"pulp_created": "2022-11-29T16:12:43.579823Z",
"versions_href": "/pulp/api/v3/repositories/python/python/200ac92f-b598-4030-b8ef-4020e8862393/versions/",
"pulp_labels": {
"repo_type": "python"
},
"latest_version_href": "/pulp/api/v3/repositories/python/python/200ac92f-b598-4030-b8ef-4020e8862393/versions/0/",
"name": "pulp",
"description": null,
"retain_repo_versions": null,
"remote": "/pulp/api/v3/remotes/python/python/51f15308-3751-4aae-874f-e9891b11c785/",
"autopublish": true
}

Interesting enough I have another instance that is using the older plugin and the output of the sync task is a little different. Under progress_reports, "Fetching Project Metadata", done says 11 but in the task output above it says done 0.

{
"pulp_href": "/pulp/api/v3/tasks/ef3bf3c4-68ab-49d1-9fe5-d2920994fbcf/",
"pulp_created": "2022-12-15T21:08:13.546700Z",
"state": "completed",
"name": "pulp_python.app.tasks.sync.sync",
"logging_cid": "444c31889a85489ba9a76ed9a5c44fa2",
"started_at": "2022-12-15T21:08:13.719332Z",
"finished_at": "2022-12-15T21:08:21.322854Z",
"error": null,
"worker": "/pulp/api/v3/workers/e18c747c-4890-4c8c-aa85-78ea120d3f25/",
"parent_task": null,
"child_tasks": [],
"task_group": null,
"progress_reports": [
{
"message": "Fetching Project Metadata",
"code": "sync.fetching.project",
"state": "completed",
"total": null,
"done": 11,
"suffix": null
},
{
"message": "Downloading Artifacts",
"code": "sync.downloading.artifacts",
"state": "completed",
"total": null,
"done": 0,
"suffix": null
},
{
"message": "Associating Content",
"code": "associating.content",
"state": "completed",
"total": null,
"done": 0,
"suffix": null
}
],
"created_resources": [],
"reserved_resources_record": [
"/pulp/api/v3/repositories/python/python/fca9dc39-b5cb-4d70-8fec-efdc20fea936/",
"shared:/pulp/api/v3/remotes/python/python/d77561be-e7d6-4fad-abc0-fd01d387ee7c/"
]
}

[gerrod3]

@razorbladex401 What was the older plugin version? The sync task will gather all the package's metadata and then will determine if any new releases needs to be added to the repository. So seeing 0 for download & associating probably means the repository already has the up-to-date versions of each package.

As for the newer task report, I have a feeling it has to do with using a proxy. There was a change backported to 3.7.3 [0] to stop reading from .netrc file (since we didn't ask for permission) when performing a sync. If I had to guess this probably means we are no longer sending the right credentials to your proxy. Try setting the proxy_username and proxy_password on your remote if you haven't already. [1] If you already have and the sync is still not fetching the metadata, then that means we have a bug to fix.

[0] #567
[1] https://docs.pulpproject.org/pulp_python/restapi.html#tag/Remotes:-Python/operation/remotes_python_python_create

[razorbladex401]

@gerrod3 the older version of the plugin is 3.7.2 with core version being 3.21.0. Our proxies don't require authentication and actually aren't setup for it.

btw, I just checked the logs on our proxy and I don't see the instance try to make a connection to anything when I'm running the sync.

[gerrod3]

@razorbladex401 Well I am stumped, that change shouldn't have broken syncs using proxies (especially ones that don't use auth). Let me try to set up a proxy to see if I can reproduce the issue.

[gerrod3]

@razorbladex401 Ok, I see where the bug is now. In an effort to prevent pulp from reading the .netrc file I also stopped it from using the proxy for making the requests. If you can I would suggest down-grading to pulp_python 3.7.2 until I can release a fix for this issue.