chore: add debug for time chaos

controllers/utils/chaosdaemon/chaosdaemon.go

@@ -17,6 +17,8 @@ package chaosdaemon
 
 import (
 	"context"
+	"encoding/json"
+	"fmt"
 
 	"github.com/pkg/errors"
 	"go.uber.org/fx"
@@ -34,17 +36,29 @@ import (
 var log = ctrl.Log.WithName("controller-chaos-daemon-client-utils")
 
 func findIPOnEndpoints(e *v1.Endpoints, nodeName string) string {
+	log.Info("findIPOnEndpoints: %s", nodeName)
+	log.Info("endpoints: %s", jsonDump(e))
 	for _, subset := range e.Subsets {
 		for _, addr := range subset.Addresses {
 			if addr.NodeName != nil && *addr.NodeName == nodeName {
 				return addr.IP
 			}
+			if addr.NodeName == nil {
+				log.Info("Not Matched: addr.NodeName is nil")
+			} else {
+				log.Info(fmt.Sprintf("Not Matched: addr.NodeName %s", addr.NodeName))
+			}
 		}
 	}
 
 	return ""
 }
 
+func jsonDump(i interface{}) string {
+	s, _ := json.Marshal(i)
+	return string(s)
+}
+
 type ChaosDaemonClientBuilder struct {
 	client.Reader
 }

pkg/chaosdaemon/server.go

@@ -93,7 +93,11 @@ func (s *DaemonServer) getLoggerFromContext(ctx context.Context) logr.Logger {
 	return log.EnrichLoggerWithContext(ctx, s.rootLogger)
 }
 
-func newDaemonServer(clientConfig *crclients.CrClientConfig, reg prometheus.Registerer, log logr.Logger) (*DaemonServer, error) {
+func newDaemonServer(
+	clientConfig *crclients.CrClientConfig,
+	reg prometheus.Registerer,
+	log logr.Logger,
+) (*DaemonServer, error) {
 	crClient, err := crclients.CreateContainerRuntimeInfoClient(clientConfig)
 	if err != nil {
 		return nil, err
@@ -103,7 +107,11 @@ func newDaemonServer(clientConfig *crclients.CrClientConfig, reg prometheus.Regi
 }
 
 // NewDaemonServerWithCRClient returns DaemonServer with container runtime client
-func NewDaemonServerWithCRClient(crClient crclients.ContainerRuntimeInfoClient, reg prometheus.Registerer, log logr.Logger) *DaemonServer {
+func NewDaemonServerWithCRClient(
+	crClient crclients.ContainerRuntimeInfoClient,
+	reg prometheus.Registerer,
+	log logr.Logger,
+) *DaemonServer {
 	return &DaemonServer{
 		IPSetLocker:              locker.New(),
 		crClient:                 crClient,
@@ -112,14 +120,20 @@ func NewDaemonServerWithCRClient(crClient crclients.ContainerRuntimeInfoClient,
 		rootLogger:               log,
 		timeChaosServer: TimeChaosServer{
 			podContainerNameProcessMap: tasks.NewPodProcessMap(),
-			manager:                    tasks.NewTaskManager(logr.New(log.GetSink()).WithName("TimeChaos")),
-			nameLocker:                 tasks.NewLockMap[tasks.PodContainerName](),
-			logger:                     logr.New(log.GetSink()).WithName("TimeChaos"),
+			manager: tasks.NewTaskManager(
+				logr.New(log.GetSink()).WithName("TimeChaos"),
+			),
+			nameLocker: tasks.NewLockMap[tasks.PodContainerName](),
+			logger:     logr.New(log.GetSink()).WithName("TimeChaos"),
 		},
 	}
 }
 
-func newGRPCServer(daemonServer *DaemonServer, reg prometheus.Registerer, tlsConf tlsConfig) (*grpc.Server, error) {
+func newGRPCServer(
+	daemonServer *DaemonServer,
+	reg prometheus.Registerer,
+	tlsConf tlsConfig,
+) (*grpc.Server, error) {
 	grpcMetrics := grpc_prometheus.NewServerMetrics()
 	grpcMetrics.EnableHandlingTimeHistogram(
 		grpc_prometheus.WithHistogramBuckets(metrics.ChaosDaemonGrpcServerBuckets),
@@ -135,6 +149,7 @@ func newGRPCServer(daemonServer *DaemonServer, reg prometheus.Registerer, tlsCon
 			grpcUtils.TimeoutServerInterceptor,
 			grpcMetrics.UnaryServerInterceptor(),
 			MetadataExtractor(log.MetaNamespacedName),
+			grpcUtils.RequestLoggingServerInterceptor(daemonServer.rootLogger),
 		),
 	}
 
@@ -213,7 +228,10 @@ func BuildServer(conf *Config, reg RegisterGatherer, log logr.Logger) (*Server,
 		return nil, errors.Wrap(err, "create daemon server")
 	}
 
-	server.httpServer = newHTTPServerBuilder().Addr(conf.HttpAddr()).Metrics(reg).Profiling(conf.Profiling).Build()
+	server.httpServer = newHTTPServerBuilder().Addr(conf.HttpAddr()).
+		Metrics(reg).
+		Profiling(conf.Profiling).
+		Build()
 	server.grpcServer, err = newGRPCServer(server.daemonServer, reg, conf.tlsConfig)
 	if err != nil {
 		return nil, errors.Wrap(err, "create grpc server")
@@ -241,7 +259,13 @@ func (s *Server) Start() error {
 	})
 
 	eg.Go(func() error {
-		s.logger.Info("Starting grpc endpoint", "address", grpcBindAddr, "runtime", s.conf.CrClientConfig.Runtime)
+		s.logger.Info(
+			"Starting grpc endpoint",
+			"address",
+			grpcBindAddr,
+			"runtime",
+			s.conf.CrClientConfig.Runtime,
+		)
 		if err := s.grpcServer.Serve(grpcListener); err != nil {
 			return errors.Wrap(err, "start grpc endpoint")
 		}

pkg/grpc/utils.go

@@ -24,6 +24,7 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/go-logr/logr"
 	"github.com/pkg/errors"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials"
@@ -61,8 +62,7 @@ type RawProvider struct {
 	raw TLSRaw
 }
 
-type InsecureProvider struct {
-}
+type InsecureProvider struct{}
 
 type CredentialProvider interface {
 	getCredentialOption() (grpc.DialOption, error)
@@ -122,7 +122,10 @@ func Builder(address string, port int) *GrpcBuilder {
 }
 
 func (it *GrpcBuilder) WithDefaultTimeout() *GrpcBuilder {
-	it.options = append(it.options, grpc.WithUnaryInterceptor(TimeoutClientInterceptor(DefaultRPCTimeout)))
+	it.options = append(
+		it.options,
+		grpc.WithUnaryInterceptor(TimeoutClientInterceptor(DefaultRPCTimeout)),
+	)
 	return it
 }
 
@@ -161,7 +164,11 @@ func (it *GrpcBuilder) TLSFromRaw(caCert []byte, cert []byte, key []byte) *GrpcB
 	return it
 }
 
-func (it *GrpcBuilder) TLSFromFile(caCertPath string, certPath string, keyPath string) *GrpcBuilder {
+func (it *GrpcBuilder) TLSFromFile(
+	caCertPath string,
+	certPath string,
+	keyPath string,
+) *GrpcBuilder {
 	it.credentialProvider = &FileProvider{
 		file: TLSFile{
 			CaCert: caCertPath,
@@ -185,10 +192,13 @@ func (it *GrpcBuilder) Build() (*grpc.ClientConn, error) {
 }
 
 // TimeoutClientInterceptor wraps the RPC with a timeout.
-func TimeoutClientInterceptor(timeout time.Duration) func(context.Context, string, interface{}, interface{},
+func TimeoutClientInterceptor(
+	timeout time.Duration,
+) func(context.Context, string, interface{}, interface{},
 	*grpc.ClientConn, grpc.UnaryInvoker, ...grpc.CallOption) error {
 	return func(ctx context.Context, method string, req, reply interface{},
-		cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
+		cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption,
+	) error {
 		ctx, cancel := context.WithTimeout(ctx, timeout)
 		defer cancel()
 		return invoker(ctx, method, req, reply, cc, opts...)
@@ -198,9 +208,20 @@ func TimeoutClientInterceptor(timeout time.Duration) func(context.Context, strin
 // TimeoutServerInterceptor ensures the context is intact before handling over the
 // request to application.
 func TimeoutServerInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo,
-	handler grpc.UnaryHandler) (interface{}, error) {
+	handler grpc.UnaryHandler,
+) (interface{}, error) {
 	if ctx.Err() != nil {
 		return nil, ctx.Err()
 	}
 	return handler(ctx, req)
 }
+
+func RequestLoggingServerInterceptor(logger logr.Logger) grpc.UnaryServerInterceptor {
+	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
+		if ctx.Err() != nil {
+			return nil, ctx.Err()
+		}
+		logger.Info("grpc request", "server", info.Server, "method", info.FullMethod)
+		return handler(ctx, req)
+	}
+}

pkg/time/fake_image_linux.go

@@ -61,39 +61,46 @@ func (it *FakeImage) AttachToProcess(pid int, variables map[string]uint64) (err
 		return errors.New("fake image: extern variable number not match")
 	}
 
+	it.logger.Info("AttachToProcess: before LockOSThread")
 	runtime.LockOSThread()
 	defer func() {
 		runtime.UnlockOSThread()
 	}()
 
+	it.logger.Info("AttachToProcess: before ptrace.Trace")
 	program, err := ptrace.Trace(pid, it.logger.WithName("ptrace").WithValues("pid", pid))
 	if err != nil {
 		return errors.Wrapf(err, "ptrace on target process, pid: %d", pid)
 	}
 	defer func() {
+		it.logger.Info("AttachToProcess: before program.Detach")
 		err = program.Detach()
 		if err != nil {
 			it.logger.Error(err, "fail to detach program", "pid", program.Pid())
 		}
 	}()
 
+	it.logger.Info("AttachToProcess: before FindVDSOEntry")
 	vdsoEntry, err := FindVDSOEntry(program)
 	if err != nil {
 		return errors.Wrapf(err, "PID : %d", pid)
 	}
 
+	it.logger.Info("AttachToProcess: before FindInjectedImage")
 	fakeEntry, err := it.FindInjectedImage(program, len(variables))
 	if err != nil {
 		return errors.Wrapf(err, "PID : %d", pid)
 	}
 	// target process has not been injected yet
 	if fakeEntry == nil {
+		it.logger.Info("AttachToProcess: before InjectFakeImage")
 		fakeEntry, err = it.InjectFakeImage(program, vdsoEntry)
 		if err != nil {
 			return errors.Wrapf(err, "injecting fake image , PID : %d", pid)
 		}
 		defer func() {
 			if err != nil {
+				it.logger.Info("AttachToProcess: before TryReWriteFakeImage")
 				errIn := it.TryReWriteFakeImage(program)
 				if errIn != nil {
 					it.logger.Error(errIn, "rewrite fail, recover fail")
@@ -105,6 +112,7 @@ func (it *FakeImage) AttachToProcess(pid int, variables map[string]uint64) (err
 	}
 
 	for k, v := range variables {
+		it.logger.Info("AttachToProcess: before SetVarUint64, " + k)
 		err = it.SetVarUint64(program, fakeEntry, k, v)
 
 		if err != nil {

pkg/time/time_skew_linux.go

@@ -200,6 +200,7 @@ func (s *Skew) Inject(pid tasks.IsID) error {
 	if err != nil {
 		return err
 	}
+	s.logger.Info("after clockGetTime.AttachToProcess")
 
 	err = s.getTimeOfDay.AttachToProcess(int(sysPID), map[string]uint64{
 		externVarTvSecDelta:  uint64(s.SkewConfig.deltaSeconds),
@@ -208,6 +209,8 @@ func (s *Skew) Inject(pid tasks.IsID) error {
 	if err != nil {
 		return err
 	}
+	s.logger.Info("after getTimeOfDay.AttachToProcess")
+
 	return nil
 }