cancel, lp, lpoptions, nfsrahead report 0% coverage despite being executed

[ilmanzo]

Edited 2026-08-31. The original body proposed two debuginfo-packaging causes. Both were wrong and have been retracted — see this comment for the retraction, a reproducer script, and a verified patch. This body now describes the actual findings.

Observation

openQA job https://openqa.opensuse.org/tests/6194777 reports 0% function coverage for binaries that definitely execute during the test:

• cancel, lp, lpoptions — console/cups (coverage_targets key cups-client)
• nfsrahead — console/rpcbind, console/postgresql_server (key nfs-client)

Schedule: cups_rpcbind_coverage.yaml. The coverage_targets mapping is correct — binaries are keyed under their real owning packages, so coverage_setup.pm does request cups-client-debuginfo and nfs-client-debuginfo, and both exist and are complete. Debuginfo packaging is not the problem.

Two independent root causes, both reproduced on an openSUSE Tumbleweed VM.

A — lp / cancel / lpoptions: the only instrumented function is the error path

Not a tracing failure. CUPS 2.4.19 systemv/lp.c defines four functions: main (on funkoverage's funcBlacklist), restart_job and set_job_attrs (static, inlined away, absent from .symtab), and usage (_CUPS_NORETURN, reached only from --help or an argument error — 17 call sites, all error paths).

So the entire instrumented set is usage, and a successful run can never reach it:

$ funkoverage enumerate --no-libs /usr/bin/lp
/usr/bin/lp usage
Total: 1 functions across 1 image(s)

normal run  (lp -d nonexistent /etc/hostname) : 0 functions called -> 0%
help run    (lp --help)                       : 1 function  called -> 100%

The traceable-function count predicts the reported set exactly — including the binaries that were not reported:

binary	traceable functions	reported 0%?
lp, cancel	1 (usage)	✅
lpoptions	2	✅
lpadmin	3	❌
lpstat	10	❌

The 0% is arithmetically correct but indistinguishable from "never executed".

B — nfsrahead: the shim aborts under udev, so the binary never runs at all

nfsrahead is a udev callout (99-nfs.rules: SUBSYSTEM=="bdi", ACTION=="add", PROGRAM="/usr/libexec/nfsrahead %k"), not a shell command.

• Direct invocation from a root shell → 10 functions traced, fine.
• Invocation by udev → 0, every _called.log 0 bytes.

11:0: '/usr/libexec/nfsrahead 11:0'(err) 'funkoverage-shim: helper: tracer start: \
      tracer: attach fork tracepoint: ope...'
11:0: Process '/usr/libexec/nfsrahead 11:0' failed with exit code 1.

Tracer.Start() aborts at link.Tracepoint("sched","sched_process_fork") — the only attach needing perf_event_open(2) rather than bpf(2). systemd-udevd's seccomp allow-list has bpf but not perf_event_open (capabilities are fine: its bounding set includes cap_bpf, cap_perfmon, cap_sys_admin). Allowing just that syscall makes coverage appear immediately.

This is worse than lost coverage: the error propagates to os.Exit(1) before syscall.Exec(realBin), so while shimmed, udev's callout is a stub that always fails — nfsrahead never runs and NFS readahead tuning silently breaks. Any shimmed binary invoked from a seccomp-sandboxed unit hits this.

Proposed fix

Implemented and verified (see the comment for the diff and reproducer):

1. Remove main from funcBlacklist — it is the one entry point that is real user code, and the liveness signal that separates "ran" from "never ran".
2. Make the fork tracepoint non-fatal — it only extends tracing to children; degrade instead of aborting.
3. Fail open in runWithTracing — if the tracer can't attach, warn and exec the real binary anyway. Never replace the user's program with a failing stub.

case	before	after
lp -d nonexistent file	0/1 → 0%	1/2 → 50%
nfsrahead via udev	0/16 → 0%, binary never ran	10/16 → 62.5%, binary runs

Environment: openSUSE Tumbleweed, cups-2.4.19-2.3, nfs-client-2.9.2-54.1, BinaryCoverage @ 5907733.

[ilmanzo]

CORRECTION — the original root-cause analysis in this issue was wrong

I re-investigated on a Tumbleweed VM and the two causes I proposed when filing are both incorrect. Retracting them explicitly so nobody chases them:

Original claim	Reality
libcups2-debuginfo missing → install hard-fails for lp/cancel/lpoptions	Wrong. Install succeeds. My "counterfactual" test was invalid: I had already run install once, which eu-unstrips debug info into the binary, so the retest saw embedded DWARF and passed regardless of the packages.
nfs-utils-debuginfo is incomplete / missing nfsrahead.debug	Wrong package. coverage_targets keys nfsrahead under nfs-client, so coverage_setup.pm requests nfs-client-debuginfo — which exists and ships nfsrahead.debug fine. With it installed, nfsrahead enumerates 15 functions.

The real causes are two genuine bugs, unrelated to debuginfo packaging. Reproducer + verified patch below.

---

Root cause A — lp / cancel / lpoptions: the only instrumented function is the error path

Not a tracing failure. The tracer works perfectly. The instrumented set is 1 function, and it is unreachable on a successful run.

CUPS 2.4.19 systemv/lp.c defines exactly four functions:

main            <- on funkoverage's funcBlacklist
restart_job     <- static, inlined away by the optimiser (absent from .symtab)
set_job_attrs   <- static, inlined away by the optimiser (absent from .symtab)
usage           <- _CUPS_NORETURN

usage() has 17 call sites in lp.c; every one is --help or an argument-parse error. So:

$ funkoverage enumerate --no-libs /usr/bin/lp
/usr/bin/lp usage
Total: 1 functions across 1 image(s)

cancel.c is the same shape (main + usage only). A successful lp -d printer file therefore calls 0 of its 1 instrumented functions → a permanent, structural 0%.

The strongest evidence is which binaries were not reported. The instrumented-function count predicts the reported set exactly:

binary	traceable functions	reported at 0%?
lp	1 (usage)	✅ yes
cancel	1 (usage)	✅ yes
lpoptions	2 (usage, list_group)	✅ yes
lpstat	10	❌ no
lpadmin	3 (incl. validate_name)	❌ no

Same binary, two invocations, proving the mechanism:

normal run  (lp -d nonexistent /etc/hostname) : 0 functions called -> 0%
help run    (lp --help)                       : 1 function  called -> 100%

0% here is arithmetically "correct" and completely uninformative — it is indistinguishable from "the binary never ran", which is exactly why it looked like a bug.

Root cause B — nfsrahead: the shim aborts under udev and the binary never executes

nfsrahead is not a shell command, it is a udev callout:

/usr/lib/udev/rules.d/99-nfs.rules:
SUBSYSTEM=="bdi", ACTION=="add", PROGRAM="/usr/libexec/nfsrahead %k", ATTR{read_ahead_kb}="%c"

• Invoked directly from a root shell → 10 functions traced, works fine.
• Invoked by udev (the only way it runs in the job) → 0, every _called.log is 0 bytes.

udev's debug log shows why:

11:0: '/usr/libexec/nfsrahead 11:0'(err) 'funkoverage-shim: helper: tracer start: \
      tracer: attach fork tracepoint: ope...'
11:0: Process '/usr/libexec/nfsrahead 11:0' failed with exit code 1.

Tracer.Start() aborts at link.Tracepoint("sched","sched_process_fork") — the one attach that needs perf_event_open(2) instead of bpf(2). systemd-udevd runs under a seccomp allow-list that permits the latter but not the former:

bpf in udev SystemCallFilter             : 1
perf_event_open in udev SystemCallFilter : 0

(Capabilities are not the problem — udev's bounding set has cap_bpf, cap_perfmon and cap_sys_admin.)

Confirmed by temporarily allowing just that syscall — coverage immediately appears:

via udev, default seccomp             : 0 functions called
via udev, perf_event_open allowed     : 30 functions called (3 bdi devices x 10)

This is worse than a coverage gap. runWithTracing() returns the error, main() does os.Exit(1), and that happens before syscall.Exec(realBin) — so while the shim is installed, udev's callout is replaced by a stub that always fails. nfsrahead never runs and NFS readahead tuning silently stops working. Any shimmed binary invoked from a seccomp-sandboxed unit has the same failure mode.

---

Reproducer

Run as root on Tumbleweed. Restores the host afterwards (uninstalls shims, removes its udev drop-in, reinstalls the round-tripped RPM).

repro_158.sh

#!/bin/bash
# Reproducer for ilmanzo/BinaryCoverage#158
#   "cancel, lp, lpoptions, nfsrahead report 0% coverage despite being executed"
#
# There are TWO independent root causes behind the same symptom. This script
# demonstrates both on openSUSE Tumbleweed. Run as root.
#
#   Part A — thin-wrapper binaries (cancel, lp, lpoptions)
#            The instrumented set is 1-2 functions, all of them error paths.
#   Part B — udev-invoked binaries (nfsrahead)
#            The shim aborts under udev's seccomp filter and the real binary
#            never executes at all.
#
# Usage: sudo ./repro_158.sh [/path/to/funkoverage]
set -uo pipefail

FV="${1:-$(command -v funkoverage)}"
LOG_DIR=/var/coverage/data
[[ $EUID -eq 0 ]] || { echo "must run as root" >&2; exit 1; }
[[ -x "$FV" ]] || { echo "funkoverage not found; pass its path as \$1" >&2; exit 1; }

# NOTE: on a host with both a packaged /usr/bin/funkoverage and a locally built
# /usr/local/bin/funkoverage, sudo's secure_path picks the former. Always invoke
# by absolute path, which is why $FV is resolved once here.
echo "### using: $FV ($("$FV" --version 2>&1))"

hr() { printf '\n%s\n' "=================================================================="; }
clean_logs() { rm -f "$LOG_DIR"/*.log; }

zypper -n install -y cups-client cups-client-debuginfo libcups2-debuginfo \
    nfs-client nfs-client-debuginfo >/dev/null 2>&1
"$FV" setup >/dev/null || exit 1

##############################################################################
hr; echo "PART A — thin wrappers: the whole instrumented set is the error path"
hr
# CUPS 2.4.19 systemv/lp.c defines exactly four functions:
#   main, restart_job, set_job_attrs, usage
# restart_job/set_job_attrs are static and get inlined away, main is on
# funkoverage's funcBlacklist -> the only survivor is usage(), which is
# _CUPS_NORETURN and is reached ONLY from --help or an argument error.
echo "--- what funkoverage will instrument in each cups-client binary ---"
for b in /usr/bin/lp /usr/bin/cancel /usr/bin/lpoptions /usr/bin/lpstat /usr/sbin/lpadmin; do
    printf '%-12s ' "$(basename "$b")"
    # the "Total:" summary line goes to stderr, hence 2>&1
    "$FV" enumerate --no-libs "$b" 2>&1 | tail -1
done
echo
echo ">>> lp/cancel: 1 function (usage). lpstat/lpadmin: many."
echo ">>> That is exactly the split between the binaries reported at 0% and"
echo ">>> the ones that were not — lpstat and lpadmin were never reported."

echo
echo "--- proof: same binary, two invocations, 0% vs 100% ---"
clean_logs
"$FV" install --no-libs /usr/bin/lp >/dev/null || exit 1

# (1) A normal invocation: never touches usage().
lp -d nonexistent /etc/hostname >/dev/null 2>&1
sleep 2
echo -n "normal run  (lp -d ... file) : "
grep -h CALLED "$LOG_DIR"/lp_*_called.log 2>/dev/null | wc -l | tr -d '\n'
echo " function(s) called  -> 0% in the report"

# (2) The help path: the one way to reach usage().
clean_logs
lp --help >/dev/null 2>&1
sleep 2
echo -n "help run    (lp --help)      : "
grep -h CALLED "$LOG_DIR"/lp_*_called.log 2>/dev/null | wc -l | tr -d '\n'
echo " function(s) called  -> 100% in the report"

"$FV" uninstall /usr/bin/lp >/dev/null
echo
echo ">>> The tracer is working perfectly. The binary genuinely never calls its"
echo ">>> one instrumented function during a successful run. 0% is 'correct'"
echo ">>> and completely uninformative: it cannot be told apart from 'never ran'."

##############################################################################
hr; echo "PART B — nfsrahead: the shim aborts under udev, binary never runs"
hr
echo "--- nfsrahead has plenty to trace (needs nfs-client-debuginfo) ---"
"$FV" enumerate --no-libs /usr/libexec/nfsrahead 2>&1 | tail -1
echo
echo "--- nfsrahead is a udev callout, not a shell command ---"
grep -h nfsrahead /usr/lib/udev/rules.d/*.rules

clean_logs
"$FV" install /usr/libexec/nfsrahead >/dev/null || exit 1

echo
echo "--- (1) invoked directly from a root shell: works ---"
/usr/libexec/nfsrahead "$(ls /sys/class/bdi | head -1)" >/dev/null 2>&1
sleep 2
echo -n "direct invocation : "
cat "$LOG_DIR"/nfsrahead_*_called.log 2>/dev/null | wc -l | tr -d '\n'
echo " functions called"

echo
echo "--- (2) invoked the real way, by udev: zero ---"
clean_logs
# udev only logs a callout's stderr and exit code at debug level
udevadm control --log-level=debug
udevadm trigger --subsystem-match=bdi --action=add
udevadm settle --timeout=30
sleep 3
udevadm control --log-level=info
echo -n "via udev          : "
cat "$LOG_DIR"/nfsrahead_*_called.log 2>/dev/null | wc -l | tr -d '\n'
echo " functions called (summed over every bdi device on the host)"

echo
echo "--- why: the shim exits 1 and never execs the real binary ---"
journalctl -b --no-pager -o cat --since "-2min" 2>/dev/null \
    | grep -iE "funkoverage-shim|nfsrahead.*failed with exit code" | head -4
echo
echo "--- the blocked syscall: udev allows bpf(2) but not perf_event_open(2) ---"
echo -n "bpf in udev SystemCallFilter             : "
systemctl show systemd-udevd -p SystemCallFilter --value | tr ' ' '\n' | grep -cx bpf
echo -n "perf_event_open in udev SystemCallFilter : "
systemctl show systemd-udevd -p SystemCallFilter --value | tr ' ' '\n' | grep -cx perf_event_open
echo
echo ">>> Tracer.Start() aborts on link.Tracepoint(\"sched\",\"sched_process_fork\"),"
echo ">>> the one attach that needs perf_event_open(2). runWithTracing() turns that"
echo ">>> into a non-zero exit BEFORE syscall.Exec(realBin), so udev's callout is"
echo ">>> replaced by a stub that always fails: no coverage AND no readahead tuning."

echo
echo "--- confirm it is the seccomp filter (temporarily allow the syscall) ---"
mkdir -p /etc/systemd/system/systemd-udevd.service.d
printf '[Service]\nSystemCallFilter=perf_event_open\n' \
    > /etc/systemd/system/systemd-udevd.service.d/zz-repro158.conf
systemctl daemon-reload && systemctl restart systemd-udevd && sleep 2
clean_logs
udevadm trigger --subsystem-match=bdi --action=add
udevadm settle --timeout=30
sleep 3
echo -n "via udev, perf_event_open allowed : "
cat "$LOG_DIR"/nfsrahead_*_called.log 2>/dev/null | wc -l | tr -d '\n'
echo " functions called"

# restore
rm -f /etc/systemd/system/systemd-udevd.service.d/zz-repro158.conf
rmdir /etc/systemd/system/systemd-udevd.service.d 2>/dev/null
systemctl daemon-reload && systemctl restart systemd-udevd
"$FV" uninstall /usr/libexec/nfsrahead >/dev/null
# install/uninstall round-trips the eu-unstrip'd copy back into place, so the
# file no longer matches the RPM; restore it so the host is left as found.
zypper -n install -f nfs-client >/dev/null 2>&1

hr; echo "done — host restored (shims uninstalled, udev drop-in removed)"

---

Proposed fix (implemented + verified)

Three changes; all existing tests pass (one assertion updated, noted below).

1. internal/funkutil/funkutil.go — take main off the blacklist.
main is the one "entry point" that is genuinely user code. For a thin wrapper it is the only function a successful run reaches, and tracing it gives the liveness signal that distinguishes "ran, did nothing instrumented" from "never ran" — the exact ambiguity that produced this issue.

2. cmd/shim_binary/tracer.go — make the fork tracepoint non-fatal.
It only widens the watched set to child processes; losing it costs coverage of forks, not of the process itself. Degrade with a debug log instead of failing the whole tracer.

3. cmd/shim_binary/main.go — fail open, never closed.
If the tracer cannot attach, warn on stderr and exec the real binary anyway. Losing a run's coverage is acceptable; replacing the user's program with a failing stub is not.

--- a/internal/funkutil/funkutil.go
+++ b/internal/funkutil/funkutil.go
-var funcBlacklist = []string{"main", "_init", "_start", ".plt.got", ".plt", "_dl_relocate_static_pie"}
+var funcBlacklist = []string{"_init", "_start", ".plt.got", ".plt", "_dl_relocate_static_pie"}

--- a/cmd/shim_binary/tracer.go
+++ b/cmd/shim_binary/tracer.go
-	fl, err := link.Tracepoint("sched", "sched_process_fork", t.objs.TraceFork, nil)
-	if err != nil {
-		return fmt.Errorf("tracer: attach fork tracepoint: %w", err)
+	if fl, err := link.Tracepoint("sched", "sched_process_fork", t.objs.TraceFork, nil); err != nil {
+		debugLog("funkoverage-shim: fork tracepoint unavailable (%v); not tracing child processes", err)
+	} else {
+		t.addLink(fl)
 	}
-	t.addLink(fl)

--- a/cmd/shim_binary/main.go
+++ b/cmd/shim_binary/main.go
 	reply, err := io.ReadAll(readyR)
 	if err != nil {
-		return fmt.Errorf("read helper status: %w", err)
-	}
-	if msg := string(reply); msg != "OK" {
-		return fmt.Errorf("helper: %s", strings.TrimPrefix(msg, "ERR:"))
+		fmt.Fprintf(os.Stderr, "funkoverage-shim: read helper status: %v; running untraced\n", err)
+	} else if msg := string(reply); msg != "OK" {
+		fmt.Fprintf(os.Stderr, "funkoverage-shim: tracing unavailable (%s); running untraced\n",
+			strings.TrimPrefix(msg, "ERR:"))
 	}

internal/funkutil/funkutil_test.go needs its {"main", false} case flipped to {"main", true}; the rest of the suite is unchanged and green.

Measured before/after on the VM

case	before	after
lp -d nonexistent file (normal run)	0/1 → 0%	1/2 → 50% (main called)
nfsrahead via udev	0/16 → 0%, and the binary never ran	10/16 → 62.5%, binary runs normally

Still worth deciding separately

• Even with main traced, lp tops out at 50% and its real logic (779 functions in libcups2) is only counted if the run is not --no-libs. A per-image row of 1/2 is honest but thin — an install-time warning like "only 2 traceable functions; most logic is in libcups2" would set expectations.

[ilmanzo]

Upstream sources for the traced binaries

Adding the source references behind the Part A analysis. I diffed each openSUSE
debugsource file against the matching upstream release tag — all six are
byte-identical, so every line number below is exact for the binaries that
actually shipped in the job.

$ diff /usr/src/debug/cups-2.4.19/systemv/lp.c  <upstream v2.4.19 systemv/lp.c>
  -> identical   (same for cancel.c, lpoptions.c, lpstat.c, lpadmin.c)
$ diff /usr/src/debug/nfs-utils-2.9.2/tools/nfsrahead/main.c  <upstream nfs-utils-2-9-2>
  -> identical

cups-client → OpenPrinting/cups @ v2.4.19 (cups-client-2.4.19-2.3)

binary	source	functions defined	usage()
lp	systemv/lp.c	main L33, restart_job L657, set_job_attrs L703, usage L753	L753, 17 call sites
cancel	systemv/cancel.c	main L31, usage L401	L401, 4 call sites
lpoptions	systemv/lpoptions.c	main L34, list_group L385, list_options L481, usage L533	L533, 9 call sites
lpstat	systemv/lpstat.c	11, incl. show_jobs L1304, show_printers L1545	L2085
lpadmin	systemv/lpadmin.c	11, incl. validate_name L1565	L1513

Every one of lp's 17 usage() call sites is --help or an argument-parse error, and usage() is _CUPS_NORETURN — it prints and exits. There is no path through a successful lp run that reaches it.

nfs-client → nfs-utils @ nfs-utils-2-9-2 (nfs-client-2.9.2-54.1)

tools/nfsrahead/main.c — 7 functions: fill_device_number L32, init_device_info L62, free_device_info L71, get_mountinfo L78, get_device_info L121, conf_get_readahead L182, main L191.

Note nfsrahead enumerates 15 traceable functions, more than this file defines, because nfs-utils statically links its support/ tree into the binary — the conf_* and xlog_* symbols come from support/nfs/conffile.c and support/nfs/xlog.c. So this binary has plenty to measure — cause B (the udev seccomp abort) is the only reason it reported nothing.

What the optimiser removes

Source function count is not the traceable count. GCC inlines the single-call-site statics, and main is then dropped by funcBlacklist:

binary	defined in source	survive as .symtab symbols	traceable (after main blacklisted)	reported 0%?
lp	4	main, usage	1	✅
cancel	2	main, usage	1	✅
lpoptions	4	main, list_group, usage	2	✅
lpadmin	11	4 (7 inlined away)	3	❌
lpstat	11	11 (none inlined)	10	❌

restart_job/set_job_attrs (lp) and list_options (lpoptions) are simply absent from the symbol table — confirmed with nm on the debug files, e.g. for lp:

$ nm /usr/lib/debug/usr/bin/lp.debug | grep -E ' (T|t) '
00000000000037b0 t deregister_tm_clones
0000000000003820 t __do_global_dtors_aux
0000000000003a28 T _fini
0000000000003860 t frame_dummy
0000000000002000 T _init
00000000000024e0 T main
00000000000037e0 t register_tm_clones
0000000000003780 T _start
0000000000003870 t usage

Everything there except main and usage is CRT glue (_start/_init/_fini are blacklisted; the *_tm_clones/frame_dummy/__do_global_dtors_aux stubs are dropped for st_size == 0 or the __ prefix). That is how a 790-line source file ends up with a single traceable function whose only caller is the error path.

[ilmanzo]

Status after #159

#159 is merged (77eaecf). Splitting the two causes, because only one of them was a bug:

Cause B — nfsrahead — fixed

The shim no longer aborts when the tracer can't attach. The sched_process_fork tracepoint is non-fatal, and runWithTracing fails open and execs the real binary regardless. Under udev's unmodified seccomp filter, nfsrahead went from 0/16 and never executing to 10/16 with the binary running normally. This also removes the collateral damage — NFS readahead tuning no longer silently breaks while a shim is installed, and the same applies to any shimmed binary invoked from a sandboxed unit.

Cause A — lp / cancel / lpoptions — working as intended, not fixed

main stays on funcBlacklist (maintainer decision). These binaries therefore keep reporting 0%, and that number is arithmetically correct: after inlining, their entire traceable set is usage(), which only a --help or an argument error reaches.

So the openQA job will still show 0% for these three. Nothing in the tool will change that.

Suggested follow-up on the openQA side

Given the above, lp, cancel and lpoptions are not meaningful coverage targets — there is nothing to measure in them. Their real logic lives in libcups2 (779 functions), which is already covered whenever any cups-client binary is traced without --no-libs.

Dropping them from coverage_targets in cups_rpcbind_coverage.yaml would remove three permanently-0% rows from the report without losing any actual coverage signal:

cups-client:
  - /sbin/lpadmin      # 3 traceable functions
  - /usr/bin/lpq
  - /usr/bin/lpstat    # 10 traceable functions
  # lp, cancel, lpoptions: 1-2 traceable functions each, all error paths

lpstat (10) and lpadmin (3) are worth keeping — and notably neither was ever reported as 0%.

A generic guard on the tool side would be an install-time warning when a binary yields fewer than N traceable functions, so this is visible at instrumentation time rather than as a confusing report number weeks later. Happy to open that as a separate issue if it's wanted — it does not belong in this one.

---

Leaving this open since cause A is still user-visible and the coverage_targets decision is unresolved. Close it whenever you're happy that the remaining half is a config question rather than a tool bug.