** Description changed: [SRU] 2.78: https://bugs.launchpad.net/ubuntu/+source/snapd/+bug/2166403 [Impact] The bug would perpetually occupy one CPU and cause a large amount of data to be written. [Test Plan] Automated testing sufficiently covers the case: https://github.com/canonical/snapd/pull/17418/changes#diff-b4fd0da1d8819b7b1272b7454724bfc048af0e03b622392855ac7058b3c5e08a + + Manual steps for snapd debs < 2.78 and snapd debs 2.78: + + Follow reproducer in + https://bugs.launchpad.net/snapd/+bug/2161845/comments/2. Verify that + before 2.78 the logs contain the error repeatedly and for 2.78 that the + error no longer occurs every few seconds. [Where problems could occur] The fix affects when security profiles gets regenerated, if the fix was completely wrong it could either: - Cause less than (or no) expected profile regenerations, causing stale profile - Cause more than expected profile regenerations, causing performance degradation and a ton of disk writes causing HW degradation ---original--- I have a server on Ubuntu 26.04 with snapd 2.76.1. snapd never stops regenerating security profiles. It creates about 19 changes per minute and it keeps going. It survives a reboot. It takes one full CPU core all the time. The bigger problem is the disk. It writes about 2.6 GiB per minute, so close to 4 TB per day. Environment ----------- snap 2.76.1 (latest/stable, rev 27591) snapd 2.76.1 series 16 ubuntu 26.04 kernel 7.0.0-28-generic, amd64 snaps bare, canonical-livepatch, core22, core24, gnome-46-2404, gtk-common-themes, lxd, mesa-2404, snapd Host apparmor userspace is 5.0.0~beta1, but snapd uses its own bundled parser 4.1.7 and probes it fine. I do not think this is related, I mention it anyway. What I see ----------- With SNAPD_DEBUG=1 the daemon repeats this about every 3 seconds, forever: api_general.go: DEBUG: client reports mismatch with system-key: {..."apparmor-parser-features":null...} ifacestate.go: DEBUG: reported system key mismatch action: regenerate-profiles taskrunner.go: DEBUG: Running task NNNNNN on Do: Regenerate security profiles On the client side every error is the same one: cmd_run.go: DEBUG: SystemKeyMismatch returned an error: system-key missing on disk In 90 seconds with 452 lxc launches I got 86 mismatch reports on the server side. The answer was regenerate-profiles every single time. I also polled the key file from another process and it was absent in 89 of 2226 reads, so 4 percent. Why it never stops ----------- I read the source at tag 2.76.1 and I believe there are two separate problems. First one. The system key contains a field called apparmor-parser- features. To fill this field you have to actually run apparmor_parser and test what it accepts. A client never does this. Only snapd does it, and only when it writes the key to disk. So the field is always empty in a key that a client sends, and always filled in the key that snapd has on disk. This is true on every machine, not only mine. The client already knows about this. Its own compare function, SystemKeyMismatch(), clears this field on both sides before it compares, and there is a comment saying the field is excluded on purpose. The server does not do this. SystemKeysMatch() compares the whole struct with a plain reflect.DeepEqual and excludes nothing. It even carries a TODO about writing a proper struct compare. The result is that one side is always empty and the other is always filled, so the server always finds a difference. It can never answer that the keys match. Every report a client sends comes back as regenerate-profiles. Second one. regenerateAllSecurityProfiles() in overlord/ifacestate/helpers.go starts with os.Remove on the system key file and writes it back only after all backends are done. The comment says this is intentional, so an old key is not trusted while the profiles are being rebuilt. That looks correct to me on its own. But during the rebuild the file is simply not there. Any snap that starts in this window fails with "system-key missing on disk". cmd_run.go returns early only when there is no mismatch and no error, so this error falls into the report path instead. The report hits the first problem, which asks for another regeneration, which removes the key again. So the regeneration creates the exact situation that triggers the next regeneration. My server runs around 80 lxc calls per minute from scheduled timers, and /snap/bin/lxc is snap run. So the window gets hit almost always. I think this is why I see this and most people do not. Numbers ----------- I measured with snapd masked 3 minutes, running 12 minutes, masked again 3 minutes, sampling /proc/diskstats every 10 seconds, 102 samples. These are whole system writes, not only snapd, so the masked rows are just the normal load of 12 LXD containers on this box. phase samples writes snapd cpu masked before 12 51.1 MiB/min 0.0 % running 72 2627.1 MiB/min 95.7 % masked after 18 39.6 MiB/min 0.0 % That makes snapd 98.3 percent of all disk writes on the machine. Sustained it is 43.8 MiB/s, which alone is nothing special for an SSD, the problem is that it never stops. Per day it is 3.97 TB and per year 1.45 PB. A normal NVMe rated 300 to 600 TBW would reach its rated write endurance in 2 to 5 months. The file being written is /var/lib/snapd/state.json at 40 MB. 39.74 MB of that is notices, 120489 change-update notices with expire-after 168h and no limit on the count. Changes and tasks together are only 330 KB, because changes are capped around 500. So the state file grows with change rate multiplied by retention, and every save rewrites all of it. One rewrite per change would be 770 MiB/min, which is only 29 percent of what I measured. So state.json looks like it is written about 3.4 times per change. I did not instrument the single writes, this factor is only derived from the total, please take it as such. As a check that is independent, 120489 notices at 19.25 per minute is 4.3 days of accumulation and this matches the timestamp of the oldest notice. What I tried and it did not help ----------- reboot, the rate was the same before and after removing chromium and cups, then also removing canonical-livepatch and adding it back Workaround ----------- I masked snapd.service and snapd.socket. LXD is not affected, snap.lxd.daemon does not Require snapd.service, and all containers kept running. I left snapd.apparmor.service enabled so the snap profiles still load at boot. The cost is no snap refreshes at all until I unmask. Maybe I misread parts of the source, please correct me. I attach the daemon and client debug logs, both system keys, the write measurements and a patch with two tests that fail on unmodified 2.76.1.
-- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/2161845 Title: snapd loops forever on "Regenerate security profiles" and writes about 4 TB per day To manage notifications about this bug go to: https://bugs.launchpad.net/snapd/+bug/2161845/+subscriptions -- ubuntu-bugs mailing list [email protected] https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
