On Mac, lsof outputs a warning to stderr, causing a failure "missing txt data returned by lsof"

[djs55]

Describe the bug

A call to process.Exe() on MacOS with CGO disabled is failing with "missing txt data returned by lsof"

When I run /usr/sbin/lsof -p 60232 -Fpfn (mirroring what

gopsutil/process/process_darwin_nocgo.go

Line 19 in 987c949

out, err := invoke.CommandWithContext(ctx, lsof_bin, "-p", strconv.Itoa(int(p.Pid)), "-Fpfn")

does) I observe there is a warning on stderr:

lsof: WARNING: can't stat() apfs file system /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/David’s MacBook Pro (2)/2020-05-11-105950/Macintosh HD - Data
      Output information may be incomplete.
      assuming "dev=310002df" from mount table

The CommandWithContext function includes stderr as well as stdout:

gopsutil/internal/common/common.go

Line 51 in 987c949

cmd.Stderr = &buf

which breaks the parsing of the command output. It's "fixed" if I comment-out the line which captures stderr. I would have made a PR but this seems like common code used everywhere, so I don't know what the best policy would be: always ignore stderr globally or make another CommandWithContextStdout or add parameters or something else.

To Reproduce
This requires:

1. the extra warning on stderr (probably triggered by an in-progress time machine backup)
2. CGO_ENABLED=0

package main

import(
	"fmt"
	"github.com/shirou/gopsutil/process"
)

func main() {
	processes, err := process.Processes()
	if err != nil {
		panic(err)
	}
	for _, p := range processes {
		name, err := p.Name()
		if err != nil {
			panic(err)
		}
		if name != "bash" {
			// find a normal user process
			continue
		}
		exePath, err := p.Exe()
		if err != nil {
			panic(err)
		}
		fmt.Println(exePath)
	}
}

Expected behavior

$ CGO_ENABLED=0 go run main.go
/bin/bash
/bin/bash
/bin/bash
/bin/bash

Actual behavior

$ CGO_ENABLED=0 go run main.go
panic: missing txt data returned by lsof

goroutine 1 [running]:
main.main()
/Users/djs/go/src/gops/main.go:24 +0x1c2
exit status 2

(Note it works fine with cgo)

Environment (please complete the following information):

