#8537 Nightly failure (master/updates-testing) in test_cert.py::TestCertmongerRekey::test_rekey_keytype_DSA
Closed: fixed 10 days ago by frenaud. Opened 2 months ago by frenaud.

Issue

The nightly test test_cert.py::TestCertmongerRekey::test_rekey_keytype_DSA failed in PR #468 [testing_master_testing] that is running on master branch with the repo updates-testing enabled.

Logs, report

self = <ipatests.test_integration.test_cert.TestCertmongerRekey object at 0x7fed6ec9b910>

    def test_rekey_keytype_DSA(self):
        """Test certmonger rekey command works fine

        Test is to check if -G (keytype) with DSA fails

        related: https://bugzilla.redhat.com/show_bug.cgi?id=1249165
        """
        result = self.master.run_command([
            'ipa-getcert', 'request',
            '-f', '/etc/pki/tls/certs/test_dsa.pem',
            '-k', '/etc/pki/tls/private/test_dsa.key',
            '-K', 'test/{}'.format(self.master.hostname)])
        req_id = re.findall(r'\d+', result.stdout_text)
        status = tasks.wait_for_request(self.master, req_id[0], 100)
        assert status == "MONITORING"

        # rekey with RSA key type
        self.master.run_command(['getcert', 'rekey',
                                 '-i', req_id[0],
                                 '-g', '3072',
                                 '-G', 'DSA'])
        time.sleep(100)
        # look for keytpe as DSA in request file
        self.master.run_command([
            'grep', 'DSA', '/var/lib/certmonger/requests/{}'.format(req_id[0])
        ])

        err_msg = 'Unable to create enrollment request: Invalid Request'
        result = self.master.run_command(['getcert', 'list', '-i', req_id[0]])
>       assert err_msg in result.stdout_text
E       assert 'Unable to create enrollment request: Invalid Request' in "Number of certificates and requests being tracked: 10.\nRequest ID '20201011041756':\n\tstatus: SUBMITTING\n\tstuck: ...eku: id-kp-serverAuth,id-kp-clientAuth\n\tpre-save command: \n\tpost-save command: \n\ttrack: yes\n\tauto-renew: yes\n"
E        +  where "Number of certificates and requests being tracked: 10.\nRequest ID '20201011041756':\n\tstatus: SUBMITTING\n\tstuck: ...eku: id-kp-serverAuth,id-kp-clientAuth\n\tpre-save command: \n\tpost-save command: \n\ttrack: yes\n\tauto-renew: yes\n" = <pytest_multihost.transport.SSHCommand object at 0x7fed6ec43220>.stdout_text

pki seems to correctly detect that DSA is not supported, see /var/log/pki/pki-tomcat/ca/debug.2020-10-11.log.gz:

2020-10-11 04:18:03 [ajp-nio-127.0.0.1-8009-exec-4] INFO: EnrollProfile: Parsing PKCS #10 request:
2020-10-11 04:18:03 [ajp-nio-127.0.0.1-8009-exec-4] SEVERE: Unable to parse PKCS #10 request: no such algorithm: OID.2.16.840.1.101.3.4.3.2 for provider Mozilla-JSS

but certmonger coredumps around the same time, see the journal:

