Merge pull request #256 from simonmittag/255

255

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
 }

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
 }

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()).

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
 }

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

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

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

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

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()).

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

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
 }