Bug #2020798 “(3.3) RackD constantly restarting: MulticastJoinEr...” : Bugs : MAAS

Linus Walther (linwalth) on 2023-05-25

no longer affects:	maas (Ubuntu)
summary:	- RackD constantly restarting: MulticastJoinError - Address already in use + (3.3) RackD constantly restarting: MulticastJoinError - Address already + in use

Revision history for this message

Jerzy Husakowski (jhusakowski) wrote on 2023-06-08:

#1

Could you provide the logs from the system when the rackds are restarting?

Changed in maas:
importance:	Undecided → Medium
status:	New → Incomplete

Revision history for this message

Linus Walther (linwalth) wrote on 2023-06-08:

#2

Download full text (16.4 KiB)

Sure. I sought out the logs i thought most pertaining to the issue:

################

Preliminary information:

At 9:29:35 the rackD reports not being able to report test results. This corresponds with the following entry in kern.log:

Jun 8 09:29:35 maas-rackd001 kernel: [749024.447228] audit: type=1400 audit(1686216575.729:26065): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025042 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

ens18 is the interface to which RACKD001_ADDRESS is bound.

################

MAAS RackD logs:

2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:36 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36090, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36100, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36112, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57688, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57702, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57708, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha002:pid=2854011' authenticated.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha002:pid=2854011' authenticated.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice...

Sure. I sought out the logs i thought most pertaining to the issue:

################

Preliminary information:

At 9:29:35 the rackD reports not being able to report test results. This corresponds with the following entry in kern.log:

Jun  8 09:29:35 maas-rackd001 kernel: [749024.447228] audit: type=1400 audit(1686216575.729:26065): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025042 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

ens18 is the interface to which RACKD001_ADDRESS is bound.

################

MAAS RackD logs:

2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832963) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:36 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36090, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36100, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:39 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36112, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57688, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57702, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=57708, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND002_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha002:pid=2854011' authenticated.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha002:pid=2854011' authenticated.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha002:pid=2854011' authenticated.
2023-06-08 09:28:59 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-06-08 09:28:59 twisted.internet.defer: [critical]
	Traceback (most recent call last):
	Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x04\x00\x0c', 98, 'Address already in use')

2023-06-08 09:28:59 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-06-08 09:28:59 twisted.internet.defer: [critical]
	Traceback (most recent call last):
	Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x1e\x00\x0c', 98, 'Address already in use')

2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha002:pid=2854011) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha002:pid=2854011) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:28:59 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha002:pid=2854011) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:29:05 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-06-08 09:29:09 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=52690, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:09 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=52698, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:09 ClusterClient,client: [info] ClusterClient connection lost (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=52706, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:29 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36110, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:29 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36126, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:29 Uninitialized: [info] ClusterClient connection established (HOST:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=36136, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:REGIOND003_ADDRESS', port=5252, flowInfo=0, scopeID=0))
2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha003:pid=2832965' authenticated.
2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha003:pid=2832965' authenticated.
2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Event-loop 'maas-regiond-ha003:pid=2832965' authenticated.
2023-06-08 09:29:29 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-06-08 09:29:29 twisted.internet.defer: [critical]
	Traceback (most recent call last):
	Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x04\x00\x0c', 98, 'Address already in use')

2023-06-08 09:29:29 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-06-08 09:29:29 twisted.internet.defer: [critical]
	Traceback (most recent call last):
	Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x1e\x00\x0c', 98, 'Address already in use')

2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832965) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832965) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:29:29 provisioningserver.rpc.clusterservice: [info] Rack controller 'gqhhy7' registered (via maas-regiond-ha003:pid=2832965) with MAAS version 3.3.3-13184-g.3e9972c19.
2023-06-08 09:29:35 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]

################

This is the syslog:

