feat(log): log http requests for OCI and docker based on trace level …

…by injecting a logger (#1118)

<!-- markdownlint-disable MD041 -->
#### What this PR does / why we need it

it is now possible to inject a trace attribute to OCMs logging
architecture to allow tracing back HTTP calls for oci registries and the
docker client:

```
ocm --logkeys /+ocm/oci=trace [YOUR COMMAND INTERACTING WITH OCI HERE]
```

Note that this does not take care of all access types yet because we
dont have a unified http.Client.

Note that it is now also possible to pass `/+ocm/docker=trace` to enable
logging for the docker client infrastructure, or set `--loglevel=trace`
to get a full tracelog with HTTP statements.

Authorization Headers are redacted

#### Which issue(s) this PR fixes
<!--
Usage: `Fixes #<issue number>`, or `Fixes (paste link of issue)`.
-->

This allows introspecting HTTP calls for debugging purposes, e.g.

```
bin/ocm --logkeys /+ocm/oci=trace transfer artifact CommonTransportFormat::XXX/ocm/gen/ctf//component-descriptors/ocm.software/ocmcli ghcr.io/jakobmoellerdev/ocm:latest
copying CommonTransportFormat::XXX/ocm/gen/ctf//component-descriptors/ocm.software/ocmcli:0.17.0-dev to ghcr.io/jakobmoellerdev/ocm:latest...
 2024-11-20T19:09:14+01:00 trace   [ocm/oci/ocireg] roundtrip header="{\"Accept\":[\"application/vnd.ocm.software.component.config.v1+json, */*\"],\"User-Agent\":[\"containerd/1.7.23+unknown\"]}" host=ghcr.io method=HEAD namespace=jakobmoellerdev/ocm url=https://ghcr.io/v2/jakobmoellerdev/ocm/blobs/sha256:0351859d79ce5900e610226ed03ab0fb5586f4f19b26693487bf13fac1ce6923
 2024-11-20T19:09:14+01:00 trace   [ocm/oci/ocireg] "query credentials" host=ghcr.io namespace=jakobmoellerdev/ocm pass="***" user=jakobmoellerdev
```

api/oci/extensions/repositories/docker/client.go

@@ -9,10 +9,13 @@ import (
 	"github.com/docker/cli/cli/config"
 	cliflags "github.com/docker/cli/cli/flags"
 	dockerclient "github.com/docker/docker/client"
+	mlog "github.com/mandelsoft/logging"
 	"github.com/spf13/pflag"
+
+	"ocm.software/ocm/api/utils/logging"
 )
 
-func newDockerClient(dockerhost string) (*dockerclient.Client, error) {
+func newDockerClient(dockerhost string, logger mlog.UnboundLogger) (*dockerclient.Client, error) {
 	if dockerhost == "" {
 		opts := cliflags.NewClientOptions()
 		// set defaults
@@ -30,7 +33,14 @@ func newDockerClient(dockerhost string) (*dockerclient.Client, error) {
 	}
 	url, err := dockerclient.ParseHostURL(dockerhost)
 	if err == nil && url.Scheme == "unix" {
-		dockerclient.WithScheme(url.Scheme)(c)
+		if err := dockerclient.WithScheme(url.Scheme)(c); err != nil {
+			return nil, err
+		}
+	}
+	clnt := c.HTTPClient()
+	clnt.Transport = logging.NewRoundTripper(clnt.Transport, logger)
+	if err := dockerclient.WithHTTPClient(clnt)(c); err != nil {
+		return nil, err
 	}
 	return c, nil
 }

api/oci/extensions/repositories/docker/logging.go

@@ -0,0 +1,5 @@
+package docker
+
+import ocmlog "ocm.software/ocm/api/utils/logging"
+
+var REALM = ocmlog.DefineSubRealm("Docker repository handling", "oci", "docker")

api/oci/extensions/repositories/docker/repository.go

@@ -6,8 +6,10 @@ import (
 	"github.com/containers/image/v5/types"
 	dockertypes "github.com/docker/docker/api/types/image"
 	"github.com/docker/docker/client"
+	"github.com/mandelsoft/logging"
 
 	"ocm.software/ocm/api/oci/cpi"
+	ocmlog "ocm.software/ocm/api/utils/logging"
 )
 
 type RepositoryImpl struct {
@@ -20,7 +22,9 @@ type RepositoryImpl struct {
 var _ cpi.RepositoryImpl = (*RepositoryImpl)(nil)
 
 func NewRepository(ctx cpi.Context, spec *RepositorySpec) (cpi.Repository, error) {
-	client, err := newDockerClient(spec.DockerHost)
+	urs := spec.UniformRepositorySpec()
+	logger := logging.DynamicLogger(ctx, REALM, logging.NewAttribute(ocmlog.ATTR_HOST, urs.Host))
+	client, err := newDockerClient(spec.DockerHost, logger)
 	if err != nil {
 		return nil, err
 	}

api/oci/extensions/repositories/docker/type.go

@@ -3,9 +3,12 @@ package docker
 import (
 	"context"
 
+	"github.com/mandelsoft/logging"
+
 	"ocm.software/ocm/api/credentials"
 	"ocm.software/ocm/api/oci/cpi"
 	"ocm.software/ocm/api/utils"
+	ocmlog "ocm.software/ocm/api/utils/logging"
 	"ocm.software/ocm/api/utils/runtime"
 )
 
@@ -50,7 +53,9 @@ func (a *RepositorySpec) Repository(ctx cpi.Context, creds credentials.Credentia
 }
 
 func (a *RepositorySpec) Validate(ctx cpi.Context, creds credentials.Credentials, usageContext ...credentials.UsageContext) error {
-	client, err := newDockerClient(a.DockerHost)
+	urs := a.UniformRepositorySpec()
+	logger := logging.DynamicLogger(ctx, REALM, logging.NewAttribute(ocmlog.ATTR_HOST, urs.Host))
+	client, err := newDockerClient(a.DockerHost, logger)
 	if err != nil {
 		return err
 	}

api/oci/extensions/repositories/ocireg/logging.go

@@ -1,7 +1,5 @@
 package ocireg
 
-import (
-	ocmlog "ocm.software/ocm/api/utils/logging"
-)
+import ocmlog "ocm.software/ocm/api/utils/logging"
 
 var REALM = ocmlog.DefineSubRealm("OCI repository handling", "oci", "ocireg")

api/oci/extensions/repositories/ocireg/repository.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"crypto/tls"
 	"crypto/x509"
+	"net/http"
 	"path"
 	"strings"
 
@@ -58,12 +59,13 @@ var (
 
 func NewRepository(ctx cpi.Context, spec *RepositorySpec, info *RepositoryInfo) (cpi.Repository, error) {
 	urs := spec.UniformRepositorySpec()
+	logger := logging.DynamicLogger(ctx, REALM, logging.NewAttribute(ocmlog.ATTR_HOST, urs.Host))
 	if urs.Scheme == "http" {
-		ocmlog.Logger(REALM).Warn("using insecure http for oci registry {{host}}", "host", urs.Host)
+		logger.Warn("using insecure http for oci registry {{host}}", "host", urs.Host)
 	}
 	i := &RepositoryImpl{
 		RepositoryImplBase: cpi.NewRepositoryImplBase(ctx),
-		logger:             logging.DynamicLogger(ctx, REALM, logging.NewAttribute(ocmlog.ATTR_HOST, urs.Host)),
+		logger:             logger,
 		spec:               spec,
 		info:               info,
 	}
@@ -126,6 +128,11 @@ func (r *RepositoryImpl) getResolver(comp string) (resolve.Resolver, error) {
 
 	opts := docker.ResolverOptions{
 		Hosts: docker.ConvertHosts(config.ConfigureHosts(context.Background(), config.HostOptions{
+			UpdateClient: func(client *http.Client) error {
+				// copy from http.DefaultTransport with a roundtripper injection
+				client.Transport = ocmlog.NewRoundTripper(client.Transport, logger)
+				return nil
+			},
 			Credentials: func(host string) (string, string, error) {
 				if creds != nil {
 					p := creds.GetProperty(credentials.ATTR_IDENTITY_TOKEN)

api/utils/logging/roundtripper.go

@@ -0,0 +1,36 @@
+package logging
+
+import (
+	"net/http"
+
+	"github.com/mandelsoft/logging"
+)
+
+func NewRoundTripper(rt http.RoundTripper, logger logging.Logger) *RoundTripper {
+	return &RoundTripper{
+		logger:       logger,
+		RoundTripper: rt,
+	}
+}
+
+// RoundTripper is a http.RoundTripper that logs requests.
+type RoundTripper struct {
+	logger logging.Logger
+	http.RoundTripper
+}
+
+func (t *RoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	// Redact the Authorization header to make sure it doesn't get logged at any point.
+	header := req.Header
+	if key := "Authorization"; req.Header.Get(key) != "" {
+		header = header.Clone()
+		header.Set(key, "***")
+	}
+
+	t.logger.Trace("roundtrip",
+		"url", req.URL,
+		"method", req.Method,
+		"header", header,
+	)
+	return t.RoundTripper.RoundTrip(req)
+}

api/utils/logging/roundtripper_test.go

@@ -0,0 +1,65 @@
+package logging_test
+
+import (
+	"bytes"
+	"net/http"
+	"net/http/httptest"
+
+	logcfg "github.com/mandelsoft/logging/config"
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+	"github.com/tonglil/buflogr"
+
+	"github.com/mandelsoft/logging"
+
+	local "ocm.software/ocm/api/utils/logging"
+)
+
+var _ = Describe("RoundTripper", func() {
+	var buf bytes.Buffer
+	var ctx *local.StaticContext
+	var roundTripper http.RoundTripper
+	var server *httptest.Server
+
+	BeforeEach(func() {
+		buf.Reset()
+		local.SetContext(logging.NewDefault())
+		ctx = local.Context()
+		ctx.SetBaseLogger(buflogr.NewWithBuffer(&buf))
+	})
+
+	AfterEach(func() {
+		if server != nil {
+			server.Close()
+		}
+	})
+
+	It("redacts Authorization header", func() {
+		r := logcfg.ConditionalRule("trace")
+		cfg := &logcfg.Config{
+			Rules: []logcfg.Rule{r},
+		}
+		Expect(ctx.Configure(cfg)).To(Succeed())
+
+		server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		}))
+
+		roundTripper = local.NewRoundTripper(http.DefaultTransport, ctx.Logger())
+		client := &http.Client{Transport: roundTripper}
+
+		req, err := http.NewRequest("GET", server.URL, nil)
+		Expect(err).NotTo(HaveOccurred())
+		req.Header.Set("Authorization", "this should be redacted")
+
+		_, err = client.Do(req)
+		Expect(err).NotTo(HaveOccurred())
+
+		Expect(buf.String()).To(ContainSubstring("roundtrip"))
+		Expect(buf.String()).To(ContainSubstring("url"))
+		Expect(buf.String()).To(ContainSubstring("method"))
+		Expect(buf.String()).To(ContainSubstring("header"))
+		Expect(buf.String()).To(ContainSubstring("***"))
+		Expect(buf.String()).NotTo(ContainSubstring("this should be redacted"))
+	})
+})

docs/reference/ocm_logging.md

@@ -29,6 +29,7 @@ The following *realms* are used by the command line tool:
   - <code>ocm/downloader</code>: Downloaders
   - <code>ocm/maven</code>: Maven repository
   - <code>ocm/npm</code>: NPM registry
+  - <code>ocm/oci/docker</code>: Docker repository handling
   - <code>ocm/oci/mapping</code>: OCM to OCI Registry Mapping
   - <code>ocm/oci/ocireg</code>: OCI repository handling
   - <code>ocm/plugins</code>: OCM plugin handling