Log plugin RPC operations and connections

.golangci.yml

@@ -8,6 +8,5 @@ linters:
     - gofmt
     - gosec
     - gocritic
-    - deadcode
     - misspell
     - revive

drivers/fakedriver/fakedriver.go

@@ -19,7 +19,7 @@ func (d *Driver) DriverName() string {
 	return "Driver"
 }
 
-func (d *Driver) UpdateConfigRaw(rawData []byte) error {
+func (d *Driver) UpdateConfigRaw(_ []byte) error {
 	return nil
 }
 

libmachine/drivers/base.go

@@ -75,7 +75,7 @@ func (d *BaseDriver) GetBundleName() (string, error) {
 	return d.BundleName, nil
 }
 
-func (d *BaseDriver) UpdateConfigRaw(rawData []byte) error {
+func (d *BaseDriver) UpdateConfigRaw(_ []byte) error {
 	return ErrNotImplemented
 }
 

libmachine/drivers/plugin/register_driver.go

@@ -19,6 +19,32 @@ var (
 	heartbeatTimeout = 10 * time.Second
 )
 
+type loggingListener struct {
+	net.Listener
+}
+
+func (l *loggingListener) Accept() (net.Conn, error) {
+	conn, err := l.Listener.Accept()
+	if err != nil {
+		return nil, err
+	}
+	log.WithField("remote", conn.RemoteAddr().String()).Info("RPC connection accepted")
+	return &loggingConn{Conn: conn, start: time.Now()}, nil
+}
+
+type loggingConn struct {
+	net.Conn
+	start time.Time
+}
+
+func (c *loggingConn) Close() error {
+	log.WithFields(log.Fields{
+		"remote":   c.RemoteAddr().String(),
+		"duration": time.Since(c.start),
+	}).Info("RPC connection closed")
+	return c.Conn.Close()
+}
+
 func RegisterDriver(d drivers.Driver) {
 	if os.Getenv(localbinary.PluginEnvKey) != localbinary.PluginEnvVal {
 		fmt.Fprintf(os.Stderr, `This is a hypervisor plugin binary for CodeReady Containers.
@@ -51,7 +77,8 @@ Please use this plugin through the main 'crc' binary.
 	fmt.Println(listener.Addr())
 
 	go func() {
-		_ = http.Serve(listener, nil)
+		//nolint:gosec // localhost-only rpc server
+		_ = http.Serve(&loggingListener{Listener: listener}, nil)
 	}()
 
 	for {

libmachine/drivers/rpc/server_driver.go

@@ -8,6 +8,7 @@ import (
 	"github.com/crc-org/machine/libmachine/drivers"
 	"github.com/crc-org/machine/libmachine/state"
 	"github.com/crc-org/machine/libmachine/version"
+	log "github.com/sirupsen/logrus"
 )
 
 type Stacker interface {
@@ -38,12 +39,30 @@ func NewRPCServerDriver(d drivers.Driver) *RPCServerDriver {
 	}
 }
 
+func (r *RPCServerDriver) logRPC(op string, level log.Level, extra log.Fields) {
+	fields := log.Fields{"operation": op}
+	if r.ActualDriver != nil {
+		func() {
+			defer func() { _ = recover() }()
+			if name := r.ActualDriver.GetMachineName(); name != "" {
+				fields["machine"] = name
+			}
+		}()
+	}
+	for k, v := range extra {
+		fields[k] = v
+	}
+	log.WithFields(fields).Log(level, "RPC server invocation")
+}
+
 func (r *RPCServerDriver) Close(_, _ *struct{}) error {
+	r.logRPC("Close", log.InfoLevel, nil)
 	r.CloseCh <- true
 	return nil
 }
 
 func (r *RPCServerDriver) GetVersion(_ *struct{}, reply *int) error {
+	r.logRPC("GetVersion", log.DebugLevel, nil)
 	*reply = version.APIVersion
 	return nil
 }
@@ -55,15 +74,18 @@ func (r *RPCServerDriver) GetConfigRaw(_ *struct{}, reply *[]byte) error {
 	}
 
 	*reply = driverData
+	r.logRPC("GetConfigRaw", log.DebugLevel, log.Fields{"config_bytes": len(driverData)})
 
 	return nil
 }
 
 func (r *RPCServerDriver) UpdateConfigRaw(data []byte, _ *struct{}) error {
+	r.logRPC("UpdateConfigRaw", log.WarnLevel, log.Fields{"config_bytes": len(data)})
 	return r.ActualDriver.UpdateConfigRaw(data)
 }
 
 func (r *RPCServerDriver) SetConfigRaw(data []byte, _ *struct{}) error {
+	r.logRPC("SetConfigRaw", log.WarnLevel, log.Fields{"config_bytes": len(data)})
 	return json.Unmarshal(data, &r.ActualDriver)
 }
 
@@ -74,6 +96,7 @@ func trapPanic(err *error) {
 }
 
 func (r *RPCServerDriver) Create(_, _ *struct{}) (err error) {
+	r.logRPC("Create", log.WarnLevel, nil)
 	// In an ideal world, plugins wouldn't ever panic.  However, panics
 	// have been known to happen and cause issues.  Therefore, we recover
 	// and do not crash the RPC server completely in the case of a panic
@@ -86,50 +109,60 @@ func (r *RPCServerDriver) Create(_, _ *struct{}) (err error) {
 }
 
 func (r *RPCServerDriver) DriverName(_ *struct{}, reply *string) error {
+	r.logRPC("DriverName", log.DebugLevel, nil)
 	*reply = r.ActualDriver.DriverName()
 	return nil
 }
 
 func (r *RPCServerDriver) GetIP(_ *struct{}, reply *string) error {
+	r.logRPC("GetIP", log.DebugLevel, nil)
 	ip, err := r.ActualDriver.GetIP()
 	*reply = ip
 	return err
 }
 
 func (r *RPCServerDriver) GetMachineName(_ *struct{}, reply *string) error {
+	r.logRPC("GetMachineName", log.DebugLevel, nil)
 	*reply = r.ActualDriver.GetMachineName()
 	return nil
 }
 
 func (r *RPCServerDriver) GetBundleName(_ *struct{}, reply *string) error {
+	r.logRPC("GetBundleName", log.DebugLevel, nil)
 	path, err := r.ActualDriver.GetBundleName()
 	*reply = path
 	return err
 }
 
 func (r *RPCServerDriver) GetState(_ *struct{}, reply *state.State) error {
+	r.logRPC("GetState", log.DebugLevel, nil)
 	s, err := r.ActualDriver.GetState()
 	*reply = s
 	return err
 }
 
 func (r *RPCServerDriver) Kill(_ *struct{}, _ *struct{}) error {
+	r.logRPC("Kill", log.WarnLevel, nil)
 	return r.ActualDriver.Kill()
 }
 
 func (r *RPCServerDriver) PreCreateCheck(_ *struct{}, _ *struct{}) error {
+	r.logRPC("PreCreateCheck", log.InfoLevel, nil)
 	return r.ActualDriver.PreCreateCheck()
 }
 
 func (r *RPCServerDriver) Remove(_ *struct{}, _ *struct{}) error {
+	r.logRPC("Remove", log.WarnLevel, nil)
 	return r.ActualDriver.Remove()
 }
 
 func (r *RPCServerDriver) Start(_ *struct{}, _ *struct{}) error {
+	r.logRPC("Start", log.InfoLevel, nil)
 	return r.ActualDriver.Start()
 }
 
 func (r *RPCServerDriver) Stop(_ *struct{}, _ *struct{}) error {
+	r.logRPC("Stop", log.InfoLevel, nil)
 	return r.ActualDriver.Stop()
 }
 
@@ -141,5 +174,8 @@ func (r *RPCServerDriver) Heartbeat(_ *struct{}, _ *struct{}) error {
 func (r *RPCServerDriver) GetSharedDirs(_ *struct{}, reply *[]drivers.SharedDir) error {
 	sharedDirs, err := r.ActualDriver.GetSharedDirs()
 	*reply = sharedDirs
+	if err == nil {
+		r.logRPC("GetSharedDirs", log.DebugLevel, log.Fields{"shared_dirs": len(sharedDirs)})
+	}
 	return err
 }