Jun  8 09:28:06 maas-rackd001 systemd[1]: Started snap.maas.maas.e5c47c61-ba31-42cb-af8e-95245d6acccb.scope.
Jun  8 09:28:08 maas-rackd001 systemd[1]: snap.maas.maas.e5c47c61-ba31-42cb-af8e-95245d6acccb.scope: Deactivated successfully.
Jun  8 09:28:08 maas-rackd001 systemd[1]: snap.maas.maas.e5c47c61-ba31-42cb-af8e-95245d6acccb.scope: Consumed 2.789s CPU time.
Jun  8 09:28:12 maas-rackd001 dhcpd[3023368]: peer failover-vlan-5001: disconnected
Jun  8 09:28:12 maas-rackd001 dhcpd[3023368]: failover peer failover-vlan-5001: I move from normal to communications-interrupted
Jun  8 09:28:13 maas-rackd001 dhcpd[3023368]: failover peer failover-vlan-5001: peer moves from normal to normal
Jun  8 09:28:13 maas-rackd001 dhcpd[3023368]: failover peer failover-vlan-5001: I move from communications-interrupted to normal
Jun  8 09:28:13 maas-rackd001 dhcpd[3023368]: failover peer failover-vlan-5001: Both servers normal
Jun  8 09:28:13 maas-rackd001 dhcpd[3023368]: balancing pool 55ba17a3a0f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-own (+/-)13
Jun  8 09:28:13 maas-rackd001 dhcpd[3023368]: balanced pool 55ba17a3a0f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-misbal 19
Jun  8 09:28:35 maas-rackd001 kernel: [748964.643610] audit: type=1400 audit(1686216515.823:26063): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3024900 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Internet Systems Consortium DHCP Server 4.4.1
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Copyright 2004-2018 Internet Systems Consortium.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: All rights reserved.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: For info, please visit https://www.isc.org/software/dhcp/
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Config file: /var/snap/maas/common/maas/dhcpd.conf
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Database file: /var/snap/maas/common/maas/dhcp/dhcpd.leases
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: PID file: /var/snap/maas/common/maas/dhcp/dhcpd.pid
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Wrote 0 class decls to leases file.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Wrote 0 deleted host decls to leases file.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Wrote 0 new dynamic host decls to leases file.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Wrote 83 leases to leases file.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Listening on LPF/ens18/MA:CA:DR:ES:S1/vlan-5001
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Sending on   LPF/ens18/MA:CA:DR:ES:S1/vlan-5001
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Sending on   Socket/fallback/fallback-net
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: failover peer failover-vlan-5001: I move from normal to startup
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: Server starting service.
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: failover peer failover-vlan-5001: peer moves from normal to communications-interrupted
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: failover peer failover-vlan-5001: I move from startup to normal
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: balancing pool 55c90564d0f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-own (+/-)13
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: balanced pool 55c90564d0f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-misbal 19
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: failover peer failover-vlan-5001: peer moves from communications-interrupted to normal
Jun  8 09:28:57 maas-rackd001 dhcpd[3024913]: failover peer failover-vlan-5001: Both servers normal
Jun  8 09:29:05 maas-rackd001 kernel: [748994.448792] audit: type=1400 audit(1686216545.700:26064): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3024961 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Internet Systems Consortium DHCP Server 4.4.1
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Copyright 2004-2018 Internet Systems Consortium.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: All rights reserved.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: For info, please visit https://www.isc.org/software/dhcp/
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Config file: /var/snap/maas/common/maas/dhcpd.conf
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Database file: /var/snap/maas/common/maas/dhcp/dhcpd.leases
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: PID file: /var/snap/maas/common/maas/dhcp/dhcpd.pid
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Wrote 0 class decls to leases file.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Wrote 0 deleted host decls to leases file.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Wrote 0 new dynamic host decls to leases file.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Wrote 83 leases to leases file.
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Listening on LPF/ens18/MA:CA:DR:ES:S1/vlan-5001
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Sending on   LPF/ens18/MA:CA:DR:ES:S1/vlan-5001
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Sending on   Socket/fallback/fallback-net
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from normal to startup
Jun  8 09:29:12 maas-rackd001 dhcpd[3024983]: Server starting service.
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: peer moves from normal to communications-interrupted
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from startup to normal
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: balancing pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-own (+/-)13
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: balanced pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-misbal 19
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: peer moves from communications-interrupted to normal
Jun  8 09:29:17 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: Both servers normal
Jun  8 09:29:35 maas-rackd001 kernel: [749024.447228] audit: type=1400 audit(1686216575.729:26065): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025042 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun  8 09:29:42 maas-rackd001 chronyd[822]: Selected source NTPSERVER_IPADDRESS (ntp.foo.net)Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: peer failover-vlan-5001: disconnected
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from normal to communications-interrupted
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: peer moves from normal to normal
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from communications-interrupted to normal
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: Both servers normal
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: balancing pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-own (+/-)13
Jun  8 09:29:59 maas-rackd001 dhcpd[3024983]: balanced pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-misbal 19
Jun  8 09:30:05 maas-rackd001 kernel: [749054.381614] audit: type=1400 audit(1686216605.571:26066): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025099 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: peer failover-vlan-5001: disconnected
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from normal to communications-interrupted
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: peer moves from normal to normal
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: I move from communications-interrupted to normal
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: failover peer failover-vlan-5001: Both servers normal
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: balancing pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-own (+/-)13
Jun  8 09:30:13 maas-rackd001 dhcpd[3024983]: balanced pool 55d3f4e390f0 vlan-5001  total 127  free 64  backup 63  lts 0  max-misbal 19
Jun  8 09:30:35 maas-rackd001 kernel: [749084.630043] audit: type=1400 audit(1686216635.710:26067): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025182 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun  8 09:31:05 maas-rackd001 kernel: [749114.322276] audit: type=1400 audit(1686216665.324:26068): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=3025270 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

