apparmor not properly handling file deletion on NFS

Thank you for using Ubuntu and taking the time to report a bug. Can you attach your /var/log/kern.log right after you try to open a PDF? It is possible that the new apparmor profile is causing you trouble.

Good intelligent guesswork! My kern.log has a lot of these in:

Aug 18 23:56:11 corona kernel: [14335.422844] type=1503 audit(1250636171.706:27): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=7731 parent=4075 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name=2F686F6D652F74776967617468792F2E726563656E746C792D757365642E7862656C2E444555495955202864656C6574656429

Thanks. This decodes to:
/home/twigathy/.recently-used.xbel.DEUIYU (deleted)

Can you attach your entire /var/log/kern.log right after you try to open a PDF to make sure we can address all of the paths?

Sure - pasted below [apparently only two...]

Aug 19 14:14:51 corona kernel: [ 748.256584] type=1503 audit(1250687691.088:12): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3846 parent=3621 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name=2F746D702F6F726269742D74776967617468792F6C696E632D6630362D302D32343134643233643135633963202864656C6574656429
Aug 19 14:14:51 corona kernel: [ 748.260835] type=1503 audit(1250687691.092:13): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3846 parent=3621 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name=2F686F6D652F74776967617468792F2E676E6F6D65322F6576696E63652F6576696E63652D637261736865642E385757555955202864656C6574656429

$ cat /tmp/415632 | aa-decode
Processing: 2F746D702F6F726269742D74776967617468792F6C696E632D6630362D302D32343134643233643135633963202864656C6574656429
Aug 19 14:14:51 corona kernel: [ 748.256584] type=1503 audit(1250687691.088:12): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3846 parent=3621 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/tmp/orbit-twigathy/linc-f06-0-2414d23d15c9c (deleted)'
Processing: 2F686F6D652F74776967617468792F2E676E6F6D65322F6576696E63652F6576696E63652D637261736865642E385757555955202864656C6574656429
Aug 19 14:14:51 corona kernel: [ 748.260835] type=1503 audit(1250687691.092:13): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3846 parent=3621 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/home/twigathy/.gnome2/evince/evince-crashed.8WWUYU (deleted)'

Thanks! I'll get this fixed up and uploaded in a few minutes.

Excellent - cheers :)

I'll have to remember that aa-decode tool. Could come in handy some time...

Well, I just wrote it this morning. See http://bazaar.launchpad.net/~ubuntu-core-dev/apparmor/profiles-devel/annotate/head%3A/bin/aa-decode. I may try to get that into apparmor proper.

This bug was fixed in the package evince - 2.27.90-0ubuntu6

