RPM Support

Upload of RPM packages are failing. A few tests failed today, most them related to upload an RPM packge to Pulp 2. Similar error happened when attempting to upload different types of RPMs.

Steps to reproduce:

pulp-admin rpm repo create --repo-id=foo
wget https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-with-non-ascii/rpm-with-non-ascii-1-1.fc25.noarch.rpm
pulp-admin -vvv rpm repo uploads rpm --repo-id foo --file rpm-with-non-ascii-1-1.fc25.noarch.rpm 

Output:

[root@r76 ~]# pulp-admin -vvvvv rpm repo uploads rpm --repo-id foo --file rpm-with-non-ascii-1-1.fc25.noarch.rpm 
+----------------------------------------------------------------------+
                              Unit Upload
+----------------------------------------------------------------------+

2018-11-06 14:20:54,369 - DEBUG - sending GET request to /pulp/api/v2/repositories/foo/
2018-11-06 14:20:54,443 - INFO - GET request to /pulp/api/v2/repositories/foo/ with parameters None
2018-11-06 14:20:54,443 - INFO - Response status : 200 

2018-11-06 14:20:54,443 - INFO - Response body :
 {
  "scratchpad": {}, 
  "display_name": null, 
  "description": null, 
  "last_unit_added": null, 
  "notes": {
    "_repo-type": "rpm-repo"
  }, 
  "last_unit_removed": null, 
  "content_unit_counts": {}, 
  "_ns": "repos", 
  "_id": {
    "$oid": "5be1e983db5ee92b35299634"
  }, 
  "id": "foo", 
  "_href": "/pulp/api/v2/repositories/foo/"
}

Extracting necessary metadata for each request...
[==================================================] 100%
Analyzing: rpm-with-non-ascii-1-1.fc25.noarch.rpm
... completed

Creating upload requests on the server...
[==================================================] 100%
Initializing: rpm-with-non-ascii-1-1.fc25.noarch.rpm
2018-11-06 14:20:54,444 - DEBUG - sending POST request to /pulp/api/v2/content/uploads/
2018-11-06 14:20:54,519 - INFO - POST request to /pulp/api/v2/content/uploads/ with parameters None
2018-11-06 14:20:54,519 - INFO - Response status : 201 

2018-11-06 14:20:54,519 - INFO - Response body :
 {
  "upload_id": "b77d8a04-cfb8-47c3-a188-9906736185b2", 
  "_href": "/pulp/api/v2/content/uploads/b77d8a04-cfb8-47c3-a188-9906736185b2/"
}

... completed

Starting upload of selected units. If this process is stopped through ctrl+c,
the uploads will be paused and may be resumed later using the resume command or
canceled entirely using the cancel command.

Uploading: rpm-with-non-ascii-1-1.fc25.noarch.rpm
2018-11-06 14:20:54,521 - DEBUG - sending PUT request to /pulp/api/v2/content/uploads/b77d8a04-cfb8-47c3-a188-9906736185b2/0/
2018-11-06 14:20:54,615 - INFO - PUT request to /pulp/api/v2/content/uploads/b77d8a04-cfb8-47c3-a188-9906736185b2/0/
2018-11-06 14:20:54,615 - INFO - Response status : 200 

2018-11-06 14:20:54,615 - INFO - Response body :
 null

[==================================================] 100%
6392/6392 bytes
... completed

Importing into the repository...
2018-11-06 14:20:54,617 - DEBUG - sending POST request to /pulp/api/v2/repositories/foo/actions/import_upload/
2018-11-06 14:20:54,774 - INFO - POST request to /pulp/api/v2/repositories/foo/actions/import_upload/ with parameters {"override_config": {}, "unit_type_id": "rpm", "upload_id": "b77d8a04-cfb8-47c3-a188-9906736185b2", "unit_key": {}, "unit_metadata": {}}
2018-11-06 14:20:54,774 - INFO - Response status : 202 

2018-11-06 14:20:54,774 - INFO - Response body :
 {
  "spawned_tasks": [
    {
      "_href": "/pulp/api/v2/tasks/53955228-dc8e-4935-ab96-ef59c5504ad6/", 
      "task_id": "53955228-dc8e-4935-ab96-ef59c5504ad6"
    }
  ], 
  "result": null, 
  "error": null
}

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

[-]
Running...
2018-11-06 14:20:55,777 - DEBUG - sending GET request to /pulp/api/v2/tasks/53955228-dc8e-4935-ab96-ef59c5504ad6/
2018-11-06 14:20:55,891 - INFO - GET request to /pulp/api/v2/tasks/53955228-dc8e-4935-ab96-ef59c5504ad6/ with parameters None
2018-11-06 14:20:55,891 - INFO - Response status : 200 

