From 10f26eb7a2aabc383d3793aa4ddd95d86ec0c1fd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakob=20M=C3=B6ller?= Date: Thu, 21 Nov 2024 10:32:32 +0100 Subject: [PATCH] feat(log): log http requests for OCI and docker based on trace level by injecting a logger (#1118) #### 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 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 ``` --- .../extensions/repositories/docker/client.go | 14 +++- .../extensions/repositories/docker/logging.go | 5 ++ .../repositories/docker/repository.go | 6 +- .../extensions/repositories/docker/type.go | 7 +- .../extensions/repositories/ocireg/logging.go | 4 +- .../repositories/ocireg/repository.go | 11 +++- api/utils/logging/roundtripper.go | 36 ++++++++++ api/utils/logging/roundtripper_test.go | 65 +++++++++++++++++++ docs/reference/ocm_logging.md | 1 + 9 files changed, 140 insertions(+), 9 deletions(-) create mode 100644 api/oci/extensions/repositories/docker/logging.go create mode 100644 api/utils/logging/roundtripper.go create mode 100644 api/utils/logging/roundtripper_test.go diff --git a/api/oci/extensions/repositories/docker/client.go b/api/oci/extensions/repositories/docker/client.go index 6d66be26c..064613aee 100644 --- a/api/oci/extensions/repositories/docker/client.go +++ b/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 } diff --git a/api/oci/extensions/repositories/docker/logging.go b/api/oci/extensions/repositories/docker/logging.go new file mode 100644 index 000000000..154d91934 --- /dev/null +++ b/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") diff --git a/api/oci/extensions/repositories/docker/repository.go b/api/oci/extensions/repositories/docker/repository.go index 52836d19b..9f8035104 100644 --- a/api/oci/extensions/repositories/docker/repository.go +++ b/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 } diff --git a/api/oci/extensions/repositories/docker/type.go b/api/oci/extensions/repositories/docker/type.go index adcf5fa05..8fd2ade17 100644 --- a/api/oci/extensions/repositories/docker/type.go +++ b/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 } diff --git a/api/oci/extensions/repositories/ocireg/logging.go b/api/oci/extensions/repositories/ocireg/logging.go index 9e78b02c7..1c8904b00 100644 --- a/api/oci/extensions/repositories/ocireg/logging.go +++ b/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") diff --git a/api/oci/extensions/repositories/ocireg/repository.go b/api/oci/extensions/repositories/ocireg/repository.go index 1bae127a7..bff1e5107 100644 --- a/api/oci/extensions/repositories/ocireg/repository.go +++ b/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) diff --git a/api/utils/logging/roundtripper.go b/api/utils/logging/roundtripper.go new file mode 100644 index 000000000..99a3dadd4 --- /dev/null +++ b/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) +} diff --git a/api/utils/logging/roundtripper_test.go b/api/utils/logging/roundtripper_test.go new file mode 100644 index 000000000..a7bdbf8a7 --- /dev/null +++ b/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")) + }) +}) diff --git a/docs/reference/ocm_logging.md b/docs/reference/ocm_logging.md index 7d48096c9..9a1c45800 100644 --- a/docs/reference/ocm_logging.md +++ b/docs/reference/ocm_logging.md @@ -29,6 +29,7 @@ The following *realms* are used by the command line tool: - ocm/downloader: Downloaders - ocm/maven: Maven repository - ocm/npm: NPM registry + - ocm/oci/docker: Docker repository handling - ocm/oci/mapping: OCM to OCI Registry Mapping - ocm/oci/ocireg: OCI repository handling - ocm/plugins: OCM plugin handling