---------------
evince (2.27.90-0ubuntu6) karmic; urgency=low

  * debian/apparmor-profile.abstraction: include abstractions/user-tmp
    (LP: #415632)
  * debian/apparmor-profile*:
    - add support for DVI
    - add support for EPS
    - add epiphany-browser
    - add email clients (evolution, kmail, thunderbird and mutt)
    - add comments on using mutt via xterm and konsole (but don't allow
      by default)
  * add apport hook:
    - add debian/evince.apport
    - debian/evince.dirs: add usr/share/apport/package-hooks
    - debian/rules: install evince.apport

 -- Jamie Strandboge <email address hidden> Wed, 19 Aug 2009 09:11:41 -0500

Not fixed for me -- see comments

Still getting this problem. I removed .recently-used.xbel and that didn't help either. Created a new user and they can use evince just fine.... So some conf file somewhere has got borked. What should I remove to stop this happening and make evince work again?

twigathy@corona:~$ evince zigbee.pdf

** (evince:11941): WARNING **: Failed to create dbus proxy for org.gnome.SettingsDaemon: Could not get owner of name 'org.gnome.SettingsDaemon': no such name

(evince:11941): GLib-CRITICAL **: g_bookmark_file_load_from_data: assertion `length != 0' failed

** (evince:11941): WARNING **: Failed to create file '/home/twigathy/.gnome2/evince/evince-crashed.ZBK5YU': No such file or directory

(evince:11941): Gtk-WARNING **: Attempting to store changes into `/home/twigathy/.recently-used.xbel', but failed: Failed to create file '/home/twigathy/.recently-used.xbel.79PNZU': No such file or directory

I'm not sure this is not still an AppArmor issue. Please run:
apport-collect -p evince 415632

Architecture: i386
DistroRelease: Ubuntu 9.10
NonfreeKernelModules: nvidia
Package: evince 2.27.90-0ubuntu6
PackageArchitecture: i386
ProcCmdline: root=/dev/nfs nfsroot=192.168.0.30:/mnt/monkey/corona/ ip=dhcp
ProcEnviron:
 SHELL=/bin/bash
 PATH=(custom, user)
 LANG=en_GB.UTF-8
ProcVersionSignature: Ubuntu 2.6.31-6.26-generic
Uname: Linux 2.6.31-6-generic i686
UserGroups: adm admin audio cdrom dialout lpadmin plugdev sambashare tty video

I cannot reproduce this. Are you using and encrypted $HOME or an NFS mounted $HOME? Does the problem go away if you do:
$ sudo apparmor_parser -R /etc/apparmor.d/usr.bin.evince

Yes, ~ is on NFS (Along with the rest of root...)

twigathy@corona:~$ sudo apparmor_parser -R /etc/apparmor.d/usr.bin.evince
Removal succeeded for "/usr/bin/evince".
Removal succeeded for "/usr/bin/evince-previewer".
Removal succeeded for "/usr/bin/evince-thumbnailer".

^ After doing this, I can open evince just fine! I guess I've hit a pretty obscure and weird bug then :-)

Ok, I'll look into this more. FTR, the unencoded paths are:
Processing: 2F746D702F6F726269742D74776967617468792F6C696E632D6434632D302D33383265306665303636396664202864656C6574656429
Aug 24 15:53:48 corona kernel: [ 486.011858] type=1503 audit(1251125628.417:12): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3404 parent=3332 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/tmp/orbit-twigathy/linc-d4c-0-382e0fe0669fd (deleted)'
Processing: 2F686F6D652F74776967617468792F2E676E6F6D65322F6576696E63652F6576696E63652D637261736865642E5A3639385955202864656C6574656429
Aug 24 15:53:48 corona kernel: [ 486.016236] type=1503 audit(1251125628.420:13): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3404 parent=3332 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/home/twigathy/.gnome2/evince/evince-crashed.Z698YU (deleted)'
Processing: 2F686F6D652F74776967617468792F2E726563656E746C792D757365642E7862656C2E4C4336335955202864656C6574656429
Aug 24 15:53:51 corona kernel: [ 488.822641] type=1503 audit(1251125631.229:14): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=3404 parent=3332 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/home/twigathy/.recently-used.xbel.LC63YU (deleted)'
Processing: 2F746D702F6F726269742D74776967617468792F6C696E632D326264642D302D37633434663637613866343563202864656C6574656429
Aug 25 01:59:28 corona kernel: [36826.178354] type=1503 audit(1251161968.584:15): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=11229 parent=8884 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/tmp/orbit-twigathy/linc-2bdd-0-7c44f67a8f45c (deleted)'
Processing: 2F686F6D652F74776967617468792F2E676E6F6D65322F6576696E63652F6576696E63652D637261736865642E505954475A55202864656C6574656429
Aug 25 01:59:28 corona kernel: [36826.182691] type=1503 audit(1251161968.588:16): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=11229 parent=8884 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/home/twigathy/.gnome2/evince/evince-crashed.PYTGZU (deleted)'
Processing: 2F686F6D652F74776967617468792F2E726563656E746C792D757365642E7862656C2E504E474F5A55202864656C6574656429
Aug 25 01:59:44 corona kernel: [36842.416644] type=1503 audit(1251161984.824:17): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=11229 parent=8884 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/home/twigathy/.recently-used.xbel.PNGOZU (deleted)'
Processing: 2F746D702F6F726269742D74776967617468792F6C696E632D326338302D302D37313835613664623637343534202864656C6574656429
Aug 25 02:00:38 corona kernel: [36896.014505] type=1503 audit(1251162038.420:18): operation="mknod" info="Failed name lookup - deleted entry" error=-2 pid=11392 parent=8884 profile="/usr/bin/evince" requested_mask="w::" denied_mask="w::" fsuid=1000 ouid=1000 name='/tmp/orbit-twigathy/linc-2c80-0-7185a6db67454 (deleted)'
Processing: 2F686F6...

Twigathy, as a work around unitl this is fixed, you can do:
sudo aa-complain /etc/apparmor.d/usr.bin.evince

This will allow evince to work, but log policy violations.

Do you use autofs or otherwise have the nfs unmounting/remounting or lazy unmounting?

Also, accessing PDFs on NFS works fine, so it is not a networking issue.

I use the in-kernel NFS root support and $HOME is just another directory inside of that. My fstab does not have an entry for / or /home. I'm not sure about autofs, but / never gets unmounted or remounted (Lazily or otherwise) as far as I know...

Reducing to Medium for now as I am not sure if High is appropriate. Please adjust as necessary.

I use the in-kernel NFS root support and $HOME is just another directory inside of that. My fstab does not have an entry for / or /home. I'm not sure about autofs, but / never gets unmounted or remounted (Lazily or otherwise) as far as I know...

Ack, apologies for bugspam. Refreshing page did something odd.

This is looking like a failure in AppArmor's path resolution

Twigathy can you upload your

  /etc/fstab
  /etc/default/portmap
  /etc/exports

Sure. Things incoming....

Note that exports-server and exports are for server and client. portmap is the same on both machines. fstab is for the client.

This seems to have been two issues,

1. AppArmor was enforcing tighter deleted file delegation semantics and
2. With the new hook placement under certain filesystems creation of files/nods was showing up as deleted paths.

The attached patch is the proposed fix and a test kernel with the patch applied can be grabbed from
http://kernel.ubuntu.com/~jj/linux-image-2.6.31-13-generic_2.6.31-13.43_amd64.deb

This bug was fixed in the package linux - 2.6.31-14.46

---------------
linux (2.6.31-14.46) karmic; urgency=low

  [ Andy Whitcroft ]

  * reinstate armel.mk with no flavours
    - LP: #449637
  * [Upstream] elevator: fix fastfail checks to allow merge of readahead
    requests
    - LP: #444915
  * [Upstream] block: silently error unsupported empty barriers too
    - LP: #420423

  [ John Johansen ]

  * SAUCE: AppArmor: Fix mediation of "deleted" paths
    - LP: #415632

  [ Tim Gardner ]

  * [Config] CONFIG_X86_MCE
    https://lists.ubuntu.com/archives/kernel-team/2009-October/007584.html
  * Revert "appletalk: Fix skb leak when ipddp interface is not loaded,
    CVE-2009-2903" - Use patch from 2.6.31.4 which is slightly different.

  [ Upstream Kernel Changes ]

  * x86: fix csum_ipv6_magic asm memory clobber
  * tty: Avoid dropping ldisc_mutex over hangup tty re-initialization
  * x86: Don't leak 64-bit kernel register values to 32-bit processes
  * tracing: correct module boundaries for ftrace_release
  * ftrace: check for failure for all conversions
  * futex: fix requeue_pi key imbalance
  * futex: Move exit_pi_state() call to release_mm()
  * futex: Nullify robust lists after cleanup
  * futex: Fix locking imbalance
  * NOHZ: update idle state also when NOHZ is inactive
  * ima: ecryptfs fix imbalance message
  * libata: fix incorrect link online check during probe
  * sound: via82xx: move DXS volume controls to PCM interface
  * ASoC: WM8350 capture PGA mutes are inverted
  * KVM: Prevent overflow in KVM_GET_SUPPORTED_CPUID
  * KVM: VMX: flush TLB with INVEPT on cpu migration
  * KVM: fix LAPIC timer period overflow
  * KVM: SVM: Fix tsc offset adjustment when running nested
  * KVM: SVM: Handle tsc in svm_get_msr/svm_set_msr correctly
  * net: Fix wrong sizeof
  * mm: add_to_swap_cache() must not sleep
  * sis5513: fix PIO setup for ATAPI devices
  * PIT fixes to unbreak suspend/resume (bug #14222)
  * IMA: open new file for read
  * ACPI: Clarify resource conflict message
  * ACPI: fix Compaq Evo N800c (Pentium 4m) boot hang regression
  * net: restore tx timestamping for accelerated vlans
  * net: unix: fix sending fds in multiple buffers
  * tun: Return -EINVAL if neither IFF_TUN nor IFF_TAP is set.
  * tcp: fix CONFIG_TCP_MD5SIG + CONFIG_PREEMPT timer BUG()
  * net: Fix sock_wfree() race
  * smsc95xx: fix transmission where ZLP is expected
  * sky2: Set SKY2_HW_RAM_BUFFER in sky2_init
  * appletalk: Fix skb leak when ipddp interface is not loaded
  * ax25: Fix possible oops in ax25_make_new
  * ax25: Fix SIOCAX25GETINFO ioctl
  * sit: fix off-by-one in ipip6_tunnel_get_prl
  * Linux 2.6.31.4
  * drm/i915: Fix FDI M/N setting according with correct color depth
    - LP: #416792

 -- Andy Whitcroft <email address hidden> Tue, 13 Oct 2009 12:06:59 +0100