network interface discovery commissioning scripts timeout

[Andres Rodriguez]

The network interface discovery commissioning script (99-maas-03-network-interfaces) timeout. The log seen on the rsyslog is a constant of this:

andreserl@maas:/var/log/maas/rsyslog/tidy-salmon/2019-02-18$ sudo tail -f messages
2019-02-18T13:59:02+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.37 port 67 (xid=0x4d7e7b25)
2019-02-18T13:59:04+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T13:59:06+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T13:59:12+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 255.255.255.255 port 67 (xid=0xd2292ae)
2019-02-18T13:59:12+00:00 tidy-salmon dhclient[4343]: XMT: Solicit on eno4, interval 109360ms.
2019-02-18T13:59:17+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T13:59:17+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T13:59:19+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T13:59:22+00:00 tidy-salmon dhclient[4337]: XMT: Solicit on eno6, interval 120950ms.
2019-02-18T13:59:23+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 255.255.255.255 port 67 (xid=0xd2292ae)
2019-02-18T13:59:27+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T13:59:28+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T13:59:30+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T13:59:35+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T13:59:37+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 255.255.255.255 port 67 (xid=0xd2292ae)
2019-02-18T13:59:38+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T13:59:41+00:00 tidy-salmon dhclient[4327]: XMT: Solicit on eno1, interval 121090ms.
2019-02-18T13:59:45+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T13:59:50+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T13:59:54+00:00 tidy-salmon dhclient[4328]: XMT: Solicit on eno2, interval 118150ms.
2019-02-18T13:59:54+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T13:59:57+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 255.255.255.255 port 67 (xid=0xd2292ae)
2019-02-18T14:00:02+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T14:00:02+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4278]: DHCPDISCOVER on eno2 to 255.255.255.255 port 67 interval 3 (xid=0xf124c965)
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 255.255.255.255 port 67 (xid=0x65c924f1)
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4278]: DHCPOFFER of 192.168.1.143 from 192.168.1.10
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4278]: DHCPACK of 192.168.1.143 from 192.168.1.37
2019-02-18T14:00:04+00:00 tidy-salmon dhclient[4278]: bound to 192.168.1.143 -- renewal in 246 seconds.
2019-02-18T14:00:08+00:00 tidy-salmon dhclient[4345]: XMT: Solicit on eno5, interval 115310ms.
2019-02-18T14:00:09+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T14:00:16+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:00:21+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:00:23+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x4d7e7b25)
2019-02-18T14:00:27+00:00 tidy-salmon dhclient[4288]: DHCPDISCOVER on eno3 to 255.255.255.255 port 67 interval 3 (xid=0x7f233d78)
2019-02-18T14:00:27+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 255.255.255.255 port 67 (xid=0x783d237f)
2019-02-18T14:00:27+00:00 tidy-salmon dhclient[4288]: DHCPOFFER of 192.168.1.167 from 192.168.1.10
2019-02-18T14:00:27+00:00 tidy-salmon dhclient[4288]: DHCPACK of 192.168.1.167 from 192.168.1.10
2019-02-18T14:00:27+00:00 tidy-salmon dhclient[4288]: bound to 192.168.1.167 -- renewal in 279 seconds.
2019-02-18T14:00:30+00:00 tidy-salmon dhclient[4331]: XMT: Solicit on eno3, interval 123370ms.
2019-02-18T14:00:35+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:00:42+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:00:48+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:00:57+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:01:02+00:00 tidy-salmon dhclient[4343]: XMT: Solicit on eno4, interval 124620ms.
2019-02-18T14:01:03+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:01:12+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:01:14+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:01:23+00:00 tidy-salmon dhclient[4337]: XMT: Solicit on eno6, interval 123450ms.
2019-02-18T14:01:30+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:01:32+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 192.168.1.10 port 67 (xid=0x38e97011)
2019-02-18T14:01:42+00:00 tidy-salmon dhclient[4327]: XMT: Solicit on eno1, interval 117170ms.
2019-02-18T14:01:47+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 255.255.255.255 port 67 (xid=0x38e97011)
2019-02-18T14:01:49+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:01:51+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:01:52+00:00 tidy-salmon dhclient[4328]: XMT: Solicit on eno2, interval 115200ms.
2019-02-18T14:01:54+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:02:02+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:02:02+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 192.168.1.10 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:03+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 255.255.255.255 port 67 (xid=0x38e97011)
2019-02-18T14:02:04+00:00 tidy-salmon dhclient[4345]: XMT: Solicit on eno5, interval 129130ms.
2019-02-18T14:02:10+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:13+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 255.255.255.255 port 67 (xid=0x38e97011)
2019-02-18T14:02:16+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:02:21+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:27+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 255.255.255.255 port 67 (xid=0x38e97011)
2019-02-18T14:02:27+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:02:29+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:34+00:00 tidy-salmon dhclient[4331]: XMT: Solicit on eno3, interval 129060ms.
2019-02-18T14:02:38+00:00 tidy-salmon dhclient[4321]: DHCPDISCOVER on eno6 to 255.255.255.255 port 67 interval 3 (xid=0xfe5d547b)
2019-02-18T14:02:38+00:00 tidy-salmon dhclient[4321]: DHCPREQUEST of 192.168.1.179 on eno6 to 255.255.255.255 port 67 (xid=0x7b545dfe)
2019-02-18T14:02:38+00:00 tidy-salmon dhclient[4321]: DHCPOFFER of 192.168.1.179 from 192.168.1.10
2019-02-18T14:02:38+00:00 tidy-salmon dhclient[4321]: DHCPACK of 192.168.1.179 from 192.168.1.10
2019-02-18T14:02:39+00:00 tidy-salmon dhclient[4321]: bound to 192.168.1.179 -- renewal in 243 seconds.
2019-02-18T14:02:43+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:48+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:02:55+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x3d73ddf8)
2019-02-18T14:02:59+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:03:06+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:03:06+00:00 tidy-salmon dhclient[4343]: XMT: Solicit on eno4, interval 109010ms.
2019-02-18T14:03:08+00:00 tidy-salmon dhclient[4309]: DHCPDISCOVER on eno5 to 255.255.255.255 port 67 interval 3 (xid=0x26c5ca57)
2019-02-18T14:03:08+00:00 tidy-salmon dhclient[4309]: DHCPREQUEST of 192.168.1.150 on eno5 to 255.255.255.255 port 67 (xid=0x57cac526)
2019-02-18T14:03:08+00:00 tidy-salmon dhclient[4309]: DHCPOFFER of 192.168.1.150 from 192.168.1.10
2019-02-18T14:03:08+00:00 tidy-salmon dhclient[4309]: DHCPACK of 192.168.1.150 from 192.168.1.37
2019-02-18T14:03:08+00:00 tidy-salmon dhclient[4309]: bound to 192.168.1.150 -- renewal in 210 seconds.
^[[1;2B2019-02-18T14:03:17+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:03:26+00:00 tidy-salmon dhclient[4337]: XMT: Solicit on eno6, interval 131090ms.
2019-02-18T14:03:36+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:03:40+00:00 tidy-salmon dhclient[4327]: XMT: Solicit on eno1, interval 126730ms.
2019-02-18T14:03:47+00:00 tidy-salmon dhclient[4328]: XMT: Solicit on eno2, interval 129350ms.
2019-02-18T14:03:48+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:05+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:10+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:13+00:00 tidy-salmon dhclient[4345]: XMT: Solicit on eno5, interval 112690ms.
2019-02-18T14:04:13+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:16+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:16+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:20+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:27+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:29+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:38+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:40+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:43+00:00 tidy-salmon dhclient[4331]: XMT: Solicit on eno3, interval 119300ms.
2019-02-18T14:04:54+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:04:54+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 192.168.1.10 port 67 (xid=0x5ab1636b)
2019-02-18T14:04:56+00:00 tidy-salmon dhclient[4343]: XMT: Solicit on eno4, interval 128650ms.
2019-02-18T14:05:06+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:05:09+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:05:11+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:05:14+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 255.255.255.255 port 67 (xid=0x5ab1636b)
2019-02-18T14:05:17+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:05:21+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 255.255.255.255 port 67 (xid=0x5ab1636b)
2019-02-18T14:05:26+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:05:30+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:05:37+00:00 tidy-salmon dhclient[4337]: XMT: Solicit on eno6, interval 110710ms.
2019-02-18T14:05:38+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:05:40+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 255.255.255.255 port 67 (xid=0x5ab1636b)
2019-02-18T14:05:46+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:05:47+00:00 tidy-salmon dhclient[4327]: XMT: Solicit on eno1, interval 113960ms.
2019-02-18T14:05:47+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 255.255.255.255 port 67 (xid=0x5ab1636b)
2019-02-18T14:05:53+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:05:56+00:00 tidy-salmon dhclient[4298]: DHCPDISCOVER on eno4 to 255.255.255.255 port 67 interval 3 (xid=0x8c08390d)
2019-02-18T14:05:56+00:00 tidy-salmon dhclient[4298]: DHCPREQUEST of 192.168.1.199 on eno4 to 255.255.255.255 port 67 (xid=0xd39088c)
2019-02-18T14:05:56+00:00 tidy-salmon dhclient[4298]: DHCPOFFER of 192.168.1.199 from 192.168.1.10
2019-02-18T14:05:56+00:00 tidy-salmon dhclient[4298]: DHCPACK of 192.168.1.199 from 192.168.1.10
2019-02-18T14:05:56+00:00 tidy-salmon dhclient[4298]: bound to 192.168.1.199 -- renewal in 224 seconds.
2019-02-18T14:05:57+00:00 tidy-salmon dhclient[4328]: XMT: Solicit on eno2, interval 109690ms.
2019-02-18T14:06:05+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:06:06+00:00 tidy-salmon dhclient[4345]: XMT: Solicit on eno5, interval 114670ms.
2019-02-18T14:06:12+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)
2019-02-18T14:06:14+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:06:23+00:00 tidy-salmon dhclient[4288]: DHCPREQUEST of 192.168.1.167 on eno3 to 192.168.1.10 port 67 (xid=0x783d237f)
2019-02-18T14:06:26+00:00 tidy-salmon dhclient[4278]: DHCPREQUEST of 192.168.1.143 on eno2 to 192.168.1.37 port 67 (xid=0x65c924f1)

This could mean that there are no more available IPs on the dynamic DHCP range for this network, however, it seems that the way MAAS is running DHCP client may be causing this to block the commissioning from successfully completing.

[Andres Rodriguez (andreserl)]

Weird thing noticed, which seems unrelated, is this:

2019-02-18 14:33:03 maasserver.rack_controller: [critical] Failed configuring DHCP on rack controller 'id:249'.
 Traceback (most recent call last):
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1442, in gotResult
     _inlineCallbacks(r, g, deferred)
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1432, in _inlineCallbacks
     deferred.errback()
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 500, in errback
     self._startRunCallbacks(fail)
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 567, in _startRunCallbacks
     self._runCallbacks()
 --- <exception caught here> ---
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 653, in _runCallbacks
     current.result = callback(current.result, *args, **kw)
   File "/usr/lib/python3/dist-packages/maasserver/rack_controller.py", line 256, in <lambda>
     d.addErrback(lambda f: f.trap(NoConnectionsAvailable))
   File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 359, in trap
     self.raiseException()
   File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 385, in raiseException
     raise self.value.with_traceback(self.tb)
   File "/usr/lib/python3/dist-packages/twisted/internet/defer.py", line 1384, in _inlineCallbacks
     result = result.throwExceptionIntoGenerator(g)
   File "/usr/lib/python3/dist-packages/twisted/python/failure.py", line 408, in throwExceptionIntoGenerator
     return g.throw(self.type, self.value, self.tb)
   File "/usr/lib/python3/dist-packages/maasserver/dhcp.py", line 751, in configure_dhcp
     config = yield deferToDatabase(get_dhcp_configuration, rack_controller)
   File "/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 250, in inContext
     result = inContext.theWork()
   File "/usr/lib/python3/dist-packages/twisted/python/threadpool.py", line 266, in <lambda>
     inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
   File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 122, in callWithContext
     return self.currentContext().callWithContext(ctx, func, *args, **kw)
   File "/usr/lib/python3/dist-packages/twisted/python/context.py", line 85, in callWithContext
     return func(*args,**kw)
   File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 885, in callInContext
     return func(*args, **kwargs)
   File "/usr/lib/python3/dist-packages/provisioningserver/utils/twisted.py", line 234, in wrapper
     result = func(*args, **kwargs)
   File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 756, in call_within_transaction
     return func_outside_txn(*args, **kwargs)
   File "/usr/lib/python3/dist-packages/maasserver/utils/orm.py", line 563, in retrier
     return func(*args, **kwargs)
   File "/usr/lib/python3.6/contextlib.py", line 52, in inner
     return func(*args, **kwds)
   File "/usr/lib/python3/dist-packages/maasserver/dhcp.py", line 684, in get_dhcp_configuration
     dhcp_snippets=dhcp_snippets, use_rack_proxy=use_rack_proxy)
   File "/usr/lib/python3/dist-pa...

