anchore / anchore/go-make

Debug stack trace affects unit output in syft

Open
#101 0 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
Go
Stars
0
Forks
3
Avg merge
6m
Merged PRs (30d)
4

Description

When specifying `DEBUG=1` I see confusing output mixed in with unit test output in syft:

```
DEBUG=1 make unit

[refresh-fixtures] $ /Users/wagoodman/code/syft/.tool/binny --version
[refresh-fixtures] $ /Users/wagoodman/code/syft/.tool/binny -c /var/folders/c0/4y79v5k56bz8v34chcmvq2k80000gp/T/binny-config2746726818/default.yaml install task
[refresh-fixtures] $ /Users/wagoodman/code/syft/.tool/task refresh-fixtures
[unit] $ /Users/wagoodman/.local/share/mise/installs/go/1.26.2/bin/go list ./...
[unit] $ /Users/wagoodman/.local/share/mise/installs/go/1.26.2/bin/go test github.com/anchore/syft/cmd/syft github.com/anchore/syft/cmd/syft/cli ...SNIP... -coverprofile /var/folders/c0/4y79v5k56bz8v34chcmvq2k80000gp/T/cover-dir-2404711076/cover.out -covermode=atomic -coverpkg=./... -tags=coverage
github.com/anchore/syft/cmd/syft coverage: 0.0% of statements
github.com/anchore/syft/cmd/syft/cli coverage: 0.0% of statements
...
ok github.com/anchore/syft/syft/pkg/cataloger/cpp 1.127s coverage: 3.4% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/dart 3.663s coverage: 3.2% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/debian 2.959s coverage: 5.7% of statements in ./...
[unit] stack trace:
[unit] goroutine profile: total 5
1 @ 0x1049bf5cc 0x1049fb854 0x104caf464 0x104caf290 0x104caca94 0x104cbfd30 0x104a044f4
# 0x104caf463 runtime/pprof.writeRuntimeProfile+0xb3 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/pprof/pprof.go:851
# 0x104caf28f runtime/pprof.writeGoroutine+0x4f /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/pprof/pprof.go:784
# 0x104caca93 runtime/pprof.(*Profile).WriteTo+0x143 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/pprof/pprof.go:408
# 0x104cbfd2f github.com/anchore/go-make/run.PeriodicStackTraces.func1+0xcf /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/run/stack_trace.go:18

1 @ 0x1049c3c20 0x1049fef28 0x104caa78c 0x104a044f4
# 0x1049fef27 os/signal.signal_recv+0x107 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/sigqueue.go:149
# 0x104caa78b os/signal.loop+0x1b /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/signal/signal_unix.go:23

1 @ 0x1049fca4c 0x1049923c0 0x104991f14 0x104cbfb0c 0x104a044f4
# 0x104cbfb0b github.com/anchore/go-make/run.HandleSignals.func1+0x2b /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/run/signal.go:17

1 @ 0x1049fca4c 0x1049dcc8c 0x104ae8da4 0x104a044f4
# 0x104ae8da3 os/exec.(*Cmd).watchCtx+0x73 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec/exec.go:797

1 @ 0x104a00850 0x104a4a268 0x104a477cc 0x104a45448 0x104a6dc3c 0x104a6dc25 0x104a6dbf1 0x104a6db64 0x104ae9128 0x104ae911d 0x104ae82d8 0x104cbe998 0x104cc86a0 0x104ce0264 0x104ce00d0 0x104cc9e20 0x104cc97cc 0x104cc9408 0x104cc8d00 0x104ce4fa4 0x1049c9334 0x104a044f4
# 0x104a0084f syscall.syscalln+0x1f /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/sys_darwin.go:38
# 0x104a4a267 syscall.syscall6+0x27 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/syscall/syscall_darwin.go:388
# 0x104a477cb syscall.wait4+0x4b /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/syscall/zsyscall_darwin_arm64.go:44
# 0x104a45447 syscall.Wait4+0x27 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/syscall/syscall_bsd.go:144
# 0x104a6dc3b os.(*Process).pidWait.func1+0x9b /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec_unix.go:64
# 0x104a6dc24 os.ignoringEINTR2[...]+0x84 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/file_posix.go:266
# 0x104a6dbf0 os.(*Process).pidWait+0x50 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec_unix.go:63
# 0x104a6db63 os.(*Process).wait+0x23 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec_unix.go:28
# 0x104ae9127 os.(*Process).Wait+0x37 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec.go:346
# 0x104ae911c os/exec.(*Cmd).Wait+0x2c /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec/exec.go:930
# 0x104ae82d7 os/exec.(*Cmd).Run+0x37 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/os/exec/exec.go:632
# 0x104cbe997 github.com/anchore/go-make/run.Command+0x857 /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/run/run.go:109
# 0x104cc869f github.com/anchore/go-make.Run+0x1af /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/run.go:39
# 0x104ce0263 github.com/anchore/go-make/tasks/gotest.runTests+0x173 /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks/gotest/test.go:63
# 0x104ce00cf github.com/anchore/go-make/tasks/gotest.Tasks.func1+0x1f /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks/gotest/test.go:52
# 0x104cc9e1f github.com/anchore/go-make.(*taskRunner).runTask+0x5ef /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks.go:244
# 0x104cc97cb github.com/anchore/go-make.(*taskRunner).Run+0xbb /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks.go:214
# 0x104cc9407 github.com/anchore/go-make.runTaskFile+0x6a7 /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks.go:188
# 0x104cc8cff github.com/anchore/go-make.Makefile+0xbf /Users/wagoodman/code/worktrees/go-make/arid-oasis/go-make/tasks.go:108
# 0x104ce4fa3 main.main+0x2803 /Users/wagoodman/code/syft/.make/main.go:27
# 0x1049c9333 runtime.main+0x2b3 /Users/wagoodman/.local/share/mise/installs/go/1.26.2/src/runtime/proc.go:290

ok github.com/anchore/syft/syft/pkg/cataloger/dotnet 6.498s coverage: 6.9% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/elixir 4.620s coverage: 2.9% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/erlang 4.918s coverage: 3.5% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/generic (cached) coverage: 0.6% of statements in ./...
ok github.com/anchore/syft/syft/pkg/cataloger/gentoo 5.469s coverage: 3.6% of statements in ./...
...
ok github.com/anchore/syft/syft/source/stereoscopesource (cached) coverage: 0.4% of statements in ./...
github.com/anchore/syft/syft/testutil coverage: 0.0% of statements
[unit] Done running unit tests in 36.005224875s
[unit] $ /Users/wagoodman/.local/share/mise/installs/go/1.26.2/bin/go tool cover -func /var/folders/c0/4y79v5k56bz8v34chcmvq2k80000gp/T/cover-dir-2404711076/cover.out
[unit] Coverage: 72.8%
```

I think what's happening is when `DEBUG=1` is set, go-make spawns a goroutine that periodically dumps all goroutine stack traces on a backoff schedule. It's intended as a hang-diagnostic... if a task ever wedges, you get periodic dumps showing where it's stuck. So since unit tests are running long enough we're seeing the first 30 second hand detection hit.

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with run/stack_trace.go and the run.Command path shown in the trace, then reproduce the behavior with DEBUG=1 during a long task such as the unit test command. Check how periodic diagnostic output is routed and determine a way to prevent it from disrupting normal test output while preserving hang diagnostics.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
tooling
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Quiet
Clarity
Needs clarification
Newbie friendliness
42/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.