From 4b557dc54cac5f302ea28b4344488bdd60f7bb9e Mon Sep 17 00:00:00 2001 From: Yusuke Kuoka Date: Sat, 19 Feb 2022 09:21:14 +0000 Subject: [PATCH] Add logging transport to log HTTP requests in log level -3 The log level -3 is the minimum log level that is supported today, smaller than debug(-1) and -2(used to log some HRA related logs). This commit adds a logging HTTP transport to log HTTP requests and responses to that log level. It implements http.RoundTripper so that it can log each HTTP request with useful metadata like `from_cache` and `ratelimit_remaining`. The former is set to `true` only when the logged request's response was served from ARC's in-memory cache. The latter is set to X-RateLimit-Remaining response header value if and only if the response was served by GitHub, not by ARC's cache. --- acceptance/values.yaml | 3 +- cmd/githubwebhookserver/main.go | 30 +++--------------- github/github.go | 7 ++++- logging/logger.go | 54 +++++++++++++++++++++++++++++++++ logging/transport.go | 51 +++++++++++++++++++++++++++++++ main.go | 28 +++-------------- 6 files changed, 123 insertions(+), 50 deletions(-) create mode 100644 logging/logger.go create mode 100644 logging/transport.go diff --git a/acceptance/values.yaml b/acceptance/values.yaml index 496589b9..1a86610e 100644 --- a/acceptance/values.yaml +++ b/acceptance/values.yaml @@ -1,7 +1,8 @@ # Set actions-runner-controller settings for testing githubAPICacheDuration: 10s +logLevel: "-3" githubWebhookServer: - logLevel: debug + logLevel: "-3" enabled: true labels: {} replicaCount: 1 diff --git a/cmd/githubwebhookserver/main.go b/cmd/githubwebhookserver/main.go index 436e8b4a..4e3e604b 100644 --- a/cmd/githubwebhookserver/main.go +++ b/cmd/githubwebhookserver/main.go @@ -29,15 +29,14 @@ import ( actionsv1alpha1 "github.com/actions-runner-controller/actions-runner-controller/api/v1alpha1" "github.com/actions-runner-controller/actions-runner-controller/controllers" "github.com/actions-runner-controller/actions-runner-controller/github" + "github.com/actions-runner-controller/actions-runner-controller/logging" "github.com/kelseyhightower/envconfig" - zaplib "go.uber.org/zap" "k8s.io/apimachinery/pkg/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" _ "k8s.io/client-go/plugin/pkg/client/auth/exec" _ "k8s.io/client-go/plugin/pkg/client/auth/gcp" _ "k8s.io/client-go/plugin/pkg/client/auth/oidc" ctrl "sigs.k8s.io/controller-runtime" - "sigs.k8s.io/controller-runtime/pkg/log/zap" // +kubebuilder:scaffold:imports ) @@ -47,11 +46,6 @@ var ( ) const ( - logLevelDebug = "debug" - logLevelInfo = "info" - logLevelWarn = "warn" - logLevelError = "error" - webhookSecretTokenEnvName = "GITHUB_WEBHOOK_SECRET_TOKEN" ) @@ -97,7 +91,7 @@ func main() { flag.BoolVar(&enableLeaderElection, "enable-leader-election", false, "Enable leader election for controller manager. Enabling this will ensure there is only one active controller manager.") flag.DurationVar(&syncPeriod, "sync-period", 10*time.Minute, "Determines the minimum frequency at which K8s resources managed by this controller are reconciled. When you use autoscaling, set to a lower value like 10 minute, because this corresponds to the minimum time to react on demand change") - flag.StringVar(&logLevel, "log-level", logLevelDebug, `The verbosity of the logging. Valid values are "debug", "info", "warn", "error". Defaults to "debug".`) + flag.StringVar(&logLevel, "log-level", logging.LogLevelDebug, `The verbosity of the logging. Valid values are "debug", "info", "warn", "error". Defaults to "debug".`) flag.StringVar(&webhookSecretToken, "github-webhook-secret-token", "", "The personal access token of GitHub.") flag.StringVar(&c.Token, "github-token", c.Token, "The personal access token of GitHub.") flag.Int64Var(&c.AppID, "github-app-id", c.AppID, "The application ID of GitHub App.") @@ -126,23 +120,7 @@ func main() { setupLog.Info("-watch-namespace is %q. Only HorizontalRunnerAutoscalers in %q are watched, cached, and considered as scale targets.") } - logger := zap.New(func(o *zap.Options) { - switch logLevel { - case logLevelDebug: - o.Development = true - lvl := zaplib.NewAtomicLevelAt(-2) // maps to logr's V(2) - o.Level = &lvl - case logLevelInfo: - lvl := zaplib.NewAtomicLevelAt(zaplib.InfoLevel) - o.Level = &lvl - case logLevelWarn: - lvl := zaplib.NewAtomicLevelAt(zaplib.WarnLevel) - o.Level = &lvl - case logLevelError: - lvl := zaplib.NewAtomicLevelAt(zaplib.ErrorLevel) - o.Level = &lvl - } - }) + logger := logging.NewLogger(logLevel) ctrl.SetLogger(logger) @@ -152,6 +130,8 @@ func main() { // That is, all runner groups managed by ARC are assumed to be visible to any repositories, // which is wrong when you have one or more non-default runner groups in your organization or enterprise. if len(c.Token) > 0 || (c.AppID > 0 && c.AppInstallationID > 0 && c.AppPrivateKey != "") || (len(c.BasicauthUsername) > 0 && len(c.BasicauthPassword) > 0) { + c.Log = &logger + ghClient, err = c.NewClient() if err != nil { fmt.Fprintln(os.Stderr, "Error: Client creation failed.", err) diff --git a/github/github.go b/github/github.go index 146130d9..d8d0acf6 100644 --- a/github/github.go +++ b/github/github.go @@ -11,7 +11,9 @@ import ( "time" "github.com/actions-runner-controller/actions-runner-controller/github/metrics" + "github.com/actions-runner-controller/actions-runner-controller/logging" "github.com/bradleyfalzon/ghinstallation" + "github.com/go-logr/logr" "github.com/google/go-github/v39/github" "github.com/gregjones/httpcache" "golang.org/x/oauth2" @@ -29,6 +31,8 @@ type Config struct { BasicauthUsername string `split_words:"true"` BasicauthPassword string `split_words:"true"` RunnerGitHubURL string `split_words:"true"` + + Log *logr.Logger } // Client wraps GitHub client with some additional @@ -85,7 +89,8 @@ func (c *Config) NewClient() (*Client, error) { cached := httpcache.NewTransport(httpcache.NewMemoryCache()) cached.Transport = transport - metricsTransport := metrics.Transport{Transport: cached} + loggingTransport := logging.Transport{Transport: cached, Log: c.Log} + metricsTransport := metrics.Transport{Transport: loggingTransport} httpClient := &http.Client{Transport: metricsTransport} var client *github.Client diff --git a/logging/logger.go b/logging/logger.go new file mode 100644 index 00000000..463726b9 --- /dev/null +++ b/logging/logger.go @@ -0,0 +1,54 @@ +package logging + +import ( + "fmt" + "os" + "strconv" + + "github.com/go-logr/logr" + zaplib "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "sigs.k8s.io/controller-runtime/pkg/log/zap" +) + +const ( + LogLevelDebug = "debug" + LogLevelInfo = "info" + LogLevelWarn = "warn" + LogLevelError = "error" +) + +func NewLogger(logLevel string) logr.Logger { + log := zap.New(func(o *zap.Options) { + switch logLevel { + case LogLevelDebug: + o.Development = true + lvl := zaplib.NewAtomicLevelAt(zaplib.DebugLevel) // maps to logr's V(1) + o.Level = &lvl + case LogLevelInfo: + lvl := zaplib.NewAtomicLevelAt(zaplib.InfoLevel) + o.Level = &lvl + case LogLevelWarn: + lvl := zaplib.NewAtomicLevelAt(zaplib.WarnLevel) + o.Level = &lvl + case LogLevelError: + lvl := zaplib.NewAtomicLevelAt(zaplib.ErrorLevel) + o.Level = &lvl + default: + // We use bitsize of 8 as zapcore.Level is a type alias to int8 + levelInt, err := strconv.ParseInt(logLevel, 10, 8) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to parse --log-level=%s: %v", logLevel, err) + os.Exit(1) + } + + // For example, --log-level=debug a.k.a --log-level=-1 maps to zaplib.DebugLevel, which is associated to logr's V(1) + // --log-level=-2 maps the specific custom log level that is associated to logr's V(2). + level := zapcore.Level(levelInt) + atomicLevel := zaplib.NewAtomicLevelAt(level) + o.Level = &atomicLevel + } + }) + + return log +} diff --git a/logging/transport.go b/logging/transport.go new file mode 100644 index 00000000..9d61a318 --- /dev/null +++ b/logging/transport.go @@ -0,0 +1,51 @@ +// Package logging provides various logging helpers for ARC +package logging + +import ( + "net/http" + + "github.com/go-logr/logr" + "github.com/gregjones/httpcache" +) + +const ( + // https://docs.github.com/en/rest/overview/resources-in-the-rest-api#rate-limiting + headerRateLimitRemaining = "X-RateLimit-Remaining" +) + +// Transport wraps a transport with metrics monitoring +type Transport struct { + Transport http.RoundTripper + + Log *logr.Logger +} + +func (t Transport) RoundTrip(req *http.Request) (*http.Response, error) { + resp, err := t.Transport.RoundTrip(req) + if resp != nil { + t.log(req, resp) + } + return resp, err +} + +func (t Transport) log(req *http.Request, resp *http.Response) { + if t.Log == nil { + return + } + + var args []interface{} + + marked := resp.Header.Get(httpcache.XFromCache) == "1" + + args = append(args, "from_cache", marked, "method", req.Method, "url", req.URL.String()) + + if !marked { + // Do not log outdated rate limit remaining value + + remaining := resp.Header.Get(headerRateLimitRemaining) + + args = append(args, "ratelimit_remaining", remaining) + } + + t.Log.V(3).Info("Seen HTTP response", args...) +} diff --git a/main.go b/main.go index 43c55961..7383fc5f 100644 --- a/main.go +++ b/main.go @@ -26,24 +26,18 @@ import ( actionsv1alpha1 "github.com/actions-runner-controller/actions-runner-controller/api/v1alpha1" "github.com/actions-runner-controller/actions-runner-controller/controllers" "github.com/actions-runner-controller/actions-runner-controller/github" + "github.com/actions-runner-controller/actions-runner-controller/logging" "github.com/kelseyhightower/envconfig" - zaplib "go.uber.org/zap" "k8s.io/apimachinery/pkg/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" _ "k8s.io/client-go/plugin/pkg/client/auth/gcp" ctrl "sigs.k8s.io/controller-runtime" - "sigs.k8s.io/controller-runtime/pkg/log/zap" // +kubebuilder:scaffold:imports ) const ( defaultRunnerImage = "summerwind/actions-runner:latest" defaultDockerImage = "docker:dind" - - logLevelDebug = "debug" - logLevelInfo = "info" - logLevelWarn = "warn" - logLevelError = "error" ) var ( @@ -120,24 +114,12 @@ func main() { flag.DurationVar(&syncPeriod, "sync-period", 10*time.Minute, "Determines the minimum frequency at which K8s resources managed by this controller are reconciled. When you use autoscaling, set to a lower value like 10 minute, because this corresponds to the minimum time to react on demand change. . If you're tweaking this in order to make autoscaling more responsive, you'll probably want to tweak github-api-cache-duration, too") flag.Var(&commonRunnerLabels, "common-runner-labels", "Runner labels in the K1=V1,K2=V2,... format that are inherited all the runners created by the controller. See https://github.com/actions-runner-controller/actions-runner-controller/issues/321 for more information") flag.StringVar(&namespace, "watch-namespace", "", "The namespace to watch for custom resources. Set to empty for letting it watch for all namespaces.") - flag.StringVar(&logLevel, "log-level", logLevelDebug, `The verbosity of the logging. Valid values are "debug", "info", "warn", "error". Defaults to "debug".`) + flag.StringVar(&logLevel, "log-level", logging.LogLevelDebug, `The verbosity of the logging. Valid values are "debug", "info", "warn", "error". Defaults to "debug".`) flag.Parse() - logger := zap.New(func(o *zap.Options) { - switch logLevel { - case logLevelDebug: - o.Development = true - case logLevelInfo: - lvl := zaplib.NewAtomicLevelAt(zaplib.InfoLevel) - o.Level = &lvl - case logLevelWarn: - lvl := zaplib.NewAtomicLevelAt(zaplib.WarnLevel) - o.Level = &lvl - case logLevelError: - lvl := zaplib.NewAtomicLevelAt(zaplib.ErrorLevel) - o.Level = &lvl - } - }) + logger := logging.NewLogger(logLevel) + + c.Log = &logger ghClient, err = c.NewClient() if err != nil {