[Bug 2107332] Re: AppArmor denied audit messages related to __pycache__ in dmesg

[Sitsofe Wheeler]

@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.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to subiquity in Ubuntu.
https://bugs.launchpad.net/bugs/2107332

Title:
  AppArmor denied audit messages related to __pycache__ in dmesg

Status in subiquity package in Ubuntu:
  New
Status in ubuntu-advantage-tools package in Ubuntu:
  Triaged

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/subiquity/+bug/2107332/+subscriptions