AppArmor denied audit messages related to __pycache__ in dmesg

[Sitsofe Wheeler]

Description of the problem
Every night AppArmor denial logs related to trying to write to /lib/python3/dist-packages/uaclient/__pycache__/ are reported in the kernel logs.

Steps to reproduce:
1. Install latest server version of Ubuntu 24.04?

Expected result:
Kernel logs to only have unusual messages.

Actual result:
Each night output like the following appears in the kernel logs:
[592502.661712] kauditd_printk_skb: 89 callbacks suppressed
[592502.661714] audit: type=1400 audit(1744604059.356:1017): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_apt_news" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/__init__.cpython-312.pyc.126322914539312" pid=91895 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.667012] audit: type=1400 audit(1744604059.361:1018): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_apt_news" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/apt.cpython-312.pyc.126322914712960" pid=91895 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.676280] audit: type=1400 audit(1744604059.370:1019): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/__init__.cpython-312.pyc.135222400273840" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.677457] audit: type=1400 audit(1744604059.372:1020): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/log.cpython-312.pyc.135222401808656" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.684794] audit: type=1400 audit(1744604059.379:1021): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/defaults.cpython-312.pyc.135222399178672" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.685174] audit: type=1400 audit(1744604059.379:1022): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/secret_manager.cpython-312.pyc.135222399178672" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.689781] audit: type=1400 audit(1744604059.384:1023): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/system.cpython-312.pyc.135222399180720" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.699986] audit: type=1400 audit(1744604059.394:1024): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/exceptions.cpython-312.pyc.135222399544752" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.706501] audit: type=1400 audit(1744604059.401:1025): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_esm_cache" name="/usr/lib/python3/dist-packages/uaclient/messages/__pycache__/__init__.cpython-312.pyc.135222398418480" pid=91896 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
[592502.706551] audit: type=1400 audit(1744604059.401:1026): apparmor="DENIED" operation="mknod" class="file" profile="ubuntu_pro_apt_news" name="/usr/lib/python3/dist-packages/uaclient/__pycache__/event_logger.cpython-312.pyc.126322909730864" pid=91895 comm="python3" requested_mask="c" denied_mask="c" fsuid=0 ouid=0

How reproducible is the problem?
The problem happens every day.

Version information
Ubuntu 24.04.2 LTS
ubuntu-pro-client 34~24.04 amd64

Additional information
Running
sudo systemctl restart apt-news.service
makes the messages appear in the logs straightaway.

[Sitsofe Wheeler (sitsofe)]

This sounds similar to https://github.com/canonical/ubuntu-pro-client/issues/3193 but I can see the installed package already has the changes of https://github.com/canonical/ubuntu-pro-client/commit/bd8e2b05c0907a8e39d8e28e6a76f4f6303838a2 inside /etc/apparmor.d/ubuntu_pro_apt_news .

[Andreas Hasenack (ahasenack)]

Please try regenerating that cache with:

  sudo apt install --reinstall ubuntu-pro-client

[Sitsofe Wheeler (sitsofe)]

Andreas:
Thanks for the prompt reply your suggestion has fixed the problem. The only thing to note is that after the reinstall the following appeared on dmesg

[693175.025594] kauditd_printk_skb: 29 callbacks suppressed
[693175.025596] audit: type=1400 audit(1744704729.950:1332): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="ubuntu_pro_apt_news" pid=121719 comm="apparmor_parser"
[693175.224630] audit: type=1400 audit(1744704730.149:1333): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache" pid=121722 comm="apparmor_parser"
[693175.235162] audit: type=1400 audit(1744704730.159:1334): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//apt_methods" pid=121722 comm="apparmor_parser"
[693175.236055] audit: type=1400 audit(1744704730.160:1335): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//apt_methods_gpgv" pid=121722 comm="apparmor_parser"
[693175.237143] audit: type=1400 audit(1744704730.161:1336): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//cloud_id" pid=121722 comm="apparmor_parser"
[693175.237705] audit: type=1400 audit(1744704730.162:1337): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//dpkg" pid=121722 comm="apparmor_parser"
[693175.238482] audit: type=1400 audit(1744704730.163:1338): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//ps" pid=121722 comm="apparmor_parser"
[693175.238911] audit: type=1400 audit(1744704730.163:1339): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache//ubuntu_distro_info" pid=121722 comm="apparmor_parser"
[693175.239485] audit: type=1400 audit(1744704730.164:1340): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache_systemctl" pid=121722 comm="apparmor_parser"
[693175.239932] audit: type=1400 audit(1744704730.164:1341): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="ubuntu_pro_esm_cache_systemd_detect_virt" pid=121722 comm="apparmor_parser"

