LTTng » LTTng-UST

While tracing fork09 test from LTP, the test failed unexpectedly. LTTng required some of the FDs the test aims at exhausting. It seems such a test will always fail when tracing, for it assumes it will be the sole user of its FD space.

LTTng-ust master as of dd77bd5b20e95fefa8d857fdd3b7c9bdbbf24bc7.

Steps to reproduce:

git clone https://github.com/linux-test-project/ltp.git
cd ltp
make autotools
./configure
make

Then, when running as root, the test will abort if the problem is triggered:

lttng create
lttng enable-channel -u chan_ust
lttng enable-channel -k chan_kernel
lttng add-context -u -t vpid -t ip -t procname -t vtid -c chan_ust
lttng enable-event -u -a -c chan_ust
lttng enable-event -k -c chan_kernel --syscall --all
lttng start
LD_PRELOAD=liblttng-ust-dl.so:liblttng-ust-fork.so:liblttng-ust-fd.so ./fork09

Example output:

  
ltp/testcases/kernel/syscalls/fork# LD_PRELOAD=liblttng-ust-dl.so:liblttng-ust-fork.so:liblttng-ust-fd.so ./fork09
fork09      0  TINFO  :  OPEN_MAX is 1024
fork09      0  TINFO  :  first file descriptor is 22 
fork09      0  TINFO  :  Parent reporting 1023 files open
fork09      0  TINFO  :  Child opened new file #1023
libgcc_s.so.1 must be installed for pthread_cancel to work
fork09      1  TBROK  :  tst_sig.c:233: unexpected signal SIGIOT/SIGABRT(6) received (pid = 2568).
fork09      2  TBROK  :  tst_sig.c:233: Remaining cases broken
fork09      0  TWARN  :  tst_tmpdir.c:337: tst_rmdir: rmobj(/tmp/forz9gzhZ) failed: unlink(/tmp/forz9gzhZ) failed; errno=21: EISDIR
fork09      1  TFAIL  :  fork09.c:147: test 1 FAILED

When checking the trace, one can see that some calls to open() failed with errno == 24, "Too many open files":

...
[13:46:47.130018542] (+0.000013569) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/etc/ld.so.cache", flags = 524288, mode = 1 }
[13:46:47.130020273] (+0.000001731) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130021801] (+0.000001528) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/lib64/tls/x86_64/libgcc_s.so.1", flags = 524288, mode = 55440 }
[13:46:47.130022801] (+0.000001000) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130023703] (+0.000000902) rns syscall_entry_newstat: { cpu_id = 1 }, { filename = "/lib64/tls/x86_64" }
[13:46:47.130026945] (+0.000003242) rns syscall_exit_newstat: { cpu_id = 1 }, { ret = -2, statbuf = 140723106378272 }
[13:46:47.130027652] (+0.000000707) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/lib64/tls/libgcc_s.so.1", flags = 524288, mode = 55440 }
[13:46:47.130028567] (+0.000000915) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130028952] (+0.000000385) rns syscall_entry_newstat: { cpu_id = 1 }, { filename = "/lib64/tls" }
[13:46:47.130030619] (+0.000001667) rns syscall_exit_newstat: { cpu_id = 1 }, { ret = -2, statbuf = 140723106378272 }
[13:46:47.130031155] (+0.000000536) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/lib64/x86_64/libgcc_s.so.1", flags = 524288, mode = 55440 }
[13:46:47.130032002] (+0.000000847) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130032395] (+0.000000393) rns syscall_entry_newstat: { cpu_id = 1 }, { filename = "/lib64/x86_64" }
[13:46:47.130034017] (+0.000001622) rns syscall_exit_newstat: { cpu_id = 1 }, { ret = -2, statbuf = 140723106378272 }
[13:46:47.130034583] (+0.000000566) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/lib64/libgcc_s.so.1", flags = 524288, mode = 55440 }
[13:46:47.130035432] (+0.000000849) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130035793] (+0.000000361) rns syscall_entry_newstat: { cpu_id = 1 }, { filename = "/lib64" }
[13:46:47.130039354] (+0.000003561) rns syscall_exit_newstat: { cpu_id = 1 }, { ret = 0, statbuf = 140723106378272 }
[13:46:47.130045019] (+0.000005665) rns syscall_entry_open: { cpu_id = 1 }, { filename = "/dev/tty", flags = 2306, mode = 0 }
[13:46:47.130046134] (+0.000001115) rns syscall_exit_open: { cpu_id = 1 }, { ret = -24 }
[13:46:47.130046973] (+0.000000839) rns syscall_entry_writev: { cpu_id = 1 }, { fd = 2, vec = 140723106380368, vlen = 1 }
[13:46:47.130060399] (+0.000013426) rns syscall_exit_writev: { cpu_id = 1 }, { ret = 59, vec = 140723106380368 }
[13:46:47.130061293] (+0.000000894) rns syscall_entry_mmap: { cpu_id = 1 }, { addr = 0x0, len = 4096, prot = 3, flags = 34, fd = -1, offset = 0 }
[13:46:47.130067022] (+0.000005729) rns syscall_exit_mmap: { cpu_id = 1 }, { ret = 0x7FB33758B000 }
[13:46:47.130075155] (+0.000008133) rns syscall_entry_rt_sigprocmask: { cpu_id = 1 }, { how = 1, nset = 140723106380064, sigsetsize = 8 }
[13:46:47.130075728] (+0.000000573) rns syscall_exit_rt_sigprocmask: { cpu_id = 1 }, { ret = 0, oset = 0 }
[13:46:47.130126316] (+0.000050588) rns syscall_entry_rt_sigprocmask: { cpu_id = 1 }, { how = 0, nset = 140723106379920, sigsetsize = 8 }
[13:46:47.130128042] (+0.000001726) rns syscall_exit_rt_sigprocmask: { cpu_id = 1 }, { ret = 0, oset = 140723106379792 }
[13:46:47.130128816] (+0.000000774) rns syscall_entry_getpid: { cpu_id = 1 }, { }
[13:46:47.130129698] (+0.000000882) rns syscall_exit_getpid: { cpu_id = 1 }, { ret = 2568 }
[13:46:47.130130243] (+0.000000545) rns syscall_entry_gettid: { cpu_id = 1 }, { }
[13:46:47.130131252] (+0.000001009) rns syscall_exit_gettid: { cpu_id = 1 }, { ret = 2568 }
[13:46:47.130132261] (+0.000001009) rns syscall_entry_tgkill: { cpu_id = 1 }, { tgid = 2568, pid = 2568, sig = 6 }