#8728 Random nightly test failure in test_commands.py::TestIPACommand::test_ssh_key_connection
Closed: fixed 3 years ago by frenaud. Opened 3 years ago by frenaud.

The nightly test test_commands.py::TestIPACommand::test_ssh_key_connection randomly fails, see for instance PR #749 on fedora 33 (logs, report):

self = <ipatests.test_integration.test_commands.TestIPACommand object at 0x7f46e3bca9d0>
tmpdir = local('/tmp/pytest-of-root/pytest-0/test_ssh_key_connection0')

    def test_ssh_key_connection(self, tmpdir):
        """
        Integration test for https://pagure.io/SSSD/sssd/issue/3747
        """

        test_user = 'test-ssh'

        pub_keys = []

        for i in range(40):
            ssh_key_pair = tasks.generate_ssh_keypair()
            pub_keys.append(ssh_key_pair[1])
            with open(os.path.join(
                    tmpdir, 'ssh_priv_{}'.format(i)), 'w') as fp:
                fp.write(ssh_key_pair[0])
                fp.write(os.linesep)

        tasks.kinit_admin(self.master)
        self.master.run_command(['ipa', 'user-add', test_user,
                                 '--first=tester', '--last=tester'])

        keys_opts = ' '.join(['--ssh "{}"'.format(k) for k in pub_keys])
        self.master.run_command(
            shlex.split('ipa user-mod {} {}'.format(test_user, keys_opts))
        )

        # connect with first SSH key
        first_priv_key_path = os.path.join(tmpdir, 'ssh_priv_1')
        # change private key permission to comply with SS rules
        os.chmod(first_priv_key_path, 0o600)

        # start to look at logs a bit before "now"
        # https://pagure.io/freeipa/issue/8432
        since = time.strftime(
            '%H:%M:%S', (datetime.now() - timedelta(seconds=10)).timetuple()
        )

        tasks.run_ssh_cmd(
            to_host=self.master.external_hostname, username=test_user,
            auth_method="key", private_key_path=first_priv_key_path
        )

        expected_missing_msg = "exited on signal 13"
        # closing session marker(depends on PAM stack of sshd)
        expected_msgs = [
            f"session closed for user {test_user}",
            f"Disconnected from user {test_user}",
        ]

        def test_cb(stdout):
            # check if expected message logged and expected missing one not
            return (
                any(m in stdout for m in expected_msgs)
                and expected_missing_msg not in stdout
            )

        # sshd don't flush its logs to syslog immediately
        cmd = ["journalctl", "-u", "sshd", f"--since={since}"]
>       tasks.run_repeatedly(self.master, command=cmd, test=test_cb)

The test is performing a ssh connection and checks the content of the journal using --since=%H:%M:%S. According to journalctl man page, if the date component is omitted, the current day is assumed.
When the test starts just before midnight and finishes just after midnight, this means that journalctl won't find any log as it will look for lines logged today after 11:58PM for instance:

RUN ['journalctl', '-u', 'sshd', '--since=23:59:58']

The test needs to be fixed in order to provide the whole date to --since parameter.


Metadata Update from @frenaud:
- Issue assigned to frenaud

3 years ago

Metadata Update from @frenaud:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/5596

3 years ago

master:

  • 5cd3944 ipatests: use whole date when calling journalctl --since

ipa-4-9:

  • caf7488 ipatests: use whole date when calling journalctl --since

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

3 years ago

Login to comment on this ticket.

Metadata