diff --git a/acmehandler.go b/acmehandler.go index af02694..9dafd96 100644 --- a/acmehandler.go +++ b/acmehandler.go @@ -51,7 +51,7 @@ func (a *AcmeHandler) Present(domain, token, keyAuth string) error { a.Domains[token] = domain a.KeyAuths[token] = []byte(keyAuth) - log.Debug().Msgf("ACME handler for domain %s activated, ready to serve challenge response for token %s.", domain, token) + log.Info().Msgf("ACME handler for domain %s activated, ready to serve challenge response for token %s.", domain, token) return nil } @@ -60,7 +60,7 @@ func (a *AcmeHandler) CleanUp(domain, token, keyAuth string) error { delete(a.Domains, token) delete(a.KeyAuths, token) - log.Debug().Msgf("ACME handler for domain %s deactivated.", domain) + log.Info().Msgf("ACME handler for domain %s deactivated.", domain) return nil } @@ -77,7 +77,7 @@ const acmeEvent = "responded to remote ACME challenge path %s, with %s for domai func acmeHandler(w http.ResponseWriter, r *http.Request) { defer func() { if r1 := recover(); r1 != nil { - log.Debug().Msgf("unsuccessful response to remote ACME challenge, URI %s, cause: %v", r.RequestURI, r1) + log.Warn().Msgf("unsuccessful response to remote ACME challenge, URI %s, cause: %v", r.RequestURI, r1) } }() @@ -88,7 +88,7 @@ func acmeHandler(w http.ResponseWriter, r *http.Request) { path := http01.ChallengePath(token) w.WriteHeader(200) w.Write([]byte(a.KeyAuths[token])) - log.Debug().Msgf(acmeEvent, path, a.KeyAuths[token], a.Domains[token]) + log.Info().Msgf(acmeEvent, path, a.KeyAuths[token], a.Domains[token]) } type AcmeUser struct { @@ -140,7 +140,7 @@ func (runtime *Runtime) loadAcmeCertAndKeyFromCache(provider string) error { os.Remove(keyFile) os.Remove(certFile) os.Remove(hashFile) - log.Debug().Msg(msg) + log.Info().Msg(msg) } if c := bytes.Compare(hash, runtime.acmeProviderHashAsBytes()); c != 0 { @@ -152,7 +152,7 @@ func (runtime *Runtime) loadAcmeCertAndKeyFromCache(provider string) error { if _, e3 := checkFullCertChainFromBytes(cert, key); e3 == nil { runtime.Connection.Downstream.Tls.Key = string(key) runtime.Connection.Downstream.Tls.Cert = string(cert) - log.Debug().Msgf("TLS cert and key for ACME provider %s loaded from cache", provider) + log.Info().Msgf("TLS cert and key for ACME provider %s loaded from cache", provider) } else { //if delete doesn't work ignore this it may already be gone (partially). msg := fmt.Sprintf("unable to load data, clearing TLS cache for ACME provider %s", provider) @@ -199,7 +199,7 @@ func (runtime *Runtime) cacheAcmeCertAndKey(provider string) error { return e3 } - log.Debug().Msgf("stored TLS cert and key for ACME provider %s in cache", provider) + log.Info().Msgf("stored TLS cert and key for ACME provider %s in cache", provider) return e } @@ -220,7 +220,7 @@ func (runtime *Runtime) fetchAcmeCertAndKey(url string) error { defer func() { if r := recover(); r != nil { msg := fmt.Sprintf("TLS ACME certificate not fetched, cause: %s", r) - log.Debug().Msg(msg) + log.Warn().Msg(msg) e = errors.New(msg) } }() @@ -264,14 +264,14 @@ func (runtime *Runtime) fetchAcmeCertAndKey(url string) error { var c *certificate.Resource c, e = client.Certificate.Obtain(request) if e != nil { - log.Debug().Msgf("ACME certificate from %s unsuccessful, cause %v", url, e) + log.Warn().Msgf("ACME certificate from %s unsuccessful, cause %v", url, e) return e } runtime.Connection.Downstream.Tls.Cert = string(c.Certificate) runtime.Connection.Downstream.Tls.Key = string(c.PrivateKey) - log.Debug().Msgf("ACME certificate successfully fetched from %s", url) + log.Info().Msgf("ACME certificate successfully fetched from %s", url) return e } diff --git a/config.go b/config.go index 803b170..c787108 100644 --- a/config.go +++ b/config.go @@ -36,28 +36,28 @@ const DefaultConfigFile = "j8acfg.yml" func (config Config) load() *Config { if len(ConfigFile) > 0 { - log.Debug().Msgf("attempting config from file '%s'", ConfigFile) + log.Info().Msgf("attempting config from file '%s'", ConfigFile) if cfg := *config.readYmlFile(ConfigFile); cfg.ok() { config = cfg } else { config.panic(fmt.Sprintf("error loading config from file '%s'", ConfigFile)) } } else if len(os.Getenv(J8ACFG_YML)) > 0 { - log.Debug().Msgf("attempting config from env %s", J8ACFG_YML) + log.Info().Msgf("attempting config from env %s", J8ACFG_YML) if cfg := *config.readYmlEnv(); cfg.ok() { config = cfg } else { config.panic(fmt.Sprintf("error loading config from env '%s'", J8ACFG_YML)) } } else { - log.Debug().Msgf("attempting config from default file '%s'", DefaultConfigFile) + log.Info().Msgf("attempting config from default file '%s'", DefaultConfigFile) if cfg := config.readYmlFile(DefaultConfigFile); cfg.ok() { config = *cfg } else { config.panic(fmt.Sprintf("error loading config from default file '%s'", DefaultConfigFile)) } } - log.Debug().Msgf("parsed config with %d live routes", config.Routes.Len()) + log.Info().Msgf("parsed config with %d live routes", config.Routes.Len()) return &config } @@ -335,7 +335,7 @@ func (config Config) validateJwt() *Config { } config.Jwt[name] = jwt } - log.Debug().Msgf("parsed %d jwt configurations", len(config.Jwt)) + log.Info().Msgf("parsed %d jwt configurations", len(config.Jwt)) } return &config } diff --git a/httpclient.go b/httpclient.go index 0b8dae4..a480865 100644 --- a/httpclient.go +++ b/httpclient.go @@ -46,7 +46,7 @@ func scaffoldHTTPClient(runtime *Runtime) HTTPClient { }, } - log.Debug(). + log.Info(). Int("upMaxIdleConns", runtime.Connection.Upstream.PoolSize). Int("upMaxIdleConnsPerHost", runtime.Connection.Upstream.PoolSize). Float64("upTransportDialTimeoutSecs", socketTimeoutDuration.Seconds()). diff --git a/jwt.go b/jwt.go index 4f75a4f..19cc7c7 100644 --- a/jwt.go +++ b/jwt.go @@ -203,7 +203,7 @@ func (jwt *Jwt) LoadJwks() error { var keyset jwk.Set keyset, err = jwk.Fetch(context.Background(), jwt.JwksUrl) if err == nil { - log.Debug().Msgf("jwt [%s] fetched %d jwk from jwks URL %s", jwt.Name, keyset.Len(), jwt.JwksUrl) + log.Info().Msgf("jwt [%s] fetched %d jwk from jwks URL %s", jwt.Name, keyset.Len(), jwt.JwksUrl) } else { log.Warn().Msgf("jwt [%s] unable to fetch jwk from jwks URL %s, cause: %v", jwt.Name, jwt.JwksUrl, err) } @@ -261,7 +261,7 @@ func (jwt *Jwt) LoadJwks() error { default: err = errors.New(fmt.Sprintf("unknown key type in Jwks %v", alg.String())) } - log.Debug().Msgf("jwt [%s] successfully parsed %s key from remote jwk", jwt.Name, alg) + log.Info().Msgf("jwt [%s] successfully parsed %s key from remote jwk", jwt.Name, alg) } else { break Keyrange } @@ -276,7 +276,7 @@ func (jwt *Jwt) LoadJwks() error { //release here, don't use defer jwt.lock.Release(1) } else { - log.Debug(). + log.Info(). Str("jwt", jwt.Name). Msgf("jwt [%s] already updating within 10s, skipping attempt.", jwt.Name) } @@ -406,7 +406,7 @@ func (jwt *Jwt) parseKey(alg jwa.SignatureAlgorithm) error { return errors.New(fmt.Sprintf(keyTypeInvalid, jwt.Name, validAlg)) } - log.Debug().Msgf("jwt [%s] successfully parsed %s key", jwt.Name, alg) + log.Info().Msgf("jwt [%s] successfully parsed %s key", jwt.Name, alg) return err } diff --git a/logger.go b/logger.go index 804cf77..6a8d696 100644 --- a/logger.go +++ b/logger.go @@ -45,7 +45,7 @@ func initServerID() { hasher := md5.New() hasher.Write([]byte(getHost() + getVersion())) ID = hex.EncodeToString(hasher.Sum(nil))[0:8] - log.Debug().Str("srvID", ID).Msg("srvID determined") + log.Info().Str("srvID", ID).Msg("srvID determined") log.Logger = log.With().Str("srvId", ID).Logger() } @@ -54,12 +54,12 @@ func getHost() string { if len(host) == 0 { host, _ = os.Hostname() } - log.Debug().Str("hostName", host).Msg("hostName determined") + log.Info().Str("hostName", host).Msg("hostName determined") return host } func getVersion() string { - log.Debug().Str("version", Version).Msg("version determined") + log.Info().Str("version", Version).Msg("version determined") return Version } @@ -93,5 +93,5 @@ func initLogger() { initServerID() initTime() - log.Debug().Msgf("setting global log level to %s", logLevel) + log.Info().Msgf("setting global log level to %s", logLevel) } diff --git a/proxy.go b/proxy.go index 1d75bb9..cd65394 100644 --- a/proxy.go +++ b/proxy.go @@ -506,6 +506,16 @@ func infoOrTraceEv(proxy *Proxy) *zerolog.Event { return ev } +func infoOrDebugEv(proxy *Proxy) *zerolog.Event { + var ev *zerolog.Event + if proxy.XRequestInfo { + ev = log.Info() + } else { + ev = log.Debug() + } + return ev +} + func parseMethod(request *http.Request) string { return strings.ToUpper(request.Method) } @@ -906,7 +916,7 @@ func (proxy *Proxy) triggerKeyRotationCheck(kid string) { if len(routeSec.JwksUrl) > 0 { //MUST run async since it will block on loading remote JWKS key go routeSec.LoadJwks() - log.Debug(). + log.Info(). Str("route", route.Path). Str("jwt", route.Jwt). Str(XRequestID, proxy.XRequestID). diff --git a/proxyhandler.go b/proxyhandler.go index 9ed1514..1b09c0e 100644 --- a/proxyhandler.go +++ b/proxyhandler.go @@ -168,14 +168,7 @@ func scaffoldUpstreamRequest(proxy *Proxy) *http.Request { upURI, proxy.bodyReader()) - var ev *zerolog.Event - if proxy.XRequestInfo { - ev = log.Info() - } else { - ev = log.Trace() - } - - ev.Str(dwnReqPath, proxy.Dwn.Path). + infoOrTraceEv(proxy).Str(dwnReqPath, proxy.Dwn.Path). Int64(dwnElpsdMicros, time.Since(proxy.Dwn.startDate).Microseconds()). Str(XRequestID, proxy.XRequestID). Str(upReqURI, upURI). @@ -430,14 +423,7 @@ func shouldProxyHeader(header string) bool { } func scaffoldUpAttemptLog(proxy *Proxy) *zerolog.Event { - var ev *zerolog.Event - if proxy.XRequestInfo { - ev = log.Info() - } else { - ev = log.Trace() - } - - return ev. + return infoOrTraceEv(proxy). Str(XRequestID, proxy.XRequestID). Int64(upAtmtpElpsdMicros, time.Since(proxy.Up.Atmpt.startDate).Microseconds()). Int64(dwnElpsdMicros, time.Since(proxy.Dwn.startDate).Microseconds()). @@ -452,7 +438,7 @@ const pdS = "%d" func logHandledDownstreamRoundtrip(proxy *Proxy) { elapsed := time.Since(proxy.Dwn.startDate) msg := downstreamResponseServed - ev := log.Info() + ev := infoOrDebugEv(proxy) if proxy.hasMadeUpstreamAttempt() { ev = ev.Str(upReqURI, proxy.resolveUpstreamURI()). @@ -466,6 +452,7 @@ func logHandledDownstreamRoundtrip(proxy *Proxy) { if proxy.Dwn.Resp.StatusCode > 399 { msg = downstreamErrorResponseServed + //upgrade the message to warn for anything 400 and up ev = log.Warn() ev = ev.Str(dwnResErrMsg, proxy.Dwn.Resp.Message) } diff --git a/redirecthandler.go b/redirecthandler.go index 3a784fb..b2375dd 100644 --- a/redirecthandler.go +++ b/redirecthandler.go @@ -2,7 +2,6 @@ package j8a import ( "fmt" - "github.com/rs/zerolog/log" "net/http" "strings" "time" @@ -40,7 +39,7 @@ func redirectHandler(response http.ResponseWriter, request *http.Request) { target += Q + request.URL.RawQuery } - log.Info().Str("dwnReqListnr", proxy.Dwn.Listener). + infoOrDebugEv(proxy).Str("dwnReqListnr", proxy.Dwn.Listener). Str("dwnReqPort", fmt.Sprintf("%d", proxy.Dwn.Port)). Str("dwnReqPath", proxy.Dwn.Path). Str("dwnReqRemoteAddr", ipr.extractAddr(proxy.Dwn.Req.RemoteAddr)). diff --git a/server.go b/server.go index 47563be..02fb3b4 100644 --- a/server.go +++ b/server.go @@ -67,7 +67,7 @@ func (r *ReloadableCert) triggerInit() error { r.Cert.Leaf, err = x509.ParseCertificate(cert.Certificate[0]) } if err == nil { - log.Debug().Msgf("TLS certificate #%v initialized", formatSerial(cert.Leaf.SerialNumber)) + log.Info().Msgf("TLS certificate #%v initialized", formatSerial(cert.Leaf.SerialNumber)) } r.Init = false return err @@ -211,11 +211,11 @@ func (r *Runtime) initCacheDir() *Runtime { e2 := os.Mkdir(myCacheDir, acmeRwx) if e2 == nil { r.cacheDir = myCacheDir - log.Debug().Msg("init cache dir in user home") + log.Info().Msg("init cache dir in user home") } } else { r.cacheDir = myCacheDir - log.Debug().Msg("found cache dir in user home") + log.Info().Msg("found cache dir in user home") } } return r @@ -241,7 +241,7 @@ func (rt *Runtime) startListening() { roundTripTimeoutDurationWithGrace := roundTripTimeoutDuration + (time.Second * 1) idleTimeoutDuration := time.Second * time.Duration(rt.Connection.Downstream.IdleTimeoutSeconds) - log.Debug(). + log.Info(). Int64("dwnMaxBodyBytes", rt.Connection.Downstream.MaxBodyBytes). Float64("dwnReadTimeoutSeconds", readTimeoutDuration.Seconds()). Float64("dwnRoundTripTimeoutSeconds", roundTripTimeoutDuration.Seconds()). diff --git a/stats.go b/stats.go index 735b052..763d653 100644 --- a/stats.go +++ b/stats.go @@ -46,11 +46,11 @@ var procStatsLock sync.Mutex var procHistory samples const pid = "pid" -const pidCPUCorePct = "pidCpuCore" +const pidCPUCorePct = "pidCpuCorePct" const pidMemPct = "pidMemPct" -const pidRssBytes = "pidRssBytes" -const pidVmsBytes = "pidVmsBytes" -const pidSwapBytes = "pidSwapBytes" +const pidRssBytes = "pidMemRssBytes" +const pidVmsBytes = "pidMemVmsBytes" +const pidSwapBytes = "pidMemSwapBytes" const pidDwnOpenTcpConns = "pidDwnOpenTcpConns" const pidDwnMaxOpenTcpConns = "pidDwnMaxOpenTcpConns" const pidUpOpenTcpConns = "pidUpOpenTcpConns" @@ -62,7 +62,7 @@ const pcd2f = "%.2f" const rssMemIncrease = "RSS memory increase for previous %s with high factor >=%s, monitor actively." func (s sample) log() { - log.Debug(). + log.Info(). Int32(pid, s.pid). Str(pidCPUCorePct, fmt.Sprintf(pcd2f, s.cpuPc)). Str(pidMemPct, fmt.Sprintf(pcd2f, s.mPc)). @@ -106,7 +106,7 @@ func (samples *samples) log() []growthRate { High: for m := len(*samples) - 1; m >= 0; m-- { if growthRates[m].high { - log.Debug(). + log.Info(). Msgf(rssMemIncrease, durafmt.Parse(time.Duration(time.Second*historySamplerSleepSeconds*historyMaxSamples)).LimitFirstN(1).String(), fmt.Sprintf("%.1f", growthRateThreshold)) @@ -235,7 +235,7 @@ func (rt *Runtime) logUptime() { upNanos := time.Since(rt.Start) if upNanos > time.Second*10 { uptime := durafmt.Parse(upNanos).LimitFirstN(1).String() - log.Debug(). + log.Info(). Int(pid, os.Getpid()). Int64(uptimeMicros, int64(upNanos/1000)). Msgf(fmt.Sprintf("server upTime is %s", uptime)) diff --git a/time.go b/time.go index 89ca3ff..a595e1c 100644 --- a/time.go +++ b/time.go @@ -13,7 +13,7 @@ func initTime() string { if len(tz) == 0 { tz = "UTC" } - log.Debug().Str("timeZone", tz).Msg("timeZone determined") + log.Info().Str("timeZone", tz).Msg("timeZone determined") TZ = tz return tz } diff --git a/tls.go b/tls.go index ba34b1e..efa4a12 100644 --- a/tls.go +++ b/tls.go @@ -96,7 +96,7 @@ const acmeRetry24h = "unable to renew ACME certificate from provider %s, cause: func (r *Runtime) renewAcmeCertAndKey() error { p := r.Connection.Downstream.Tls.Acme.Provider - log.Debug().Msgf("triggering renewal of ACME certificate from provider %s ", p) + log.Info().Msgf("triggering renewal of ACME certificate from provider %s ", p) e1 := r.fetchAcmeCertAndKey(acmeProviders[p]) if e1 == nil { @@ -114,7 +114,7 @@ func (r *Runtime) renewAcmeCertAndKey() error { e3 := r.ReloadableCert.triggerInit() if e3 == nil { logCertStats(newCerts) - log.Debug().Msgf("successful renewal of ACME certificate from provider %s complete", p) + log.Info().Msgf("successful renewal of ACME certificate from provider %s complete", p) } else { log.Warn().Msgf(acmeRetry24h, p, e3) return e3 @@ -292,7 +292,7 @@ func logCertStats(tlsLinks []TlsLink) { if t.expiresTooCloseForComfort() || t.legalBrowserValidityPeriodPassed() { ev = log.Warn() } else { - ev = log.Debug() + ev = log.Info() } ev.Msg(sb.String()) }