Issue #4281
Updated by bherring over 5 years ago
h2. Notes
Nightly Jenkins [0] experienced sanity failures starting last night, 12/19
Only FIPs is affected.
Local test re-creations on 2.18-stable (fips/non-fips) and 2.19 non-fips experienced no issues with pulp-admin status smoke test or test harness execution
Still investigating, but could use some help to understand why `pulp-admin status` is returning errors and where to dig into the pulp code or additional logs to find the source of error.
h2. Re-creation
# Install the latest Pulp2-nightly.
# Verify pulp is functioning with `pulp-admin status` or run some tests, if you are so inclined.
# Enable FIPs
# Post-install, run `pulp-admin status`.
# Verify the errors seen below and a failure return.
# Bonus: Return back to non-FIPs and note Pulp2 functions. Back to FIPs, and the error is reproducible locally.
## Verifying FIPs state with: `cat /proc/sys/crypto/fips_enabled`
h2. Test Harness
* SW: Pulp2-nightly (2.19a1)
* FIPs Enabled: Yes
h3. django version
<pre>
[root@rhel76-fips-219 ~]# rpm -qa | grep -i django
python2-django-1.11.13-4.el7.noarch
python-django-bash-completion-1.11.13-4.el7.noarch
[root@rhel76-fips-219 ~]#
</pre>
h3. journalctl
<pre>
Dec 19 11:49:57 rhel76-fips-219 dracut[7120]: *** Creating initramfs image file '/boot/initramfs-3.10.0-957.1.3.el7.x86_64kdump.img' done ***
Dec 19 11:49:58 rhel76-fips-219 kdumpctl[4859]: kexec: loaded kdump kernel
Dec 19 11:49:58 rhel76-fips-219 kdumpctl[4859]: Starting kdump: [OK]
Dec 19 11:49:58 rhel76-fips-219 systemd[1]: Started Crash recovery kernel arming.
Dec 19 11:49:58 rhel76-fips-219 systemd[1]: Startup finished in 490ms (kernel) + 3.557s (initrd) + 44.199s (userspace) = 48.248s.
Dec 19 11:51:41 rhel76-fips-219 chronyd[4292]: Source 216.229.0.49 replaced with 72.14.181.128
Dec 19 11:56:54 rhel76-fips-219 auditd[4260]: Audit daemon rotating log files
Dec 19 12:01:01 rhel76-fips-219 systemd[1]: Started Session 2 of user root.
Dec 19 12:01:01 rhel76-fips-219 CROND[16396]: (root) CMD (run-parts /etc/cron.hourly)
Dec 19 12:01:01 rhel76-fips-219 run-parts(/etc/cron.hourly)[16399]: starting 0anacron
Dec 19 12:01:01 rhel76-fips-219 run-parts(/etc/cron.hourly)[16405]: finished 0anacron
Dec 19 12:04:11 rhel76-fips-219 systemd[1]: Starting Cleanup of Temporary Directories...
Dec 19 12:04:11 rhel76-fips-219 systemd[1]: Started Cleanup of Temporary Directories.
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) Internal Server Error: /pulp/api/v2/status/
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) Traceback (most recent call last):
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 131, in get_response
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) response = middleware_method(request, response)
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) File "/usr/lib/python2.7/site-packages/django/middleware/http.py", line 23, in process_response
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) set_response_etag(response)
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) File "/usr/lib/python2.7/site-packages/django/utils/cache.py", line 109, in set_response_etag
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) response['ETag'] = quote_etag(hashlib.md5(response.content).hexdigest())
Dec 19 12:07:15 rhel76-fips-219 pulp[5043]: django.request:ERROR: (5043-60928) ValueError: error:060800A3:digital envelope routines:EVP_DigestInit_ex:disabled for fips
Dec 19 12:14:27 rhel76-fips-219 dhclient[4644]: DHCPREQUEST on ens3 to 192.168.122.1 port 67 (xid=0x2ec2a980)
Dec 19 12:14:27 rhel76-fips-219 dhclient[4644]: DHCPACK from 192.168.122.1 (xid=0x2ec2a980)
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2262] dhcp4 (ens3): address 192.168.122.210
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2267] dhcp4 (ens3): plen 24 (255.255.255.0)
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2268] dhcp4 (ens3): gateway 192.168.122.1
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2268] dhcp4 (ens3): lease time 3600
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2268] dhcp4 (ens3): hostname 'rhel76-fips-219'
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2268] dhcp4 (ens3): nameserver '192.168.122.1'
Dec 19 12:14:27 rhel76-fips-219 NetworkManager[4342]: <info> [1545239667.2268] dhcp4 (ens3): state changed bound -> bound
Dec 19 12:14:27 rhel76-fips-219 dbus[4286]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Dec 19 12:14:27 rhel76-fips-219 systemd[1]: Starting Network Manager Script Dispatcher Service...
Dec 19 12:14:27 rhel76-fips-219 dhclient[4644]: bound to 192.168.122.210 -- renewal in 1278 seconds.
Dec 19 12:14:27 rhel76-fips-219 dbus[4286]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 19 12:14:27 rhel76-fips-219 nm-dispatcher[16418]: req:1 'dhcp4-change' [ens3]: new request (5 scripts)
Dec 19 12:14:27 rhel76-fips-219 nm-dispatcher[16418]: req:1 'dhcp4-change' [ens3]: start running ordered scripts...
Dec 19 12:14:27 rhel76-fips-219 systemd[1]: Started Network Manager Script Dispatcher Service.
Dec 19 12:19:31 rhel76-fips-219 pulp[4855]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Dec 19 12:19:31 rhel76-fips-219 pulp[4855]: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred)
Dec 19 12:19:31 rhel76-fips-219 pulp[4946]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[299291c5-991d-45dc-a47f-a66b772f300e]
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: kombu.transport.qpid:INFO: [299291c5] Connected to qpid with SASL mechanism ANONYMOUS
Dec 19 12:19:31 rhel76-fips-219 pulp[4946]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[2e90f887-1657-4e18-8dac-203e298f5927]
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: py.warnings:WARNING: [299291c5] (5653-50688) /usr/lib64/python2.7/site-packages/pymongo/topology.py:74: UserWarning: MongoClient opened before fork. Create MongoClient
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: py.warnings:WARNING: [299291c5] (5653-50688) "MongoClient opened before fork. Create MongoClient "
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: py.warnings:WARNING: [299291c5] (5653-50688)
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: celery.app.trace:INFO: [299291c5] Task pulp.server.controllers.repository.queue_download_deferred[299291c5-991d-45dc-a47f-a66b772f300e] succeeded in 0.104735261s: None
Dec 19 12:19:31 rhel76-fips-219 pulp[5653]: celery.app.trace:INFO: [2e90f887] Task pulp.server.controllers.repository.download_deferred[2e90f887-1657-4e18-8dac-203e298f5927] succeeded in 0.0167369139999s: None
Dec 19 12:26:04 rhel76-fips-219 chronyd[4292]: Source 204.11.201.12 replaced with 45.33.84.208
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) Internal Server Error: /pulp/api/v2/plugins/types/
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) Traceback (most recent call last):
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 131, in get_response
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) response = middleware_method(request, response)
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) File "/usr/lib/python2.7/site-packages/django/middleware/http.py", line 23, in process_response
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) set_response_etag(response)
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) File "/usr/lib/python2.7/site-packages/django/utils/cache.py", line 109, in set_response_etag
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) response['ETag'] = quote_etag(hashlib.md5(response.content).hexdigest())
Dec 19 12:32:53 rhel76-fips-219 pulp[5042]: django.request:ERROR: (5042-46336) ValueError: error:060800A3:digital envelope routines:EVP_DigestInit_ex:disabled for fips
Dec 19 12:35:45 rhel76-fips-219 dhclient[4644]: DHCPREQUEST on ens3 to 192.168.122.1 port 67 (xid=0x2ec2a980)
Dec 19 12:35:45 rhel76-fips-219 dhclient[4644]: DHCPACK from 192.168.122.1 (xid=0x2ec2a980)
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6943] dhcp4 (ens3): address 192.168.122.210
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): plen 24 (255.255.255.0)
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): gateway 192.168.122.1
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): lease time 3600
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): hostname 'rhel76-fips-219'
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): nameserver '192.168.122.1'
Dec 19 12:35:45 rhel76-fips-219 NetworkManager[4342]: <info> [1545240945.6944] dhcp4 (ens3): state changed bound -> bound
Dec 19 12:35:45 rhel76-fips-219 dbus[4286]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Dec 19 12:35:45 rhel76-fips-219 systemd[1]: Starting Network Manager Script Dispatcher Service...
Dec 19 12:35:45 rhel76-fips-219 dhclient[4644]: bound to 192.168.122.210 -- renewal in 1584 seconds.
Dec 19 12:35:45 rhel76-fips-219 dbus[4286]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 19 12:35:45 rhel76-fips-219 systemd[1]: Started Network Manager Script Dispatcher Service.
Dec 19 12:35:45 rhel76-fips-219 nm-dispatcher[16473]: req:1 'dhcp4-change' [ens3]: new request (5 scripts)
Dec 19 12:35:45 rhel76-fips-219 nm-dispatcher[16473]: req:1 'dhcp4-change' [ens3]: start running ordered scripts...
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) Internal Server Error: /pulp/api/v2/status/
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) Traceback (most recent call last):
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 131, in get_response
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) response = middleware_method(request, response)
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) File "/usr/lib/python2.7/site-packages/django/middleware/http.py", line 23, in process_response
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) set_response_etag(response)
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) File "/usr/lib/python2.7/site-packages/django/utils/cache.py", line 109, in set_response_etag
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) response['ETag'] = quote_etag(hashlib.md5(response.content).hexdigest())
Dec 19 12:38:23 rhel76-fips-219 pulp[5041]: django.request:ERROR: (5041-39040) ValueError: error:060800A3:digital envelope routines:EVP_DigestInit_ex:disabled for fips
Dec 19 12:49:31 rhel76-fips-219 pulp[4855]: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred)
Dec 19 12:49:31 rhel76-fips-219 pulp[4946]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[9db6c832-7553-4449-97a9-f444de4d65b5]
Dec 19 12:49:31 rhel76-fips-219 pulp[4946]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[f5cfb227-540d-45a6-b193-66552344d32b]
Dec 19 12:49:31 rhel76-fips-219 pulp[5653]: celery.app.trace:INFO: [9db6c832] Task pulp.server.controllers.repository.queue_download_deferred[9db6c832-7553-4449-97a9-f444de4d65b5] succeeded in 0.0134792559998s:
</pre>
h3. httpd/error_log
<pre>
[Wed Dec 19 11:44:38.226539 2018] [mpm_prefork:notice] [pid 18091] AH00170: caught SIGWINCH, shutting down gracefully
[Wed Dec 19 11:45:03.164808 2018] [core:notice] [pid 4837] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Wed Dec 19 11:45:03.177642 2018] [mime_magic:error] [pid 4837] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:45:03.190029 2018] [suexec:notice] [pid 4837] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 192.168.122.210. Set the 'ServerName' directive globally to suppress this message
[Wed Dec 19 11:45:03.696125 2018] [mime_magic:error] [pid 4837] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:45:03.696136 2018] [auth_digest:notice] [pid 4837] AH01757: generating secret for digest authentication ...
[Wed Dec 19 11:45:03.704563 2018] [lbmethod_heartbeat:notice] [pid 4837] AH02282: No slotmem from mod_heartmonitor
[Wed Dec 19 11:45:03.862247 2018] [mpm_prefork:notice] [pid 4837] AH00163: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips mod_wsgi/3.4 Python/2.7.5 configured -- resuming normal operations
[Wed Dec 19 11:45:03.862272 2018] [core:notice] [pid 4837] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[Wed Dec 19 11:47:33.138775 2018] [mpm_prefork:notice] [pid 4837] AH00170: caught SIGWINCH, shutting down gracefully
[Wed Dec 19 11:47:55.430449 2018] [core:notice] [pid 3430] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Wed Dec 19 11:47:55.440461 2018] [mime_magic:error] [pid 3430] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:47:55.456732 2018] [suexec:notice] [pid 3430] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 192.168.122.210. Set the 'ServerName' directive globally to suppress this message
[Wed Dec 19 11:47:55.999249 2018] [mime_magic:error] [pid 3430] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:47:55.999265 2018] [auth_digest:notice] [pid 3430] AH01757: generating secret for digest authentication ...
[Wed Dec 19 11:47:56.015928 2018] [lbmethod_heartbeat:notice] [pid 3430] AH02282: No slotmem from mod_heartmonitor
[Wed Dec 19 11:47:56.151806 2018] [mpm_prefork:notice] [pid 3430] AH00163: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips mod_wsgi/3.4 Python/2.7.5 configured -- resuming normal operations
[Wed Dec 19 11:47:56.151827 2018] [core:notice] [pid 3430] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[Wed Dec 19 11:48:56.230693 2018] [mpm_prefork:notice] [pid 3430] AH00170: caught SIGWINCH, shutting down gracefully
[Wed Dec 19 11:49:20.875143 2018] [core:notice] [pid 4850] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Wed Dec 19 11:49:20.890359 2018] [mime_magic:error] [pid 4850] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:49:20.895820 2018] [suexec:notice] [pid 4850] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 192.168.122.210. Set the 'ServerName' directive globally to suppress this message
[Wed Dec 19 11:49:21.436851 2018] [mime_magic:error] [pid 4850] (2)No such file or directory: AH01515: mod_mime_magic: can't read magic file /etc/httpd/NEVER_EVER_USE
[Wed Dec 19 11:49:21.436865 2018] [auth_digest:notice] [pid 4850] AH01757: generating secret for digest authentication ...
[Wed Dec 19 11:49:21.453957 2018] [lbmethod_heartbeat:notice] [pid 4850] AH02282: No slotmem from mod_heartmonitor
[Wed Dec 19 11:49:21.573101 2018] [mpm_prefork:notice] [pid 4850] AH00163: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips mod_wsgi/3.4 Python/2.7.5 configured -- resuming normal operations
[Wed Dec 19 11:49:21.573123 2018] [core:notice] [pid 4850] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
</pre>
h2. 2.19-nightly pulp-admin status failure
<pre>
[root@rhel76-fips-219 ~]# pulp-admin status
+----------------------------------------------------------------------+
Status of the server
+----------------------------------------------------------------------+
There was an internal server error while trying to access the Pulp application.
One possible cause is that the database needs to be migrated to the latest
version. If this is the case, run pulp-manage-db and restart the services. More
information may be found in Apache's log.
[root@rhel76-fips-219 ~]#
</pre>
h2. Bonus: Non-fips 2.19 Nightly Check
<pre>
[root@rhel76-fips-219 ~]# pulp-admin status
+----------------------------------------------------------------------+
Status of the server
+----------------------------------------------------------------------+
Api Version: 2
Database Connection:
Connected: True
Known Workers:
_id: scheduler@rhel76-fips-219
_ns: workers
Last Heartbeat: 2018-12-19T18:31:08Z
_id: resource_manager@rhel76-fips-219
_ns: workers
Last Heartbeat: 2018-12-19T18:31:12Z
_id: reserved_resource_worker-0@rhel76-fips-219
_ns: workers
Last Heartbeat: 2018-12-19T18:31:12Z
Messaging Connection:
Connected: True
Versions:
Platform Version: 2.19a1
[root@rhel76-fips-219 ~]# cat /proc/sys/crypto/fips_enabled
0
</pre>
h2. References:
[0] https://pulp-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/Pulp%202%20-%20Master/job/pulp-2-master-dev-rhel7-fips/178/
.