[Mark Shuttleworth (sabdfl)]

I wonder if rack controller 'id:249' is ypso or charybdis? I see that the dhcpd.conf on that in /var/lib/maas has remained unchanged for a different period than the other rack controller dhcpd.conf:

ypso:

-rw-r----- 1 root root 14105 Feb 17 14:15 dhcpd.conf
-rw-r----- 1 root maas 9 Feb 17 14:15 dhcpd-interfaces

charybdis:

-rw-r----- 1 root root 14133 Feb 8 08:02 dhcpd.conf
-rw-r----- 1 root maas 8 Feb 8 08:02 dhcpd-interfaces

[Mark Shuttleworth (sabdfl)]

Interestingly, although the dates are very different, the contents are the same w.r.t. hosts, and both of them are missing a device I added recently (the stealth-ipmi device which is part of the new tidy-salmon server).

[Mark Shuttleworth (sabdfl)]

Restarting the rack servers seems to have updated the dhcpd.conf on both of them.

[Mike Pontillo (mpontillo)]

Does this behavior persist after the DHCP has been properly configured and restarted?

The log pasted in the bug description indicates that the DHCP transaction has stalled mid-way through. (DHCP transactions happen in four basic phases: Discover, Offer, Request, and Acknowledge - or DORA, if you want a mnemonic.) So in this case the DHCP transaction passes through the discover and offer phases, but the DHCP server never replies to the 'Request' packet with an acknowledgement.

