[pkg-apparmor] Bug#1120454: Bug#1120454: apparmor.service takes time to finish with the 6.17.6+deb14-amd64 kernel

[Vincent Lefevre]

Hi,

On 2025-11-11 21:55:00 +0100, Christian Boltz wrote:
> The cache gets rebuild if the feature set supported by the kernel 
> changes - typically with major kernel releases (like your 6.16.x -> 
> 6.17.x update).
> 
> Note that not every major kernel release comes with new AppArmor 
> features. Looking at
> https://gitlab.com/apparmor/apparmor/-/wikis/Kernel_Feature_Matrix
> you can see that the last kernels which got new AppArmor features were 
> 6.7, 6.8, 6.13 and then 6.17. (Minor releases don't introduce new 
> AppArmor features.)

Indeed, from 6.12.41+deb13-amd64 to 6.16.3+deb14-amd64, I got:

2025-08-28T17:46:31+02:00 cventin kernel: Linux version 6.16.3+deb14-amd64 (debian-kernel at lists.debian.org) (x86_64-linux-gnu-gcc-14 (Debian 14.3.0-5) 14.3.0, GNU ld (GNU Binutils for Debian) 2.45) #1 SMP PREEMPT_DYNAMIC Debian 6.16.3-1 (2025-08-24)
[...]
2025-08-28T17:46:32+02:00 cventin systemd[1]: Starting apparmor.service - Load AppArmor profiles...
[...]
2025-08-28T17:46:36+02:00 cventin systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables...
2025-08-28T17:46:36+02:00 cventin systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables.
2025-08-28T17:46:52+02:00 cventin kernel: kauditd_printk_skb: 111 callbacks suppressed
2025-08-28T17:46:52+02:00 cventin kernel: audit: type=1400 audit(1756396012.889:123): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-soffice" pid=832 comm="apparmor_parser"
2025-08-28T17:46:52+02:00 cventin kernel: audit: type=1400 audit(1756396012.893:124): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-soffice//gpg" pid=832 comm="apparmor_parser"
2025-08-28T17:46:52+02:00 cventin systemd[1]: Finished apparmor.service - Load AppArmor profiles.
[...]

Thus 16 seconds.

But from 6.7.12-amd64 to 6.8.9-amd64, it was fast:

2024-05-23T13:44:29+02:00 cventin kernel: Linux version 6.8.9-amd64 (debian-kernel at lists.debian.org) (x86_64-linux-gnu-gcc-13 (Debian 13.2.0-25) 13.2.0, GNU ld (GNU Binutils for Debian) 2.42) #1 SMP PREEMPT_DYNAMIC Debian 6.8.9-1 (2024-05-15)
[...]
2024-05-23T13:44:29+02:00 cventin systemd[1]: Starting apparmor.service - Load AppArmor profiles...
[...]
2024-05-23T13:44:29+02:00 cventin systemd[1]: Finished apparmor.service - Load AppArmor profiles.
[...]

And from 6.6.15-amd64 to 6.7.12-amd64:

2024-05-07T13:45:02+02:00 cventin kernel: Linux version 6.7.12-amd64 (debian-kernel at lists.debian.org) (x86_64-linux-gnu-gcc-13 (Debian 13.2.0-23) 13.2.0, GNU ld (GNU Binutils for Debian) 2.42) #1 SMP PREEMPT_DYNAMIC Debian 6.7.12-1 (2024-04-24)
[...]
2024-05-07T13:45:02+02:00 cventin systemd[1]: Starting apparmor.service - Load AppArmor profiles...
[...]
2024-05-07T13:45:07+02:00 cventin systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables...
2024-05-07T13:45:07+02:00 cventin systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables.
2024-05-07T13:45:08+02:00 cventin kernel: audit: type=1400 audit(1715082308.784:20): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-soffice" pid=455 comm="apparmor_parser"
2024-05-07T13:45:08+02:00 cventin kernel: audit: type=1400 audit(1715082308.788:21): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-soffice//gpg" pid=455 comm="apparmor_parser"
2024-05-07T13:45:08+02:00 cventin systemd[1]: Finished apparmor.service - Load AppArmor profiles.
[...]

Since a cache rebuild can take time, shouldn't the start of a
cache rebuild be logged?

[...]
> > I don't know whether this could be related to the issue,
> > but these "audit" lines about libreoffice-soffice normally
> > do not appear during the boot.
> 
> These lines says that the profile was loaded into the kernel, so it's 
> quite boring ;-)
> 
> I'd guess the reason why you don't always see it is that IIRC there is a 
> limit of log messages per second, so it could be lost because of that 
> limit.

In such a case, shouldn't I get a message like

  cventin kernel: kauditd_printk_skb: 111 callbacks suppressed

above? This is not always the case.

> If you have auditd running, check /var/log/audit/audit.log. AFAIK it's 
> not affected by the rate limiting, and should contain profile_load lines 
> for all profiles.

I do not have auditd running.

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Pascaline project (LIP, ENS-Lyon)