but running "systemctl restart apt-news.service" no longer results in any more messages being printed.

Does this mean that the problem wasn't a real issue? The machine this happened on was freshly installed on the 4th April 2025. However looking through /var/log/apt/history.log says the ubuntu-pro-client package was originally installed as part of a transaction from "Start-Date: 2025-02-16 21:00:10 / End-Date: 2025-02-16 21:00:28" which pre-dates the machine's actual install!

[Andreas Hasenack (ahasenack)]

The STATUS messages are fine, and are just confirming that the apparmor profile was loaded/replaced.

That cache directory is created at package installation, and would only change if the python code changed. When the package is installed or upgraded, its post-installation scripts will trigger a regeneration of this cache.

If the python code is changed locally, like by directly editing a file, the cache will no longer correspond to the code, and will auto-update. Or attempt to auto-update, at least. The systemd service applies the apparmor profile and won't allow that update to happen (which is correct). My guess is that at some point a local change was perhaps made to one of the python files, and that invalidated the cache. Or maybe the post-install script had failed before, and didn't update the cache files.

[Sitsofe Wheeler (sitsofe)]

Andreas:

> My guess is that at some point a local change was perhaps made to one of the python files, and that invalidated the cache. Or maybe the post-install script had failed before, and didn't update the cache files.

I see. Just to check, it's never the case that the cache is somehow generated at install media creation time and just copied directly on to the target machine?

[Sitsofe Wheeler (sitsofe)]

OK I've just tested a "normal" (i.e. non-minimal) install from ubuntu-24.04.2-live-server-amd64.iso in a VMM VM and after I log in and run sudo -s, systemctl restart apt-news.service and check dmesg the AppArmor denials are there. Doing a minimal server install, logging in, running sudo -s, apt install -y ubuntu-pro-client, systemctl restart apt-news.service and checking dmesg shows the issue is NOT present in that circumstance.

[Andreas Hasenack (ahasenack)]

That's an interesting find. I would expect the cache to always match the installed package/code, because it is generated at post-install time:

/var/lib/dpkg/info/ubuntu-pro-client.postinst:
...
# Automatically added by dh_python3
if command -v py3compile >/dev/null 2>&1; then
 py3compile -p ubuntu-pro-client:amd64
fi
if command -v pypy3compile >/dev/null 2>&1; then
 pypy3compile -p ubuntu-pro-client:amd64 || true
fi
...

Those commands are what generate the cache.

I'll add this bug to our internal triage discussion call.

[Andreas Hasenack (ahasenack)]

Also, even if you selected to update packages during the installation, and fetch a new ubuntu-pro-client version, that would also run the same postinst code, and update the cache. Intriguing.

[Sitsofe Wheeler (sitsofe)]

Something to note is that in the "normal" server install case the ubuntu-pro-client is part of default install and is somehow provided as part of the install media ISO. In the "minimal" server install case ubuntu-pro-client is NOT part of the default packages and has to be installed manually after the system is running.

I do wonder if the "normal" server install is copying an image where most of the packages have been pre-installed at install media creation time which would explain the installation dates that pre-date my actual install. If so, the question becomes why is the pre-install process generating a different outcome?

[Renan Rodrigo (renanrodrigo)]

Hello @sitsofe, @ahasenack

First of all, I could reproduce this problem exactly as described - thanks for the details!
The full server install has ubuntu-pro-client seeded and server-minimal does not have it.

## Debugging the problem

The timestamp hint was a good start for me to check what is happening.

