Thanks for your ideas up to now. I am getting a better idea of it now. I have gone through some of the logs on a new “Commission” (which failed installing dependencies for “smartctl-validate”) and looking at the rsyslog for it I have a timeline like this:
Shortly after loading ephemeral, loading snap service succeeds, time and date starts etc.:
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: snap.lxd.activate.service: Succeeded.
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: Finished Service for snap application lxd.activate.
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: Started snap.lxd.hook.configure.32c6306c-897f-4995-808b-b0762ebf69a4.scope.
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: snap.lxd.hook.configure.32c6306c-897f-4995-808b-b0762ebf69a4.scope: Succeeded.
2022-01-25T02:06:07+00:00 fair-mammal dbus-daemon[1720]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.12' (uid=0 pid=1733 comm="/usr/lib/snapd/snapd ")
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: Starting Time & Date Service...
2022-01-25T02:06:07+00:00 fair-mammal dbus-daemon[1720]: [system] Successfully activated service 'org.freedesktop.timedate1'
2022-01-25T02:06:07+00:00 fair-mammal systemd[1]: Started Time & Date Service.
2022-01-25T02:06:11+00:00 fair-mammal systemd[1]: dmesg.service: Succeeded.
A few seconds later, something tries to connect directly to the internet (IP 91.189.94.10) This fails because of our firewall I assume:
2022-01-25T02:06:12+00:00 fair-mammal pollinate[1729]: WARNING: Network communication failed [28] ...
* Trying 91.189.94.10:443.
A few seconds after that network failure, we get the Proxy being set and what seems like a succesful apt-get update:
2022-01-25T02:06:49+00:00 fair-mammal systemd-timesyncd[2545]: Initial synchronization to time server 172.27.41.2:123 (172.27.41.2).
2022-01-25T02:06:49+00:00 fair-mammal cloud-init[2514]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'modules:config' at Tue, 25 Jan 2022 02:06:48 +0000. Up 68.00 seconds.
2022-01-25T02:06:49+00:00 fair-mammal cloud-init[2514]: Begin run command: snap set system proxy.http="http://172.27.41.2:8000/" proxy.https="http://172.27.41.2:8000/"
2022-01-25T02:06:49+00:00 fair-mammal cloud-init[2514]: End run command: exit(0)
2022-01-25T02:06:49+00:00 fair-mammal systemd[1]: Finished Apply the settings specified in cloud-config.
2022-01-25T02:06:49+00:00 fair-mammal systemd[1]: Starting Execute cloud user/final scripts...
2022-01-25T02:06:49+00:00 fair-mammal cloud-init[2557]: Hit:1 http://archive.ubuntu.com/ubuntu focal InRelease
2022-01-25T02:06:49+00:00 fair-mammal cloud-init[2557]: Get:2 http://archive.ubuntu.com/ubuntu focal-updates InRelease [114 kB]
A few minutes later it successfully installs packages for lldpd as far I can tell, but fails at the end for smartctl-validate
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Installing apt packages for 20-maas-01-install-lldpd (id: 1198, script_version_id: 1)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting 20-maas-01-install-lldpd (id: 1198, script_version_id: 1)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished 20-maas-01-install-lldpd (id: 1198, script_version_id: 1): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting 20-maas-02-dhcp-unconfigured-ifaces (id: 1199, script_version_id: 2)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished 20-maas-02-dhcp-unconfigured-ifaces (id: 1199, script_version_id: 2): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting 40-maas-01-machine-resources (id: 1201, script_version_id: 4)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished 40-maas-01-machine-resources (id: 1201, script_version_id: 4): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting 50-maas-01-commissioning (id: 1202, script_version_id: 5)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished 50-maas-01-commissioning (id: 1202, script_version_id: 5): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-capture-lldpd (id: 1209, script_version_id: 12)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-get-fruid-api-data (id: 1206, script_version_id: 9)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-kernel-cmdline (id: 1207, script_version_id: 10)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-list-modaliases (id: 1205, script_version_id: 8)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-lshw (id: 1204, script_version_id: 7)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-serial-ports (id: 1208, script_version_id: 11)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Starting maas-support-info (id: 1203, script_version_id: 6)
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-serial-ports (id: 1208, script_version_id: 11): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-list-modaliases (id: 1205, script_version_id: 8): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-support-info (id: 1203, script_version_id: 6): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-get-fruid-api-data (id: 1206, script_version_id: 9): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-kernel-cmdline (id: 1207, script_version_id: 10): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-lshw (id: 1204, script_version_id: 7): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Finished maas-capture-lldpd (id: 1209, script_version_id: 12): 0
2022-01-25T02:09:06+00:00 fair-mammal cloud-init[2557]: Installing apt packages for smartctl-validate (id: 1211, script_version_id: 13)
2022-01-25T02:09:07+00:00 fair-mammal cloud-init[2557]: Failed installing package(s) for smartctl-validate (id: 1211, script_version_id: 13)
2022-01-25T02:09:07+00:00 fair-mammal cloud-init[2557]: 1 test scripts failed to run
The proxy access.log has a TCP_MISS / 304 for the first line but is fine after that:
1643076409.862 36 172.27.41.196 TCP_MISS/304 370 GET http://archive.ubuntu.com/ubuntu/dists/focal/InRelease - HIER_DIRECT/91.189.88.152 -
Then we have a TCP_TUNNEL to snapcraft in the access.log, but I assume that is transparent to the firewall. So it seems to be correct in general, but that something like a cache miss in the proxy is causing that script not to install dependencies the first time.
Either way, I have kicked off another round of commisioning and will check it tomorrow!