no fatrace output in focal

Bug #1861053 reported by Seth Arnold on 2020-01-28
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
fatrace (Ubuntu)
Undecided
Unassigned
linux (Ubuntu)
Undecided
Unassigned

Bug Description

Hello, fatrace in focal doesn't seem to work for me in focal.

Start fatrace in one terminal, and perform file operations in another terminal: man man, echo hi > hi, echo hi > /run/user/1000/hi, etc.

sarnold@millbarge:~$ sudo fatrace
[sudo] password for sarnold:
^Csarnold@millbarge:~$ sudo strace -yy fatrace
execve("/usr/sbin/fatrace", ["fatrace"], 0x7ffcc89ad9c8 /* 15 vars */) = 0
brk(NULL) = 0x55c9a1947000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd18dbde80) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3</etc/ld.so.cache>
fstat(3</etc/ld.so.cache>, {st_mode=S_IFREG|0644, st_size=71040, ...}) = 0
mmap(NULL, 71040, PROT_READ, MAP_PRIVATE, 3</etc/ld.so.cache>, 0) = 0x7f3539b15000
close(3</etc/ld.so.cache>) = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3</usr/lib/x86_64-linux-gnu/libc-2.30.so>
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360r\2\0\0\0\0\0"..., 832) = 832
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 64, SEEK_SET) = 64
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784) = 784
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 848, SEEK_SET) = 848
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 880, SEEK_SET) = 880
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0u\343\342\331Yj\256%\0230\256~\363\371\32\204"..., 68) = 68
fstat(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, {st_mode=S_IFREG|0755, st_size=2025032, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3539b13000
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 64, SEEK_SET) = 64
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784) = 784
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 848, SEEK_SET) = 848
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
lseek(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 880, SEEK_SET) = 880
read(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0u\343\342\331Yj\256%\0230\256~\363\371\32\204"..., 68) = 68
mmap(NULL, 2032984, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 0) = 0x7f3539922000
mmap(0x7f3539947000, 1540096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 0x25000) = 0x7f3539947000
mmap(0x7f3539abf000, 303104, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 0x19d000) = 0x7f3539abf000
mmap(0x7f3539b09000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3</usr/lib/x86_64-linux-gnu/libc-2.30.so>, 0x1e6000) = 0x7f3539b09000
mmap(0x7f3539b0f000, 13656, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3539b0f000
close(3</usr/lib/x86_64-linux-gnu/libc-2.30.so>) = 0
arch_prctl(ARCH_SET_FS, 0x7f3539b14580) = 0
mprotect(0x7f3539b09000, 12288, PROT_READ) = 0
mprotect(0x55c99fee8000, 4096, PROT_READ) = 0
mprotect(0x7f3539b53000, 4096, PROT_READ) = 0
munmap(0x7f3539b15000, 71040) = 0
getpid() = 120700
fanotify_init(FAN_CLASS_NOTIF, O_RDONLY|O_LARGEFILE) = 3<anon_inode:[fanotify]>
brk(NULL) = 0x55c9a1947000
brk(0x55c9a1968000) = 0x55c9a1968000
openat(AT_FDCWD, "/proc/self/mounts", O_RDONLY|O_CLOEXEC) = 4</proc/120700/mounts>
fstat(4</proc/120700/mounts>, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(4</proc/120700/mounts>, "sysfs /sys sysfs rw,nosuid,nodev"..., 1024) = 1024
access("sysfs", F_OK) = -1 ENOENT (No such file or directory)
access("proc", F_OK) = -1 ENOENT (No such file or directory)
access("udev", F_OK) = -1 ENOENT (No such file or directory)
access("devpts", F_OK) = -1 ENOENT (No such file or directory)
access("tmpfs", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/ROOT/ubuntu", F_OK) = -1 ENOENT (No such file or directory)
access("securityfs", F_OK) = -1 ENOENT (No such file or directory)
access("tmpfs", F_OK) = -1 ENOENT (No such file or directory)
access("tmpfs", F_OK) = -1 ENOENT (No such file or directory)
access("tmpfs", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup2", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("pstore", F_OK) = -1 ENOENT (No such file or directory)
access("efivarfs", F_OK) = -1 ENOENT (No such file or directory)
read(4</proc/120700/mounts>, "de=700 0 0\ncgroup /sys/fs/cgroup"..., 1024) = 1024
access("none", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
access("cgroup", F_OK) = -1 ENOENT (No such file or directory)
read(4</proc/120700/mounts>, "_ino=4864 0 0\nmqueue /dev/mqueue"..., 1024) = 1024
access("systemd-1", F_OK) = -1 ENOENT (No such file or directory)
access("mqueue", F_OK) = -1 ENOENT (No such file or directory)
access("debugfs", F_OK) = -1 ENOENT (No such file or directory)
access("hugetlbfs", F_OK) = -1 ENOENT (No such file or directory)
access("fusectl", F_OK) = -1 ENOENT (No such file or directory)
access("configfs", F_OK) = -1 ENOENT (No such file or directory)
access("/dev/loop0", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/chromium/1005") = 0
access("/dev/loop1", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/core18/1650") = 0
access("/dev/loop3", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/core/8213") = 0
access("/dev/loop2", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/youtube-dl/2209") = 0
access("/dev/loop4", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/youtube-dl/1832") = 0
access("/dev/loop6", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/gtk-common-themes/1440") = 0
access("rpool/tmp", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/log", F_OK) = -1 ENOENT (No such file or directory)
access("/dev/loop5", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/core/8268") = 0
access("/dev/loop7", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/snap/chromium/986") = 0
read(4</proc/120700/mounts>, "ttr,posixacl 0 0\nrpool/var/spool"..., 1024) = 1024
access("rpool/var/tmp", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/spool", F_OK) = -1 ENOENT (No such file or directory)
access("bpool/BOOT/ubuntu", F_OK) = -1 ENOENT (No such file or directory)
access("/dev/nvme0n1p2", F_OK) = 0
fanotify_mark(3<anon_inode:[fanotify]>, FAN_MARK_ADD|FAN_MARK_MOUNT, FAN_ACCESS|FAN_MODIFY|FAN_CLOSE_WRITE|FAN_CLOSE_NOWRITE|FAN_OPEN|FAN_ONDIR|FAN_EVENT_ON_CHILD, AT_FDCWD, "/boot/efi") = 0
access("rpool/home/root", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/www", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/mail", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/home", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/usr/local", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/snap", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/lib/docker", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/lib/nfs", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/home/sarnold", F_OK) = -1 ENOENT (No such file or directory)
access("rpool/var/lib/schroot", F_OK) = -1 ENOENT (No such file or directory)
access("tracefs", F_OK) = -1 ENOENT (No such file or directory)
read(4</proc/120700/mounts>, "suid,nodev,relatime,size=1613792"..., 1024) = 65
access("tmpfs", F_OK) = -1 ENOENT (No such file or directory)
read(4</proc/120700/mounts>, "", 1024) = 0
close(4</proc/120700/mounts>) = 0
mmap(NULL, 270336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f35398e0000
rt_sigaction(SIGINT, {sa_handler=0x55c99fee6de0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f3539968470}, NULL, 8) = 0
read(3<anon_inode:[fanotify]>, ^Cstrace: Process 120700 detached
 <detached ...>

sarnold@millbarge:~$

Thanks

ProblemType: Bug
DistroRelease: Ubuntu 20.04
Package: fatrace 0.13-2
ProcVersionSignature: Ubuntu 5.4.0-12.15-generic 5.4.8
Uname: Linux 5.4.0-12-generic x86_64
NonfreeKernelModules: zfs zunicode zavl icp zcommon znvpair
ApportVersion: 2.20.11-0ubuntu15
Architecture: amd64
Date: Tue Jan 28 00:14:43 2020
ProcEnviron:
 TERM=rxvt-unicode-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: fatrace
UpgradeStatus: Upgraded to focal on 2020-01-24 (3 days ago)
---
ProblemType: Bug
ApportVersion: 2.20.11-0ubuntu15
Architecture: amd64
DistroRelease: Ubuntu 20.04
NonfreeKernelModules: zfs zunicode zavl icp zcommon znvpair
Package: linux
PackageArchitecture: amd64
ProcEnviron:
 TERM=rxvt-unicode-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 5.4.0-12.15-generic 5.4.8
Tags: focal
Uname: Linux 5.4.0-12-generic x86_64
UpgradeStatus: Upgraded to focal on 2020-01-24 (3 days ago)
UserGroups: adm cdrom libvirt lpadmin plugdev sambashare sbuild sudo
_MarkForUpload: True

Seth Arnold (seth-arnold) wrote :
tags: added: champagn
tags: added: champagne
removed: champagn
Seth Arnold (seth-arnold) wrote :

I added the linux package too, because the strace doesn't seem too unusual.

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1861053

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

Changed in linux (Ubuntu):
status: New → Incomplete

apport information

tags: added: apport-collected
description: updated

apport information

Changed in linux (Ubuntu):
status: Incomplete → Confirmed
Tyler Hicks (tyhicks) wrote :

FWIW, fatrace works fine for me under the same kernel and fatrace version:

$ sudo fatrace
...
bash(51938): O /tmp/hi
bash(51938): CW /tmp/hi
...
tyhicks@elm:~$ cat /proc/version_signature
Ubuntu 5.4.0-12.15-generic 5.4.8
$ apt policy fatrace
fatrace:
  Installed: 0.13-2
  Candidate: 0.13-2
  Version table:
 *** 0.13-2 500
        500 http://us.archive.ubuntu.com/ubuntu focal/universe amd64 Packages
        100 /var/lib/dpkg/status

Seth Arnold (seth-arnold) wrote :
Download full text (6.1 KiB)

Very curious. I tried again with new kernel and no change in results:

$ cat /proc/version_signature
Ubuntu 5.4.0-12.15-generic 5.4.8
$ uname -a
Linux millbarge 5.4.0-12-generic #15-Ubuntu SMP Tue Jan 21 15:12:29 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

$ apt policy fatrace
fatrace:
  Installed: 0.13-2
  Candidate: 0.13-2
  Version table:
 *** 0.13-2 500
        500 http://wopr/ubuntu focal/universe amd64 Packages
        100 /var/lib/dpkg/status

journalctl -f output while testing:

Jan 30 19:00:48 millbarge audit[1440438]: SYSCALL arch=c000003e syscall=59 success=yes exit=0 a0=55f754fc09f0 a1=55f754fb00a0 a2=55f754fb5a70 a3=8 items=2 ppid=22587 pid=1440438 auid=1000 uid=1000 gid=1000 euid=0 suid=0 fsuid=0 egid=1000 sgid=1000 fsgid=1000 tty=pts2 ses=1 comm="sudo" exe="/usr/bin/sudo" key="execpriv"
Jan 30 19:00:48 millbarge audit: EXECVE argc=2 a0="sudo" a1="fatrace"
Jan 30 19:00:48 millbarge audit: CWD cwd="/home/sarnold"
Jan 30 19:00:48 millbarge audit: PATH item=0 name="/usr/bin/sudo" inode=51282 dev=00:1b mode=0104755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
Jan 30 19:00:48 millbarge audit: PATH item=1 name="/lib64/ld-linux-x86-64.so.2" inode=9834 dev=00:1b mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
Jan 30 19:00:48 millbarge audit: PROCTITLE proctitle=7375646F0066617472616365
Jan 30 19:00:48 millbarge sudo[1440438]: pam_unix(sudo:auth): Couldn't open /etc/securetty: No such file or directory
Jan 30 19:00:49 millbarge sudo[1440438]: pam_unix(sudo:auth): Couldn't open /etc/securetty: No such file or directory
Jan 30 19:00:49 millbarge audit[1440438]: USER_AUTH pid=1440438 uid=1000 auid=1000 ses=1 msg='op=PAM:authentication grantors=pam_permit,pam_cap acct="sarnold" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
Jan 30 19:00:49 millbarge audit[1440438]: USER_ACCT pid=1440438 uid=1000 auid=1000 ses=1 msg='op=PAM:accounting grantors=pam_permit acct="sarnold" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
Jan 30 19:00:49 millbarge sudo[1440438]: sarnold : TTY=pts/2 ; PWD=/home/sarnold ; USER=root ; COMMAND=/usr/sbin/fatrace
Jan 30 19:00:49 millbarge audit[1440438]: USER_CMD pid=1440438 uid=1000 auid=1000 ses=1 msg='cwd="/home/sarnold" cmd="fatrace" terminal=pts/2 res=success'
Jan 30 19:00:49 millbarge audit[1440438]: CRED_REFR pid=1440438 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_permit,pam_cap acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
Jan 30 19:00:49 millbarge sudo[1440438]: pam_unix(sudo:session): session opened for user root by sarnold(uid=0)
Jan 30 19:00:49 millbarge audit[1440438]: USER_START pid=1440438 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_env,pam_env,pam_permit,pam_umask,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
Jan 30 19:00:57 millbarge bash[1005653]: Thu, 30 Jan 2020 19:00:57 +0000 src 46 (fix: 3) currently receiving: 0,3@0 0,9@0 0,16@0 0,22@0 0,23@0 0,26@0 2,1@1 2,4@1 2,21@1 3,14@0 3,24@0 3,25@0
Jan 30 19:01:03 millbarge sudo[1440438]: pam_unix(sud...

Read more...

Andrea Righi (arighi) wrote :

Hi Seth, is this still happening with the latest focal kernel? I'm trying to reproduce the problem, but I can't:

$ cat /proc/version_signature
Ubuntu 5.4.0-18.22-generic 5.4.24
righiandr@xps-13:~$ apt policy fatrace
fatrace:
  Installed: 0.13-2
  Candidate: 0.13-2
  Version table:
 *** 0.13-2 500
        500 http://it.archive.ubuntu.com/ubuntu focal/universe amd64 Packages
        100 /var/lib/dpkg/status

$ sudo fatrace
...
bash(386152): O /tmp/hi
bash(386152): W /tmp/hi
bash(386152): CW /tmp/hi
...

Seth Forshee (sforshee) on 2020-03-23
Changed in linux (Ubuntu):
status: Confirmed → Incomplete
Martin Pitt (pitti) wrote :

FTR, I just ran fatrace a lot in a current Ubuntu 20.04 VM to debug #1885188, and it seems fine.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers