3pp-mirror/pomerium
1
0
Fork 0
mirror of https://github.com/pomerium/pomerium.git synced 2025-05-11 08:07:38 +02:00
Code Issues Projects Releases Packages Wiki Activity

logging: remove ctx from global log methods (#5337)

Browse source 
* log: remove warn

* log: update debug

* log: update info

* remove level, log

* remove contextLogger function
This commit is contained in:
Caleb Doxsey 2024-10-23 14:18:52 -06:00 • committed by GitHub
parent 1ccaf1b22b
commit d2c14cd6d2
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
53 changed files with 150 additions and 198 deletions
Download patch file Download diff file Expand all files Collapse all files

4
authorize/evaluator/evaluator.go
View file

@ -192,7 +192,7 @@ func getOrCreatePolicyEvaluators(
m[p.id] = p.evaluator
}
log.Debug(ctx).
log.Ctx(ctx).Debug().
Dur("duration", time.Since(now)).
Int("reused-policies", reusedCount).
Int("created-policies", len(cfg.Policies)-reusedCount).
@ -361,7 +361,7 @@ func getJWK(cfg *evaluatorConfig) (*jose.JSONWebKey, error) {
if err != nil {
return nil, fmt.Errorf("couldn't generate signing key: %w", err)
}
log.Info(context.TODO()).Str("Algorithm", jwk.Algorithm).
log.Info().Str("Algorithm", jwk.Algorithm).
Str("KeyID", jwk.KeyID).
Interface("Public Key", jwk.Public()).
Msg("authorize: signing key")

3
authorize/evaluator/functions.go
View file

@ -1,7 +1,6 @@
package evaluator
import (
"context"
"crypto/x509"
"encoding/asn1"
"encoding/json"
@ -124,7 +123,7 @@ func isValidClientCertificate(
valid := verifyErr == nil
if verifyErr != nil {
log.Debug(context.Background()).Err(verifyErr).Msg("client certificate failed verification: %w")
log.Debug().Err(verifyErr).Msg("client certificate failed verification: %w")
}
isValidClientCertificateCache.Add(cacheKey, valid)

2
authorize/evaluator/policy_evaluator.go
View file

@ -147,7 +147,7 @@ func NewPolicyEvaluator(
// for each script, create a rego and prepare a query.
for i := range e.queries {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("script", e.queries[i].script).
Str("from", configPolicy.From).
Interface("to", configPolicy.To).

2
authorize/grpc.go
View file

@ -61,7 +61,7 @@ func (a *Authorize) Check(ctx context.Context, in *envoy_service_auth_v3.CheckRe
log.Ctx(ctx).Debug().Str("request-id", requestID).Err(err).Msg("temporary error checking authorization: data broker unavailable")
return nil, err
} else if err != nil {
log.Info(ctx).Err(err).Str("request-id", requestID).Msg("clearing session due to missing or invalid session or service account")
log.Ctx(ctx).Info().Err(err).Str("request-id", requestID).Msg("clearing session due to missing or invalid session or service account")
sessionState = nil
}
}

4
authorize/log.go
View file

@ -31,7 +31,7 @@ func (a *Authorize) logAuthorizeCheck(
hdrs := getCheckRequestHeaders(in)
impersonateDetails := a.getImpersonateDetails(ctx, s)
evt := log.Info(ctx).Str("service", "authorize")
evt := log.Ctx(ctx).Info().Str("service", "authorize")
fields := a.currentOptions.Load().GetAuthorizeLogFields()
for _, field := range fields {
evt = populateLogEvent(ctx, field, evt, in, s, u, hdrs, impersonateDetails)
@ -69,7 +69,7 @@ func (a *Authorize) logAuthorizeCheck(
log.Ctx(ctx).Error().Err(err).Msg("authorize: error encrypting audit record")
return
}
log.Info(ctx).
log.Ctx(ctx).Info().
Str("request-id", requestid.FromContext(ctx)).
EmbedObject(sealed).
Msg("audit log")

2
cmd/pomerium/main.go
View file

@ -38,7 +38,7 @@ func main() {
runFn = zero_cmd.Run
}
root.RunE = func(_ *cobra.Command, _ []string) error {
defer log.Info(ctx).Msg("cmd/pomerium: exiting")
defer log.Ctx(ctx).Info().Msg("cmd/pomerium: exiting")
return runFn(ctx, configFile)
}

12
config/config_source.go
View file

@ -137,7 +137,7 @@ func NewFileOrEnvironmentSource(
if cfg.Options.IsRuntimeFlagSet(RuntimeFlagConfigHotReload) {
src.watcher.Watch(ctx, []string{configFile})
} else {
log.Info(ctx).Msg("hot reload disabled")
log.Ctx(ctx).Info().Msg("hot reload disabled")
src.watcher.Watch(ctx, nil)
}
}
@ -155,7 +155,7 @@ func (src *FileOrEnvironmentSource) check(ctx context.Context) {
ctx = log.WithContext(ctx, func(c zerolog.Context) zerolog.Context {
return c.Str("config_change_id", uuid.New().String())
})
log.Info(ctx).Msg("config: file updated, reconfiguring...")
log.Ctx(ctx).Info().Msg("config: file updated, reconfiguring...")
src.mu.Lock()
cfg := src.config
options, err := newOptionsFromConfig(src.configFile)
@ -170,7 +170,7 @@ func (src *FileOrEnvironmentSource) check(ctx context.Context) {
src.config = cfg
src.mu.Unlock()
log.Info(ctx).Msg("config: loaded configuration")
log.Ctx(ctx).Info().Msg("config: loaded configuration")
src.Trigger(ctx, cfg)
}
@ -240,7 +240,7 @@ func (src *FileWatcherSource) onConfigChange(ctx context.Context, cfg *Config) {
// store the config and trigger an update
src.cfg = cfg.Clone()
src.hash = getAllConfigFilePathsHash(src.cfg)
log.Info(ctx).Uint64("hash", src.hash).Msg("config/filewatchersource: underlying config change, triggering update")
log.Ctx(ctx).Info().Uint64("hash", src.hash).Msg("config/filewatchersource: underlying config change, triggering update")
src.Trigger(ctx, src.cfg)
}
@ -251,12 +251,12 @@ func (src *FileWatcherSource) onFileChange(ctx context.Context) {
hash := getAllConfigFilePathsHash(src.cfg)
if hash == src.hash {
log.Info(ctx).Uint64("hash", src.hash).Msg("config/filewatchersource: no change detected")
log.Ctx(ctx).Info().Uint64("hash", src.hash).Msg("config/filewatchersource: no change detected")
} else {
// if the hash changed, trigger an update
// the actual config will be identical
src.hash = hash
log.Info(ctx).Uint64("hash", src.hash).Msg("config/filewatchersource: change detected, triggering update")
log.Ctx(ctx).Info().Uint64("hash", src.hash).Msg("config/filewatchersource: change detected, triggering update")
src.Trigger(ctx, src.cfg)
}
}

2
config/envoyconfig/envoyconfig.go
View file

@ -210,7 +210,7 @@ func getRootCertificateAuthority() (string, error) {
log.Error().Strs("known-locations", knownRootLocations).
Msgf("no root certificates were found in any of the known locations")
} else {
log.Info(context.TODO()).Msgf("using %s as the system root certificate authority bundle", rootCABundle.value)
log.Info().Msgf("using %s as the system root certificate authority bundle", rootCABundle.value)
}
})
if rootCABundle.value == "" {

2
config/metrics.go
View file

@ -97,7 +97,7 @@ func (mgr *MetricsManager) updateServer(ctx context.Context, cfg *Config) {
mgr.handler = nil
if mgr.addr == "" {
log.Info(ctx).Msg("metrics: http server disabled")
log.Ctx(ctx).Info().Msg("metrics: http server disabled")
return
}

2
config/options.go
View file

@ -700,7 +700,7 @@ func (o *Options) Validate() error {
o.HTTPRedirectAddr = strings.Trim(o.HTTPRedirectAddr, `"'`)
if !o.InsecureServer && !hasCert && !o.AutocertOptions.Enable {
log.Info(ctx).Msg("neither `autocert`, " +
log.Ctx(ctx).Info().Msg("neither `autocert`, " +
"`insecure_server` or manually provided certificates were provided, server will be using a self-signed certificate")
}

7
config/policy.go
View file

@ -1,7 +1,6 @@
package config
import (
"context"
"crypto/tls"
"encoding/base64"
"fmt"
@ -489,7 +488,7 @@ func (p *Policy) Validate() error {
source.String())
}
if source.Scheme == "http" {
log.Info(context.Background()).Msgf("config: policy source url (%s) uses HTTP but only HTTPS is supported",
log.Info().Msgf("config: policy source url (%s) uses HTTP but only HTTPS is supported",
source.String())
}
@ -554,7 +553,7 @@ func (p *Policy) Validate() error {
"reference/routes/tls#tls-downstream-client-certificate-authority for more information"
if p.TLSDownstreamClientCA != "" {
log.Info(context.Background()).Msgf(clientCADeprecationMsg, "tls_downstream_client_ca")
log.Info().Msgf(clientCADeprecationMsg, "tls_downstream_client_ca")
_, err := base64.StdEncoding.DecodeString(p.TLSDownstreamClientCA)
if err != nil {
return fmt.Errorf("config: couldn't decode downstream client ca: %w", err)
@ -562,7 +561,7 @@ func (p *Policy) Validate() error {
}
if p.TLSDownstreamClientCAFile != "" {
log.Info(context.Background()).Msgf(clientCADeprecationMsg, "tls_downstream_client_ca_file")
log.Info().Msgf(clientCADeprecationMsg, "tls_downstream_client_ca_file")
bs, err := os.ReadFile(p.TLSDownstreamClientCAFile)
if err != nil {
return fmt.Errorf("config: couldn't load downstream client ca: %w", err)

4
config/trace.go
View file

@ -95,7 +95,7 @@ func (mgr *TraceManager) OnConfigChange(ctx context.Context, cfg *Config) {
}
if reflect.DeepEqual(traceOpts, mgr.traceOpts) {
log.Debug(ctx).Msg("no change detected in trace options")
log.Ctx(ctx).Debug().Msg("no change detected in trace options")
return
}
mgr.traceOpts = traceOpts
@ -109,7 +109,7 @@ func (mgr *TraceManager) OnConfigChange(ctx context.Context, cfg *Config) {
return
}
log.Info(ctx).Interface("options", traceOpts).Msg("trace: starting exporter")
log.Ctx(ctx).Info().Interface("options", traceOpts).Msg("trace: starting exporter")
mgr.provider, err = trace.GetProvider(traceOpts)
if err != nil {

2
databroker/cache.go
View file

@ -180,7 +180,7 @@ func (c *DataBroker) update(ctx context.Context, cfg *config.Config) error {
legacyOptions = append(legacyOptions, legacymanager.WithAuthenticator(authenticator))
}
} else {
log.Info(ctx).Msg("databroker: disabling refresh of user sessions")
log.Ctx(ctx).Info().Msg("databroker: disabling refresh of user sessions")
}
if c.manager == nil {

14
internal/autocert/manager.go
View file

@ -193,7 +193,7 @@ func (mgr *Manager) renewConfigCerts(ctx context.Context) error {
needsReload := false
var renew, ocsp []string
log.Debug(ctx).Strs("domains", sourceHostnames(cfg)).Msg("checking domains")
log.Ctx(ctx).Debug().Strs("domains", sourceHostnames(cfg)).Msg("checking domains")
for _, domain := range sourceHostnames(cfg) {
cert, err := cm.CacheManagedCertificate(ctx, domain)
if err != nil {
@ -222,7 +222,7 @@ func (mgr *Manager) renewConfigCerts(ctx context.Context) error {
}
return c
})
log.Info(ctx).Msg("updating certificates")
log.Ctx(ctx).Info().Msg("updating certificates")
cfg = mgr.src.GetConfig().Clone()
mgr.updateServer(ctx, cfg)
@ -252,7 +252,7 @@ func (mgr *Manager) update(ctx context.Context, cfg *config.Config) error {
func (mgr *Manager) obtainCert(ctx context.Context, domain string, cm *certmagic.Config) (certmagic.Certificate, error) {
cert, err := cm.CacheManagedCertificate(ctx, domain)
if err != nil {
log.Info(ctx).Str("domain", domain).Msg("obtaining certificate")
log.Ctx(ctx).Info().Str("domain", domain).Msg("obtaining certificate")
err = cm.ObtainCertSync(ctx, domain)
if err != nil {
log.Ctx(ctx).Error().Err(err).Msg("autocert failed to obtain client certificate")
@ -267,7 +267,7 @@ func (mgr *Manager) obtainCert(ctx context.Context, domain string, cm *certmagic
// renewCert attempts to renew given certificate.
func (mgr *Manager) renewCert(ctx context.Context, domain string, cert certmagic.Certificate, cm *certmagic.Config) (certmagic.Certificate, error) {
expired := time.Now().After(cert.Leaf.NotAfter)
log.Info(ctx).Str("domain", domain).Msg("renewing certificate")
log.Ctx(ctx).Info().Str("domain", domain).Msg("renewing certificate")
renewCertLock.Lock()
err := cm.RenewCertSync(ctx, domain, false)
renewCertLock.Unlock()
@ -301,7 +301,7 @@ func (mgr *Manager) updateAutocert(ctx context.Context, cfg *config.Config) erro
continue
}
log.Info(ctx).Strs("names", cert.Names).Msg("autocert: added certificate")
log.Ctx(ctx).Info().Strs("names", cert.Names).Msg("autocert: added certificate")
cfg.AutoCertificates = append(cfg.AutoCertificates, cert.Certificate)
}
@ -337,7 +337,7 @@ func (mgr *Manager) updateServer(ctx context.Context, cfg *config.Config) {
}),
}
go func() {
log.Info(ctx).Str("addr", hsrv.Addr).Msg("starting http redirect server")
log.Ctx(ctx).Info().Str("addr", hsrv.Addr).Msg("starting http redirect server")
err := hsrv.ListenAndServe()
if err != nil {
log.Ctx(ctx).Error().Err(err).Msg("failed to run http redirect server")
@ -391,7 +391,7 @@ func (mgr *Manager) updateACMETLSALPNServer(ctx context.Context, cfg *config.Con
orig := tlsConfig.GetCertificate
tlsConfig.GetCertificate = func(chi *tls.ClientHelloInfo) (*tls.Certificate, error) {
log.Info(ctx).Str("server-name", chi.ServerName).
log.Ctx(ctx).Info().Str("server-name", chi.ServerName).
Msg("received request for ACME TLS ALPN certificate")
return orig(chi)
}

4
internal/autocert/manager_test.go
View file

@ -270,7 +270,7 @@ func TestConfig(t *testing.T) {
initialOCSPStaple = cert.OCSPStaple
} else {
if !bytes.Equal(initialOCSPStaple, cert.OCSPStaple) {
log.Info(ctx).Msg("OCSP updated")
log.Ctx(ctx).Info().Msg("OCSP updated")
ocspUpdated <- true
}
}
@ -278,7 +278,7 @@ func TestConfig(t *testing.T) {
certValidTime = &cert.Leaf.NotAfter
} else {
if !certValidTime.Equal(cert.Leaf.NotAfter) {
log.Info(ctx).Msg("domain renewed")
log.Ctx(ctx).Info().Msg("domain renewed")
domainRenewed <- true
}
}

6
internal/controlplane/grpc_accesslog.go
View file

@ -45,7 +45,7 @@ func accessLogListener(
if failure == "" {
continue
}
e := log.Info(ctx).Str("service", "envoy")
e := log.Ctx(ctx).Info().Str("service", "envoy")
dict := zerolog.Dict()
populateCertEventDict(entry.GetCommonProperties().GetTlsProperties().GetPeerCertificateProperties(), dict)
e.Dict("client-certificate", dict)
@ -63,9 +63,9 @@ func (srv *Server) accessLogHTTP(
reqPath := entry.GetRequest().GetPath()
var evt *zerolog.Event
if reqPath == "/ping" || reqPath == "/healthz" {
evt = log.Debug(ctx)
evt = log.Ctx(ctx).Debug()
} else {
evt = log.Info(ctx)
evt = log.Ctx(ctx).Info()
}
evt = evt.Str("service", "envoy")

4
internal/controlplane/server.go
View file

@ -180,7 +180,7 @@ func (srv *Server) Run(ctx context.Context) error {
// start the gRPC server
eg.Go(func() error {
log.Debug(ctx).Str("addr", srv.GRPCListener.Addr().String()).Msg("starting control-plane gRPC server")
log.Ctx(ctx).Debug().Str("addr", srv.GRPCListener.Addr().String()).Msg("starting control-plane gRPC server")
return grpcutil.ServeWithGracefulStop(ctx, srv.GRPCServer, srv.GRPCListener, time.Second*5)
})
@ -199,7 +199,7 @@ func (srv *Server) Run(ctx context.Context) error {
// start the HTTP server
eg.Go(func() error {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("addr", entry.Listener.Addr().String()).
Msgf("starting control-plane %s server", entry.Name)
return httputil.ServeWithGracefulStop(ctx, entry.Handler, entry.Listener, time.Second*5)

4
internal/controlplane/xds.go
View file

@ -26,7 +26,7 @@ func (srv *Server) buildDiscoveryResources(ctx context.Context) (map[string][]*e
cfg := srv.currentConfig.Load()
log.Debug(ctx).Msg("controlplane: building discovery resources")
log.Ctx(ctx).Debug().Msg("controlplane: building discovery resources")
eg, ctx := errgroup.WithContext(ctx)
@ -83,7 +83,7 @@ func (srv *Server) buildDiscoveryResources(ctx context.Context) (map[string][]*e
return nil, err
}
log.Debug(ctx).
log.Ctx(ctx).Debug().
Int("cluster-count", len(clusterResources)).
Int("listener-count", len(listenerResources)).
Int("route-configuration-count", len(routeConfigurationResources)).

5
internal/controlplane/xdsmgr/log.go
View file

@ -1,7 +1,6 @@
package xdsmgr
import (
"context"
"errors"
envoy_config_cluster_v3 "github.com/envoyproxy/go-control-plane/envoy/config/cluster/v3"
@ -21,7 +20,7 @@ var (
)
func logNACK(req *envoy_service_discovery_v3.DeltaDiscoveryRequest) {
log.Debug(context.Background()).
log.Debug().
Str("type-url", req.GetTypeUrl()).
Any("error-detail", req.GetErrorDetail()).
Msg("xdsmgr: nack")
@ -30,7 +29,7 @@ func logNACK(req *envoy_service_discovery_v3.DeltaDiscoveryRequest) {
}
func logACK(req *envoy_service_discovery_v3.DeltaDiscoveryRequest) {
log.Debug(context.Background()).
log.Debug().
Str("type-url", req.GetTypeUrl()).
Msg("xdsmgr: ack")

4
internal/controlplane/xdsmgr/xdsmgr.go
View file

@ -124,7 +124,7 @@ func (mgr *Manager) DeltaAggregatedResources(
logACK(req)
default:
// an ACK for a response that's not the last response
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("type-url", req.GetTypeUrl()).
Msg("xdsmgr: ack")
}
@ -206,7 +206,7 @@ func (mgr *Manager) DeltaAggregatedResources(
case <-ctx.Done():
return ctx.Err()
case res := <-outgoing:
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("type-url", res.GetTypeUrl()).
Int("resource-count", len(res.GetResources())).
Int("removed-resource-count", len(res.GetRemovedResources())).

6
internal/databroker/config_source.go
View file

@ -91,7 +91,7 @@ func (src *ConfigSource) rebuild(ctx context.Context, firstTime firstTime) {
now := time.Now()
src.mu.Lock()
defer src.mu.Unlock()
log.Debug(ctx).Str("lock-wait", time.Since(now).String()).Msg("databroker: rebuilding configuration")
log.Ctx(ctx).Debug().Str("lock-wait", time.Since(now).String()).Msg("databroker: rebuilding configuration")
cfg := src.underlyingConfig.Clone()
@ -106,7 +106,7 @@ func (src *ConfigSource) rebuild(ctx context.Context, firstTime firstTime) {
return
}
health.ReportOK(health.BuildDatabrokerConfig)
log.Debug(ctx).Str("elapsed", time.Since(now).String()).Msg("databroker: built new config")
log.Ctx(ctx).Debug().Str("elapsed", time.Since(now).String()).Msg("databroker: built new config")
src.computedConfig = cfg
if !firstTime {
@ -274,7 +274,7 @@ func (src *ConfigSource) runUpdater(cfg *config.Config) {
}, databroker.WithTypeURL(grpcutil.GetTypeURL(new(configpb.Config))),
databroker.WithFastForward())
go func() {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("outbound_port", cfg.OutboundPort).
Msg("config: starting databroker config source syncer")
_ = grpc.WaitForReady(ctx, cc, time.Second*10)

4
internal/databroker/registry.go
View file

@ -98,7 +98,7 @@ func (srv *Server) newRegistryLocked(backend storage.Backend) (registry.Interfac
if hasRegistryServer, ok := backend.(interface {
RegistryServer() registrypb.RegistryServer
}); ok {
log.Info(ctx).Msg("using registry via storage")
log.Ctx(ctx).Info().Msg("using registry via storage")
return struct {
io.Closer
registrypb.RegistryServer
@ -107,7 +107,7 @@ func (srv *Server) newRegistryLocked(backend storage.Backend) (registry.Interfac
switch srv.cfg.storageType {
case config.StorageInMemoryName:
log.Info(ctx).Msg("using in-memory registry")
log.Ctx(ctx).Info().Msg("using in-memory registry")
return inmemory.New(ctx, srv.cfg.registryTTL), nil
}

30
internal/databroker/server.go
View file

@ -49,7 +49,7 @@ func (srv *Server) UpdateConfig(options ...ServerOption) {
cfg := newServerConfig(options...)
if cmp.Equal(cfg, srv.cfg, cmp.AllowUnexported(serverConfig{})) {
log.Debug(ctx).Msg("databroker: no changes detected, re-using existing DBs")
log.Ctx(ctx).Debug().Msg("databroker: no changes detected, re-using existing DBs")
return
}
srv.cfg = cfg
@ -75,7 +75,7 @@ func (srv *Server) UpdateConfig(options ...ServerOption) {
func (srv *Server) AcquireLease(ctx context.Context, req *databroker.AcquireLeaseRequest) (*databroker.AcquireLeaseResponse, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.AcquireLease")
defer span.End()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("name", req.GetName()).
Dur("duration", req.GetDuration().AsDuration()).
Msg("acquire lease")
@ -102,7 +102,7 @@ func (srv *Server) AcquireLease(ctx context.Context, req *databroker.AcquireLeas
func (srv *Server) Get(ctx context.Context, req *databroker.GetRequest) (*databroker.GetResponse, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.Get")
defer span.End()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("type", req.GetType()).
Str("id", req.GetId()).
Msg("get")
@ -129,7 +129,7 @@ func (srv *Server) Get(ctx context.Context, req *databroker.GetRequest) (*databr
func (srv *Server) ListTypes(ctx context.Context, _ *emptypb.Empty) (*databroker.ListTypesResponse, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.ListTypes")
defer span.End()
log.Debug(ctx).Msg("list types")
log.Ctx(ctx).Debug().Msg("list types")
db, err := srv.getBackend()
if err != nil {
@ -146,7 +146,7 @@ func (srv *Server) ListTypes(ctx context.Context, _ *emptypb.Empty) (*databroker
func (srv *Server) Query(ctx context.Context, req *databroker.QueryRequest) (*databroker.QueryResponse, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.Query")
defer span.End()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("type", req.GetType()).
Str("query", req.GetQuery()).
Int64("offset", req.GetOffset()).
@ -202,7 +202,7 @@ func (srv *Server) Put(ctx context.Context, req *databroker.PutRequest) (*databr
records := req.GetRecords()
if len(records) == 1 {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("record-type", records[0].GetType()).
Str("record-id", records[0].GetId()).
Msg("put")
@ -211,7 +211,7 @@ func (srv *Server) Put(ctx context.Context, req *databroker.PutRequest) (*databr
for _, record := range records {
recordType = record.GetType()
}
log.Debug(ctx).
log.Ctx(ctx).Debug().
Int("record-count", len(records)).
Str("record-type", recordType).
Msg("put")
@ -241,7 +241,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da
records := req.GetRecords()
if len(records) == 1 {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("record-type", records[0].GetType()).
Str("record-id", records[0].GetId()).
Msg("patch")
@ -250,7 +250,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da
for _, record := range records {
recordType = record.GetType()
}
log.Debug(ctx).
log.Ctx(ctx).Debug().
Int("record-count", len(records)).
Str("record-type", recordType).
Msg("patch")
@ -277,7 +277,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da
func (srv *Server) ReleaseLease(ctx context.Context, req *databroker.ReleaseLeaseRequest) (*emptypb.Empty, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.ReleaseLease")
defer span.End()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("name", req.GetName()).
Str("id", req.GetId()).
Msg("release lease")
@ -299,7 +299,7 @@ func (srv *Server) ReleaseLease(ctx context.Context, req *databroker.ReleaseLeas
func (srv *Server) RenewLease(ctx context.Context, req *databroker.RenewLeaseRequest) (*emptypb.Empty, error) {
ctx, span := trace.StartSpan(ctx, "databroker.grpc.RenewLease")
defer span.End()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("name", req.GetName()).
Str("id", req.GetId()).
Dur("duration", req.GetDuration().AsDuration()).
@ -351,7 +351,7 @@ func (srv *Server) Sync(req *databroker.SyncRequest, stream databroker.DataBroke
ctx, cancel := context.WithCancel(ctx)
defer cancel()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Uint64("server_version", req.GetServerVersion()).
Uint64("record_version", req.GetRecordVersion()).
Msg("sync")
@ -388,7 +388,7 @@ func (srv *Server) SyncLatest(req *databroker.SyncLatestRequest, stream databrok
ctx, cancel := context.WithCancel(ctx)
defer cancel()
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("type", req.GetType()).
Msg("sync latest")
@ -457,10 +457,10 @@ func (srv *Server) newBackendLocked() (backend storage.Backend, err error) {
switch srv.cfg.storageType {
case config.StorageInMemoryName:
log.Info(ctx).Msg("using in-memory store")
log.Ctx(ctx).Info().Msg("using in-memory store")
return inmemory.New(), nil
case config.StoragePostgresName:
log.Info(ctx).Msg("using postgres store")
log.Ctx(ctx).Info().Msg("using postgres store")
backend = postgres.New(srv.cfg.storageConnectionString)
default:
return nil, fmt.Errorf("unsupported storage type: %s", srv.cfg.storageType)

2
internal/fileutil/watcher.go
View file

@ -95,7 +95,7 @@ func (watcher *Watcher) initLocked(ctx context.Context) {
// handle events
go func() {
for evt := range events {
log.Info(ctx).Str("name", evt.Name).Str("op", evt.Op.String()).Msg("fileutil/watcher: file notification event")
log.Ctx(ctx).Info().Str("name", evt.Name).Str("op", evt.Op.String()).Msg("fileutil/watcher: file notification event")
watcher.Broadcast(ctx)
}
}()

2
internal/httputil/client.go
View file

@ -33,7 +33,7 @@ func (l loggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error
if res != nil {
statusCode = res.StatusCode
}
evt := log.Debug(req.Context()).
evt := log.Ctx(req.Context()).Debug().
Str("method", req.Method).
Str("authority", req.URL.Host).
Str("path", req.URL.Path).

2
internal/httputil/server.go
View file

@ -97,7 +97,7 @@ func Shutdown(srv *http.Server) {
rec := <-sigint
ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
defer cancel()
log.Info(context.TODO()).Str("signal", rec.String()).Msg("internal/httputil: shutting down servers")
log.Info().Str("signal", rec.String()).Msg("internal/httputil: shutting down servers")
if err := srv.Shutdown(ctx); err != nil {
log.Error().Err(err).Msg("internal/httputil: shutdown failed")
}

43
internal/log/log.go
View file

@ -83,31 +83,18 @@ func With() zerolog.Context {
return Logger().With()
}
// Level creates a child logger with the minimum accepted level set to level.
func Level(ctx context.Context, level zerolog.Level) *zerolog.Logger {
l := contextLogger(ctx).Level(level)
return &l
}
// Debug starts a new message with debug level.
//
// You must call Msg on the returned event in order to send the event.
func Debug(ctx context.Context) *zerolog.Event {
return contextLogger(ctx).Debug()
func Debug() *zerolog.Event {
return log.Debug()
}
// Info starts a new message with info level.
//
// You must call Msg on the returned event in order to send the event.
func Info(ctx context.Context) *zerolog.Event {
return contextLogger(ctx).Info()
}
// Warn starts a new message with warn level.
//
// You must call Msg on the returned event in order to send the event.
func Warn(ctx context.Context) *zerolog.Event {
return contextLogger(ctx).Warn()
func Info() *zerolog.Event {
return log.Info()
}
// Error starts a new message with error level.
@ -117,21 +104,9 @@ func Error() *zerolog.Event {
return log.Error()
}
func contextLogger(ctx context.Context) *zerolog.Logger {
global := Logger()
if global.GetLevel() == zerolog.Disabled {
return global
}
l := zerolog.Ctx(ctx)
if l.GetLevel() == zerolog.Disabled { // no logger associated with context
return global
}
return l
}
// WithContext returns a context that has an associated logger and extra fields set via update
func WithContext(ctx context.Context, update func(c zerolog.Context) zerolog.Context) context.Context {
l := contextLogger(ctx).With().Logger()
l := log.Ctx(ctx).With().Logger()
l.UpdateContext(update)
return l.WithContext(ctx)
}
@ -152,14 +127,6 @@ func Panic() *zerolog.Event {
return Logger().Panic()
}
// Log starts a new message with no level. Setting zerolog.GlobalLevel to
// zerolog.Disabled will still disable events produced by this method.
//
// You must call Msg on the returned event in order to send the event.
func Log(_ context.Context) *zerolog.Event {
return Logger().Log()
}
// Print sends a log event using debug level and no extra field.
// Arguments are handled in the manner of fmt.Print.
func Print(v ...any) {

37
internal/log/log_test.go
View file

@ -61,18 +61,10 @@ func ExamplePrintf() {
// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
}
// Example of a log with no particular "level"
func ExampleLog() {
captureOutput(func() {
log.Log(context.Background()).Msg("hello world")
})
// Output: {"time":"2008-01-08T17:05:05Z","message":"hello world"}
}
// Example of a log at a particular "level" (in this case, "debug")
func ExampleDebug() {
captureOutput(func() {
log.Debug(context.Background()).Msg("hello world")
log.Debug().Msg("hello world")
})
// Output: {"level":"debug","time":"2008-01-08T17:05:05Z","message":"hello world"}
}
@ -80,7 +72,7 @@ func ExampleDebug() {
// Example of a log at a particular "level" (in this case, "info")
func ExampleInfo() {
captureOutput(func() {
log.Info(context.Background()).Msg("hello world")
log.Info().Msg("hello world")
})
// Output: {"level":"info","time":"2008-01-08T17:05:05Z","message":"hello world"}
}
@ -121,10 +113,10 @@ func Example() {
zerolog.SetGlobalLevel(zerolog.DebugLevel)
}
log.Debug(context.Background()).Msg("This message appears only when log level set to Debug")
log.Info(context.Background()).Msg("This message appears when log level set to Debug or Info")
log.Debug().Msg("This message appears only when log level set to Debug")
log.Info().Msg("This message appears when log level set to Debug or Info")
if e := log.Debug(context.Background()); e.Enabled() {
if e := log.Debug(); e.Enabled() {
// Compute log output only if enabled.
value := "bar"
e.Str("foo", value).Msg("some debug message")
@ -136,23 +128,20 @@ func Example() {
func ExampleSetLevel() {
captureOutput(func() {
log.SetLevel(zerolog.InfoLevel)
log.Debug(context.Background()).Msg("Debug")
log.Info(context.Background()).Msg("Debug or Info")
log.Debug().Msg("Debug")
log.Info().Msg("Debug or Info")
log.SetLevel(zerolog.WarnLevel)
log.Debug(context.Background()).Msg("Debug")
log.Info(context.Background()).Msg("Debug or Info")
log.Warn(context.Background()).Msg("Debug or Info or Warn")
log.Debug().Msg("Debug")
log.Info().Msg("Debug or Info")
log.SetLevel(zerolog.ErrorLevel)
log.Debug(context.Background()).Msg("Debug")
log.Info(context.Background()).Msg("Debug or Info")
log.Warn(context.Background()).Msg("Debug or Info or Warn")
log.Debug().Msg("Debug")
log.Info().Msg("Debug or Info")
log.Error().Msg("Debug or Info or Warn or Error")
log.SetLevel(zerolog.DebugLevel)
log.Debug(context.Background()).Msg("Debug")
log.Debug().Msg("Debug")
})
// Output:
// {"level":"info","time":"2008-01-08T17:05:05Z","message":"Debug or Info"}
// {"level":"warn","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn"}
// {"level":"error","time":"2008-01-08T17:05:05Z","message":"Debug or Info or Warn or Error"}
// {"level":"debug","time":"2008-01-08T17:05:05Z","message":"Debug"}
}
@ -176,7 +165,7 @@ func ExampleContext() {
return c.Int("counter", i)
})
}
log.Info(ctx1).Str("non_ctx_param", "value").Msg("after counter")
log.Ctx(ctx1).Info().Str("non_ctx_param", "value").Msg("after counter")
})
// Output:
// {"level":"error","non_context_param":"value","time":"2008-01-08T17:05:05Z","message":"background"}

7
internal/log/warnings.go
View file

@ -1,7 +1,6 @@
package log
import (
"context"
"sync"
"github.com/pomerium/pomerium/internal/syncutil"
@ -12,7 +11,7 @@ var warnCookieSecretOnce sync.Once
// WarnCookieSecret warns about the cookie secret.
func WarnCookieSecret() {
warnCookieSecretOnce.Do(func() {
Info(context.Background()).
Info().
Msg("using a generated COOKIE_SECRET. " +
"Set the COOKIE_SECRET to avoid users being logged out on restart. " +
"https://www.pomerium.com/docs/reference/cookie-secret")
@ -24,7 +23,7 @@ var warnNoTLSCertificateOnce syncutil.OnceMap[string]
// WarnNoTLSCertificate warns about no TLS certificate.
func WarnNoTLSCertificate(domain string) {
warnNoTLSCertificateOnce.Do(domain, func() {
Info(context.Background()).
Info().
Str("domain", domain).
Msg("no TLS certificate found for domain, using a self-signed certificate")
})
@ -35,7 +34,7 @@ var warnWebSocketHTTP1_1Once syncutil.OnceMap[string]
// WarnWebSocketHTTP1_1 warns about falling back to http 1.1 due to web socket support.
func WarnWebSocketHTTP1_1(clusterID string) {
warnWebSocketHTTP1_1Once.Do(clusterID, func() {
Info(context.Background()).
Info().
Str("cluster-id", clusterID).
Msg("forcing http/1.1 due to web socket support")
})

2
internal/registry/reporter.go
View file

@ -145,7 +145,7 @@ func runReporter(
after = resp.CallBackAfter.AsDuration()
backoff.Reset()
case <-ctx.Done():
log.Info(ctx).Msg("service registry reporter stopping")
log.Ctx(ctx).Info().Msg("service registry reporter stopping")
return
}
}

4
internal/retry/backoff.go
View file

@ -17,8 +17,8 @@ type serviceName struct{}
func WithBackoff(ctx context.Context, name string, fn func(context.Context) error) error {
name, ctx = getServiceNameContext(ctx, name)
log.Debug(ctx).Str("service-name", name).Msg("starting")
defer log.Debug(ctx).Str("service-name", name).Msg("stopped")
log.Ctx(ctx).Debug().Str("service-name", name).Msg("starting")
defer log.Ctx(ctx).Debug().Str("service-name", name).Msg("stopped")
b := backoff.NewExponentialBackOff()
b.MaxElapsedTime = 0

4
internal/telemetry/metrics/info.go
View file

@ -313,7 +313,7 @@ func RecordIdentityManagerSessionRefresh(ctx context.Context, err error) {
// SetDBConfigInfo records status, databroker version and error count while parsing
// the configuration from a databroker
func SetDBConfigInfo(ctx context.Context, service, configID string, version uint64, errCount int64) {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("service", service).
Str("config_id", configID).
Uint64("version", version).
@ -374,7 +374,7 @@ func SetConfigInfo(ctx context.Context, service, configName string, checksum uin
} else {
stats.Record(context.Background(), configLastReloadSuccess.M(0))
}
log.Info(ctx).
log.Ctx(ctx).Info().
Str("service", service).
Str("config", configName).
Str("checksum", fmt.Sprintf("%x", checksum)).

2
internal/telemetry/trace/trace.go
View file

@ -74,7 +74,7 @@ func GetProvider(opts *TracingOptions) (Provider, error) {
}
octrace.ApplyConfig(octrace.Config{DefaultSampler: octrace.ProbabilitySampler(opts.SampleRate)})
log.Debug(context.TODO()).Interface("Opts", opts).Msg("telemetry/trace: provider created")
log.Debug().Interface("Opts", opts).Msg("telemetry/trace: provider created")
return provider, nil
}

8
internal/tests/xdserr/cmd/main.go
View file

@ -73,7 +73,7 @@ func main() {
return
}
}
log.Info(ctx).Str("url", *to).Msg("echo server")
log.Ctx(ctx).Info().Str("url", *to).Msg("echo server")
eg.Go(func() error {
return run(ctx, conn, *toURL, *domain, opts{
@ -114,7 +114,7 @@ func run(ctx context.Context, conn *grpc.ClientConn, to url.URL, domain string,
changed[j] = idx
cfg.Routes[idx] = makeRoute(domain, to)
}
log.Info(ctx).Ints("changed", changed).Msg("changed")
log.Ctx(ctx).Info().Ints("changed", changed).Msg("changed")
if err := saveAndLogConfig(ctx, dbc, cfg, o.graceful); err != nil {
return err
}
@ -175,7 +175,7 @@ func waitHealthy(ctx context.Context, _ *http.Client, routes []*config.Route) er
return err
}
log.Info(ctx).
log.Ctx(ctx).Info().
Int("routes", len(routes)).
Str("elapsed", time.Since(now).String()).
Msg("ok")
@ -195,6 +195,6 @@ func saveConfig(ctx context.Context, client databroker.DataBrokerServiceClient,
if err != nil {
return err
}
log.Info(ctx).Uint64("version", r.GetRecord().GetVersion()).Msg("set config")
log.Ctx(ctx).Info().Uint64("version", r.GetRecord().GetVersion()).Msg("set config")
return nil
}

2
internal/tests/xdserr/config.go
View file

@ -56,7 +56,7 @@ func DumpConfig(ctx context.Context, adminURL string) (*adminv3.RoutesConfigDump
// RawJSON("data", data).
Msg("decode")
} else {
log.Info(ctx).Msg(a.TypeUrl)
log.Ctx(ctx).Info().Msg(a.TypeUrl)
}
}
return nil, err

4
internal/zero/controller/usagereporter/usagereporter.go
View file

@ -79,10 +79,10 @@ func (ur *UsageReporter) report(ctx context.Context, records []usageReporterReco
Users: convertUsageReporterRecords(ur.pseudonymizationKey, records),
}
return backoff.Retry(func() error {
log.Debug(ctx).Int("updated-users", len(req.Users)).Msg("reporting usage")
log.Ctx(ctx).Debug().Int("updated-users", len(req.Users)).Msg("reporting usage")
err := ur.api.ReportUsage(ctx, req)
if err != nil {
log.Warn(ctx).Err(err).Msg("error reporting usage")
log.Ctx(ctx).Error().Err(err).Msg("error reporting usage")
}
return err
}, backoff.WithContext(backoff.NewExponentialBackOff(), ctx))

14
pkg/cmd/pomerium/pomerium.go
View file

@ -32,9 +32,9 @@ import (
// Run runs the main pomerium application.
func Run(ctx context.Context, src config.Source) error {
_, _ = maxprocs.Set(maxprocs.Logger(func(s string, i ...any) { log.Debug(context.Background()).Msgf(s, i...) }))
_, _ = maxprocs.Set(maxprocs.Logger(func(s string, i ...any) { log.Debug().Msgf(s, i...) }))
evt := log.Info(ctx).
evt := log.Ctx(ctx).Info().
Str("envoy_version", files.FullVersion()).
Str("version", version.FullVersion())
if buildTime := version.BuildTime(); buildTime != "" {
@ -86,7 +86,7 @@ func Run(ctx context.Context, src config.Source) error {
return fmt.Errorf("applying config: %w", err)
}
log.Info(ctx).
log.Ctx(ctx).Info().
Str("grpc-port", src.GetConfig().GRPCPort).
Str("http-port", src.GetConfig().HTTPPort).
Str("outbound-port", src.GetConfig().OutboundPort).
@ -177,7 +177,7 @@ func setupAuthenticate(ctx context.Context, src config.Source, controlPlane *con
src.OnConfigChange(ctx, svc.OnConfigChange)
svc.OnConfigChange(ctx, src.GetConfig())
log.Info(ctx).Msg("enabled authenticate service")
log.Ctx(ctx).Info().Msg("enabled authenticate service")
return nil
}
@ -189,7 +189,7 @@ func setupAuthorize(ctx context.Context, src config.Source, controlPlane *contro
}
envoy_service_auth_v3.RegisterAuthorizationServer(controlPlane.GRPCServer, svc)
log.Info(ctx).Msg("enabled authorize service")
log.Ctx(ctx).Info().Msg("enabled authorize service")
src.OnConfigChange(ctx, svc.OnConfigChange)
svc.OnConfigChange(ctx, src.GetConfig())
return svc, nil
@ -205,7 +205,7 @@ func setupDataBroker(ctx context.Context,
return nil, fmt.Errorf("error creating databroker service: %w", err)
}
svc.Register(controlPlane.GRPCServer)
log.Info(ctx).Msg("enabled databroker service")
log.Ctx(ctx).Info().Msg("enabled databroker service")
src.OnConfigChange(ctx, svc.OnConfigChange)
svc.OnConfigChange(ctx, src.GetConfig())
return svc, nil
@ -232,7 +232,7 @@ func setupProxy(ctx context.Context, src config.Source, controlPlane *controlpla
return fmt.Errorf("error adding proxy service to control plane: %w", err)
}
log.Info(ctx).Msg("enabled proxy service")
log.Ctx(ctx).Info().Msg("enabled proxy service")
src.OnConfigChange(ctx, svc.OnConfigChange)
svc.OnConfigChange(ctx, src.GetConfig())

2
pkg/cryptutil/tls.go
View file

@ -40,7 +40,7 @@ func GetCertPool(ca, caFile string) (*x509.CertPool, error) {
if ok := rootCAs.AppendCertsFromPEM(data); !ok {
return nil, fmt.Errorf("failed to append any PEM-encoded certificates")
}
log.Debug(ctx).Msg("pkg/cryptutil: added custom certificate authority")
log.Ctx(ctx).Debug().Msg("pkg/cryptutil: added custom certificate authority")
return rootCAs, nil
}

16
pkg/envoy/envoy.go
View file

@ -60,7 +60,7 @@ type Server struct {
// NewServer creates a new server with traffic routed by envoy.
func NewServer(ctx context.Context, src config.Source, builder *envoyconfig.Builder) (*Server, error) {
if err := preserveRlimitNofile(); err != nil {
log.Debug(ctx).Err(err).Msg("couldn't preserve RLIMIT_NOFILE before starting Envoy")
log.Ctx(ctx).Debug().Err(err).Msg("couldn't preserve RLIMIT_NOFILE before starting Envoy")
}
envoyPath, err := Extract()
@ -88,7 +88,7 @@ func NewServer(ctx context.Context, src config.Source, builder *envoyconfig.Buil
src.OnConfigChange(ctx, srv.onConfigChange)
srv.onConfigChange(ctx, src.GetConfig())
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("path", envoyPath).
Str("checksum", files.Checksum()).
Msg("running envoy")
@ -129,12 +129,12 @@ func (srv *Server) update(ctx context.Context, cfg *config.Config) {
}
if cmp.Equal(srv.options, options, cmp.AllowUnexported(serverOptions{})) {
log.Debug(ctx).Str("service", "envoy").Msg("envoy: no config changes detected")
log.Ctx(ctx).Debug().Str("service", "envoy").Msg("envoy: no config changes detected")
return
}
srv.options = options
log.Debug(ctx).Msg("envoy: starting envoy process")
log.Ctx(ctx).Debug().Msg("envoy: starting envoy process")
if err := srv.run(ctx, cfg); err != nil {
log.Ctx(ctx).Error().Err(err).Str("service", "envoy").Msg("envoy: failed to run envoy process")
return
@ -189,12 +189,12 @@ func (srv *Server) run(ctx context.Context, cfg *config.Config) error {
go srv.monitorProcess(monitorProcessCtx, int32(cmd.Process.Pid))
if srv.resourceMonitor != nil {
log.Debug(ctx).Str("service", "envoy").Msg("starting resource monitor")
log.Ctx(ctx).Debug().Str("service", "envoy").Msg("starting resource monitor")
go func() {
err := srv.resourceMonitor.Run(ctx, cmd.Process.Pid)
if err != nil {
if errors.Is(err, context.Canceled) {
log.Debug(ctx).Err(err).Str("service", "envoy").Msg("resource monitor stopped")
log.Ctx(ctx).Debug().Err(err).Str("service", "envoy").Msg("resource monitor stopped")
} else {
log.Ctx(ctx).Error().Err(err).Str("service", "envoy").Msg("resource monitor exited with error")
}
@ -213,7 +213,7 @@ func (srv *Server) writeConfig(ctx context.Context, cfg *config.Config) error {
}
cfgPath := filepath.Join(srv.wd, configFileName)
log.Debug(ctx).Str("service", "envoy").Str("location", cfgPath).Msg("wrote config file to location")
log.Ctx(ctx).Debug().Str("service", "envoy").Str("location", cfgPath).Msg("wrote config file to location")
return atomic.WriteFile(cfgPath, bytes.NewReader(confBytes))
}
@ -301,7 +301,7 @@ func (srv *Server) handleLogs(ctx context.Context, rc io.ReadCloser) {
}
func (srv *Server) monitorProcess(ctx context.Context, pid int32) {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Int32("pid", pid).
Msg("envoy: start monitoring subprocess")

2
pkg/envoy/envoy_darwin.go
View file

@ -18,7 +18,7 @@ func (srv *Server) runProcessCollector(_ context.Context) {}
func (srv *Server) prepareRunEnvoyCommand(ctx context.Context, sharedArgs []string) (exePath string, args []string) {
if srv.cmd != nil && srv.cmd.Process != nil {
log.Info(ctx).Msg("envoy: terminating previous envoy process")
log.Ctx(ctx).Info().Msg("envoy: terminating previous envoy process")
_ = srv.cmd.Process.Kill()
}

2
pkg/envoy/envoy_linux.go
View file

@ -66,7 +66,7 @@ func (srv *Server) runProcessCollector(ctx context.Context) {
func (srv *Server) prepareRunEnvoyCommand(ctx context.Context, sharedArgs []string) (exePath string, args []string) {
// release the previous process so we can hot-reload
if srv.cmd != nil && srv.cmd.Process != nil {
log.Info(ctx).Msg("envoy: releasing envoy process for hot-reload")
log.Ctx(ctx).Info().Msg("envoy: releasing envoy process for hot-reload")
err := srv.cmd.Process.Release()
if err != nil {
log.Ctx(ctx).Error().Err(err).Str("service", "envoy").Msg("envoy: failed to release envoy process for hot-reload")

2
pkg/envoy/envoy_other.go
View file

@ -13,7 +13,7 @@ func (srv *Server) runProcessCollector(ctx context.Context) {}
func (srv *Server) prepareRunEnvoyCommand(ctx context.Context, sharedArgs []string) (exePath string, args []string) {
if srv.cmd != nil && srv.cmd.Process != nil {
log.Info(ctx).Msg("envoy: terminating previous envoy process")
log.Ctx(ctx).Info().Msg("envoy: terminating previous envoy process")
_ = srv.cmd.Process.Kill()
}

4
pkg/envoy/get-envoy/main.go
View file

@ -93,7 +93,7 @@ func download(
}
if timesMatch(fi.ModTime(), lastModified) {
log.Debug(ctx).Str("url", srcURL).Str("dst", dstPath).Msg("skipping download")
log.Ctx(ctx).Debug().Str("url", srcURL).Str("dst", dstPath).Msg("skipping download")
return nil
}
@ -101,7 +101,7 @@ func download(
return fmt.Errorf("error reading destination path file info (dst=%s): %w", dstPath, err)
}
log.Info(ctx).Str("url", srcURL).Str("dst", dstPath).Msg("downloading")
log.Ctx(ctx).Info().Str("url", srcURL).Str("dst", dstPath).Msg("downloading")
req, err := http.NewRequestWithContext(ctx, http.MethodGet, srcURL, nil)
if err != nil {

16
pkg/envoy/resource_monitor_linux.go
View file

@ -283,7 +283,7 @@ func (s *sharedResourceMonitor) Run(ctx context.Context, envoyPid int) error {
if envoyCgroup != s.cgroup {
return fmt.Errorf("envoy process is not in the expected cgroup: %s", envoyCgroup)
}
log.Info(ctx).Str("service", "envoy").Str("cgroup", s.cgroup).Msg("starting resource monitor")
log.Ctx(ctx).Info().Str("service", "envoy").Str("cgroup", s.cgroup).Msg("starting resource monitor")
ctx, ca := context.WithCancelCause(ctx)
@ -346,7 +346,7 @@ LOOP:
}
s.updateActionStates(ctx, saturation)
metrics.RecordEnvoyCgroupMemorySaturation(ctx, s.cgroup, saturation)
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("service", "envoy").
Str("metric", metricCgroupMemorySaturation).
Str("value", saturationStr).
@ -693,10 +693,10 @@ func (w *memoryLimitWatcher) Watch(ctx context.Context) error {
return err
}
closeInotify := sync.OnceFunc(func() {
log.Debug(ctx).Msg("stopping memory limit watcher")
log.Ctx(ctx).Debug().Msg("stopping memory limit watcher")
unix.Close(fd)
})
log.Debug(ctx).Str("file", w.limitFilePath).Msg("starting watch")
log.Ctx(ctx).Debug().Str("file", w.limitFilePath).Msg("starting watch")
wd, err := unix.InotifyAddWatch(fd, w.limitFilePath, unix.IN_MODIFY)
if err != nil {
closeInotify()
@ -704,7 +704,7 @@ func (w *memoryLimitWatcher) Watch(ctx context.Context) error {
}
w.watches.Add(1)
closeWatch := sync.OnceFunc(func() {
log.Debug(ctx).Str("file", w.limitFilePath).Msg("stopping watch")
log.Ctx(ctx).Debug().Str("file", w.limitFilePath).Msg("stopping watch")
_, _ = unix.InotifyRmWatch(fd, uint32(wd))
closeInotify()
w.watches.Done()
@ -717,7 +717,7 @@ func (w *memoryLimitWatcher) Watch(ctx context.Context) error {
return err
}
w.value.Store(v)
log.Debug(ctx).Uint64("bytes", v).Msg("current memory limit")
log.Ctx(ctx).Debug().Uint64("bytes", v).Msg("current memory limit")
context.AfterFunc(ctx, closeWatch) // to unblock unix.Read below
go func() {
@ -728,7 +728,7 @@ func (w *memoryLimitWatcher) Watch(ctx context.Context) error {
if err != nil {
log.Ctx(ctx).Error().Err(err).Msg("error reading memory limit")
} else if prev := w.value.Swap(v); prev != v {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Uint64("prev", prev).
Uint64("current", v).
Msg("memory limit updated")
@ -747,7 +747,7 @@ func (w *memoryLimitWatcher) Watch(ctx context.Context) error {
if (event.Mask & unix.IN_IGNORED) != 0 {
// watch was removed, or the file was deleted (this can happen if
// the memory controller is removed from the parent's subtree_control)
log.Info(ctx).Str("file", w.limitFilePath).Msg("watched file removed")
log.Ctx(ctx).Info().Str("file", w.limitFilePath).Msg("watched file removed")
return
}
}

2
pkg/grpc/client.go
View file

@ -55,7 +55,7 @@ func NewGRPCClientConn(ctx context.Context, opts *Options, other ...grpc.DialOpt
grpc.WithInsecure(),
}
dialOptions = append(dialOptions, other...)
log.Debug(ctx).Str("address", opts.Address).Msg("grpc: dialing")
log.Ctx(ctx).Debug().Str("address", opts.Address).Msg("grpc: dialing")
return grpc.DialContext(ctx, opts.Address, dialOptions...)
}

2
pkg/grpc/databroker/fast_forward.go
View file

@ -91,7 +91,7 @@ func (ff *fastForwardHandler) UpdateRecords(ctx context.Context, serverVersion u
})
dropped := cnt - len(records)
if dropped > 0 {
log.Info(ctx).Msgf("databroker: fast-forwarded %d records", dropped)
log.Ctx(ctx).Info().Msgf("databroker: fast-forwarded %d records", dropped)
}
// reverse back so they appear in the order they were delivered
slices.Reverse(records)

4
pkg/grpc/databroker/leaser.go
View file

@ -101,7 +101,7 @@ func (locker *Leaser) runOnce(ctx context.Context, resetBackoff func()) error {
resetBackoff()
leaseID := res.Id
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("lease_name", locker.leaseName).
Str("lease_id", leaseID).
Msg("leaser: lease acquired")
@ -142,7 +142,7 @@ func (locker *Leaser) withLease(ctx context.Context, leaseID string) error {
Duration: durationpb.New(locker.ttl),
})
if status.Code(err) == codes.AlreadyExists {
log.Debug(ctx).
log.Ctx(ctx).Debug().
Str("lease_name", locker.leaseName).
Str("lease_id", leaseID).
Msg("leaser: lease lost")

6
pkg/grpc/databroker/syncer.go
View file

@ -128,7 +128,7 @@ func (syncer *Syncer) Run(ctx context.Context) error {
}
func (syncer *Syncer) init(ctx context.Context) error {
log.Debug(ctx).Msg("initial sync")
log.Ctx(ctx).Debug().Msg("initial sync")
records, recordVersion, serverVersion, err := InitialSync(ctx, syncer.handler.GetDataBrokerServiceClient(), &SyncLatestRequest{
Type: syncer.cfg.typeURL,
})
@ -157,7 +157,7 @@ func (syncer *Syncer) sync(ctx context.Context) error {
return fmt.Errorf("error calling sync: %w", err)
}
log.Debug(ctx).Msg("listening for updates")
log.Ctx(ctx).Debug().Msg("listening for updates")
for {
res, err := stream.Recv()
@ -171,7 +171,7 @@ func (syncer *Syncer) sync(ctx context.Context) error {
}
rec := res.GetRecord()
log.Debug(logCtxRec(ctx, rec)).Msg("syncer got record")
log.Ctx(logCtxRec(ctx, rec)).Debug().Msg("syncer got record")
syncer.recordVersion = res.GetRecord().GetVersion()
if syncer.cfg.typeURL == "" || syncer.cfg.typeURL == res.GetRecord().GetType() {

2
pkg/grpc/health.go
View file

@ -20,7 +20,7 @@ func NewHealthCheckServer() grpc_health.HealthServer {
// Check confirms service is reachable, and assumes any service is operational
// an outlier detection should be used to detect runtime malfunction based on consequitive 5xx
func (h *healthCheckSrv) Check(ctx context.Context, req *grpc_health.HealthCheckRequest) (*grpc_health.HealthCheckResponse, error) {
log.Debug(ctx).Str("service", req.Service).Msg("health check")
log.Ctx(ctx).Debug().Str("service", req.Service).Msg("health check")
return &grpc_health.HealthCheckResponse{
Status: grpc_health.HealthCheckResponse_SERVING,
}, nil

18
pkg/identity/legacymanager/manager.go
View file

@ -135,7 +135,7 @@ func (mgr *Manager) refreshLoop(ctx context.Context, update <-chan updateRecords
mgr.onUpdateRecords(ctx, msg)
}
log.Debug(ctx).
log.Ctx(ctx).Debug().
Int("sessions", mgr.sessions.Len()).
Int("users", mgr.users.Len()).
Msg("initial sync complete")
@ -205,14 +205,14 @@ func (mgr *Manager) refreshLoop(ctx context.Context, update <-chan updateRecords
// user info refresh. If an access token refresh or a user info refresh fails
// with a permanent error, the session will be deleted.
func (mgr *Manager) refreshSession(ctx context.Context, userID, sessionID string) {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Str("session_id", sessionID).
Msg("refreshing session")
s, ok := mgr.sessions.Get(userID, sessionID)
if !ok {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Str("session_id", sessionID).
Msg("no session found for refresh")
@ -234,7 +234,7 @@ func (mgr *Manager) refreshSessionInternal(
) bool {
authenticator := mgr.cfg.Load().authenticator
if authenticator == nil {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Str("session_id", sessionID).
Msg("no authenticator defined, deleting session")
@ -244,7 +244,7 @@ func (mgr *Manager) refreshSessionInternal(
expiry := s.GetExpiresAt().AsTime()
if !expiry.After(mgr.now()) {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Str("session_id", sessionID).
Msg("deleting expired session")
@ -253,7 +253,7 @@ func (mgr *Manager) refreshSessionInternal(
}
if s.Session == nil || s.Session.OauthToken == nil {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Str("session_id", sessionID).
Msg("no session oauth2 token found for refresh")
@ -313,7 +313,7 @@ func (mgr *Manager) refreshSessionInternal(
}
func (mgr *Manager) refreshUser(ctx context.Context, userID string) {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Msg("refreshing user")
@ -324,7 +324,7 @@ func (mgr *Manager) refreshUser(ctx context.Context, userID string) {
u, ok := mgr.users.Get(userID)
if !ok {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Msg("no user found for refresh")
return
@ -334,7 +334,7 @@ func (mgr *Manager) refreshUser(ctx context.Context, userID string) {
for _, s := range mgr.sessions.GetSessionsForUser(userID) {
if s.Session == nil || s.Session.OauthToken == nil {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", userID).
Msg("no session oauth2 token found for refresh")
continue

4
pkg/identity/manager/manager.go
View file

@ -218,7 +218,7 @@ func (mgr *Manager) refreshSession(ctx context.Context, sessionID string) {
expiry := s.GetExpiresAt().AsTime()
if !expiry.After(mgr.cfg.Load().now()) {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", s.GetUserId()).
Str("session_id", s.GetId()).
Msg("deleting expired session")
@ -227,7 +227,7 @@ func (mgr *Manager) refreshSession(ctx context.Context, sessionID string) {
}
if s.GetOauthToken() == nil {
log.Info(ctx).
log.Ctx(ctx).Info().
Str("user_id", s.GetUserId()).
Str("session_id", s.GetId()).
Msg("no session oauth2 token found for refresh")

2
pkg/identity/oauth/github/github.go
View file

@ -152,7 +152,7 @@ func (p *Provider) userEmail(ctx context.Context, t *oauth2.Token, v any) error
Email string `json:"email"`
Verified bool `json:"email_verified"`
}
log.Debug(ctx).Interface("emails", response).Msg("github: user emails")
log.Ctx(ctx).Debug().Interface("emails", response).Msg("github: user emails")
for _, email := range response {
if email.Primary && email.Verified {
out.Email = email.Email

2
proxy/proxy.go
View file

@ -105,7 +105,7 @@ func (p *Proxy) OnConfigChange(_ context.Context, cfg *config.Config) {
func (p *Proxy) setHandlers(opts *config.Options) error {
if opts.NumPolicies() == 0 {
log.Info(context.TODO()).Msg("proxy: configuration has no policies")
log.Info().Msg("proxy: configuration has no policies")
}
r := httputil.NewRouter()
r.NotFoundHandler = httputil.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) error {