2018-11-06 14:20:55,891 - INFO - Response body :
 {
  "exception": null, 
  "task_type": "pulp.server.managers.content.upload.import_uploaded_unit", 
  "_href": "/pulp/api/v2/tasks/53955228-dc8e-4935-ab96-ef59c5504ad6/", 
  "task_id": "53955228-dc8e-4935-ab96-ef59c5504ad6", 
  "tags": [
    "pulp:repository:foo", 
    "pulp:action:import_upload"
  ], 
  "finish_time": "2018-11-06T19:20:54Z", 
  "_ns": "task_status", 
  "start_time": "2018-11-06T19:20:54Z", 
  "traceback": "Traceback (most recent call last):\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 367, in trace_task\n    R = retval = fun(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py\", line 529, in __call__\n    return super(Task, self).__call__(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py\", line 107, in __call__\n    return super(PulpTask, self).__call__(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 622, in __protected_call__\n    return self.run(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/managers/content/upload.py\", line 218, in import_uploaded_unit\n    unit_metadata, file_path, conduit, call_config)\n  File \"/usr/lib/python2.7/site-packages/pulp_rpm/plugins/importers/yum/importer.py\", line 65, in upload_unit\n    return upload.upload(repo, type_id, unit_key, metadata, file_path, conduit, config)\n  File \"/usr/lib/python2.7/site-packages/pulp_rpm/plugins/importers/yum/upload.py\", line 123, in upload\n    handlers[type_id](repo, type_id, unit_key, metadata, file_path, conduit, config)\n  File \"/usr/lib/python2.7/site-packages/pulp_rpm/plugins/importers/yum/upload.py\", line 391, in _handle_package\n    raise PulpCodedException(error_codes.RPM1016)\nPulpCodedException: Uploaded file is not a valid RPM.\n", 
  "spawned_tasks": [], 
  "progress_report": {}, 
  "queue": "reserved_resource_worker-0@r76.pulp.vm.dq2", 
  "state": "error", 
  "worker_name": "reserved_resource_worker-0@r76.pulp.vm", 
  "result": null, 
  "error": {
    "code": "RPM1016", 
    "data": {}, 
    "description": "Uploaded file is not a valid RPM.", 
    "sub_errors": []
  }, 
  "_id": {
    "$oid": "5be1e996f57913ba8b8f06d5"
  }, 
  "id": "5be1e996f57913ba8b8f06d5"
[\]
Running...

Task Failed

Uploaded file is not a valid RPM.

Deleting the upload request...
2018-11-06 14:20:55,892 - DEBUG - sending DELETE request to /pulp/api/v2/content/uploads/b77d8a04-cfb8-47c3-a188-9906736185b2/
2018-11-06 14:20:55,967 - INFO - DELETE request to /pulp/api/v2/content/uploads/b77d8a04-cfb8-47c3-a188-9906736185b2/ with parameters None
2018-11-06 14:20:55,967 - INFO - Response status : 200 

2018-11-06 14:20:55,967 - INFO - Response body :
 null

... completed

journalctl -n 30:

-- Logs begin at Tue 2018-11-06 13:44:35 EST, end at Tue 2018-11-06 14:21:47 EST. --
Nov 06 14:13:18 r76.pulp.vm pulp[11060]: gofer.messaging.adapter.qpid.connection:INFO: opened: qpid+ssl://r76.pulp.vm:5671
Nov 06 14:13:18 r76.pulp.vm pulp[11060]: gofer.messaging.adapter.connect:INFO: connected: qpid+ssl://r76.pulp.vm:5671
Nov 06 14:16:07 r76.pulp.vm chronyd[4364]: Selected source 162.23.41.10
Nov 06 14:16:12 r76.pulp.vm chronyd[4364]: Can't synchronise: no selectable sources
Nov 06 14:17:25 r76.pulp.vm sshd[11401]: FIPS mode initialized
Nov 06 14:17:25 r76.pulp.vm sshd[11401]: Accepted publickey for root from 192.168.122.1 port 60870 ssh2: RSA SHA256:1/LIskjXx+3aNEUAP6iWb1lYknrbp2huYKqbuVPsvbs
Nov 06 14:17:25 r76.pulp.vm systemd-logind[4350]: New session 5 of user root.
Nov 06 14:17:25 r76.pulp.vm systemd[1]: Started Session 5 of user root.
Nov 06 14:17:25 r76.pulp.vm sshd[11401]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 06 14:17:40 r76.pulp.vm yum[11418]: Installed: wget-1.14-18.el7.x86_64
Nov 06 14:20:21 r76.pulp.vm pulp[11061]: pulp.server.webservices.middleware.exception:INFO: Authentication with username None failed: invalid SSL certificate.
Nov 06 14:20:24 r76.pulp.vm chronyd[4364]: Source 44.190.6.254 replaced with 72.5.72.15
Nov 06 14:20:26 r76.pulp.vm chronyd[4364]: Selected source 216.230.228.242
Nov 06 14:20:26 r76.pulp.vm chronyd[4364]: System clock wrong by 2361.160983 seconds, adjustment started
Nov 06 14:20:54 r76.pulp.vm pulp[11060]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Nov 06 14:20:54 r76.pulp.vm pulp[10967]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[c0594d78-f0e2-4c7b-9372-f9e75f78b8f3]
Nov 06 14:20:54 r76.pulp.vm pulp[11033]: py.warnings:WARNING: [c0594d78] (11033-50144) /usr/lib64/python2.7/site-packages/pymongo/topology.py:74: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: http://api.mongodb.org/python/current/faq.html#using-pymongo-with-multiprocessing>
Nov 06 14:20:54 r76.pulp.vm pulp[11033]: py.warnings:WARNING: [c0594d78] (11033-50144)   "MongoClient opened before fork. Create MongoClient "
Nov 06 14:20:54 r76.pulp.vm pulp[11033]: py.warnings:WARNING: [c0594d78] (11033-50144)
Nov 06 14:20:54 r76.pulp.vm pulp[11033]: kombu.transport.qpid:INFO: [c0594d78] Connected to qpid with SASL mechanism ANONYMOUS
Nov 06 14:20:54 r76.pulp.vm pulp[10835]: celery.worker.strategy:INFO: Received task: pulp.server.managers.content.upload.import_uploaded_unit[53955228-dc8e-4935-ab96-ef59c5504ad6]
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: py.warnings:WARNING: [53955228] (10938-28736) /usr/lib64/python2.7/site-packages/pymongo/topology.py:74: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: http://api.mongodb.org/python/current/faq.html#using-pymongo-with-multiprocessing>
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: py.warnings:WARNING: [53955228] (10938-28736)   "MongoClient opened before fork. Create MongoClient "
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: py.warnings:WARNING: [53955228] (10938-28736)
Nov 06 14:20:54 r76.pulp.vm pulp[10835]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[024d1a9e-c6d9-4d5f-b0c7-a4882e148592]
Nov 06 14:20:54 r76.pulp.vm pulp[11033]: celery.app.trace:INFO: [c0594d78] Task pulp.server.async.tasks._queue_reserved_task[c0594d78-f0e2-4c7b-9372-f9e75f78b8f3] succeeded in 0.119898567s: None
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: pulp.server.async.tasks:INFO: [53955228] Task failed : [53955228-dc8e-4935-ab96-ef59c5504ad6] : Uploaded file is not a valid RPM.
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: celery.app.trace:INFO: [53955228] Task pulp.server.managers.content.upload.import_uploaded_unit[53955228-dc8e-4935-ab96-ef59c5504ad6] raised expected: PulpCodedException()
Nov 06 14:20:54 r76.pulp.vm pulp[10938]: celery.app.trace:INFO: [024d1a9e] Task pulp.server.async.tasks._release_resource[024d1a9e-c6d9-4d5f-b0c7-a4882e148592] succeeded in 0.00247618999992s: None
Nov 06 14:21:47 r76.pulp.vm yum[11463]: Installed: fpaste-0.3.7.4.1-2.el7.noarch

Pulp Packages:

[root@r76 ~]# rpm -qa | grep pulp
python-pulp-repoauth-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-ostree-plugins-1.4.0-0.1.alpha.201811060506git53beed4.el7.noarch
pulp-puppet-plugins-2.19.0-0.1.alpha.201811060508gitc54a546.el7.noarch
python-pulp-bindings-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-ostree-admin-extensions-1.4.0-0.1.alpha.201811060506git53beed4.el7.noarch
pulp-docker-admin-extensions-3.4.0-0.1.alpha.201811060504gita762419.el7.noarch
python-pulp-streamer-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
python-pulp-puppet-common-2.19.0-0.1.alpha.201811060508gitc54a546.el7.noarch
python-pulp-rpm-common-2.19.0-0.1.alpha.201811060511git204f995.el7.noarch
pulp-selinux-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
python-isodate-0.5.0-4.pulp.el7.noarch
python-pulp-ostree-common-1.4.0-0.1.alpha.201811060506git53beed4.el7.noarch
python-pulp-docker-common-3.4.0-0.1.alpha.201811060504gita762419.el7.noarch
python-pulp-python-common-2.1.0-0.1.alpha.201811060502git5e2aa35.el7.noarch
python-pulp-oid_validation-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-server-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-docker-plugins-3.4.0-0.1.alpha.201811060504gita762419.el7.noarch
pulp-python-plugins-2.1.0-0.1.alpha.201811060502git5e2aa35.el7.noarch
pulp-rpm-plugins-2.19.0-0.1.alpha.201811060511git204f995.el7.noarch
pulp-puppet-tools-2.19.0-0.1.alpha.201811060508gitc54a546.el7.noarch
pulp-admin-client-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-python-admin-extensions-2.1.0-0.1.alpha.201811060502git5e2aa35.el7.noarch
pulp-rpm-admin-extensions-2.19.0-0.1.alpha.201811060511git204f995.el7.noarch
pulp-deb-admin-extensions-1.9.0-0.1.alpha.201811060524gitb5fc87b.el7.noarch
pulp-deb-plugins-1.9.0-0.1.alpha.201811060524gitb5fc87b.el7.noarch
python-pulp-client-lib-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
pulp-puppet-admin-extensions-2.19.0-0.1.alpha.201811060508gitc54a546.el7.noarch
python-pulp-common-2.19.0-0.1.alpha.201811060516gita768094.el7.noarch
python-pulp-deb-common-1.9.0-0.1.alpha.201811060524gitb5fc87b.el7.noarch

System:

[root@r76 ~]# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.6 (Maipo