peertracker package logging (#2469)

Signed-off-by: amoore877 <andrew.s.moore@uber.com>

pkg/common/peertracker/listener.go

@@ -11,7 +11,7 @@ var _ net.Listener = &Listener{}
 
 type ListenerFactory struct {
 	Log             logrus.FieldLogger
-	NewTracker      func() (PeerTracker, error)
+	NewTracker      func(log logrus.FieldLogger) (PeerTracker, error)
 	NewUnixListener func(network string, laddr *net.UnixAddr) (*net.UnixListener, error)
 }
 
@@ -46,7 +46,7 @@ func (lf *ListenerFactory) listenUnix(network string, laddr *net.UnixAddr) (*Lis
 		return nil, err
 	}
 
-	tracker, err := lf.NewTracker()
+	tracker, err := lf.NewTracker(lf.Log)
 	if err != nil {
 		l.Close()
 		return nil, err

pkg/common/peertracker/listener_test.go

@@ -23,7 +23,7 @@ func (failingMockTracker) NewWatcher(CallerInfo) (Watcher, error) {
 	return nil, errMockWatcherFailed
 }
 
-func newFailingMockTracker() (PeerTracker, error) {
+func newFailingMockTracker(_ logrus.FieldLogger) (PeerTracker, error) {
 	return failingMockTracker{}, nil
 }
 

pkg/common/peertracker/peertracker.go

@@ -17,6 +17,10 @@
 // reused.
 package peertracker
 
+import (
+	"github.com/sirupsen/logrus"
+)
+
 type PeerTracker interface {
 	Close()
 	NewWatcher(CallerInfo) (Watcher, error)
@@ -30,6 +34,6 @@ type Watcher interface {
 
 // NewTracker creates a new platform-specific peer tracker. Close() must
 // be called when done to release associated resources.
-func NewTracker() (PeerTracker, error) {
-	return newTracker()
+func NewTracker(log logrus.FieldLogger) (PeerTracker, error) {
+	return newTracker(log)
 }

pkg/common/peertracker/peertracker_test.go

@@ -11,6 +11,8 @@ import (
 	"syscall"
 	"testing"
 
+	"github.com/sirupsen/logrus"
+	logtest "github.com/sirupsen/logrus/hooks/test"
 	"github.com/spiffe/spire/test/spiretest"
 	"github.com/stretchr/testify/suite"
 )
@@ -25,6 +27,7 @@ type PeerTrackerTestSuite struct {
 	childPath string
 	ul        *Listener
 	unixAddr  *net.UnixAddr
+	logHook   *logtest.Hook
 }
 
 func (p *PeerTrackerTestSuite) SetupTest() {
@@ -42,7 +45,10 @@ func (p *PeerTrackerTestSuite) SetupTest() {
 		Name: path.Join(tempDir, "test.sock"),
 	}
 
-	p.ul, err = (&ListenerFactory{}).ListenUnix(p.unixAddr.Network(), p.unixAddr)
+	log, hook := logtest.NewNullLogger()
+	p.logHook = hook
+
+	p.ul, err = (&ListenerFactory{Log: log}).ListenUnix(p.unixAddr.Network(), p.unixAddr)
 	p.NoError(err)
 }
 
@@ -135,8 +141,23 @@ func (p *PeerTrackerTestSuite) TestExitDetection() {
 	switch runtime.GOOS {
 	case "darwin":
 		p.EqualError(conn.Info.Watcher.IsAlive(), "caller exit detected via kevent notification")
+		p.Require().Len(p.logHook.Entries, 2)
+		firstEntry := p.logHook.Entries[0]
+		p.Require().Equal(logrus.WarnLevel, firstEntry.Level)
+		p.Require().Equal("Caller is no longer being watched", firstEntry.Message)
+		secondEntry := p.logHook.Entries[1]
+		p.Require().Equal(logrus.WarnLevel, secondEntry.Level)
+		p.Require().Equal("Caller exit detected via kevent notification", secondEntry.Message)
 	case "linux":
-		p.EqualError(conn.Info.Watcher.IsAlive(), "caller exit suspected due to failed readdirent: err=no such file or directory")
+		p.EqualError(conn.Info.Watcher.IsAlive(), "caller exit suspected due to failed readdirent")
+		p.Require().Len(p.logHook.Entries, 2)
+		firstEntry := p.logHook.Entries[0]
+		p.Require().Equal(logrus.WarnLevel, firstEntry.Level)
+		p.Require().Equal("Caller is no longer being watched", firstEntry.Message)
+		secondEntry := p.logHook.Entries[1]
+		p.Require().Equal(logrus.WarnLevel, secondEntry.Level)
+		p.Require().Equal("Caller exit suspected due to failed readdirent", secondEntry.Message)
+		p.Require().Equal(syscall.ENOENT, secondEntry.Data["error"])
 	default:
 		p.FailNow("missing case for OS specific failure")
 	}

pkg/common/peertracker/tracker_bsd.go

@@ -9,6 +9,13 @@ import (
 	"sync"
 	"syscall"
 	"time"
+
+	"github.com/sirupsen/logrus"
+	"github.com/spiffe/spire/pkg/common/telemetry"
+)
+
+const (
+	bsdType = "bsd"
 )
 
 var (
@@ -21,9 +28,10 @@ type bsdTracker struct {
 	kqfd        int
 	mtx         sync.Mutex
 	watchedPIDs map[int]chan struct{}
+	log         logrus.FieldLogger
 }
 
-func newTracker() (*bsdTracker, error) {
+func newTracker(log logrus.FieldLogger) (*bsdTracker, error) {
 	kqfd, err := syscall.Kqueue()
 	if err != nil {
 		return nil, err
@@ -35,6 +43,7 @@ func newTracker() (*bsdTracker, error) {
 		ctx:         ctx,
 		kqfd:        kqfd,
 		watchedPIDs: make(map[int]chan struct{}),
+		log:         log.WithField(telemetry.Type, bsdType),
 	}
 
 	go tracker.receiveKevents(kqfd)
@@ -78,8 +87,9 @@ func (b *bsdTracker) NewWatcher(info CallerInfo) (Watcher, error) {
 		done = make(chan struct{})
 		b.watchedPIDs[pid] = done
 	}
+	log := b.log.WithField(telemetry.PID, pid)
 
-	return newBSDWatcher(info, done), nil
+	return newBSDWatcher(info, done, log), nil
 }
 
 func (b *bsdTracker) addKeventForWatcher(pid int) error {
@@ -152,12 +162,14 @@ type bsdWatcher struct {
 	done   <-chan struct{}
 	mtx    sync.Mutex
 	pid    int32
+	log    logrus.FieldLogger
 }
 
-func newBSDWatcher(info CallerInfo, done <-chan struct{}) *bsdWatcher {
+func newBSDWatcher(info CallerInfo, done <-chan struct{}, log logrus.FieldLogger) *bsdWatcher {
 	return &bsdWatcher{
 		done: done,
 		pid:  info.PID,
+		log:  log,
 	}
 }
 
@@ -177,6 +189,7 @@ func (b *bsdWatcher) IsAlive() error {
 	b.mtx.Lock()
 	if b.closed {
 		b.mtx.Unlock()
+		b.log.Warn("Caller is no longer being watched")
 		return errors.New("caller is no longer being watched")
 	}
 	b.mtx.Unlock()
@@ -195,6 +208,7 @@ func (b *bsdWatcher) IsAlive() error {
 
 	select {
 	case <-b.done:
+		b.log.Warn("Caller exit detected via kevent notification")
 		return errors.New("caller exit detected via kevent notification")
 	default:
 		return nil

pkg/common/peertracker/tracker_fallback.go

@@ -6,6 +6,10 @@
 
 package peertracker
 
-func newTracker() (PeerTracker, error) {
+import (
+	"github.com/sirupsen/logrus"
+)
+
+func newTracker(log logrus.FieldLogger) (PeerTracker, error) {
 	return nil, ErrUnsupportedPlatform
 }

pkg/common/peertracker/tracker_linux.go

@@ -9,19 +9,30 @@ import (
 	"strings"
 	"sync"
 	"syscall"
+
+	"github.com/sirupsen/logrus"
+	"github.com/spiffe/spire/pkg/common/telemetry"
+)
+
+const (
+	linuxType = "linux"
 )
 
-type linuxTracker struct{}
+type linuxTracker struct {
+	log logrus.FieldLogger
+}
 
-func newTracker() (linuxTracker, error) {
-	return linuxTracker{}, nil
+func newTracker(log logrus.FieldLogger) (*linuxTracker, error) {
+	return &linuxTracker{
+		log: log.WithField(telemetry.Type, linuxType),
+	}, nil
 }
 
-func (linuxTracker) NewWatcher(info CallerInfo) (Watcher, error) {
-	return newLinuxWatcher(info)
+func (l *linuxTracker) NewWatcher(info CallerInfo) (Watcher, error) {
+	return newLinuxWatcher(info, l.log)
 }
 
-func (linuxTracker) Close() {
+func (*linuxTracker) Close() {
 }
 
 type linuxWatcher struct {
@@ -32,9 +43,10 @@ type linuxWatcher struct {
 	procfd    int
 	starttime string
 	uid       uint32
+	log       logrus.FieldLogger
 }
 
-func newLinuxWatcher(info CallerInfo) (*linuxWatcher, error) {
+func newLinuxWatcher(info CallerInfo, log logrus.FieldLogger) (*linuxWatcher, error) {
 	// If PID == 0, something is wrong...
 	if info.PID == 0 {
 		return nil, errors.New("could not resolve caller information")
@@ -54,13 +66,22 @@ func newLinuxWatcher(info CallerInfo) (*linuxWatcher, error) {
 		return nil, err
 	}
 
+	log = log.WithFields(logrus.Fields{
+		telemetry.CallerGID: info.GID,
+		telemetry.PID:       info.PID,
+		telemetry.Path:      procPath,
+		telemetry.CallerUID: info.UID,
+		telemetry.StartTime: starttime,
+	})
+
 	return &linuxWatcher{
 		gid:       info.GID,
 		pid:       info.PID,
 		procPath:  procPath,
 		procfd:    procfd,
 		starttime: starttime,
 		uid:       info.UID,
+		log:       log,
 	}, nil
 }
 
@@ -81,6 +102,7 @@ func (l *linuxWatcher) IsAlive() error {
 	defer l.mtx.Unlock()
 
 	if l.procfd < 0 {
+		l.log.Warn("Caller is no longer being watched")
 		return errors.New("caller is no longer being watched")
 	}
 
@@ -90,9 +112,11 @@ func (l *linuxWatcher) IsAlive() error {
 	var buf [8196]byte
 	n, err := syscall.ReadDirent(l.procfd, buf[:])
 	if err != nil {
-		return fmt.Errorf("caller exit suspected due to failed readdirent: err=%w", err)
+		l.log.WithError(err).Warn("Caller exit suspected due to failed readdirent")
+		return errors.New("caller exit suspected due to failed readdirent")
 	}
 	if n < 0 {
+		l.log.WithField(telemetry.StatusCode, n).Warn("Caller exit suspected due to failed readdirent")
 		return fmt.Errorf("caller exit suspected due to failed readdirent: n=%d", n)
 	}
 
@@ -106,10 +130,15 @@ func (l *linuxWatcher) IsAlive() error {
 	// TODO: Evaluate the use of `starttime` as the primary exit detection mechanism.
 	currentStarttime, err := getStarttime(l.pid)
 	if err != nil {
+		l.log.WithError(err).Warn("Caller exit suspected due to failure to get starttime")
 		return fmt.Errorf("caller exit suspected due to failure to get starttime: %w", err)
 	}
 	if currentStarttime != l.starttime {
-		return errors.New("new process detected: starttime mismatch")
+		l.log.WithFields(logrus.Fields{
+			telemetry.ExpectStartTime:   l.starttime,
+			telemetry.ReceivedStartTime: currentStarttime,
+		}).Warn("New process detected: process starttime does not match original caller")
+		return fmt.Errorf("new process detected: process starttime %v does not match original caller %v", currentStarttime, l.starttime)
 	}
 
 	// Finally, read the UID and GID off the proc directory to determine the owner. If
@@ -118,12 +147,21 @@ func (l *linuxWatcher) IsAlive() error {
 	// the original caller by comparing it to the received CallerInfo.
 	var stat syscall.Stat_t
 	if err := syscall.Stat(l.procPath, &stat); err != nil {
-		return fmt.Errorf("caller exit suspected due to failed proc stat: %w", err)
+		l.log.WithError(err).Warn("Caller exit suspected due to failed proc stat")
+		return errors.New("caller exit suspected due to failed proc stat")
 	}
 	if stat.Uid != l.uid {
+		l.log.WithFields(logrus.Fields{
+			telemetry.ExpectUID:   l.uid,
+			telemetry.ReceivedUID: stat.Uid,
+		}).Warn("New process detected: process uid does not match original caller")
 		return fmt.Errorf("new process detected: process uid %v does not match original caller %v", stat.Uid, l.uid)
 	}
 	if stat.Gid != l.gid {
+		l.log.WithFields(logrus.Fields{
+			telemetry.ExpectGID:   l.gid,
+			telemetry.ReceivedGID: stat.Gid,
+		}).Warn("New process detected: process gid does not match original caller")
 		return fmt.Errorf("new process detected: process gid %v does not match original caller %v", stat.Gid, l.gid)
 	}
 

pkg/common/telemetry/names.go

@@ -213,6 +213,15 @@ const (
 	// what kind of value was expected, and a different field should show the received value
 	Expect = "expect"
 
+	// ExpectGID is like Expect, specific to gid.
+	ExpectGID = "expect_gid"
+
+	// ExpectStartTime is like Expect, specific to a start time.
+	ExpectStartTime = "expect_start_time"
+
+	// ExpectUID is like Expect, specific to uid.
+	ExpectUID = "expect_uid"
+
 	// Expiration tags an expiration time for some entity
 	Expiration = "expiration"
 
@@ -314,6 +323,19 @@ const (
 	// Reason is the reason for something
 	Reason = "reason"
 
+	// Received tags a received value, as opposed to the one that is expected. Message should clarify
+	// what kind of value was received, and a different field should show the expected value.
+	Received = "received"
+
+	// ReceivedGID is like Received, specific to gid.
+	ReceivedGID = "received_gid"
+
+	// ReceivedStartTime is like Received, specific to a start time.
+	ReceivedStartTime = "received_start_time"
+
+	// ReceivedUID is like Received, specific to uid.
+	ReceivedUID = "received_uid"
+
 	// RefreshHint tags a bundle refresh hint
 	RefreshHint = "refresh_hint"
 
@@ -376,6 +398,9 @@ const (
 	// SPIFFEID tags a SPIFFE ID
 	SPIFFEID = "spiffe_id"
 
+	// StartTime tags some start/entry timestamp.
+	StartTime = "start_time"
+
 	// Status tags status of call (OK, or some error), or status of some process
 	Status = "status"