#9488 Nightly test failure in test_trust.py::TestTrust::test_server_option_with_unreachable_ad
Closed: fixed by frenaud. Opened by frenaud.

Issue

The nightly test test_trust.py::TestTrust::test_server_option_with_unreachable_ad started failing after commit 60fe752 ** ipaserver/dcerpc: avoid logging stack trace in retrieve_anonymously **

See for instance PR #3189 with the following logs and report:

self = <ipatests.test_integration.test_trust.TestTrust object at 0x7fa475408cd0>
    def test_server_option_with_unreachable_ad(self):
        """
        Check trust can be established with partially unreachable AD topology
        The SRV records for AD services can point to hosts unreachable for
        ipa master. In this case we must be able to establish trust and
        fetch domains list by using "--server" option.
        This is the regression test for https://pagure.io/freeipa/issue/7895.
        """
        # To simulate Windows Server advertising unreachable hosts in SRV
        # records we create specially crafted zone file for BIND DNS server
        tasks.backup_file(self.master, paths.NAMED_CONF)
        ad_zone = textwrap.dedent('''
            $ORIGIN {ad_dom}.
            $TTL 86400
            @  IN A {ad_ip}
               IN NS {ad_host}.
               IN SOA {ad_host}. hostmaster.{ad_dom}. 39 900 600 86400 3600
            _msdcs IN NS {ad_host}.
            _gc._tcp.Default-First-Site-Name._sites IN SRV 0 100 3268 unreachable.{ad_dom}.
            _kerberos._tcp.Default-First-Site-Name._sites IN SRV 0 100 88 unreachable.{ad_dom}.
            _ldap._tcp.Default-First-Site-Name._sites IN SRV 0 100 389 unreachable.{ad_dom}.
            _gc._tcp IN SRV 0 100 3268 unreachable.{ad_dom}.
            _kerberos._tcp IN SRV 0 100 88 unreachable.{ad_dom}.
            _kpasswd._tcp IN SRV 0 100 464 unreachable.{ad_dom}.
            _ldap._tcp IN SRV 0 100 389 unreachable.{ad_dom}.
            _kerberos._udp IN SRV 0 100 88 unreachable.{ad_dom}.
            _kpasswd._udp IN SRV 0 100 464 unreachable.{ad_dom}.
            {ad_short} IN A {ad_ip}
            unreachable IN A {unreachable}
            DomainDnsZones IN A {ad_ip}
            _ldap._tcp.Default-First-Site-Name._sites.DomainDnsZones IN SRV 0 100 389 unreachable.{ad_dom}.
            _ldap._tcp.DomainDnsZones IN SRV 0 100 389 unreachable.{ad_dom}.
            ForestDnsZones IN A {ad_ip}
            _ldap._tcp.Default-First-Site-Name._sites.ForestDnsZones IN SRV 0 100 389 unreachable.{ad_dom}.
            _ldap._tcp.ForestDnsZones IN SRV 0 100 389 unreachable.{ad_dom}.
        '''.format(  # noqa: E501
            ad_ip=self.ad.ip, unreachable='192.168.254.254',
            ad_host=self.ad.hostname, ad_dom=self.ad.domain.name,
            ad_short=self.ad.shortname))
        ad_zone_file = tasks.create_temp_file(self.master, directory='/etc')
        self.master.put_file_contents(ad_zone_file, ad_zone)
        self.master.run_command(
            ['chmod', '--reference', paths.NAMED_CONF, ad_zone_file])
        self.master.run_command(
            ['chown', '--reference', paths.NAMED_CONF, ad_zone_file])
        named_conf = self.master.get_file_contents(paths.NAMED_CONF,
                                                   encoding='utf-8')
        named_conf += textwrap.dedent(f'''
            zone "{self.ad.domain.name}" {{
                type master;
                file "{ad_zone_file}";
            }};
        ''')
        self.master.put_file_contents(paths.NAMED_CONF, named_conf)
        tasks.restart_named(self.master)
        try:
            # Check that trust can not be established without --server option
            # This checks that our setup is correct
            result = self.master.run_command(
                ['ipa', 'trust-add', self.ad_domain,
                 '--admin', 'Administrator@' + self.ad_domain, '--password'],
                raiseonerr=False,
                stdin_text=self.master.config.ad_admin_password)
            assert result.returncode == 1
>           assert 'CIFS server communication error: code "3221225653", ' \
                   'message "{Device Timeout}' in result.stderr_text