• Windows: [paste the result of ver]
• Linux: [paste contents of /etc/os-release and the result of uname -a]
• Mac OS: [paste the result of sw_vers and uname -a
• FreeBSD: [paste the result of freebsd-version -k -r -u and uname -a]
• OpenBSD: [paste the result of uname -a]

Davids-MacBook-Pro:gops djs$ sw_vers
ProductName:	Mac OS X
ProductVersion:	10.15.4
BuildVersion:	19E287
Davids-MacBook-Pro:gops djs$ uname -a
Darwin Davids-MacBook-Pro.local 19.4.0 Darwin Kernel Version 19.4.0: Wed Mar  4 22:28:40 PST 2020; root:xnu-6153.101.6~15/RELEASE_X86_64 x86_64

Additional context
No cross-compiling, but CGO is disabled.

[Lomanic]

Thanks for this great bug report.

We could suppress lsof warnings with -w (this line would be out, err := invoke.CommandWithContext(ctx, lsof_bin, "-w", "-p", strconv.Itoa(int(p.Pid)), "-Fpfn")), but I'm not convinced this is a proper fix.

There is also some information in this Unix.SE QA, can you confirm the warning goes away with lsof -e "/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/David’s MacBook Pro (2)/2020-05-11-105950/Macintosh HD - Data" -p 60232 -Fpfn? I might be able to reproduce on my hackintosh VM using a FUSE mounting point.

Can you show what's inside the buf variable by printing the content of out before this line?

[djs55]

Aha, it is manifesting for me right now. To answer your questions:

1. Adding -w i.e.

diff --git a/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go b/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
index 86466fde54..a99902f04a 100644
--- a/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
+++ b/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
@@ -16,7 +16,7 @@ func (p *Process) ExeWithContext(ctx context.Context) (string, error) {
        if err != nil {
                return "", err
        }
-       out, err := invoke.CommandWithContext(ctx, lsof_bin, "-p", strconv.Itoa(int(p.Pid)), "-Fpfn")
+       out, err := invoke.CommandWithContext(ctx, lsof_bin, "-w", "-p", strconv.Itoa(int(p.Pid)), "-Fpfn")
        if err != nil {
                return "", fmt.Errorf("bad call to lsof: %s", err)
        }

gives me the expected output (no panic(err)):

Davids-MacBook-Pro:lsof djs$  CGO_ENABLED=0 go run main.go
/bin/bash
/bin/bash
/bin/bash
/bin/bash
/bin/bash
/bin/bash

2. Unfortunately the -e argument seems not to work, even though it's mentioned in man lsof:

Davids-MacBook-Pro:lsof djs$ lsof -e "/Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/David’s MacBook Pro (2)/2020-05-20-110602/Macintosh HD - Data" -p 51343 -Fpfn
lsof: illegal option character: e
lsof 4.91
 latest revision: ftp://lsof.itap.purdue.edu/pub/tools/unix/lsof/
 latest FAQ: ftp://lsof.itap.purdue.edu/pub/tools/unix/lsof/FAQ
 latest man page: ftp://lsof.itap.purdue.edu/pub/tools/unix/lsof/lsof_man
 usage: [-?abhlnNoOPRtUvVX] [+|-c c] [+|-d s] [+D D] [+|-f[cgG]]
 [-F [f]] [-g [s]] [-i [i]] [+|-L [l]] [+|-M] [-o [o]] [-p s]
 [+|-r [t]] [-s [p:s]] [-S [t]] [-T [t]] [-u s] [+|-w] [-x [fl]] [--] [names]
Use the ``-h'' option to get more help information.

3. Adding

diff --git a/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go b/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
index 86466fde54..5478fa3821 100644
--- a/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
+++ b/vendor/github.com/shirou/gopsutil/process/process_darwin_nocgo.go
@@ -17,6 +17,7 @@ func (p *Process) ExeWithContext(ctx context.Context) (string, error) {
                return "", err
        }
        out, err := invoke.CommandWithContext(ctx, lsof_bin, "-p", strconv.Itoa(int(p.Pid)), "-Fpfn")
+       fmt.Println(string(out))
        if err != nil {
                return "", fmt.Errorf("bad call to lsof: %s", err)
        }

gives me

$  CGO_ENABLED=0 go run main.go
lsof: WARNING: can't stat() apfs file system /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/David’s MacBook Pro (2)/2020-05-20-110602/Macintosh HD - Data
      Output information may be incomplete.
      assuming "dev=3100042f" from mount table
p1997
fcwd
n/
ftxt
n/bin/bash
ftxt
n/usr/lib/dyld
f0
n/dev/null
f1
n/Users/djs/Library/Logs/shutdown-gpg-agent.log
f2
n/Users/djs/Library/Logs/shutdown-gpg-agent.log
f255
n/usr/local/MacGPG2/libexec/shutdown-gpg-agent

panic: missing txt data returned by lsof

goroutine 1 [running]:
main.main()
	/Users/djs/djs55/pinata/tools/cmd/lsof/main.go:24 +0x1c2
exit status 2

Hope that helps! Sorry for the delay getting back to you. By the time I saw your reply my repro had disappeared, presumably because the backup had finished. I tried triggering another backup but I couldn't reproduce the issue. It's started happening again just now so I thought I'd jump on it.

[Lomanic]

In fact, I can reproduce on Linux, with numerous lsof: WARNING: can't stat() overlay file system /var/lib/docker/overlay2/[long_hash]/XXX, I have two fixes, iterating on each line instead of on each odd line (i++ instead of i += 2), or the -w argument.

I will push a PR with the first idea, I don't want to swallow warnings (in case of errors).

Thanks for your last message, appreciated.

[djs55]

Thanks for the fix!