I'm guessing this error occurs because the DHCP client doesn't expect this to happen, and doesn't properly time out since it is still receiving 'Offer' packets from at least one of the DHCP servers.

We can look to see if there are any additional command line parameters we can pass to the ISC DHCP client so that it does the right thing, and/or change the script runner to time out with a warning if it encounters this scenario. That might stop the "failed commissioning" part of the problem, but it sounds like the root cause actually may be some kind of a race condition that prevents MAAS from properly configuring the DHCP server in some cases.

IMHO, the priority on this issue should be to root-cause the race condition that prevents proper DHCP server configuration. Making the symptoms better would be good, but it would be incorrect to call it a fix.

[Mike Pontillo (mpontillo)]

By the way, you can do the following to determine the `id` of each controller (I'm not sure why we're using a numeric ID there; normally we would log the system_id and/or hostname):

ubuntu@maas:~$ sudo maas-region dbshell
psql (10.6 (Ubuntu 10.6-0ubuntu0.18.04.1))
Type "help" for help.

maasdb=# select id, system_id, hostname from maasserver_node where node_type > 1;
 id | system_id | hostname
----+-----------+----------
  1 | 486gxc | maas
(1 row)

maasdb=#

[Andres Rodriguez (andreserl)]

After some investigation, we discovered that the reason of the failure, is that the script runner inside the commissioning environment is unable to send the data back to MAAS because it is unable to resolve to DNS.

We are still investigating.

[Mike Pontillo (mpontillo)]

If commissioning causes DNS to become so unreliable that commissioning itself cannot continue, that's a serious issue. I wonder if this is related to bug #1816452; if this bug is causing DNS reloads to become extremely slow, for example, this bug might be mitigated by fixing it.

[Björn Tillenius (bjornt)]

I'm closing this since we can't reproduce, and we don't have the full logs. Feel free to reopen it if it happens again.