E                  assert 'CIFS server communication error: code "3221225653", message "{Device Timeout}' in 'ipa: ERROR: an internal error has occurred\n'
E                   +  where 'ipa: ERROR: an internal error has occurred\n' = <pytest_multihost.transport.SSHCommand object at 0x7fa47421cd10>.stderr_text
test_integration/test_trust.py:1070: AssertionError

Test scenario:
- Create wrong records unreachable.ad.test. for a fake AD domain controller
- run ipa trust-add
The test expects the command to fail with the error msg CIFS server communication error: code "3221225653" but the command simply returns ipa: ERROR: an internal error has occurred.

Httpd's error log shows the following trace:

[Wed Nov 29 04:45:24.052050 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608] ipa: ERROR: CIFS server communication error: code "3221225653", message "{Device Timeout} The specified I/O operation on %hs was not completed before the time-out period expired." (both may be "None")
[Wed Nov 29 04:45:24.061057 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608] ipa: ERROR: non-public: KeyError: 'sid'
[Wed Nov 29 04:45:24.061093 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608] Traceback (most recent call last):
[Wed Nov 29 04:45:24.061101 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipaserver/rpcserver.py", line 407, in wsgi_execute
[Wed Nov 29 04:45:24.061143 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     result = command(*args, **options)
[Wed Nov 29 04:45:24.061149 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]              ^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Nov 29 04:45:24.061154 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipalib/frontend.py", line 471, in __call__
[Wed Nov 29 04:45:24.061160 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     return self.__do_call(*args, **options)
[Wed Nov 29 04:45:24.061166 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Nov 29 04:45:24.061172 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipalib/frontend.py", line 499, in __do_call
[Wed Nov 29 04:45:24.061177 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     ret = self.run(*args, **options)
[Wed Nov 29 04:45:24.061183 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]           ^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Nov 29 04:45:24.061189 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipalib/frontend.py", line 816, in run
[Wed Nov 29 04:45:24.061194 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     return self.execute(*args, **options)
[Wed Nov 29 04:45:24.061200 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Nov 29 04:45:24.061205 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipaserver/plugins/trust.py", line 764, in execute
[Wed Nov 29 04:45:24.061214 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     old_range, range_name, dom_sid = self.validate_range(*keys, **options)
[Wed Nov 29 04:45:24.061220 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Wed Nov 29 04:45:24.061226 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]   File "/usr/lib/python3.11/site-packages/ipaserver/plugins/trust.py", line 972, in validate_range
[Wed Nov 29 04:45:24.061231 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]     dom_sid = self.trustinstance.remote_domain.info['sid']
[Wed Nov 29 04:45:24.061237 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608]               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^
[Wed Nov 29 04:45:24.061243 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608] KeyError: 'sid'
[Wed Nov 29 04:45:24.061541 2023] [wsgi:error] [pid 23044:tid 23382] [remote 192.168.122.115:35608] ipa: INFO: [jsonserver_session] admin@IPA.TEST: trust_add/1('ad.test', realm_admin='Administrator@ad.test', realm_passwd='********', version='2.253'): InternalError

Metadata Update from @frenaud:
- Issue assigned to rjeffman
- Issue tagged with: test-failure

@rjeffman can you have a look at this regression? Thanks.

@frenaud I'm looking into it.

Metadata Update from @frenaud:
- Custom field rhbz adjusted to https://issues.redhat.com/browse/RHEL-40359

Metadata Update from @frenaud:
- Custom field rhbz adjusted to https://issues.redhat.com/browse/RHEL-40359, https://issues.redhat.com/browse/RHEL-46897 (was: https://issues.redhat.com/browse/RHEL-40359)

Metadata Update from @frenaud:
- Issue assigned to frenaud (was: rjeffman)

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

master:

  • 88123ad2b32fbdd6206028215e4a58575a37dd9e trust-add: handle unavailable domain

ipa-4-12:

  • f37c2eb8782ec06e538d8964bf904f1b7e79c15e trust-add: handle unavailable domain

ipa-4-11:

  • 0f76fa757c3b59de85d6453f64cfcc99b997c32e trust-add: handle unavailable domain

ipa-4-10:

  • 77740f09650f8013611f1464951aaf8e7cf1b616 trust-add: handle unavailable domain

ipa-4-9:

  • 81f61f81e72da0dc91be51857937ab1412e05299 trust-add: handle unavailable domain

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

Metadata