- When installing the regular, non-minimal, server the files are copied (rsyncd? I am not sure) so the metadata for the python files have the moment of installation as the timestamp. Example:
```
(...)
-rw-r--r-- 1 root root 14590 Apr 16 2025 actions.py
drwxr-xr-x 4 root root 4096 Apr 16 2025 api
-rw-r--r-- 1 root root 8516 Apr 16 2025 apt_news.py
-rw-r--r-- 1 root root 35095 Apr 16 2025 apt.py
(...)
```
Likewise, the existing __pycache__folder has the same timestamps, but it's because the .pyc files have been most probably *copied*, not generated.
```
(...)
-rw-r--r-- 1 root root 19057 Apr 16 2025 actions.cpython-312.pyc
-rw-r--r-- 1 root root 42981 Apr 16 2025 apt.cpython-312.pyc
-rw-r--r-- 1 root root 11914 Apr 16 2025 apt_news.cpython-312.pyc
(...)
```

Looking at cpython's behavior, "But in general, it doesn't recompile if the bytecode if finds the .pyc file and if the size and timestamp of the .py file hasn't changed." (Source: https://github.com/python/cpython/issues/107631)

So, given the content is the same (I diff-ed the directories to make sure), the timestamps of the .py files are different than the ones used when the .pyc files were generated, regardless of when it happened, as the .py files keep the timestamps in the .deb. That's verifiable by running
```
sudo apt install --reinstall ubuntu-advantage-tools
```

Now, the __pycache__ has been re-generated. But looking at the python files, after the reinstall, we see the original timestamps.
```
(...)
-rw-r--r-- 1 root root 14590 Sep 6 2024 actions.py
drwxr-xr-x 4 root root 4096 Apr 16 2025 api
-rw-r--r-- 1 root root 8516 Aug 8 2024 apt_news.py
-rw-r--r-- 1 root root 35095 Aug 8 2024 apt.py
(...)
```

So the problem is that the __pycache__ is being generated based on the files contained in the deb, with the old timestamps, and then there are new timestamps in the seeded version after installation.

## If so, why it's not happening to other python packages that are seeded?

Well it may be! haha
But ubuntu-pro-client installs services (like apt-news or esm-cache), which other packages may not do.
And we have active apparmor profiles, which other packages may not have.
Without apparmor, our service would just regenerate the .pyc files at runtime.

It would be interesting to check other python packages which have apparmor backed services to see if this happens too, but I won't have the time now unfortunately.

## What could be done?

I don't know :D

- Could the ubuntu-pro-client apparmor profile allow the services to write the files in __pycache__? I don't think so. The client is behaving the way it should, and relaxing those profiles for such a corner case could lead to unforeseen (and some foreseen? hehe) security issues - like modifying the service to inject whatever in the .pyc files.

- Could subiquity keep the original .py files metadata (...

[Sitsofe Wheeler (sitsofe)]

@renanrodrigo

I thoroughly enjoyed reading your investigation and explanation of what is happening and why. You also predicted one of the questions I had while reading: "[...] why it's not happening to other python packages that are seeded? Well it may be! haha" - haha indeed! Perhaps seeded package Python caches have been silently rebuilding themselves wasting unknown seconds of CPU on first use ;-)

Looking through https://github.com/python/cpython/blob/3.13/Lib/importlib/_bootstrap_external.py#L1130-L1148 confirms what you said about the validity of the .pyc files being based off the mtime timestamps of the corresponding .py files. Basically if the mtime and size of the .py file isn't EXACTLY what has been embedded within the .pyc file, the .pyc will be considered stale and won't be used resulting in a later attempt to regenerate the .pyc . In terms of options I only see the following:

- As you suggested, ensure that .py files always keep their original mtime when there are corresponding .pyc files with the original mtime embedded within
- Shift to using hash based verification (at which point timestamps simply don't matter)
- Regenerate all .pyc files after .py copying has been completed
- Disable .pyc usage at runtime

I'm glad my wild speculation and hints proved useful. At least we have a workaround provided by @ahasenack (reinstall the package) for cases where the .pyc can't automatically be regenerated.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.