#8599 Replica installation on Rawhide stucks in infinite loop in dnspython code
Opened 3 years ago by abbra. Modified 3 years ago

Using FreeIPA 4.9.0-0.1.rc1.fc34 and bind-dyndb-ldap-11.6-1.fc34, I am able to deploy IPA master and clients but fail to promote the client to a replica. When ipa-replica-install starts, the following can be seen in the /var/log/ipareplica-install.log and then the processing hangs:

2020-11-26T15:25:08Z DEBUG Check if replica1.ipa.test is a primary hostname for localhost
2020-11-26T15:25:08Z DEBUG Primary hostname for localhost: replica1.ipa.test
2020-11-26T15:25:08Z DEBUG Search DNS for replica1.ipa.test
2020-11-26T15:25:08Z DEBUG Check if replica1.ipa.test is not a CNAME

Looking with pdb, I can see looping inside dnspython code:

[root@replica1 ~]# python3 -m pdb /usr/sbin/ipa-replica-install --setup-dns --no-dnssec-validation --mkhomedir --forwarder 10.0.106.229
> /usr/sbin/ipa-replica-install(21)<module>()
-> from ipaserver.install import ipa_replica_install
(Pdb) c
^C
Program interrupted. (Use 'cont' to resume).
> /usr/lib/python3.9/site-packages/dns/name.py(368)__hash__()
-> h += (h << 3) + c
(Pdb) bt full
  /usr/lib64/python3.9/runpy.py(197)_run_module_as_main()
