#8271 Sporadic test failure in test_integration/test_adtrust_install.py::TestIpaAdTrustInstall::test_add_agent_not_allowed
Closed: insufficientinfo 3 years ago by fcami. Opened 4 years ago by fcami.

tasks.create_active_user() failed to set the password for the nonadmin user:

test_integration/test_adtrust_install.py:62: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
pytest_ipa/integration/tasks.py:2000: in create_active_user
    stdin_text='{0}\n{1}\n{1}\n'.format(temp_password, password))
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <ipatests.pytest_ipa.integration.host.Host master.ipa.test (master)>
argv = ['kinit', 'nonadmin'], set_env = True
stdin_text = 'Secret456789\nSecret123\nSecret123\n', log_stdout = True
raiseonerr = True, cwd = None, bg = False, encoding = 'utf-8', ok_returncode = 0

    def run_command(self, argv, set_env=True, stdin_text=None,
                    log_stdout=True, raiseonerr=True,
                    cwd=None, bg=False, encoding='utf-8', 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().run_command(
            argv, set_env=set_env, stdin_text=stdin_text,
            log_stdout=log_stdout, raiseonerr=False, cwd=cwd, bg=bg,
            encoding=encoding
        )
        # in FIPS mode SSH may print noise to stderr, remove the string
        # "FIPS mode initialized" + optional newline.
        result.stderr_bytes = FIPS_NOISE_RE.sub(b'', result.stderr_bytes)
        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, result.stderr_text
            )
E           subprocess.CalledProcessError: Command '['kinit', 'nonadmin']' returned non-zero exit status 1.
[ipatests.pytest_ipa.integration.host.Host.master.cmd62] RUN ['ipa', 'user-add', 'nonadmin', '--first', 'nonadmin', '--last', 'nonadmin', '--password']
[ipatests.pytest_ipa.integration.host.Host.master.cmd62] ---------------------
[ipatests.pytest_ipa.integration.host.Host.master.cmd62] Added user "nonadmin"
[ipatests.pytest_ipa.integration.host.Host.master.cmd62] ---------------------
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   User login: nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   First name: nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Last name: nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Full name: nonadmin nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Display name: nonadmin nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Initials: nn
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Home directory: /home/nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   GECOS: nonadmin nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Login shell: /bin/sh
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Principal name: nonadmin@IPA.TEST
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Principal alias: nonadmin@IPA.TEST
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   User password expiration: 20200414141937Z
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Email address: nonadmin@ipa.test
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   UID: 763800003
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   GID: 763800003
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Password: True
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Member of groups: ipausers
[ipatests.pytest_ipa.integration.host.Host.master.cmd62]   Kerberos keys available: True
[ipatests.pytest_ipa.integration.host.Host.master.cmd62] Exit code: 0
[ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport] RUN ['kinit', 'nonadmin']
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] RUN ['kinit', 'nonadmin']
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] Password for nonadmin@IPA.TEST: 
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] Password expired.  You must change it now.
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] Enter new password: 
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] Enter it again: 
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] kinit: Password has expired while getting initial credentials
[ipatests.pytest_ipa.integration.host.Host.master.cmd63] Exit code: 1
ipa: ERROR: stderr: kinit: Password has expired while getting initial credentials

krb5 logs show:

Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): AS_REQ (7 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.122.38: CLIENT KEY EXPIRED: nonadmin@IPA.TEST for krbtgt/IPA.TEST@IPA.TEST, Password has expired
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): closing down fd 4
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): AS_REQ (7 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.122.38: NEEDED_PREAUTH: nonadmin@IPA.TEST for kadmin/changepw@IPA.TEST, Additional pre-authentication required
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): closing down fd 4
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): AS_REQ (7 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.122.38: ISSUE: authtime 1586873979, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha1-96(18)}, nonadmin@IPA.TEST for kadmin/changepw@IPA.TEST
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): closing down fd 4
Apr 14 14:19:39 master.ipa.test krb5kdc[22870](info): AS_REQ (7 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.122.38: CLIENT KEY EXPIRED: nonadmin@IPA.TEST for krbtgt/IPA.TEST@IPA.TEST, Password has expired

The behavior is similar to https://pagure.io/freeipa/issue/1793 and is sporadic, re-running the test did not reproduce the issue


Information from @rharwood :
- debug information, using KRB5_TRACE from the client on failure, would help
- "for whatever reason the client either didn't receive or didn't correctly handle the changepw - perhaps it didn't get the TGT"
- maybe "routing issue or perhaps port 749 not being open"
- not enough info to have a fix or a good diagnosis

Closing. We don't have enough information for a fix.
It if reappears, enable KRB5_TRACE on each client invocation.

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

3 years ago

master:

  • e7319f6 tasks.py: add krb5_trace to create_active_user and kinit_as_user
  • 8f8c560 ipatests: add KRB5_TRACE to kinit in test_adtrust_install.py

ipa-4-8:

  • 01f27e2 tasks.py: add krb5_trace to create_active_user and kinit_as_user
  • 2032a61 ipatests: add KRB5_TRACE to kinit in test_adtrust_install.py

ipa-4-8:

  • c5abea2 ipatests: display SSSD kdcinfo in test_adtrust_install.py

Login to comment on this ticket.

Metadata