MAAS

Failed configuring DHCP on rack controller - too many values to unpack (expected 5)

Series 3.5
Bug #2054915

Bug #2054915 reported by Nathaniel W. Turner on 2024-02-25

This bug affects 1 person

	Status	Importance	Assigned to	Milestone
MAAS	Fix Committed	High	Christian Grabowski	MAAS 3.6.0
3.3	Fix Committed	High	Christian Grabowski	MAAS 3.3.7
3.4	Fix Released	High	Christian Grabowski	MAAS 3.4.2
3.5	Fix Committed	High	Christian Grabowski	MAAS 3.5.0

Bug Description

I just upgraded from 3.3 to to maas --channel 3.4/stable/hotfix-bug-2053033 to pick up a fix for https://bugs.launchpad.net/maas/+bug/2053033.

After that upgrade, the virsh connection issue is resolved, but now I'm seeing DHCP problems (e.g. servers get new addresses, but do not update DNS in MAAS). The /var/snap/maas/common/log/regiond.log is flooded with errors like the following:

2024-02-25 07:01:32 maasserver.rack_controller: [critical] Failed configuring DHCP on rack controller 'id:1'.
        Traceback (most recent call last):
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1750, in gotResult
            current_context.run(_inlineCallbacks, r, gen, status)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1740, in _inlineCallbacks
            status.deferred.errback()
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 700, in errback
            self._startRunCallbacks(fail)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 857, in _runCallbacks
            current.result = callback( # type: ignore[misc]
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/rack_controller.py", line 281, in <lambda>
            d.addErrback(lambda f: f.trap(NoConnectionsAvailable))
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/failure.py", line 451, in trap
            self.raiseException()
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/failure.py", line 475, in raiseException
            raise self.value.with_traceback(self.tb)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 857, in _runCallbacks
            current.result = callback( # type: ignore[misc]
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/rack_controller.py", line 300, in unwatch_if_does_not_exist
            f.trap(RackController.DoesNotExist)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/failure.py", line 451, in trap
            self.raiseException()
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/failure.py", line 475, in raiseException
            raise self.value.with_traceback(self.tb)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1656, in _inlineCallbacks
            result = current_context.run(
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/failure.py", line 489, in throwExceptionIntoGenerator
            return g.throw(self.type, self.value, self.tb)
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/dhcp.py", line 867, in configure_dhcp
            config = yield deferToDatabase(get_dhcp_configuration, rack_controller)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 244, in inContext
            result = inContext.theWork() # type: ignore[attr-defined]
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 260, in <lambda>
            inContext.theWork = lambda: context.call( # type: ignore[attr-defined]
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/context.py", line 117, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/python/context.py", line 82, in callWithContext
            return func(*args, **kw)
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/twisted.py", line 856, in callInContext
            return func(*args, **kwargs)
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/twisted.py", line 203, in wrapper
            result = func(*args, **kwargs)
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/utils/orm.py", line 771, in call_within_transaction
            return func_outside_txn(*args, **kwargs)
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/utils/orm.py", line 574, in retrier
            return func(*args, **kwargs)
          File "/usr/lib/python3.10/contextlib.py", line 79, in inner
            return func(*args, **kwds)
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/dhcp.py", line 786, in get_dhcp_configuration
            config = get_dhcp_configure_for(
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/dhcp.py", line 662, in get_dhcp_configure_for
            maas_dns_servers = get_default_dns_servers(
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/dhcp.py", line 573, in get_default_dns_servers
            dns_servers = get_dns_server_addresses(
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/dns/zonegenerator.py", line 149, in get_dns_server_addresses
            ips = get_maas_facing_server_addresses(
          File "/snap/maas/33528/lib/python3.10/site-packages/maasserver/server_address.py", line 76, in get_maas_facing_server_addresses
            addresses = resolve_hostname(
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/network.py", line 830, in resolve_hostname
            return {
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/network.py", line 832, in <setcomp>
            for family, socktype, proto, canonname, sockaddr in address_info
        builtins.ValueError: too many values to unpack (expected 5)

2024-02-25 07:01:32 twisted.internet.defer: [critical] Unhandled error in Deferred:
2024-02-25 07:01:32 twisted.internet.defer: [critical]
        Traceback (most recent call last):
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 661, in callback
            self._startRunCallbacks(result)
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
            self._runCallbacks()
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 857, in _runCallbacks
            current.result = callback( # type: ignore[misc]
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1750, in gotResult
            current_context.run(_inlineCallbacks, r, gen, status)
        --- <exception caught here> ---
          File "/snap/maas/33528/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
            result = current_context.run(gen.send, result)
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/network.py", line 771, in _v6_lookup
            return [
          File "/snap/maas/33528/lib/python3.10/site-packages/provisioningserver/utils/network.py", line 772, in <listcomp>
            (AF_INET6, sock_type, proto, "", (ans.address, port, 0, 0))
        builtins.AttributeError: 'RRHeader' object has no attribute 'address'

(Btw, what is the best way to debug this? I can't edit the code in place and restart because the snap is read-only.)

Related branches

~cgrabowski/maas:backport_safe_getaddrinfo_fix_3.3

Merged into maas:3.3

MAAS Lander: Approve on 2024-03-04

Christian Grabowski: Approve on 2024-03-04

~cgrabowski/maas:backport_safe_getaddrinfo_fix_3.4

Merged into maas:3.4

MAAS Lander: Approve on 2024-03-04

Christian Grabowski: Approve on 2024-03-04

Revision history for this message

Nathaniel W. Turner (nturner) wrote on 2024-02-25:

Some additional info: The maas_url has a hostname for which there is a A and AAAA record in DNS. The region controller has both addresses. As far as I can see, with that config, we end up calling provisioningserver.utils.network.safe_getaddrinfo and take the short path that simply calls socket.getaddrinfo. If I run through this codepath in an interactive shell, everything seems to work fine:

root@smaasc1008:~# sudo snap run --shell maas
root@smaasc1008:/root# python3
Python 3.10.12 (main, Nov 20 2023, 15:14:05) [GCC 11.4.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> hostname='hostname.from.url'
>>> port=0
>>> from socket import (
... AF_INET, AF_INET6,EAI_NODATA,EAI_NONAME,gaierror,getaddrinfo,IPPROTO_TCP,)
>>> addr_info = getaddrinfo(hostname, port, family=0, proto=IPPROTO_TCP)
>>> {sockaddr[0] for family, socktype, proto, canonname, sockaddr in addr_info}
{'172.21.66.4', '1234:5678:9:a::4'}

Revision history for this message

Nathaniel W. Turner (nturner) wrote on 2024-02-26:

Download full text (3.4 KiB)

I found https://snapcraft.io/docs/snap-try and was able to use this procedure to get a tree based on the latest 3.4/edge (maas_33732.snap) that I could hack up and run.

I added the following tracing:

--- ./lib/python3.10/site-packages/provisioningserver/utils/network.py.orig 2024-02-26 18:12:45.469928677 +0000
+++ ./lib/python3.10/site-packages/provisioningserver/utils/network.py 2024-02-26 18:23:53.355421849 +0000
@@ -768,6 +768,9 @@ def safe_getaddrinfo(hostname, port, fam
     def _v6_lookup():
         resolver = getResolver()
         answers = yield resolver.lookupIPV6Address(hostname)
+ import logging
+ for ans in answers[0]:
+ logging.error('_v6_lookup ans: %r', ans)
         return [
             (AF_INET6, sock_type, proto, "", (ans.address, port, 0, 0))
             for ans in answers[0]
@@ -827,6 +830,17 @@ def resolve_hostname(hostname, ip_versio
     # The contents of sockaddr differ for IPv6 and IPv4, but the
     # first element is always the address, and that's all we care
     # about.
+ import logging
+ for address_info_rec in address_info:
+ logging.error('one item in address_info: %r', address_info_rec)
+ for one_entry in address_info_rec:
+ logging.error(' - %r', one_entry)
+ try:
+ family, socktype, proto, canonname, sockaddr = address_info_rec
+ logging.error('%r, %r, %r, %r, %r', family, socktype, proto, canonname, sockaddr)
+ except Exception as e:
+ logging.error(e)
+
     return {
         IPAddress(sockaddr[0])
         for family, socktype, proto, canonname, sockaddr in address_info

The result:

2024-02-26 18:28:42 root: [error] one item in address_info: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('172.21.66.4', 0))
2024-02-26 18:28:42 root: [error] - <AddressFamily.AF_INET: 2>
2024-02-26 18:28:42 root: [error] - <SocketKind.SOCK_STREAM: 1>
2024-02-26 18:28:42 root: [error] - 6
2024-02-26 18:28:42 root: [error] - ''
2024-02-26 18:28:42 root: [error] - ('172.21.66.4', 0)
2024-02-26 18:28:42 root: [error] <AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('172.21.66.4', 0)
2024-02-26 18:28:42 root: [error] one item in address_info: <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] _v6_lookup ans: <RR name=ci-maas.eng.exagrid.com type=AAAA class=IN ttl=3468s auth=False>
2024-02-26 18:28:42 root: [error] - <Deferred at 0x7fddd7bf01c0 current result: <twisted.python.failure.Failure builtins.AttributeError: 'RR...

I found https://snapcraft.io/docs/snap-try and was able to use this procedure to get a tree based on the latest 3.4/edge (maas_33732.snap) that I could hack up and run.

I added the following tracing:

--- ./lib/python3.10/site-packages/provisioningserver/utils/network.py.orig     2024-02-26 18:12:45.469928677 +0000
+++ ./lib/python3.10/site-packages/provisioningserver/utils/network.py  2024-02-26 18:23:53.355421849 +0000
@@ -768,6 +768,9 @@ def safe_getaddrinfo(hostname, port, fam
     def _v6_lookup():
         resolver = getResolver()
         answers = yield resolver.lookupIPV6Address(hostname)
+        import logging
+        for ans in answers[0]:
+            logging.error('_v6_lookup ans: %r', ans)
         return [
             (AF_INET6, sock_type, proto, "", (ans.address, port, 0, 0))
             for ans in answers[0]
@@ -827,6 +830,17 @@ def resolve_hostname(hostname, ip_versio
     # The contents of sockaddr differ for IPv6 and IPv4, but the
     # first element is always the address, and that's all we care
     # about.
+    import logging
+    for address_info_rec in address_info:
+        logging.error('one item in address_info: %r', address_info_rec)
+        for one_entry in address_info_rec:
+            logging.error('     - %r', one_entry)
+        try:
+            family, socktype, proto, canonname, sockaddr = address_info_rec
+            logging.error('%r, %r, %r, %r, %r', family, socktype, proto, canonname, sockaddr)
+        except Exception as e:
+            logging.error(e)
+
     return {
         IPAddress(sockaddr[0])
         for family, socktype, proto, canonname, sockaddr in address_info

The result:

2024-02-26 18:28:42 root: [error] one item in address_info: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('172.21.66.4', 0))
2024-02-26 18:28:42 root: [error]      - <AddressFamily.AF_INET: 2>
2024-02-26 18:28:42 root: [error]      - <SocketKind.SOCK_STREAM: 1>
2024-02-26 18:28:42 root: [error]      - 6
2024-02-26 18:28:42 root: [error]      - ''
2024-02-26 18:28:42 root: [error]      - ('172.21.66.4', 0)
2024-02-26 18:28:42 root: [error] <AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('172.21.66.4', 0)
2024-02-26 18:28:42 root: [error] one item in address_info: <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0>
2024-02-26 18:28:42 root: [error] _v6_lookup ans: <RR name=ci-maas.eng.exagrid.com type=AAAA class=IN ttl=3468s auth=False>
2024-02-26 18:28:42 root: [error]      - <Deferred at 0x7fddd7bf01c0 current result: <twisted.python.failure.Failure builtins.AttributeError: 'RRHeader' object has no attribute 'address'>>

Not sure why the twisted DNS resolver is getting that result. The name in question resolves fine:

root@smaasc1008:~/squashfs-root# host ci-maas.eng.exagrid.com
ci-maas.eng.exagrid.com has address 172.21.66.4
ci-maas.eng.exagrid.com has IPv6 address 2602:fbab:e0:1066::4

Revision history for this message

Nathaniel W. Turner (nturner) wrote on 2024-02-26:

Wow, launchpad compresses whitespace within a line. (How do you paste code blocks here without that happening?) Hopefully the patch indentation is obvious.

Revision history for this message

Nathaniel W. Turner (nturner) wrote on 2024-02-27:

hack.patch Edit (591 bytes, text/plain)

The bug appears to be in the "safe_getaddrinfo" function. When called (in this case, on a system with both IPv4 and IPv6 networking) with a request for only IPv6 addresses, it takes a special codepath instead of just calling getaddrinfo, and that codepath appears to have some bugs.

On my system, simply hacking this function to always take the getaddrinfo path resolves the issue.

The buggy code refers to https://github.com/python/cpython/issues/82082, which is still open. I don't know if systems that only support IPv6 still require the special code. But forcing even dual-stack systems down this path when a query is only for v6 addresses seems unnecessary.

Peter Makowski (petermakowski) on 2024-02-28

Changed in maas:
status:	New → Triaged
importance:	Undecided → High
milestone:	none → 3.4.x

Christian Grabowski (cgrabowski) on 2024-03-04

Changed in maas:
status:	Triaged → In Progress
assignee:	nobody → Christian Grabowski (cgrabowski)

Björn Tillenius (bjornt) on 2024-05-02

Changed in maas:
status:	In Progress → Fix Committed
milestone:	3.4.x → 3.6.0

Revision history for this message

Nathaniel W. Turner (nturner) wrote on 2024-05-18:

Hi all,

I see this is marked as "Fix Committed" for MAAS 3.4.2. I did a "snap refresh maas --amend --channel 3.4/stable" and got version 3.4.2-14353-g.5a5221d57 and the bug came back. Is this version expected to have the fix?