-> return _run_code(code, main_globals, None,
  /usr/lib64/python3.9/runpy.py(87)_run_code()
-> exec(code, run_globals)
  /usr/lib64/python3.9/pdb.py(1731)<module>()
-> pdb.main()
  /usr/lib64/python3.9/pdb.py(1704)main()
-> pdb._runscript(mainpyfile)
  /usr/lib64/python3.9/pdb.py(1573)_runscript()
-> self.run(statement)
  /usr/lib64/python3.9/bdb.py(580)run()
-> exec(cmd, globals, locals)
  <string>(1)<module>()
  /usr/sbin/ipa-replica-install(21)<module>()
-> from ipaserver.install import ipa_replica_install
  /usr/lib/python3.9/site-packages/ipaserver/install/ipa_replica_install.py(91)run()
-> ReplicaInstall.run_cli()
  /usr/lib/python3.9/site-packages/ipapython/admintool.py(132)run_cli()
-> sys.exit(cls.main(sys.argv))
  /usr/lib/python3.9/site-packages/ipapython/admintool.py(156)main()
-> return command.execute()
  /usr/lib/python3.9/site-packages/ipapython/admintool.py(180)execute()
-> return_value = self.run()
  /usr/lib/python3.9/site-packages/ipapython/install/cli.py(340)run()
-> return cfgr.run()
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(358)run()
-> self.validate()
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(368)validate()
-> for _nothing in self._validator():
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(421)__runner()
-> step()
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(418)<lambda>()
-> step = lambda: next(self.__gen)
  /usr/lib/python3.9/site-packages/ipapython/install/util.py(59)run_generator_with_yield_from()
-> value = gen.send(prev_value)
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(633)_configure()
-> next(validator)
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(421)__runner()
-> step()
  /usr/lib/python3.9/site-packages/ipapython/install/core.py(418)<lambda>()
-> step = lambda: next(self.__gen)
  /usr/lib/python3.9/site-packages/ipapython/install/util.py(59)run_generator_with_yield_from()
-> value = gen.send(prev_value)
  /usr/lib/python3.9/site-packages/ipapython/install/common.py(65)_install()
-> for unused in self._installer(self.parent):
  /usr/lib/python3.9/site-packages/ipaserver/install/server/__init__.py(606)main()
-> replica_promote_check(self)
  /usr/lib/python3.9/site-packages/ipaserver/install/server/replicainstall.py(401)decorated()
-> func(installer)
  /usr/lib/python3.9/site-packages/ipaserver/install/server/replicainstall.py(423)decorated()
-> func(installer)
  /usr/lib/python3.9/site-packages/ipaserver/install/server/replicainstall.py(917)promote_check()
-> installutils.verify_fqdn(config.host_name, options.no_host_dns)
  /usr/lib/python3.9/site-packages/ipaserver/install/installutils.py(193)verify_fqdn()
-> resolve(host_name, rdatatype.CNAME)
  /usr/lib/python3.9/site-packages/ipapython/dnsutil.py(54)resolve()
-> return get_ipa_resolver().resolve(*args, **kwargs)
  /usr/lib/python3.9/site-packages/dns/resolver.py(1198)resolve()
-> (answer, done) = resolution.query_result(response, None)
  /usr/lib/python3.9/site-packages/dns/resolver.py(660)query_result()
-> answer = Answer(self.qname, self.rdtype, self.rdclass, response,
  /usr/lib/python3.9/site-packages/dns/resolver.py(213)__init__()
-> (self.canonical_name, min_ttl, self.rrset) = response.resolve_chaining()
  /usr/lib/python3.9/site-packages/dns/message.py(760)resolve_chaining()
-> rrset = self.find_rrset(self.answer, qname, question.rdclass,
  /usr/lib/python3.9/site-packages/dns/message.py(349)find_rrset()
-> rrset = self.index.get(key)
> /usr/lib/python3.9/site-packages/dns/name.py(368)__hash__()
-> h += (h << 3) + c
(Pdb) print(self)
replica1.ipa.test.
(Pdb) print(self.labels)
(b'replica1', b'ipa', b'test', b'')
(Pdb) up
> /usr/lib/python3.9/site-packages/dns/message.py(349)find_rrset()
-> rrset = self.index.get(key)
(Pdb) print(self.index)
{(<MessageSection.QUESTION: 0>, <DNS name replica1.ipa.test.>, 1, 5, <RdataType.TYPE0: 0>, None): <DNS replica1.ipa.test. IN CNAME RRset: []>, (<MessageSection.AUTHORITY: 2>, <DNS name ipa.test.>, 1, 6, <RdataType.TYPE0: 0>, None): <DNS ipa.test. IN SOA RRset: [<master.ipa.test. hostmaster.ipa.test. 1606403102 3600 900 1209600 3600>]>}
(Pdb) print(key)
(<MessageSection.ANSWER: 1>, <DNS name replica1.ipa.test.>, 1, 5, <RdataType.TYPE0: 0>, None)
(Pdb) 

Looking at master's DNS log, shows the following (after I activated logging for queries):

26-Nov-2020 14:52:42.466 LDAP configuration for instance 'ipa' synchronized
26-Nov-2020 14:52:42.477 managed-keys-zone: Key 20326 for zone . acceptance timer complete: key now trusted
26-Nov-2020 14:52:42.479 LDAP data for instance 'ipa' are being synchronized, please ignore message 'all zones loaded'
26-Nov-2020 14:52:42.523 zone ipa.test/IN: loaded serial 1606402362
26-Nov-2020 14:52:42.523 1 master zones from LDAP instance 'ipa' loaded (1 zones defined, 0 inactive, 0 failed to load)
26-Nov-2020 15:04:54.730 client @0x7fa7550a4000 10.0.107.38#60963/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': deleting rrset at 'replica1.ipa.test' A
26-Nov-2020 15:04:54.738 client @0x7fa7550f2a70 10.0.107.38#44443/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': deleting rrset at 'replica1.ipa.test' AAAA
26-Nov-2020 15:04:54.746 client @0x7fa7550a4000 10.0.107.38#54955/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' A 10.0.107.38
26-Nov-2020 15:04:55.115 client @0x7fa7550a4000 10.0.107.38#58563/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': deleting rrset at 'replica1.ipa.test' SSHFP
26-Nov-2020 15:04:55.123 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 3 1 5A395BBA3D507ABC22B353B9FEF194F3CD6BF2AA
26-Nov-2020 15:04:55.128 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 3 2 26433621BA53EF22BDB0E27FD1305780E6839C2BF6C01CB605884FAE 80E2883F
26-Nov-2020 15:04:55.133 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 1 1 17BAF02A68847C9CBD7C410C655334A1C3A875D1
26-Nov-2020 15:04:55.137 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 1 2 93DB6A7C6F871F38B33D1B342B59FDAB2A8DED9410B157993BBCB6C8 26DF7B06
26-Nov-2020 15:04:55.140 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 4 1 5C718224FC407379D8D4321BB63F7F21E0911115
26-Nov-2020 15:04:55.145 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 4 2 CBE5ACD4BF65511EFF8852F67454B4CA0B31E1B919A9F6E8E6E475CC 353FED9A
26-Nov-2020 15:04:55.150 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 2 1 A6299E07BFDB5F98F47FB750F19ADB3FBF1179C2
26-Nov-2020 15:04:55.154 client @0x7fa7600bf5d0 10.0.107.38#40399/key host/replica1.ipa.test\@IPA.TEST: updating zone 'ipa.test/IN': adding an RR at 'replica1.ipa.test' SSHFP 2 2 1013B0E93F0FB4808FA1B2AFC120930F8F94AD6D574A802ACAF55E9C 5E84BD64

26-Nov-2020 15:34:21.495 received control channel command 'querylog on'
26-Nov-2020 15:34:21.495 query logging is now on
26-Nov-2020 15:34:29.401 client @0x7fa7550f2a70 10.0.107.38#49872 (master.ipa.test): query: master.ipa.test IN CNAME + (10.0.106.229)
26-Nov-2020 15:34:42.585 client @0x7fa7550f2a70 10.0.107.38#42281 (replica1.ipa.test): query: replica1.ipa.test IN CNAME + (10.0.106.229)

At this time, /etc/resolv.conf is pointing to master and normal resolution works just fine in shell:

[root@replica1 ~]# dig -t cname replica1.ipa.test

; <<>> DiG 9.11.24-RedHat-9.11.24-2.fc34 <<>> -t cname replica1.ipa.test
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 9808
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
; COOKIE: d2101807b63256692785483c5fbfcb79bd6b0a39d2a43457 (good)
;; QUESTION SECTION:
;replica1.ipa.test.     IN  CNAME

;; AUTHORITY SECTION:
ipa.test.       3600    IN  SOA master.ipa.test. hostmaster.ipa.test. 1606403102 3600 900 1209600 3600

;; Query time: 1 msec
;; SERVER: 10.0.106.229#53(10.0.106.229)
;; WHEN: Thu Nov 26 15:36:26 UTC 2020
;; MSG SIZE  rcvd: 128

[root@replica1 ~]# host replica1.ipa.test
replica1.ipa.test has address 10.0.107.38

These two commands are seen by DNS server:

26-Nov-2020 15:36:25.664 client @0x7fa7550f2a70 10.0.107.38#53311 (replica1.ipa.test): query: replica1.ipa.test IN CNAME +E(0)K (10.0.106.229)
26-Nov-2020 15:38:59.329 client @0x7fa7550f2a70 10.0.107.38#59104 (replica1.ipa.test): query: replica1.ipa.test IN A + (10.0.106.229)
26-Nov-2020 15:38:59.331 client @0x7fa7550f2a70 10.0.107.38#43994 (replica1.ipa.test): query: replica1.ipa.test IN AAAA + (10.0.106.229)
26-Nov-2020 15:38:59.332 client @0x7fa7550f2a70 10.0.107.38#50473 (replica1.ipa.test): query: replica1.ipa.test IN MX + (10.0.106.229)

It looks like dnspython 2.1.0-0.1.rc1 has some issues with responses like this? dnspython 2.1.0 release candidate 1 has the following release notes: https://dnspython.readthedocs.io/en/latest/whatsnew.html#rc1

Fedora package information:

[root@replica1 ~]# rpm -qi python3-dns
Name        : python3-dns
Version     : 2.1.0
Release     : 0.1.rc1.fc34
Architecture: noarch
Install Date: Thu Nov 26 14:28:58 2020
Group       : Unspecified
Size        : 1524503
License     : ISC and MIT
Signature   : RSA/SHA256, Thu Nov 19 12:22:49 2020, Key ID 1161ae6945719a39
Source RPM  : python-dns-2.1.0-0.1.rc1.fc34.src.rpm
Build Date  : Thu Nov 19 12:22:20 2020
Build Host  : buildvm-ppc64le-31.iad2.fedoraproject.org
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : http://www.dnspython.org
Bug URL     : https://bugz.fedoraproject.org/python-dns
Summary     : DNS toolkit for Python
Description :
dnspython is a DNS toolkit for Python. It supports almost all record
types. It can be used for queries, zone transfers, and dynamic
updates. It supports TSIG authenticated messages and EDNS0.

dnspython provides both high and low level access to DNS. The high
level classes perform queries for data of a given name, type, and
class, and return an answer set. The low level classes allow direct
manipulation of DNS zones, messages, names, and records.

If I'd use python3-dns-2.0.0-1.fc33, replica installation processes further:

[root@replica1 ~]# rpm -Uhv --force https://kojipkgs.fedoraproject.org//packages/python-dns/2.0.0/1.fc33/noarch/python3-dns-2.0.0-1.fc33.noarch.rpm
Retrieving https://kojipkgs.fedoraproject.org//packages/python-dns/2.0.0/1.fc33/noarch/python3-dns-2.0.0-1.fc33.noarch.rpm
Verifying...                          ################################# [100%]
Preparing...                          ################################# [100%]
Updating / installing...
   1:python3-dns-2.0.0-1.fc33         ################################# [ 50%]
Cleaning up / removing...
   2:python3-dns-2.1.0-0.1.rc1.fc34   ################################# [100%]
[root@replica1 ~]# ipa-replica-install --setup-dns --no-dnssec-validation --mkhomedir --forwarder 10.11.5.19
Lookup failed: Preferred host replica1.ipa.test does not provide DNS.
The IP address 10.0.106.229 of host master.ipa.test resolves to: ci-vm-10-0-106-229.hosted.upshift.rdu2.redhat.com.. Clients may not function properly. Please check your DNS setup. (Note that this check queries IPA DNS directly and ignores /etc/hosts.)
Continue? [no]:  yes
Run connection check to master
Connection check OK
Disabled p11-kit-proxy
Configuring directory server (dirsrv). Estimated time: 30 seconds
  [1/38]: creating directory server instance
...
The ipa-replica-install command was successful

I think I've found the issue in dnspython and @pspacek is looking upstream at the potential fix.

python3-dns was updated in Rawhide with a workaround by @lbalhar so that FreeIPA can continue working. Let's keep this bug as a tracker for a proper dnspython upstream fix.

Login to comment on this ticket.

Metadata