#8785 Nightly test failure in test_integration/test_commands.py/TestIPACommand/test_proxycommand_invalid_shell
Closed: fixed by frenaud. Opened by mpolovka.

Nightly test test_commands.py::TestIPACommand::test_proxycommand_invalid_shell failed in [testing_ipa-4.9_latest_selinux] Nightly PR #804 with an error:

self = <ipatests.test_integration.test_commands.TestIPACommand object at 0x7f7a6aa755b0>
    def test_proxycommand_invalid_shell(self):
        """Test that ssh works with a user with an invalid shell.
           Specifically for this use-case:
           # getent passwd test
           test:x:1001:1001::/home/test:/sbin/nologin
           # sudo -u user ssh -v root@ipa.example.test
           ruser is our restricted user
           tuser1 is a regular user we ssh to remotely as
        """
        password = 'Secret123'
        restricted_user = 'ruser'
        regular_user = 'tuser1'
        tasks.kinit_admin(self.master)
        tasks.user_add(self.master, restricted_user,
                       extra_args=["--shell", "/sbin/nologin"],
                       password=password)
        tasks.user_add(self.master, regular_user,
                       password=password)
        user_kinit = "{password}\n{password}\n{password}\n".format(
            password=password)
        self.clients[0].run_command([
            'kinit', regular_user],
            stdin_text=user_kinit)
        self.clients[0].run_command([
            'kinit', restricted_user],
            stdin_text=user_kinit)
        tasks.kdestroy_all(self.clients[0])
        # ssh as a restricted user to a user with a valid shell should
        # work
>       self.clients[0].run_command(
            ['sudo', '-u', restricted_user,
             'sshpass', '-p', password,
             'ssh', '-v',
             '-o', 'StrictHostKeyChecking=no',
             'tuser1@%s' % self.master.hostname, 'cat /etc/hosts'],
        )
test_integration/test_commands.py:1439: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = <ipatests.pytest_ipa.integration.host.Host client0.ipa.test (client)>
argv = ['sudo', '-u', 'ruser', 'sshpass', '-p', 'Secret123', ...]
set_env = True, stdin_text = None, 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 '['sudo', '-u', 'ruser', 'sshpass', '-p', 'Secret123', 'ssh', '-v', '-o', 'StrictHostKeyChecking=no', 'tuser1@master.ipa.test', 'cat /etc/hosts']' returned non-zero exit status 5.

Furthermore, the logs show

debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available (default cache: KCM:)
debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available (default cache: KCM:)
debug1: Next authentication method: publickey
debug1: Trying private key: /home/ruser/.ssh/id_rsa
debug1: Trying private key: /home/ruser/.ssh/id_dsa
debug1: Trying private key: /home/ruser/.ssh/id_ecdsa
debug1: Trying private key: /home/ruser/.ssh/id_ecdsa_sk
debug1: Trying private key: /home/ruser/.ssh/id_ed25519
debug1: Trying private key: /home/ruser/.ssh/id_ed25519_sk
debug1: Trying private key: /home/ruser/.ssh/id_xmss
debug1: Next authentication method: keyboard-interactive

AVC log shows several denials for rpcbind and renew_ca_cert.

Full logs


The test scenario is the following:
- on the server, create ruser with --shell /sbin/nologin and create tuser1
- on the client, perform kinit tuser1 and reset password
- on the client, perform kinit ruser and reset password
- on the client, perform kdestroy -A
- on the client, perform sudo -u ruser sshpass -p password ssh tuser@server.ipa.test cat /etc/hosts

In the latest failing run (report), we can see that the kinit tuser1 does not prompt Your password has expired but warns that password will soon expire (but correctly prompts for ruser):

INFO     ipatests.pytest_ipa.integration.host.Host.client0.IPAOpenSSHTransport:transport.py:391 RUN ['kinit', 'tuser1']
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd217:transport.py:513 RUN ['kinit', 'tuser1']
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd217:transport.py:557 Password for tuser1@IPA.TEST: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd217:transport.py:557 Warning: Your password will expire in less than one hour on Fri 02 Apr 2021 05:07:15 PM UTC
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd217:transport.py:217 Exit code: 0
INFO     ipatests.pytest_ipa.integration.host.Host.client0.IPAOpenSSHTransport:transport.py:391 RUN ['kinit', 'ruser']
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:513 RUN ['kinit', 'ruser']
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:557 Password for ruser@IPA.TEST: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:557 Password expired.  You must change it now.
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:557 Enter new password: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:557 Enter it again: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.client0.cmd218:transport.py:217 Exit code: 0

It looks like the client and server have a small time shift that could explain the issue. A possible fix would be to run kinit on the server instead. @rcritten do you have any other idea?

@frenaud yes, running kinit on the server may help. I'll create a PR.

Metadata Update from @rcritten:
- Issue assigned to rcritten

https://github.com/freeipa/freeipa/pull/5767

master:

  • 4f301306974209086a6800c736cd57b8017db1ad ipatests: kinit on server for test_proxycommand_invalid_shell

ipa-4-9:

  • bfd7b6e00d00efea637f0f575570ac7abd6c5fbc ipatests: kinit on server for test_proxycommand_invalid_shell

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

Metadata