[log] [metric] Log Setting API, More TRACE Logs, and Gatherer Support

pkg/eventstreams/eventstreams.go

@@ -243,7 +243,7 @@ func (esm *esManager[CT, DT]) initEventStream(
 		return nil, err
 	}
 
-	streamCtx := log.WithLogField(esm.bgCtx, "eventstream", *spec.ESFields().Name)
+	streamCtx := log.WithLogFields(esm.bgCtx, "eventstream", *spec.ESFields().Name)
 	es = &eventStream[CT, DT]{
 		bgCtx:       streamCtx,
 		esm:         esm,

pkg/ffapi/apiserver.go

@@ -33,7 +33,9 @@ import (
 	"github.com/hyperledger/firefly-common/pkg/fftls"
 	"github.com/hyperledger/firefly-common/pkg/httpserver"
 	"github.com/hyperledger/firefly-common/pkg/i18n"
+	"github.com/hyperledger/firefly-common/pkg/log"
 	"github.com/hyperledger/firefly-common/pkg/metric"
+	"github.com/sirupsen/logrus"
 )
 
 const APIServerMetricsSubSystemName = "api_server_rest"
@@ -65,6 +67,7 @@ type apiServer[T any] struct {
 	monitoringEnabled         bool
 	metricsPath               string
 	livenessPath              string
+	loggingPath               string
 	monitoringPublicURL       string
 	mux                       *mux.Router
 	oah                       *OpenAPIHandlerFactory
@@ -121,6 +124,7 @@ func NewAPIServer[T any](ctx context.Context, options APIServerOptions[T]) APISe
 		monitoringEnabled:         options.MonitoringConfig.GetBool(ConfMonitoringServerEnabled),
 		metricsPath:               options.MonitoringConfig.GetString(ConfMonitoringServerMetricsPath),
 		livenessPath:              options.MonitoringConfig.GetString(ConfMonitoringServerLivenessPath),
+		loggingPath:               options.MonitoringConfig.GetString(ConfMonitoringServerLoggingPath),
 		alwaysPaginate:            options.APIConfig.GetBool(ConfAPIAlwaysPaginate),
 		handleYAML:                options.HandleYAML,
 		apiDynamicPublicURLHeader: options.APIConfig.GetString(ConfAPIDynamicPublicURLHeader),
@@ -271,8 +275,8 @@ func (as *apiServer[T]) routeHandler(hf *HandlerFactory, route *Route) http.Hand
 	return hf.RouteHandler(route)
 }
 
-func (as *apiServer[T]) handlerFactory() *HandlerFactory {
-	return &HandlerFactory{
+func (as *apiServer[T]) handlerFactory(logLevel logrus.Level) *HandlerFactory {
+	hf := &HandlerFactory{
 		DefaultRequestTimeout: as.requestTimeout,
 		MaxTimeout:            as.requestMaxTimeout,
 		DefaultFilterLimit:    as.defaultFilterLimit,
@@ -282,11 +286,13 @@ func (as *apiServer[T]) handlerFactory() *HandlerFactory {
 		AlwaysPaginate:        as.alwaysPaginate,
 		HandleYAML:            as.handleYAML,
 	}
+	hf.SetAPIEntryLoggingLevel(logLevel)
+	return hf
 }
 
 func (as *apiServer[T]) createMuxRouter(ctx context.Context) (*mux.Router, error) {
 	r := mux.NewRouter().UseEncodedPath()
-	hf := as.handlerFactory()
+	hf := as.handlerFactory(logrus.InfoLevel)
 
 	as.oah = &OpenAPIHandlerFactory{
 		BaseSwaggerGenOptions: SwaggerGenOptions{
@@ -390,15 +396,44 @@ func (as *apiServer[T]) noContentResponder(res http.ResponseWriter, _ *http.Requ
 	res.WriteHeader(http.StatusNoContent)
 }
 
+func (as *apiServer[T]) loggingSettingsHandler(_ http.ResponseWriter, req *http.Request) (status int, err error) {
+	if req.Method != http.MethodPut {
+		return http.StatusMethodNotAllowed, i18n.NewError(req.Context(), i18n.MsgMethodNotAllowed)
+	}
+	logLevel := req.URL.Query().Get("level")
+	if logLevel != "" {
+		l := log.L(log.WithLogFieldsMap(req.Context(), map[string]string{"new_level": logLevel}))
+		switch strings.ToLower(logLevel) {
+		case "error":
+		case "debug":
+		case "trace":
+		case "info":
+		case "warn":
+			// noop - all valid levels
+		default:
+			l.Warn("invalid log level")
+			return http.StatusBadRequest, i18n.NewError(req.Context(), i18n.MsgInvalidLogLevel, logLevel)
+		}
+		l.Warn("changing log level", logLevel)
+		log.SetLevel(logLevel)
+	}
+
+	// TODO allow for toggling formatting (json, text), sampling, etc.
+
+	return http.StatusAccepted, nil
+}
+
 func (as *apiServer[T]) createMonitoringMuxRouter(ctx context.Context) (*mux.Router, error) {
 	r := mux.NewRouter().UseEncodedPath()
-	hf := as.handlerFactory() // TODO separate factory for monitoring ??
+	// This ensures logs aren't polluted with monitoring API requests such as metrics or probes
+	hf := as.handlerFactory(logrus.TraceLevel)
 
 	h, err := as.MetricsRegistry.HTTPHandler(ctx, promhttp.HandlerOpts{})
 	if err != nil {
 		panic(err)
 	}
 	r.Path(as.metricsPath).Handler(h)
+	r.Path(as.loggingPath).Handler(hf.APIWrapper(as.loggingSettingsHandler))
 	r.HandleFunc(as.livenessPath, as.noContentResponder)
 
 	for _, route := range as.MonitoringRoutes {

pkg/ffapi/apiserver_config.go

@@ -25,6 +25,7 @@ var (
 	ConfMonitoringServerEnabled      = "enabled"
 	ConfMonitoringServerMetricsPath  = "metricsPath"
 	ConfMonitoringServerLivenessPath = "livenessPath"
+	ConfMonitoringServerLoggingPath  = "loggingPath"
 
 	ConfAPIDefaultFilterLimit     = "defaultFilterLimit"
 	ConfAPIMaxFilterLimit         = "maxFilterLimit"
@@ -51,4 +52,5 @@ func InitAPIServerConfig(apiConfig, monitoringConfig, corsConfig config.Section)
 	monitoringConfig.AddKnownKey(ConfMonitoringServerEnabled, true)
 	monitoringConfig.AddKnownKey(ConfMonitoringServerMetricsPath, "/metrics")
 	monitoringConfig.AddKnownKey(ConfMonitoringServerLivenessPath, "/livez")
+	monitoringConfig.AddKnownKey(ConfMonitoringServerLoggingPath, "/logging")
 }

pkg/ffapi/handler.go

@@ -34,6 +34,7 @@ import (
 	"github.com/ghodss/yaml"
 	"github.com/gorilla/mux"
 	"github.com/hyperledger/firefly-common/pkg/fftypes"
+	"github.com/hyperledger/firefly-common/pkg/httpserver"
 	"github.com/hyperledger/firefly-common/pkg/i18n"
 	"github.com/hyperledger/firefly-common/pkg/log"
 	"github.com/sirupsen/logrus"
@@ -77,6 +78,8 @@ type HandlerFactory struct {
 	SupportFieldRedaction bool
 	BasePath              string
 	BasePathParams        []*PathParam
+
+	apiEntryLoggingLevel logrus.Level // the log level at which entry/exit logging is enabled at all (does not affect trace logging)
 }
 
 var ffMsgCodeExtractor = regexp.MustCompile(`^(FF\d+):`)
@@ -88,6 +91,10 @@ type multipartState struct {
 	close      func()
 }
 
+func (hs *HandlerFactory) SetAPIEntryLoggingLevel(logLevel logrus.Level) {
+	hs.apiEntryLoggingLevel = logLevel
+}
+
 func (hs *HandlerFactory) getFilePart(req *http.Request) (*multipartState, error) {
 	formParams := make(map[string]string)
 	ctx := req.Context()
@@ -368,22 +375,28 @@ func (hs *HandlerFactory) APIWrapper(handler HandlerFunction) http.HandlerFunc {
 		}
 		ctx = withRequestID(ctx, httpReqID)
 		ctx = withPassthroughHeaders(ctx, req, hs.PassthroughHeaders)
-		ctx = log.WithLogField(ctx, "httpreq", httpReqID)
+		ctx = log.WithLogFields(ctx, "httpreq", httpReqID)
 
 		req = req.WithContext(ctx)
 		defer cancel()
 
 		// Wrap the request itself in a log wrapper, that gives minimal request/response and timing info
-		l := log.L(ctx)
-		l.Infof("--> %s %s", req.Method, req.URL.Path)
+		addrFields := map[string]string{}
+		if remoteAddr := httpserver.RemoteAddr(ctx); remoteAddr != nil {
+			addrFields["remote"] = remoteAddr.String()
+		}
+		if localAddr := httpserver.LocalAddr(ctx); localAddr != nil {
+			addrFields["local"] = localAddr.String()
+		}
+		l := log.L(log.WithLogFieldsMap(ctx, addrFields))
+		l.Logf(hs.apiEntryLoggingLevel, "--> %s %s", req.Method, req.URL.Path)
 		startTime := time.Now()
 		status, err := handler(res, req)
 		durationMS := float64(time.Since(startTime)) / float64(time.Millisecond)
 		if err != nil {
-
 			if ffe, ok := (interface{}(err)).(i18n.FFError); ok {
 				if logrus.IsLevelEnabled(logrus.DebugLevel) {
-					log.L(ctx).Debugf("%s:\n%s", ffe.Error(), ffe.StackTrace())
+					l.Debugf("%s:\n%s", ffe.Error(), ffe.StackTrace())
 				}
 				status = ffe.HTTPStatus()
 			} else {
@@ -412,14 +425,14 @@ func (hs *HandlerFactory) APIWrapper(handler HandlerFunction) http.HandlerFunc {
 			if status < 300 {
 				status = 500
 			}
-			l.Infof("<-- %s %s [%d] (%.2fms): %s", req.Method, req.URL.Path, status, durationMS, err)
+			l.Logf(hs.apiEntryLoggingLevel, "<-- %s %s [%d] (%.2fms): %s", req.Method, req.URL.Path, status, durationMS, err)
 			res.Header().Add("Content-Type", "application/json")
 			res.WriteHeader(status)
 			_ = json.NewEncoder(res).Encode(&fftypes.RESTError{
 				Error: err.Error(),
 			})
 		} else {
-			l.Infof("<-- %s %s [%d] (%.2fms)", req.Method, req.URL.Path, status, durationMS)
+			l.Logf(hs.apiEntryLoggingLevel, "<-- %s %s [%d] (%.2fms)", req.Method, req.URL.Path, status, durationMS)
 		}
 	}
 }

pkg/ffapi/handler_test.go

@@ -52,14 +52,16 @@ const scientificParamLiteral = `{
 const configDir = "../../test/data/config"
 
 func newTestHandlerFactory(basePath string, basePathParams []*PathParam) *HandlerFactory {
-	return &HandlerFactory{
+	hr := &HandlerFactory{
 		DefaultRequestTimeout: 5 * time.Second,
 		PassthroughHeaders: []string{
 			"X-Custom-Header",
 		},
 		BasePath:       basePath,
 		BasePathParams: basePathParams,
 	}
+	hr.SetAPIEntryLoggingLevel(logrus.DebugLevel)
+	return hr
 }
 
 func newTestServer(t *testing.T, routes []*Route, basePath string, basePathParams []*PathParam) (httpserver.HTTPServer, *mux.Router, func()) {

pkg/ffapi/openapihandler_test.go

@@ -27,6 +27,7 @@ import (
 	"github.com/gorilla/mux"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"github.com/sirupsen/logrus"
 )
 
 func TestOpenAPI3SwaggerUI(t *testing.T) {
@@ -104,6 +105,7 @@ func TestOpenAPI3SwaggerUIDynamicPublicURL(t *testing.T) {
 func TestOpenAPIHandlerNonVersioned(t *testing.T) {
 	mux := mux.NewRouter()
 	hf := HandlerFactory{}
+	hf.SetAPIEntryLoggingLevel(logrus.DebugLevel)
 	oah := &OpenAPIHandlerFactory{
 		BaseSwaggerGenOptions: SwaggerGenOptions{
 			Title:                 "FireFly Transaction Manager API",

pkg/ffresty/ffresty.go

@@ -288,7 +288,7 @@ func NewWithConfig(ctx context.Context, ffrestyConfig Config) (client *resty.Cli
 			}
 			rCtx = context.WithValue(rCtx, retryCtxKey{}, r)
 			// Create a request logger from the root logger passed into the client
-			rCtx = log.WithLogField(rCtx, "breq", r.id)
+			rCtx = log.WithLogFields(rCtx, "breq", r.id)
 			req.SetContext(rCtx)
 		}
 
@@ -368,7 +368,7 @@ func NewWithConfig(ctx context.Context, ffrestyConfig Config) (client *resty.Cli
 					return false
 				}
 				rc.attempts++
-				log.L(rCtx).Infof("retry %d/%d (min=%dms/max=%dms) status=%d", rc.attempts, retryCount, minTimeout.Milliseconds(), maxTimeout.Milliseconds(), r.StatusCode())
+				log.L(rCtx).Tracef("retry %d/%d (min=%dms/max=%dms) status=%d", rc.attempts, retryCount, minTimeout.Milliseconds(), maxTimeout.Milliseconds(), r.StatusCode())
 				return true
 			})
 	}

pkg/fftls/fftls.go

@@ -51,7 +51,7 @@ func NewTLSConfig(ctx context.Context, config *Config, tlsType TLSType) (*tls.Co
 		VerifyPeerCertificate: func(_ [][]byte, verifiedChains [][]*x509.Certificate) error {
 			if len(verifiedChains) > 0 && len(verifiedChains[0]) > 0 {
 				cert := verifiedChains[0][0]
-				log.L(ctx).Debugf("Client certificate provided Subject=%s Issuer=%s Expiry=%s", cert.Subject, cert.Issuer, cert.NotAfter)
+				log.L(ctx).Tracef("Client certificate provided Subject=%s Issuer=%s Expiry=%s", cert.Subject, cert.Issuer, cert.NotAfter)
 			} else {
 				log.L(ctx).Debugf("Client certificate unverified")
 			}
@@ -64,7 +64,7 @@ func NewTLSConfig(ctx context.Context, config *Config, tlsType TLSType) (*tls.Co
 	var rootCAs *x509.CertPool
 	switch {
 	case config.CAFile != "":
-		log.L(ctx).Debugf("Loading CA file at %s", config.CAFile)
+		log.L(ctx).Tracef("Loading CA file at %s", config.CAFile)
 		rootCAs = x509.NewCertPool()
 		var caBytes []byte
 		caBytes, err = os.ReadFile(config.CAFile)
@@ -93,7 +93,7 @@ func NewTLSConfig(ctx context.Context, config *Config, tlsType TLSType) (*tls.Co
 	var configuredCert *tls.Certificate
 	// For mTLS we need both the cert and key
 	if config.CertFile != "" && config.KeyFile != "" {
-		log.L(ctx).Debugf("Loading Cert file at %s and Key file at %s", config.CertFile, config.KeyFile)
+		log.L(ctx).Tracef("Loading Cert file at %s and Key file at %s", config.CertFile, config.KeyFile)
 		// Read the key pair to create certificate
 		cert, err := tls.LoadX509KeyPair(config.CertFile, config.KeyFile)
 		if err != nil {
@@ -112,11 +112,11 @@ func NewTLSConfig(ctx context.Context, config *Config, tlsType TLSType) (*tls.Co
 		// Rather than letting Golang pick a certificate it thinks matches from the list of one,
 		// we directly supply it the one we have in all cases.
 		tlsConfig.GetClientCertificate = func(_ *tls.CertificateRequestInfo) (*tls.Certificate, error) {
-			log.L(ctx).Debugf("Supplying client certificate")
+			log.L(ctx).Tracef("Supplying client certificate")
 			return configuredCert, nil
 		}
 		tlsConfig.GetCertificate = func(_ *tls.ClientHelloInfo) (*tls.Certificate, error) {
-			log.L(ctx).Debugf("Supplying server certificate")
+			log.L(ctx).Tracef("Supplying server certificate")
 			return configuredCert, nil
 		}
 	}
@@ -215,7 +215,7 @@ func buildDNValidator(ctx context.Context, requiredDNAttributes map[string]inter
 			// We get a chain of one or more certificates, leaf first.
 			// Only check the leaf.
 			cert := chain[0]
-			log.L(ctx).Debugf("Performing TLS DN check on '%s'", cert.Subject)
+			log.L(ctx).Tracef("Performing TLS DN check on '%s'", cert.Subject)
 			for attr, validator := range validators {
 				matched := false
 				values := SubjectDNKnownAttributes[attr](cert.Subject) // Note check above makes this safe

pkg/httpserver/httpserver.go

@@ -31,6 +31,25 @@ import (
 	"github.com/hyperledger/firefly-common/pkg/log"
 )
 
+type remoteAddrContextKey struct{}
+type localAddrContextKey struct{}
+
+func RemoteAddr(ctx context.Context) net.Addr {
+	remoteAddr := ctx.Value(remoteAddrContextKey{})
+	if remoteAddr == nil {
+		return nil
+	}
+	return remoteAddr.(net.Addr)
+}
+
+func LocalAddr(ctx context.Context) net.Addr {
+	localAddr := ctx.Value(localAddrContextKey{})
+	if localAddr == nil {
+		return nil
+	}
+	return localAddr.(net.Addr)
+}
+
 type HTTPServer interface {
 	ServeHTTP(ctx context.Context)
 	Addr() net.Addr
@@ -127,17 +146,21 @@ func (hs *httpServer) createServer(ctx context.Context, r *mux.Router) (srv *htt
 		writeTimeout = hs.options.MaximumRequestTimeout + 1*time.Second
 	}
 
-	log.L(ctx).Debugf("HTTP Server Timeouts (%s): read=%s write=%s request=%s", hs.l.Addr(), readTimeout, writeTimeout, hs.options.MaximumRequestTimeout)
+	log.L(ctx).Tracef("HTTP Server Timeouts (%s): read=%s write=%s request=%s", hs.l.Addr(), readTimeout, writeTimeout, hs.options.MaximumRequestTimeout)
 	srv = &http.Server{
 		Handler:           handler,
 		WriteTimeout:      writeTimeout,
 		ReadTimeout:       readTimeout,
 		ReadHeaderTimeout: hs.conf.GetDuration(HTTPConfReadTimeout), // safe for this to always be the read timeout - should be short
 		TLSConfig:         tlsConfig,
 		ConnContext: func(newCtx context.Context, c net.Conn) context.Context {
+			remoteAddr := c.RemoteAddr()
+			localAddr := c.LocalAddr()
 			l := log.L(ctx).WithField("req", fftypes.ShortID())
+			newCtx = context.WithValue(newCtx, remoteAddrContextKey{}, remoteAddr)
+			newCtx = context.WithValue(newCtx, localAddrContextKey{}, localAddr)
 			newCtx = log.WithLogger(newCtx, l)
-			l.Debugf("New HTTP connection: remote=%s local=%s", c.RemoteAddr().String(), c.LocalAddr().String())
+			log.L(log.WithLogFieldsMap(newCtx, map[string]string{"remote": remoteAddr.String(), "local": localAddr.String()})).Trace("New HTTP connection")
 			return newCtx
 		},
 	}

pkg/httpserver/httpserver_test.go

@@ -240,6 +240,10 @@ func TestServeAuthorization(t *testing.T) {
 	r.HandleFunc("/test", func(res http.ResponseWriter, req *http.Request) {
 		res.WriteHeader(200)
 		json.NewEncoder(res).Encode(map[string]interface{}{"hello": "world"})
+		remoteAddr := RemoteAddr(req.Context())
+		localAddr := LocalAddr(req.Context())
+		assert.NotNil(t, remoteAddr)
+		assert.NotNil(t, localAddr)
 	})
 	errChan := make(chan error)
 	hs, err := NewHTTPServer(context.Background(), "ut", r, errChan, cp, cc)

pkg/i18n/en_base_error_messages.go

@@ -190,4 +190,6 @@ var (
 	MsgMissingDefaultAPIVersion                    = ffe("FF00253", "Default version must be set when there are more than 1 API version")
 	MsgNonExistDefaultAPIVersion                   = ffe("FF00254", "Default version '%s' does not exist")
 	MsgRoutePathNotStartWithSlash                  = ffe("FF00255", "Route path '%s' must not start with '/'")
+	MsgMethodNotAllowed                            = ffe("FF00256", "Method not allowed", http.StatusMethodNotAllowed)
+	MsgInvalidLogLevel                             = ffe("FF00257", "Invalid log level: '%s'", http.StatusBadRequest)
 )