Wait for seed.loaded does not wait for all initialization tasks

[Alfonso Sanchez-Beato]

I have a script that runs on first boot which does:

snap wait system seed.loaded
snap connect <some-snap>:ttymxc-0 <gadget-snap>:ttymxc-0
...(other snap connect commands)

I would expect these commands to work after the snaps has been seeded, but I get these errors:

Oct 03 10:32:32 C031031821-00075 run.sh[1871]: + snap connect rigado-edge-connect:ttymxc-0 cascade:ttymxc-0
Oct 03 10:32:38 C031031821-00075 run.sh[1871]: error: snap "cascade" has "become-operational" change in progress
Oct 03 10:32:39 C031031821-00075 run.sh[1871]: + snap connect rigado-deviceops:led-green cascade:led-green
Oct 03 10:32:40 C031031821-00075 run.sh[1871]: error: snap "rigado-deviceops" has "connect-snap" change in progress

As can be seen, in some cases the gadget is not yet operative, or there are still ongoing automatic connections from the seeded snaps. This is a regression, as it was not happening in previous snapd versions.

$ snap version
snap 2.36~pre1
snapd 2.36~pre1
series 16
kernel 4.4.117+

[Samuele Pedroni (pedronis)]

I see, I think the change causing this was already in 2.35:

https://forum.snapcraft.io/t/cross-snap-operations-bases-and-concurrency/5685

the least invasive fix for this specific case is relatively simple, will try to create a PR

[Samuele Pedroni (pedronis)]

notice that I understand the first error, the 2nd is not clear yet to me, if it comes from gadget connection stanzas those are done before seeding

[Samuele Pedroni (pedronis)]

a "snap changes" around the 2nd error would be useful

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

See attached files ("snap change 1", and logs from the script). The script starts the connections more or less at the same time some connections are happening. Some of the automatic connections fail, I wonder if those are the one happening after the wait for the seed.

[Samuele Pedroni (pedronis)]

here's a fix for the first error:

https://github.com/snapcore/snapd/pull/5919

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

$ snap changes --abs-time
ID Status Spawn Ready Summary
1 Done 2018-10-04T09:10:53Z 2018-10-04T09:34:40Z Initialize system state
2 Done 2018-10-04T09:19:43Z 2018-10-04T09:20:12Z Change configuration of "core" snap
3 Done 2018-10-04T09:34:41Z 2018-10-04T09:36:39Z Initialize device
4 Done 2018-10-04T09:34:42Z 2018-10-04T09:35:20Z Connect rigado-deviceops:joystick to core:joystick
5 Done 2018-10-04T09:35:21Z 2018-10-04T09:35:52Z Connect rigado-deviceops:hardware-observe to core:hardware-observe
6 Done 2018-10-04T09:35:53Z 2018-10-04T09:36:14Z Connect rigado-deviceops:log-observe to core:log-observe
7 Done 2018-10-04T09:36:15Z 2018-10-04T09:36:30Z Connect rigado-deviceops:timeserver-control to core:timeserver-control
8 Done 2018-10-04T09:36:32Z 2018-10-04T09:36:46Z Connect rigado-deviceops:timezone-control to core:timezone-control
9 Done 2018-10-04T09:36:47Z 2018-10-04T09:36:57Z Connect rigado-deviceops:network-manager to network-manager:service
10 Done 2018-10-04T09:36:58Z 2018-10-04T09:36:59Z Running service command
11 Done 2018-10-04T09:37:04Z 2018-10-04T09:37:15Z Connect rigado-edge-connect:hardware-observe to core:hardware-observe
12 Done 2018-10-04T09:37:16Z 2018-10-04T09:37:32Z Connect rigado-edge-connect:gpio-1 to cascade:gpio-1
13 Done 2018-10-04T09:37:32Z 2018-10-04T09:37:46Z Connect rigado-edge-connect:gpio-2 to cascade:gpio-2
14 Done 2018-10-04T09:37:48Z 2018-10-04T09:38:02Z Connect rigado-edge-connect:gpio-22 to cascade:gpio-22
15 Done 2018-10-04T09:38:03Z 2018-10-04T09:38:19Z Connect rigado-edge-connect:gpio-23 to cascade:gpio-23
16 Done 2018-10-04T09:38:20Z 2018-10-04T09:38:35Z Connect rigado-edge-connect:gpio-30 to cascade:gpio-30
17 Done 2018-10-04T09:38:36Z 2018-10-04T09:38:50Z Connect rigado-edge-connect:gpio-31 to cascade:gpio-31
18 Done 2018-10-04T09:38:51Z 2018-10-04T09:39:06Z Connect rigado-edge-connect:gpio-69 to cascade:gpio-69
19 Done 2018-10-04T09:39:06Z 2018-10-04T09:39:23Z Connect rigado-edge-connect:gpio-77 to cascade:gpio-77
20 Done 2018-10-04T09:39:24Z 2018-10-04T09:39:39Z Connect rigado-edge-connect:gpio-78 to cascade:gpio-78
21 Done 2018-10-04T09:39:39Z 2018-10-04T09:39:54Z Connect rigado-edge-connect:gpio-117 to cascade:gpio-117
22 Done 2018-10-04T09:39:55Z 2018-10-04T09:40:10Z Connect rigado-edge-connect:gpio-118 to cascade:gpio-118
23 Done 2018-10-04T09:40:11Z 2018-10-04T09:40:29Z Running service command
24 Done 2018-10-04T09:40:31Z 2018-10-04T09:40:52Z Connect rigado-edge-connect:ttymxc-3 to cascade:ttymxc-3
25 Done 2018-10-04T09:40:53Z 2018-10-04T09:41:14Z Connect rigado-edge-connect:ttymxc-4 to cascade:ttymxc-4
26 Done 2018-10-04T09:41:14Z 2018-10-04T09:41:37Z Connect rigado-edge-connect:ttymxc-6 to cascade:ttymxc-6
27 Done 2018-10-04T09:41:37Z 2018-10-04T09:41:59Z Connect rigado-edge-connect:ttymxc-7 to cascade:ttymxc-7
28 Done 2018-10-04T09:42:00Z 2018-10-04T09:42:16Z Running service command

[Samuele Pedroni (pedronis)]

there is bunch of connect on rigage-deviceops:

4 Done 2018-10-04T09:34:42Z 2018-10-04T09:35:20Z Connect rigado-deviceops:joystick to core:joystick

etc

what is running those, run.sh or something else?

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

@pedronis, from a deviceops snap. I think we can ignore the second error for the moment, all connections should be done from either the snap or the script, as it is easy to see how they could conflict. Thanks for the solution to the first error.

[Samuele Pedroni (pedronis)]

@alfonsosanchezbeato yes, also as was mentioned a refresh just after seeding of one of the snaps would also provoke conflicts during the script run

we can explore separately how to detect or handle that kind of outcome of snap commands

[Samuele Pedroni (pedronis)]

the fix for the "become-operational" interference will be in 2.35.3 and 2.36