From 8ee9dbe8c3ee4df1e0030588240f7c51dd57435f Mon Sep 17 00:00:00 2001 From: Mike Tonks Date: Wed, 25 Sep 2024 17:17:44 +0100 Subject: [PATCH 1/3] chore: add debug for time chaos --- controllers/utils/chaosdaemon/chaosdaemon.go | 8 ++++++++ pkg/time/fake_image_linux.go | 8 ++++++++ pkg/time/time_skew_linux.go | 3 +++ 3 files changed, 19 insertions(+) diff --git a/controllers/utils/chaosdaemon/chaosdaemon.go b/controllers/utils/chaosdaemon/chaosdaemon.go index 955590b451..e1cec9afd7 100644 --- a/controllers/utils/chaosdaemon/chaosdaemon.go +++ b/controllers/utils/chaosdaemon/chaosdaemon.go @@ -17,6 +17,7 @@ package chaosdaemon import ( "context" + "encoding/json" "github.com/pkg/errors" "go.uber.org/fx" @@ -34,6 +35,8 @@ 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 { @@ -45,6 +48,11 @@ func findIPOnEndpoints(e *v1.Endpoints, nodeName string) string { return "" } +func jsonDump(i interface{}) string { + s, _ := json.Marshal(i) + return string(s) +} + type ChaosDaemonClientBuilder struct { client.Reader } diff --git a/pkg/time/fake_image_linux.go b/pkg/time/fake_image_linux.go index 83380bd5bc..4b40eb25f5 100644 --- a/pkg/time/fake_image_linux.go +++ b/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 { diff --git a/pkg/time/time_skew_linux.go b/pkg/time/time_skew_linux.go index 187dba6553..37f881c5d1 100644 --- a/pkg/time/time_skew_linux.go +++ b/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 } From 2cb85d55b1b3b74c181d8c4df978b49d8f6909bb Mon Sep 17 00:00:00 2001 From: Mike Tonks Date: Wed, 25 Sep 2024 17:30:38 +0100 Subject: [PATCH 2/3] chore: add debug for time chaos --- controllers/utils/chaosdaemon/chaosdaemon.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/controllers/utils/chaosdaemon/chaosdaemon.go b/controllers/utils/chaosdaemon/chaosdaemon.go index e1cec9afd7..0446d93862 100644 --- a/controllers/utils/chaosdaemon/chaosdaemon.go +++ b/controllers/utils/chaosdaemon/chaosdaemon.go @@ -18,6 +18,7 @@ package chaosdaemon import ( "context" "encoding/json" + "fmt" "github.com/pkg/errors" "go.uber.org/fx" @@ -42,6 +43,11 @@ func findIPOnEndpoints(e *v1.Endpoints, nodeName string) string { 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)) + } } } From bf5364adbefda4357c07aef41e58040937bb76ac Mon Sep 17 00:00:00 2001 From: Mike Tonks Date: Wed, 25 Sep 2024 17:39:45 +0100 Subject: [PATCH 3/3] chore: adds grpc server interceptor --- pkg/chaosdaemon/server.go | 40 +++++++++++++++++++++++++++++++-------- pkg/grpc/utils.go | 35 +++++++++++++++++++++++++++------- 2 files changed, 60 insertions(+), 15 deletions(-) diff --git a/pkg/chaosdaemon/server.go b/pkg/chaosdaemon/server.go index feefc1bda4..de9e08ccda 100755 --- a/pkg/chaosdaemon/server.go +++ b/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") } diff --git a/pkg/grpc/utils.go b/pkg/grpc/utils.go index fa7b5cbc51..d5b9006d9d 100644 --- a/pkg/grpc/utils.go +++ b/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) + } +}