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

@@ -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

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) {
+	logger := logging.NewLogger(logLevel)
-		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
-		}
-	})
 
 	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)

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

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
+}

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...)
+}

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) {
+	logger := logging.NewLogger(logLevel)
-		switch logLevel {
+
-		case logLevelDebug:
+	c.Log = &logger
-			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
-		}
-	})
 
 	ghClient, err = c.NewClient()
 	if err != nil {