Revision history for this message

Igor Brovtsin (igor-brovtsin) wrote on 2023-06-30:

#3

Hi Linus!

Could you please share the contents of `/var/snap/maas/common/maas/maas_id` files for each rack controller? Also, regiond log would also be helpful. Thanks!

Changed in maas:
status:	Incomplete → New
status:	New → Incomplete

Revision history for this message

Linus Walther (linwalth) wrote on 2023-06-30 (last edit on 2023-06-30):

#4

Sure thing, Igor!

RackDs:

rackd001 = gqhhy7
rackd002 = gbeh6f
rackd003 = w4ffg4

RegionDs:

regiond001 = 8cge7s
regiond002 = 4hnrsk
regiond003 = rfx4sa

Revision history for this message

Alberto Donato (ack) wrote on 2023-07-05:

#5

can you please also attach regiond logs?

Changed in maas:
status:	Incomplete → New
status:	New → Incomplete

Revision history for this message

Linus Walther (linwalth) wrote on 2023-07-05:

#6

Download full text (18.4 KiB)

Surely. Here are the RegionD logs:

################

Preliminary information:

ens18 is the interface to which REGIOND001_ADDRESS is bound.
RegionDs only have ONE interface (ens18)

################

MAAS RegionD logs:

2023-07-05 13:10:37 regiond: [info] 127.0.0.1 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 500 INTERNAL_SERVER_ERROR (referrer: -; agent: Python-urllib/3.10)
2023-07-05 13:10:37 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-07-05 13:10:43 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(type='TCP', host='::ffff:REGIOND001_ADDRESS', port=5252, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=45342, flowInfo=0, scopeID=0))
2023-07-05 13:10:43 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(type='TCP', host='::ffff:REGIOND001_ADDRESS', port=5252, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=45356, flowInfo=0, scopeID=0))
2023-07-05 13:10:44 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:RACKD001_ADDRESS:45342'.
2023-07-05 13:10:44 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:RACKD001_ADDRESS:45356'.
2023-07-05 13:10:44 maasserver.ipc: [info] Worker pid:119857 registered RPC connection to ('gqhhy7', 'REGIOND001_ADDRESS', 5252).
2023-07-05 13:10:44 maasserver.ipc: [info] Worker pid:119857 registered RPC connection to ('gqhhy7', 'REGIOND001_ADDRESS', 5252).
2023-07-05 13:10:50 maasserver: [error] ################################ Exception: get() returned more than one ScriptResult -- it returned 2! ################################
2023-07-05 13:10:50 maasserver: [error] Traceback (most recent call last):
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/utils/views.py", line 293, in view_atomic_with_post_commit_savepoint
    return view_atomic(*args, **kwargs)
  File "/usr/lib/python3.10/contextlib.py", line 79, in inner
    return func(*args, **kwds)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 62, in __call__
    response = super().__call__(request, *args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/views/decorators/vary.py", line 20, in inner_func
    response = func(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 197, in __call__
    result = self.error_handler(e, request, meth, em_format)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 195, in __call__
    result = meth(request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 370, in dispatch
    return function(self, request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 860, in signal
    target_status = process(node, ...

Surely. Here are the RegionD logs:

################

Preliminary information:

ens18 is the interface to which REGIOND001_ADDRESS is bound.
RegionDs only have ONE interface (ens18)

################

MAAS RegionD logs:

2023-07-05 13:10:37 regiond: [info] 127.0.0.1 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 500 INTERNAL_SERVER_ERROR (referrer: -; agent: Python-urllib/3.10)
2023-07-05 13:10:37 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-07-05 13:10:43 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(type='TCP', host='::ffff:REGIOND001_ADDRESS', port=5252, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=45342, flowInfo=0, scopeID=0))
2023-07-05 13:10:43 twisted.internet.protocol.Factory: [info] RegionServer connection established (HOST:IPv6Address(type='TCP', host='::ffff:REGIOND001_ADDRESS', port=5252, flowInfo=0, scopeID=0) PEER:IPv6Address(type='TCP', host='::ffff:RACKD001_ADDRESS', port=45356, flowInfo=0, scopeID=0))
2023-07-05 13:10:44 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:RACKD001_ADDRESS:45342'.
2023-07-05 13:10:44 maasserver.rpc.regionservice: [info] Rack controller authenticated from '::ffff:RACKD001_ADDRESS:45356'.
2023-07-05 13:10:44 maasserver.ipc: [info] Worker pid:119857 registered RPC connection to ('gqhhy7', 'REGIOND001_ADDRESS', 5252).
2023-07-05 13:10:44 maasserver.ipc: [info] Worker pid:119857 registered RPC connection to ('gqhhy7', 'REGIOND001_ADDRESS', 5252).
2023-07-05 13:10:50 maasserver: [error] ################################ Exception: get() returned more than one ScriptResult -- it returned 2! ################################
2023-07-05 13:10:50 maasserver: [error] Traceback (most recent call last):
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/utils/views.py", line 293, in view_atomic_with_post_commit_savepoint
    return view_atomic(*args, **kwargs)
  File "/usr/lib/python3.10/contextlib.py", line 79, in inner
    return func(*args, **kwds)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 62, in __call__
    response = super().__call__(request, *args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/views/decorators/vary.py", line 20, in inner_func
    response = func(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 197, in __call__
    result = self.error_handler(e, request, meth, em_format)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 195, in __call__
    result = meth(request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 370, in dispatch
    return function(self, request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 860, in signal
    target_status = process(node, request, status)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 682, in _process_commissioning
    self._store_results(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 559, in _store_results
    process_file(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 292, in process_file
    script_result, _ = script_set.scriptresult_set.get_or_create(
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/fields/related_descriptors.py", line 683, in get_or_create
    return super(RelatedManager, self.db_manager(db)).get_or_create(**kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 581, in get_or_create
    return self.get(**kwargs), False
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 439, in get
    raise self.model.MultipleObjectsReturned(
metadataserver.models.scriptresult.ScriptResult.MultipleObjectsReturned: get() returned more than one ScriptResult -- it returned 2!

2023-07-05 13:11:01 maasserver: [error] Error while calling ScanNetworks: Unable to get RPC connection for rack controller 'maas-rackd001' (gqhhy7).
2023-07-05 13:11:01 maasserver: [error] Error while calling ScanNetworks: Unable to get RPC connection for rack controller 'maas-rackd002' (gbeh6f).
2023-07-05 13:11:01 maasserver: [error] Error while calling ScanNetworks: Unable to get RPC connection for rack controller 'maas-rackd003' (w4ffg4).
2023-07-05 13:11:01 maasserver.regiondservices.active_discovery: [info] Active network discovery: Unable to initiate network scanning on any rack controller. Verify that the rack controllers are started and have connected to the region.
2023-07-05 13:11:01 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-07-05 13:11:01 twisted.internet.defer: [critical]
	Traceback (most recent call last):
	Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x04\x00\t', 98, 'Address already in use')

2023-07-05 13:11:04 maasserver: [error] ################################ Exception: get() returned more than one ScriptResult -- it returned 2! ################################
2023-07-05 13:11:04 maasserver: [error] Traceback (most recent call last):
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/utils/views.py", line 293, in view_atomic_with_post_commit_savepoint
    return view_atomic(*args, **kwargs)
  File "/usr/lib/python3.10/contextlib.py", line 79, in inner
    return func(*args, **kwds)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 62, in __call__
    response = super().__call__(request, *args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/views/decorators/vary.py", line 20, in inner_func
    response = func(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 197, in __call__
    result = self.error_handler(e, request, meth, em_format)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 195, in __call__
    result = meth(request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 370, in dispatch
    return function(self, request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 860, in signal
    target_status = process(node, request, status)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 682, in _process_commissioning
    self._store_results(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 559, in _store_results
    process_file(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 292, in process_file
    script_result, _ = script_set.scriptresult_set.get_or_create(
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/fields/related_descriptors.py", line 683, in get_or_create
    return super(RelatedManager, self.db_manager(db)).get_or_create(**kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 581, in get_or_create
    return self.get(**kwargs), False
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 439, in get
    raise self.model.MultipleObjectsReturned(
metadataserver.models.scriptresult.ScriptResult.MultipleObjectsReturned: get() returned more than one ScriptResult -- it returned 2!

2023-07-05 13:11:07 maasserver: [error] ################################ Exception:  ################################
2023-07-05 13:11:07 maasserver: [error] Traceback (most recent call last):
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/utils/views.py", line 293, in view_atomic_with_post_commit_savepoint
    return view_atomic(*args, **kwargs)
  File "/usr/lib/python3.10/contextlib.py", line 79, in inner
    return func(*args, **kwds)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 62, in __call__
    response = super().__call__(request, *args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/views/decorators/vary.py", line 20, in inner_func
    response = func(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 197, in __call__
    result = self.error_handler(e, request, meth, em_format)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 195, in __call__
    result = meth(request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 370, in dispatch
    return function(self, request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 860, in signal
    target_status = process(node, request, status)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 682, in _process_commissioning
    self._store_results(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 565, in _store_results
    script_result.store_result(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/models/scriptresult.py", line 270, in store_result
    assert self.status in SCRIPT_STATUS_RUNNING_OR_PENDING
AssertionError

2023-07-05 13:11:07 regiond: [info] 127.0.0.1 POST /MAAS/metadata/2012-03-01/ HTTP/1.1 --> 500 INTERNAL_SERVER_ERROR (referrer: -; agent: Python-urllib/3.10)
2023-07-05 13:11:07 provisioningserver.utils.services: [warn] Couldn't report test results: HTTP error [500]
2023-07-05 13:11:20 maasserver: [error] ################################ Exception: get() returned more than one ScriptResult -- it returned 2! ################################
2023-07-05 13:11:20 maasserver: [error] Traceback (most recent call last):
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/utils/views.py", line 293, in view_atomic_with_post_commit_savepoint
    return view_atomic(*args, **kwargs)
  File "/usr/lib/python3.10/contextlib.py", line 79, in inner
    return func(*args, **kwds)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 62, in __call__
    response = super().__call__(request, *args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/views/decorators/vary.py", line 20, in inner_func
    response = func(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 197, in __call__
    result = self.error_handler(e, request, meth, em_format)
  File "/snap/maas/28521/usr/lib/python3.10/dist-packages/piston3/resource.py", line 195, in __call__
    result = meth(request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/maasserver/api/support.py", line 370, in dispatch
    return function(self, request, *args, **kwargs)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 860, in signal
    target_status = process(node, request, status)
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 682, in _process_commissioning
    self._store_results(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 559, in _store_results
    process_file(
  File "/snap/maas/28521/lib/python3.10/site-packages/metadataserver/api.py", line 292, in process_file
    script_result, _ = script_set.scriptresult_set.get_or_create(
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/fields/related_descriptors.py", line 683, in get_or_create
    return super(RelatedManager, self.db_manager(db)).get_or_create(**kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 581, in get_or_create
    return self.get(**kwargs), False
  File "/snap/maas/28521/usr/lib/python3/dist-packages/django/db/models/query.py", line 439, in get
    raise self.model.MultipleObjectsReturned(
metadataserver.models.scriptresult.ScriptResult.MultipleObjectsReturned: get() returned more than one ScriptResult -- it returned 2!

################

This is the syslog:

Jul  5 13:10:08 maas-regiond-ha001 systemd[1]: snap.maas.maas.1b422849-d883-48c4-b715-2c8c082a7a44.scope: Succeeded.
Jul  5 13:10:14 maas-regiond-ha001 chronyd[869]: Selected source NTP_SERVER_ADDRESS
Jul  5 13:10:20 maas-regiond-ha001 chronyd[869]: Can't synchronise: no majority
Jul  5 13:10:31 maas-regiond-ha001 kernel: [5425968.876322] audit: type=1400 audit(1688562631.470:1769208): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627306 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:10:31 maas-regiond-ha001 kernel: [5425968.889787] audit: type=1400 audit(1688562631.485:1769209): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627306 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:10:37 maas-regiond-ha001 kernel: [5425975.158911] audit: type=1400 audit(1688562637.637:1769210): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=1627324 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:10:37 maas-regiond-ha001 kernel: [5425975.213956] audit: type=1400 audit(1688562637.696:1769211): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627327 comm="tmp.B33dw59gaq" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:10:37 maas-regiond-ha001 kernel: [5425975.216118] audit: type=1400 audit(1688562637.700:1769212): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627327 comm="tmp.B33dw59gaq" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:01 maas-regiond-ha001 kernel: [5425998.484602] audit: type=1400 audit(1688562661.454:1769213): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627367 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:01 maas-regiond-ha001 kernel: [5425998.489373] audit: type=1400 audit(1688562661.458:1769214): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627367 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:01 maas-regiond-ha001 kernel: [5425998.874805] audit: type=1400 audit(1688562661.842:1769215): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627380 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:01 maas-regiond-ha001 kernel: [5425998.885526] audit: type=1400 audit(1688562661.854:1769216): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627380 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.117281] audit: type=1400 audit(1688562662.086:1769217): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627387 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.118050] audit: type=1400 audit(1688562662.086:1769218): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627387 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.257442] audit: type=1400 audit(1688562662.226:1769219): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627394 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.258219] audit: type=1400 audit(1688562662.226:1769220): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627394 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.394155] audit: type=1400 audit(1688562662.362:1769221): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627401 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:02 maas-regiond-ha001 kernel: [5425999.394791] audit: type=1400 audit(1688562662.362:1769222): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627401 comm="amd64" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:07 maas-regiond-ha001 kernel: [5426004.621416] audit: type=1400 audit(1688562667.590:1769223): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/etc/wgetrc" pid=1627414 comm="wget" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:07 maas-regiond-ha001 kernel: [5426004.664811] audit: type=1400 audit(1688562667.634:1769224): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sda" pid=1627417 comm="tmp.q1HqrSVHEz" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:07 maas-regiond-ha001 kernel: [5426004.665853] audit: type=1400 audit(1688562667.634:1769225): apparmor="DENIED" operation="open" profile="snap.maas.supervisor" name="/dev/sr0" pid=1627417 comm="tmp.q1HqrSVHEz" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jul  5 13:11:19 maas-regiond-ha001 chronyd[869]: Selected source NTP_SERVER_ADDRESS
Jul  5 13:11:24 maas-regiond-ha001 chronyd[869]: Can't synchronise: no majority

Revision history for this message

Alberto Donato (ack) wrote on 2023-07-06:

#7

From the errors in regiond log itseems the cause of the issue might be LP:1988976

Revision history for this message

Linus Walther (linwalth) wrote on 2023-07-06:

#8

I beg to differ. The scripts not returning is only ONE of the problems. I do not think that this is a duplicate of #1988976.

My main problem is the unstable RackD connection based on MAAS not being able to handle 2 interfaces, crashlooping and breaking off connections with this multicast error - unable to form a stable connection.

2023-06-08 09:29:29 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-06-08 09:29:29 twisted.internet.defer: [critical]
Traceback (most recent call last):
Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x1e\x00\x0c', 98, 'Address already in use')

Of course the RackD, not being able to build a stable connection, will not be able to send test results.

Revision history for this message

Linus Walther (linwalth) wrote on 2023-07-10:

#9

I ought to correct my assesments as i just realized, looking at the above regionD logs, that the regionD also has this multicast joining error:

2023-07-10 08:48:07 twisted.internet.defer: [critical]
Traceback (most recent call last):
Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x04\x00\x0b', 98, 'Address already in use')

Since the RegionD only has one address, I don't know if i can stand by my earlier assessment that this is a problem of Servers with multiple interfaces.

Another piece of information would be that all our MAAS machines are virtualized machines. Might that play into the situation with the multicast join not working correctly?

Revision history for this message

Anton Troyanov (troyanov) wrote on 2023-08-04:

#10

It happened to me several times last night after restarting MAAS multiple times in a row.

I was running MAAS edge inside container with 2 interfaces

8: eth0@if9: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:16:3e:81:67:ef brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet 10.0.0.62/24 metric 100 brd 10.0.0.255 scope global dynamic eth0
       valid_lft 2981sec preferred_lft 2981sec
    inet6 fe80::216:3eff:fe81:67ef/64 scope link
       valid_lft forever preferred_lft forever
10: eth1@if11: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:16:3e:c9:20:fd brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet 10.10.10.1/24 brd 10.10.10.255 scope global eth1
       valid_lft forever preferred_lft forever
    inet6 fe80::216:3eff:fec9:20fd/64 scope link
       valid_lft forever preferred_lft forever

Jul 21 15:34:50 maas maas.pebble[153069]: 2023-07-21T15:34:50.027Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 15:34:50 maas maas.pebble[153069]: 2023-07-21T15:34:50.027Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Jul 21 15:43:12 maas maas.pebble[154713]: 2023-07-21T15:43:12.017Z [rackd] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>', >
Jul 21 15:43:12 maas maas.pebble[154713]: 2023-07-21T15:43:12.017Z [rackd] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01', 9>

Jul 21 15:46:31 maas maas.pebble[155490]: 2023-07-21T15:46:31.718Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 15:46:31 maas maas.pebble[155490]: 2023-07-21T15:46:31.718Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Jul 21 16:03:30 maas maas.pebble[157560]: 2023-07-21T16:03:30.877Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 16:03:30 maas maas.pebble[157560]: 2023-07-21T16:03:30.877Z [regiond] Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Using container with 3 interfaces, errors will come in a group of 3, if there are 4 interfaces in a group of 4. I didn't notice this error when I was running MAAS inside container with 1 interface.

However I didn't notice any issues related to degradation of functionality

According to some code comments such behaviour is expected?
src/provisioningserver/utils/services.py:498

# Use the first IP address on each interface. Since the
# underlying interface is the same, joining using a
# secondary IP address on the same interface will produce
# an "Address already in use" error.

It happened to me several times last night after restarting MAAS multiple times in a row.

I was running MAAS edge inside container with 2 interfaces

8: eth0@if9: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:16:3e:81:67:ef brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet 10.0.0.62/24 metric 100 brd 10.0.0.255 scope global dynamic eth0
       valid_lft 2981sec preferred_lft 2981sec
    inet6 fe80::216:3eff:fe81:67ef/64 scope link
       valid_lft forever preferred_lft forever
10: eth1@if11: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:16:3e:c9:20:fd brd ff:ff:ff:ff:ff:ff link-netnsid 0
    inet 10.10.10.1/24 brd 10.10.10.255 scope global eth1
       valid_lft forever preferred_lft forever
    inet6 fe80::216:3eff:fec9:20fd/64 scope link
       valid_lft forever preferred_lft forever

Jul 21 15:34:50 maas maas.pebble[153069]: 2023-07-21T15:34:50.027Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 15:34:50 maas maas.pebble[153069]: 2023-07-21T15:34:50.027Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Jul 21 15:43:12 maas maas.pebble[154713]: 2023-07-21T15:43:12.017Z [rackd]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>', >
Jul 21 15:43:12 maas maas.pebble[154713]: 2023-07-21T15:43:12.017Z [rackd]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01', 9>

Jul 21 15:46:31 maas maas.pebble[155490]: 2023-07-21T15:46:31.718Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 15:46:31 maas maas.pebble[155490]: 2023-07-21T15:46:31.718Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Jul 21 16:03:30 maas maas.pebble[157560]: 2023-07-21T16:03:30.877Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x00\x00>'>
Jul 21 16:03:30 maas maas.pebble[157560]: 2023-07-21T16:03:30.877Z [regiond]         Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\n\n\x01',>

Using container with 3 interfaces, errors will come in a group of 3, if there are 4 interfaces in a group of 4. I didn't notice this error when I was running MAAS inside container with 1 interface.

However I didn't notice any issues related to degradation of functionality

According to some code comments such behaviour is expected?
src/provisioningserver/utils/services.py:498

# Use the first IP address on each interface. Since the
# underlying interface is the same, joining using a
# secondary IP address on the same interface will produce
# an "Address already in use" error.

Changed in maas:
status:	Incomplete → New
status:	New → Incomplete

Revision history for this message

Muhammad Ahmad (ahmadfsbd) wrote on 2023-09-12 (last edit on 2023-09-12):

#11

Download full text (7.1 KiB)

We are hitting a similar error on a customer environment after upgrading from Maas 2.9 to 3.2.

2023-09-12 06:55:19 provisioningserver.rackdservices.dhcp_probe_service: [info] Probe for external DHCP servers started on interfaces: brappformix, brext, broam.
2023-09-12 06:55:20 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-09-12 06:55:20 twisted.internet.defer: [critical]
Traceback (most recent call last):
Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'666\t', 98, 'Address already in use')

2023-09-12 06:55:20 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-09-12 06:55:20 twisted.internet.defer: [critical]
Traceback (most recent call last):
Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x0f\xa1\x05', 98, 'Address already in use')

2023-09-12 06:55:20 twisted.internet.defer: [critical] Unhandled error in Deferred:
2023-09-12 06:55:20 twisted.internet.defer: [critical]
Traceback (most recent call last):
Failure: twisted.internet.error.MulticastJoinError: (b'\xe0\x00\x00v', b'\n\x0f\xa8\n', 98, 'Address already in use')

2023-09-12 06:48:26 provisioningserver.utils.services: [critical] Failed to update and/or record network interface configuration: Expecting value: line 1 column 1 (char 0); interfaces: {'bond0': {'type': 'bond', 'mac_address': 'Redacted', 'links': [], 'enabled': True, 'parents': ['eno12409np1', 'eno12399np0'], 'source': 'machine-resources', 'monitored': True}, 'bond0.402': {'type': 'vlan', 'mac_address': 'Redacted', 'links': [], 'enabled': True, 'parents': ['bond0'], 'source': 'machine-resources', 'vid': 402, 'monitored': False}, 'bond0.403': {'type': 'vlan', 'mac_address': 'Redacted', 'links': [], 'enabled': True, 'parents': ['bond0'], 'source': 'machine-resources', 'vid': 403, 'monitored': False}, 'brappformix': {'type': 'bridge', 'mac_address': 'Redacted', 'links': [{'mode': 'static', 'address': 'Redacted'}], 'enabled': True, 'parents': ['bond0.403'], 'source': 'machine-resources', 'monitored': False}, 'brext': {'type': 'bridge', 'mac_address': 'Redacted', 'links': [{'mode': 'static', 'address': 'Redacted'}], 'enabled': True, 'parents': ['bond0.402'], 'source': 'machine-resources', 'monitored': False}, 'broam': {'type': 'bridge', 'mac_address': 'Redacted', 'links': [{'mode': 'static', 'address': 'Redacted', 'gateway': 'Redacted'}, {'mode': 'static', 'address': 'Redacted', 'gateway': 'Redacted'}], 'enabled': True, 'parents': ['bond0'], 'source': 'machine-resources', 'monitored': False}, 'eno12399np0': {'type': 'physical', 'mac_address': 'Redacted', 'links': [], 'enabled': True, 'parents': [], 'source': 'machine-resources', 'monitored': False}, 'eno12409np1': {'type': 'physical', 'mac_address': 'Redacted', 'links': [], 'enabled': True, 'parents': [], 'source': 'machine-resources', 'monitored': False}, 'eno8303': {'type': 'physical', 'mac_address': 'Redacted', 'links': [], 'enabled': False, 'parents': [], 'source': 'machine-resources', 'monitored': False}, 'eno8403': {'type': 'physical', 'mac_address': 'Redacted', 'links': [], 'enabled': False, 'parents': [], 'source': 'machine-resour...

Changed in maas:
milestone:	none → 3.5.0
status:	Incomplete → Triaged

MAAS

(3.3) RackD constantly restarting: MulticastJoinError - Address already in use

Bug Description

Other bug subscribers

Remote bug watches