Refresh scripts are not re-run if they pass, but fail to report the results to the region

From the log files, this looks to be the culprit: https://pastebin.canonical.com/p/3rrCTTbJxs/

It seems like the machine-resources binary is failing for some reason. But 20-maas-03-machine-resources swallows the error, which makes MAAS fail in the annotation stage, at which the results are thrown away. So we can't see what error machine-resources is reporting.

I'm going to fix 20-maas-03-machine-resources so that it doesn't swallow the error.

In the meantime, if you could run this on machines where you see this error, it would
be helpful for this bug:

  $ sudo snap run --shell maas.supervisor
  $ /snap/maas/current/usr/share/maas/machine-resources/amd64

> $ sudo snap run --shell maas.supervisor
> $ /snap/maas/current/usr/share/maas/machine-resources/amd64

Note in the second line of https://bugs.launchpad.net/maas/+bug/2003310/comments/2 you should pick the architecture that matches your host

Here is the output, it is 3800 lines

Actual command that failed when above output was collected

2023-01-23-16:35:48 foundationcloudengine.layers.configuremaas INFO Creating vault-1 in sqa-lab2-infra-1-arm
2023-01-23-16:35:48 root DEBUG [localhost]: maas root vm-host compose 1 hostname=vault-1 cores=2 memory=4096 storage=40.0 zone=2 'interfaces=eth0:space=oam-space;eth1:space=internal-space'
2023-01-23-16:35:52 root ERROR [localhost] Command failed: maas root vm-host compose 1 hostname=vault-1 cores=2 memory=4096 storage=40.0 zone=2 'interfaces=eth0:space=oam-space;eth1:space=internal-space'
2023-01-23-16:35:52 root ERROR [localhost] STDOUT follows:
Pod must be on a known host if interfaces are specified.

Thanks Marian. Unfortunately, that command didn't fail, as I expected it to. Do you have any failed runs with 3.3.0-rc3? There we should have some more debug information to go on.

https://oil-jenkins.canonical.com/artifacts/bcd983da-25a9-4468-9777-7726860bbfc0/generated/generated/maas/logs-2023-01-24-18.37.57.tgz
I believe this is log from 3.3 RC3, https://solutions.qa.canonical.com/v2/testruns/bcd983da-25a9-4468-9777-7726860bbfc0

Hit this again in 3.3.0RC7: https://oil-jenkins.canonical.com/artifacts/f914e926-be06-4ba1-942a-9d6438e52cef/index.html

Here is one of 3.3.0-rc7 tests which failed on this bug

https://oil-jenkins.canonical.com/artifacts/bacd79a8-9878-4f30-9ada-44d2478b17f7/generated/generated/maas/logs-2023-02-01-00.26.06.tgz

I took a look at a live environment where this bug occurred. 20-maas-03-machine-resources had PASSED and had the expected output. 50-maas-01-commissioning was PENDING.

The fact that 50-maas-01-commissioning was PENDING should mean that it in fact was PASSED, but then due to this bug the transaction was aborted and the status reverted back to PENDING.

50-maas-01-commissioning pretty much opens up a file and parse it as json, and then dumps it again. So it should mean that it produced valid json. But then when we try to annotate the data, we get None instead.

I'm still not sure what's going on there. I restart of MAAS fixed the problem and every commissioning script succeeded.

At this point, my best guess would be an old twisted bug we saw in Landscape, where in rare occasions after executing a subprocess, reading from stdout would result in None, instead of the real stdout.

Some observerations looking at https://oil-jenkins.canonical.com/artifacts/bd827ab3-7242-4f94-a1d2-cad7a93bbcb8/generated/generated/maas/logs-2023-03-08-01.58.05.tgz

leafeon and meinfoo seems fine, they have all scripts passing. swoobat have all scripts passing, except for 50-maas-01-commissioning and maas-list-modaliases, which are pending: https://pastebin.canonical.com/p/33x5WJfT2T/

Again, we see failures to update network interface configuration. But for leafeon, it seems like we eventually succeed: https://pastebin.canonical.com/p/YfDMJyyKpS/

For swoobat we see similar failures, but the script never gets marked as passed, as with leafeon: https://pastebin.canonical.com/p/XkVVZhwypb/

The error about failing to update network interfaces comes from NetworksMonitoringService.do_action():

       try:
            interfaces = yield maybeDeferred(self.getInterfaces)
            yield self._updateInterfaces(interfaces)
        except BaseException as e:
            msg = (
                "Failed to update and/or record network interface "
                "configuration: %s; interfaces: %r" % (e, interfaces)
            )
            log.err(None, msg)

so it's actually not clear where the error is actually happening.

Seems to be some error happening while reporting the results of the refresh scripts:

  https://pastebin.canonical.com/p/v98cqnzmb6/

In addition to this, the refresh() code doesn't notice these errors. They get swallowed by signal_wrapper, and we continue with the refresh even though something went wrong.

I've created a snap branch that prints out some more debug logs, which hopefully will pin-point where the error is.

The branch for the maas snap is 3.3/edge/bug-2003310-debug

It would be great to try to reproduce the error using that snap and take a look at the logs.

Here is a failed run using your debug snap

https://oil-jenkins.canonical.com/artifacts/d7f64b7e-d8b0-47f9-9b57-d9d54a8ebf41/generated/generated/maas/logs-2023-03-09-21.36.38.tgz

Thanks!

Those logs confirms my suspicion. The problem is indeed that MAAS is swallowing the exception in signal_wrapper().

What happpens is that maas_url is set to a VIP, and it probably either gets moved around and/or pointing to a MAAS that's not ready yet.

So when MAAS runs the refresh scripts, there's first a period where most fail, since 20-maas-03-machine-resources can't download the resource binary.

But after that, all the refresh scripts pass. However, when reporting that the scripts have passed via signal_wrapper, sometimes it fails doing so. Now there is a situation where the controller thinks all scripts have passed, but it hasn't been recorded in the database. And they won't run again, unless the host interface configuration changes.

We need to act on errors in signal_wrapper and not consider the script passed in that case. The scripts need to be retried until they all pass.