freeipa

#8991 Nightly test failure in test_backup_and_restore.py/TestBackupAndRestoreWithKRA/test_full_backup_restore_with_vault - internal server error
Closed: fixed by frenaud. Opened by mpolovka.

Closed: fixed
Reopen Issue

The nightly test test_full_backup_restore_with_vault is failing in [testing_ipa-4.6] Nightly PR #1168 with an error:

    def test_full_backup_restore_with_vault(self):
        """backup, uninstall, restore"""
>       self._full_backup_restore_with_vault(reinstall=False)
test_integration/test_backup_and_restore.py:442: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test_integration/test_backup_and_restore.py:399: in _full_backup_restore_with_vault
    "--type", "symmetric",
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = <ipatests.pytest_ipa.integration.host.Host master.ipa.test (master)>
argv = ['ipa', 'vault-add', 'ci_test_vault', '--password', 'password', '--type', ...]
set_env = True, stdin_text = None, log_stdout = True, raiseonerr = True
cwd = None, ok_returncode = 0
    def run_command(self, argv, set_env=True, stdin_text=None,
                    log_stdout=True, raiseonerr=True,
                    cwd=None, ok_returncode=0):
        """Wrapper around run_command to log stderr on raiseonerr=True
            :param ok_returncode: return code considered to be correct,
                                  you can pass an integer or sequence of integers
            """
        result = super(Host, self).run_command(
            argv, set_env=set_env, stdin_text=stdin_text,
            log_stdout=log_stdout, raiseonerr=False, cwd=cwd
        )
        try:
            result_ok = result.returncode in ok_returncode
        except TypeError:
            result_ok = result.returncode == ok_returncode
        if not result_ok and raiseonerr:
            result.log.error('stderr: %s', result.stderr_text)
            raise subprocess.CalledProcessError(
                result.returncode, argv,
>               result.stdout_text
            )
E           subprocess.CalledProcessError: Command '['ipa', 'vault-add', 'ci_test_vault', '--password', 'password', '--type', 'symmetric']' returned non-zero exit status 1.
pytest_ipa/integration/host.py:90: CalledProcessError
---------------------------- Captured stdout setup -----------------------------
<ipatests.pytest_ipa.integration.config.Config object at 0x7f2dadd19438>

Furthermore, the logs show

[ipatests.pytest_ipa.integration.host.Host.master.ParamikoTransport] RUN ['kinit', 'admin']
[ipatests.pytest_ipa.integration.host.Host.master.cmd23] RUN ['kinit', 'admin']
[ipatests.pytest_ipa.integration.host.Host.master.cmd23] Password for admin@IPA.TEST: 
[ipatests.pytest_ipa.integration.host.Host.master.cmd23] Exit code: 0
[ipatests.pytest_ipa.integration.host.Host.master.ParamikoTransport] RUN ['ipa', 'vault-add', 'ci_test_vault', '--password', 'password', '--type', 'symmetric']
[ipatests.pytest_ipa.integration.host.Host.master.cmd24] RUN ['ipa', 'vault-add', 'ci_test_vault', '--password', 'password', '--type', 'symmetric']
[ipatests.pytest_ipa.integration.host.Host.master.cmd24] ipa: ERROR: an internal error has occurred
[ipatests.pytest_ipa.integration.host.Host.master.cmd24] Exit code: 1
ipa: ERROR: stderr: ipa: ERROR: an internal error has occurred

Full report

The exception raised by the pki client is:

[Sun Sep 12 16:06:44.449820 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844] Traceback (most recent call last):
[Sun Sep 12 16:06:44.449822 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/ipaserver/rpcserver.py", line 396, in wsgi_execute
[Sun Sep 12 16:06:44.449824 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     result = command(*args, **options)
[Sun Sep 12 16:06:44.449827 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 450, in __call__
[Sun Sep 12 16:06:44.449829 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     return self.__do_call(*args, **options)
[Sun Sep 12 16:06:44.449839 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 478, in __do_call
[Sun Sep 12 16:06:44.449841 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     ret = self.run(*args, **options)
[Sun Sep 12 16:06:44.449844 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/ipalib/frontend.py", line 800, in run
[Sun Sep 12 16:06:44.449846 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     return self.execute(*args, **options)
[Sun Sep 12 16:06:44.449848 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/ipaserver/plugins/vault.py", line 1074, in execute
[Sun Sep 12 16:06:44.449850 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     nonce_iv=nonce,
[Sun Sep 12 16:06:44.449852 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/pki/__init__.py", line 431, in handler
[Sun Sep 12 16:06:44.449855 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     return fn_call(inst, *args, **kwargs)
[Sun Sep 12 16:06:44.449857 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/pki/key.py", line 878, in archive_encrypted_data
[Sun Sep 12 16:06:44.449859 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     return self.submit_request(request)
[Sun Sep 12 16:06:44.449861 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]   File "/usr/lib/python3.6/site-packages/pki/__init__.py", line 450, in handler
[Sun Sep 12 16:06:44.449863 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844]     raise pki_exception
[Sun Sep 12 16:06:44.449867 2021] [wsgi:error] [pid 21046:tid 140102134875904] [remote 192.168.122.16:50844] pki.PKIException: Invalid Private Key

The KRA is logging:

[12/Sep/2021:16:06:44][ajp-nio-127.0.0.1-8009-exec-6]: Failed to create security data to archive: Failed to generate crypto context

So this test is running the ipa-4-6 branch on Fedora 27 in order to simulate other distributions. The KRA is pki-kra-10.5.12-1.fc27.noarch

This particular error message only appears once (with the colon), in base/kra/src/com/netscape/kra/SecurityDataProcessor.java

The kra debug log is at http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/759a33c0-13e1-11ec-b6b1-fa163e2b0c01/test_integration-test_backup_and_restore.py-TestBackupAndRestoreWithKRA--test_full_backup_restore_with_vault/master.ipa.test/var/log/pki/pki-tomcat/kra/debug.gz

It hasn't failed since, 5 months.

Does not happen any more

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

test-failure tests

None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.