Oct 11 04:18:03 master.ipa.test certmonger[35142]: 2020-10-11 04:18:03 [35142] Certificate not (yet?) issued.
Oct 11 04:18:03 master.ipa.test certmonger[35142]: dbus[35142]: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2760.
Oct 11 04:18:03 master.ipa.test certmonger[35142]: This is normally a bug in some application using the D-Bus library.
Oct 11 04:18:03 master.ipa.test certmonger[35142]:   D-Bus not built with -rdynamic so unable to print a backtrace
Oct 11 04:18:03 master.ipa.test audit[35142]: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 subj=system_u:system_r:certmonger_t:s0 pid=35142 comm="certmonger" exe="/usr/sbin/certmonger" sig=6 res=1
Oct 11 04:18:03 master.ipa.test systemd[1]: Created slice system-systemd\x2dcoredump.slice.
Oct 11 04:18:03 master.ipa.test audit: BPF prog-id=1696 op=LOAD
Oct 11 04:18:03 master.ipa.test audit: BPF prog-id=1697 op=LOAD
Oct 11 04:18:03 master.ipa.test audit: BPF prog-id=1698 op=LOAD
Oct 11 04:18:03 master.ipa.test systemd[1]: Started Process Core Dump (PID 38179/UID 0).
Oct 11 04:18:03 master.ipa.test audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-coredump@0-38179-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 04:18:03 master.ipa.test systemd[1]: certmonger.service: Main process exited, code=dumped, status=6/ABRT
Oct 11 04:18:03 master.ipa.test systemd[1]: certmonger.service: Failed with result 'core-dump'.
Oct 11 04:18:03 master.ipa.test audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=certmonger comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Oct 11 04:18:03 master.ipa.test systemd[1]: certmonger.service: Consumed 1min 6.359s CPU time.
Oct 11 04:18:03 master.ipa.test systemd-coredump[38180]: Process 35142 (certmonger) of user 0 dumped core.

                                                         Stack trace of thread 35142:
                                                         #0  0x00007f41c6e949e5 raise (libc.so.6 + 0x3c9e5)
                                                         #1  0x00007f41c6e7d895 abort (libc.so.6 + 0x25895)
                                                         #2  0x00007f41c7449b12 _dbus_abort.cold (libdbus-1.so.3 + 0x10b12)
                                                         #3  0x00007f41c746d2f0 _dbus_warn_check_failed (libdbus-1.so.3 + 0x342f0)
                                                         #4  0x00007f41c745df97 dbus_message_iter_append_basic (libdbus-1.so.3 + 0x24f97)
                                                         #5  0x00005560e7251569 cm_tdbusm_append_d_value.isra.0 (certmonger + 0x40569)
                                                         #6  0x00005560e72518dc cm_tdbusm_append_d.isra.0 (certmonger + 0x408dc)
                                                         #7  0x00005560e72519b2 cm_tdbusm_set_osd (certmonger + 0x409b2)
                                                         #8  0x00005560e724d00c cm_tdbush_property_get_all_or_changed (certmonger + 0x3c00c)
                                                         #9  0x00005560e7250403 cm_tdbush_property_emit_entry_changes (certmonger + 0x3f403)
                                                         #10 0x00005560e7225afa cm_iterate_entry (certmonger + 0x14afa)
                                                         #11 0x00005560e722427a cm_service_entry.constprop.0 (certmonger + 0x1327a)
                                                         #12 0x00005560e7224ce0 cm_fd_h (certmonger + 0x13ce0)
                                                         #13 0x00007f41c742af11 tevent_common_invoke_fd_handler (libtevent.so.0 + 0x7f11)
                                                         #14 0x00007f41c7431417 epoll_event_loop_once (libtevent.so.0 + 0xe417)
                                                         #15 0x00007f41c742f57b std_event_loop_once (libtevent.so.0 + 0xc57b)
                                                         #16 0x00007f41c742a598 _tevent_loop_once (libtevent.so.0 + 0x7598)
                                                         #17 0x00005560e7221b59 main (certmonger + 0x10b59)
                                                         #18 0x00007f41c6e7f042 __libc_start_main (libc.so.6 + 0x27042)
                                                         #19 0x00005560e722251e _start (certmonger + 0x1151e)

@rcritten could you have a look? It may either be related to certmonger or Dbus.

Metadata Update from @frenaud:
- Issue tagged with: test-failure, tests

2 months ago

I'm not able to manually reproduce this. Perhaps we need to install the dbus and certmonger debuginfo packages so if this happens again we can get a more specific stack trace from the automation.

The test itself is fragile because it assumes that the request id will match the request filename which is not guaranteed. And the 100 second sleep...

This also points to an issue in the way the JSON code returns errors. It is not consistent with previous behavior as it doesn't contain the specifics:

Server at https://ipa.example.test/ipa/json failed request, will retry: 4035 ().

The XML-RPC certmonger reports:

Server at https://ipa.example.test/ipa/xml failed request, will retry: 4035 (RPC failed at server. Request failed with status 500: Non-2xx response from CA REST API: 500. Unable to create enrollment request: Invalid Request).

I'm not sure why this didn't fail during the time when the certmonger JSON code was in rawhide.

I restarted the certmonger process and got a similar looking coredump, investigating.

I tested with a patched certmonger and that resolved the issue.

Failure did not happen any more with certmonger 0.79.13, closing as fixed

Metadata Update from @frenaud:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

10 days ago

Login to comment on this ticket.

Metadata