maas-rackd.service ipxe.cfg Permission denied

[Anton Troyanov]

maas 1:3.5.0~beta1-16214-g.1eeea8524-0ubuntu1~22.04.1

Mar 05 16:49:16 maas-deb systemd[1]: Starting MAAS Rack Controller...
Mar 05 16:49:16 maas-deb systemd[1]: Started MAAS Rack Controller.
Mar 05 16:49:16 maas-deb rackd[7730]: Traceback (most recent call last):
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/sbin/rackd", line 33, in <module>
Mar 05 16:49:16 maas-deb rackd[7730]: sys.exit(load_entry_point('maas==3.5.0b1', 'console_scripts', 'rackd')())
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 95, in run
Mar 05 16:49:16 maas-deb rackd[7730]: runService("maas-rackd")
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 90, in runService
Mar 05 16:49:16 maas-deb rackd[7730]: UnixApplicationRunner(config).run()
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 370, in run
Mar 05 16:49:16 maas-deb rackd[7730]: self.application = self.createOrGetApplication()
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 432, in createOrGetApplication
Mar 05 16:49:16 maas-deb rackd[7730]: ser = plg.makeService(self.config.subOptions)
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/provisioningserver/plugin.py", line 241, in makeService
Mar 05 16:49:16 maas-deb rackd[7730]: install_boot_method_templates(tftp_root)
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/__init__.py", line 367, in install_boot_method_templates
Mar 05 16:49:16 maas-deb rackd[7730]: m.install_templates(tftp_root)
Mar 05 16:49:16 maas-deb rackd[7730]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/ipxe.py", line 118, in install_templates
Mar 05 16:49:16 maas-deb rackd[7730]: with open(config_dst, "wb") as stream:
Mar 05 16:49:16 maas-deb rackd[7730]: PermissionError: [Errno 13] Permission denied: '/var/lib/maas/tftp_root/ipxe.cfg'
Mar 05 16:49:16 maas-deb systemd[1]: maas-rackd.service: Main process exited, code=exited, status=1/FAILURE
Mar 05 16:49:16 maas-deb systemd[1]: maas-rackd.service: Failed with result 'exit-code'.
Mar 05 16:49:26 maas-deb systemd[1]: maas-rackd.service: Scheduled restart job, restart counter is at 3.
Mar 05 16:49:26 maas-deb systemd[1]: Stopped MAAS Rack Controller.

[Jerzy Husakowski (jhusakowski)]

Is this reproducible on a clean VM or a clean bare metal node?

[Anton Troyanov (troyanov)]

It is reproducible on a clean VM and LXD container.

I guess we have a small data-race during services startup.

I added echo $(date) to maas-rack-controller.postinst just before the line where we call chown
```
+ echo Wed Mar 13 08:55:50 UTC 2024
Wed Mar 13 08:55:50 UTC 2024
```

After inspecting `journalctl -u maas-rackd` it is clear that the first attempt to start rackd happens before the maas-rack-controller.postinst script finishes execution.

Mar 13 08:55:46 maas-deb systemd[1]: Starting MAAS Rack Controller...
Mar 13 08:55:46 maas-deb systemd[1]: Started MAAS Rack Controller.
Mar 13 08:55:47 maas-deb rackd[72993]: Traceback (most recent call last):
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/sbin/rackd", line 33, in <module>
Mar 13 08:55:47 maas-deb rackd[72993]: sys.exit(load_entry_point('maas==3.5.0rc1', 'console_scripts', 'rackd')())
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 95, in run
Mar 13 08:55:47 maas-deb rackd[72993]: runService("maas-rackd")
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 90, in runService
Mar 13 08:55:47 maas-deb rackd[72993]: UnixApplicationRunner(config).run()
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 370, in run
Mar 13 08:55:47 maas-deb rackd[72993]: self.application = self.createOrGetApplication()
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 432, in createOrGetApplication
Mar 13 08:55:47 maas-deb rackd[72993]: ser = plg.makeService(self.config.subOptions)
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/provisioningserver/plugin.py", line 241, in makeService
Mar 13 08:55:47 maas-deb rackd[72993]: install_boot_method_templates(tftp_root)
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/__init__.py", line 367, in install_boot_method_templates
Mar 13 08:55:47 maas-deb rackd[72993]: m.install_templates(tftp_root)
Mar 13 08:55:47 maas-deb rackd[72993]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/ipxe.py", line 118, in install_templates
Mar 13 08:55:47 maas-deb rackd[72993]: with open(config_dst, "wb") as stream:
Mar 13 08:55:47 maas-deb rackd[72993]: PermissionError: [Errno 13] Permission denied: '/var/lib/maas/tftp_root/ipxe.cfg'
Mar 13 08:55:47 maas-deb systemd[1]: maas-rackd.service: Main process exited, code=exited, status=1/FAILURE
Mar 13 08:55:47 maas-deb systemd[1]: maas-rackd.service: Failed with result 'exit-code'.
Mar 13 08:55:57 maas-deb systemd[1]: maas-rackd.service: Scheduled restart job, restart counter is at 1.
Mar 13 08:55:57 maas-deb systemd[1]: Stopped MAAS Rack Controller.
Mar 13 08:55:57 maas-deb systemd[1]: Starting MAAS Rack Controller...
Mar 13 08:55:57 maas-deb systemd[1]: Started MAAS Rack Controller.
Mar 13 08:56:50 maas-deb systemd[1]: Stopping MAAS Rack Controller...
Mar 13 08:56:50 maas-deb systemd[1]: maas-rackd.service: Deactivated successfully.
Mar 13 08:56:50 maas-deb...

[Anton Troyanov (troyanov)]

Considering that this race happens on startup and after certain amount of retries MAAS behaves normally I will change importance to Medium. However we might want to return a more user-friendly message instead of throwing a Traceback

[Jacopo Rota (r00ta)]

seen also on all the 3 nodes of solqa on one run. Moving to high as it seems more severe

pr 3 01:35:38 noma rackd[2724997]: Traceback (most recent call last):
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/sbin/rackd", line 33, in <module>
Apr 3 01:35:38 noma rackd[2724997]: sys.exit(load_entry_point('maas==3.5.0rc5', 'console_scripts', 'rackd')())
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 95, in run
Apr 3 01:35:38 noma rackd[2724997]: runService("maas-rackd")
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/provisioningserver/server.py", line 90, in runService
Apr 3 01:35:38 noma rackd[2724997]: UnixApplicationRunner(config).run()
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 370, in run
Apr 3 01:35:38 noma rackd[2724997]: self.application = self.createOrGetApplication()
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/twisted/application/app.py", line 432, in createOrGetApplication
Apr 3 01:35:38 noma rackd[2724997]: ser = plg.makeService(self.config.subOptions)
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/provisioningserver/plugin.py", line 241, in makeService
Apr 3 01:35:38 noma rackd[2724997]: install_boot_method_templates(tftp_root)
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/__init__.py", line 367, in install_boot_method_templates
Apr 3 01:35:38 noma rackd[2724997]: m.install_templates(tftp_root)
Apr 3 01:35:38 noma rackd[2724997]: File "/usr/lib/python3/dist-packages/provisioningserver/boot/ipxe.py", line 118, in install_templates
Apr 3 01:35:38 noma rackd[2724997]: with open(config_dst, "wb") as stream:
Apr 3 01:35:38 noma rackd[2724997]: PermissionError: [Errno 13] Permission denied: '/var/lib/maas/tftp_root/ipxe.cfg'

[Jacopo Rota (r00ta)]

As it seems to recover by itself I'm setting to medium again