[log] logr.Logger and logr.LogSink Support for controller-runtime Compatibility

pkg/dbsql/crud.go

@@ -811,7 +811,7 @@ func (c *CrudBase[T]) getManyScoped(ctx context.Context, tableFrom string, fi *f
 		}
 		instances = append(instances, inst)
 	}
-	log.L(ctx).Debugf("SQL<- GetMany(%s): %d", c.Table, len(instances))
+	log.L(ctx).Tracef("SQL<- GetMany(%s): %d", c.Table, len(instances))
 	return instances, c.DB.QueryRes(ctx, c.Table, tx, fop, c.ReadQueryModifier, fi), err
 }
 

pkg/dbsql/database.go

@@ -192,7 +192,7 @@ func (s *Database) BeginOrUseTx(ctx context.Context) (ctx1 context.Context, tx *
 		sqlTX: sqlTX,
 	}
 	ctx1 = context.WithValue(ctx1, txContextKey{}, tx)
-	l.Debugf("SQL<- begin (%.2fms)", floatMillisSince(before))
+	l.Tracef("SQL<- begin (%.2fms)", floatMillisSince(before))
 	return ctx1, tx, false, err
 }
 
@@ -225,7 +225,7 @@ func (s *Database) RunAsQueryTx(ctx context.Context, table string, tx *TXWrapper
 		l.Errorf(`SQL query failed: %s sql=[ %s ]`, err, sqlQuery)
 		return nil, tx, i18n.WrapError(ctx, err, i18n.MsgDBQueryFailed)
 	}
-	l.Debugf(`SQL<- query %s (%.2fms)`, table, floatMillisSince(before))
+	l.Tracef(`SQL<- query %s (%.2fms)`, table, floatMillisSince(before))
 	return rows, tx, nil
 }
 
@@ -272,7 +272,7 @@ func (s *Database) CountQuery(ctx context.Context, table string, tx *TXWrapper,
 			return count, i18n.WrapError(ctx, err, i18n.MsgDBReadErr, table)
 		}
 	}
-	l.Debugf(`SQL<- count query %s: %d (%.2fms)`, table, count, floatMillisSince(before))
+	l.Tracef(`SQL<- count query %s: %d (%.2fms)`, table, count, floatMillisSince(before))
 	return count, nil
 }
 
@@ -342,7 +342,7 @@ func (s *Database) InsertTxRows(ctx context.Context, table string, tx *TXWrapper
 		}
 		sequences[0], _ = res.LastInsertId()
 	}
-	l.Debugf(`SQL<- insert %s sequences=%v (%.2fms)`, table, sequences, floatMillisSince(before))
+	l.Tracef(`SQL<- insert %s sequences=%v (%.2fms)`, table, sequences, floatMillisSince(before))
 
 	if postCommit != nil {
 		tx.AddPostCommitHook(postCommit)
@@ -364,7 +364,7 @@ func (s *Database) DeleteTx(ctx context.Context, table string, tx *TXWrapper, q
 		return i18n.WrapError(ctx, err, i18n.MsgDBDeleteFailed)
 	}
 	ra, _ := res.RowsAffected()
-	l.Debugf(`SQL<- delete %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
+	l.Tracef(`SQL<- delete %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
 	if ra < 1 {
 		return fftypes.DeleteRecordNotFound
 	}
@@ -385,7 +385,7 @@ func (s *Database) ExecTx(ctx context.Context, table string, tx *TXWrapper, sqlQ
 		return nil, i18n.WrapError(ctx, err, i18n.MsgDBExecFailed)
 	}
 	ra, _ := res.RowsAffected()
-	l.Debugf(`SQL<- exec: %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
+	l.Tracef(`SQL<- exec: %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
 	return res, nil
 }
 
@@ -403,7 +403,7 @@ func (s *Database) UpdateTx(ctx context.Context, table string, tx *TXWrapper, q
 		return -1, i18n.WrapError(ctx, err, i18n.MsgDBUpdateFailed)
 	}
 	ra, _ := res.RowsAffected()
-	l.Debugf(`SQL<- update %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
+	l.Tracef(`SQL<- update %s affected=%d (%.2fms)`, table, ra, floatMillisSince(before))
 
 	if postCommit != nil {
 		tx.AddPostCommitHook(postCommit)
@@ -423,7 +423,7 @@ func (s *Database) AcquireLockTx(ctx context.Context, lockName string, tx *TXWra
 			l.Errorf(`SQL lock failed: %s sql=[ %s ]`, err, sqlQuery)
 			return i18n.WrapError(ctx, err, i18n.MsgDBLockFailed)
 		}
-		l.Debugf(`SQL<- lock %s (%.2fms)`, lockName, floatMillisSince(before))
+		l.Tracef(`SQL<- lock %s (%.2fms)`, lockName, floatMillisSince(before))
 	}
 	return nil
 }
@@ -468,7 +468,7 @@ func (s *Database) CommitTx(ctx context.Context, tx *TXWrapper, autoCommit bool)
 		l.Errorf(`SQL commit failed: %s`, err)
 		return i18n.WrapError(ctx, err, i18n.MsgDBCommitFailed)
 	}
-	l.Debugf(`SQL<- commit (%.2fms)`, floatMillisSince(before))
+	l.Tracef(`SQL<- commit (%.2fms)`, floatMillisSince(before))
 
 	// Emit any post commit events (these aren't currently allowed to cause errors)
 	for i, pce := range tx.postCommit {

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 @@
 	"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 @@
 	monitoringEnabled         bool
 	metricsPath               string
 	livenessPath              string
+	loggingPath        string
 	monitoringPublicURL       string
 	mux                       *mux.Router
 	oah                       *OpenAPIHandlerFactory
@@ -121,6 +124,7 @@
 		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,9 @@
 	return hf.RouteHandler(route)
 }
 
-func (as *apiServer[T]) handlerFactory() *HandlerFactory {
+func (as *apiServer[T]) handlerFactory(logLevel logrus.Level) *HandlerFactory {
 	return &HandlerFactory{
+		LogLevel:              &logLevel,
 		DefaultRequestTimeout: as.requestTimeout,
 		MaxTimeout:            as.requestMaxTimeout,
 		DefaultFilterLimit:    as.defaultFilterLimit,
@@ -286,7 +291,8 @@
 
 func (as *apiServer[T]) createMuxRouter(ctx context.Context) (*mux.Router, error) {
 	r := mux.NewRouter().UseEncodedPath()
-	hf := as.handlerFactory()
+	hf := as.handlerFactory(logrus.InfoLevel)
+	hf.Init()
 
 	as.oah = &OpenAPIHandlerFactory{
 		BaseSwaggerGenOptions: SwaggerGenOptions{
@@ -390,15 +396,34 @@
 	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 != "" {
+		ctx := log.WithLogFields(req.Context(), "new_level", logLevel)
+		log.L(ctx).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)
+	hf.Init()
 
 	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

@@ -22,9 +22,10 @@
 )
 
 var (
-	ConfMonitoringServerEnabled      = "enabled"
-	ConfMonitoringServerMetricsPath  = "metricsPath"
-	ConfMonitoringServerLivenessPath = "livenessPath"
+	ConfMonitoringServerEnabled            = "enabled"
+	ConfMonitoringServerMetricsPath        = "metricsPath"
+	ConfMonitoringServerLivenessPath       = "livenessPath"
+	ConfMonitoringServerLoggingPath        = "loggingPath"
 
 	ConfAPIDefaultFilterLimit     = "defaultFilterLimit"
 	ConfAPIMaxFilterLimit         = "maxFilterLimit"
@@ -51,4 +52,5 @@
 	monitoringConfig.AddKnownKey(ConfMonitoringServerEnabled, true)
 	monitoringConfig.AddKnownKey(ConfMonitoringServerMetricsPath, "/metrics")
 	monitoringConfig.AddKnownKey(ConfMonitoringServerLivenessPath, "/livez")
+	monitoringConfig.AddKnownKey(ConfMonitoringServerLoggingPath, "/logging")
 }

pkg/ffapi/handler.go

@@ -66,6 +66,7 @@ type (
 type HandlerFunction func(res http.ResponseWriter, req *http.Request) (status int, err error)
 
 type HandlerFactory struct {
+	LogLevel              *logrus.Level
 	DefaultRequestTimeout time.Duration
 	MaxTimeout            time.Duration
 	DefaultFilterLimit    uint64
@@ -77,6 +78,8 @@ type HandlerFactory struct {
 	SupportFieldRedaction bool
 	BasePath              string
 	BasePathParams        []*PathParam
+
+	logLevel logrus.Level
 }
 
 var ffMsgCodeExtractor = regexp.MustCompile(`^(FF\d+):`)
@@ -88,6 +91,18 @@ type multipartState struct {
 	close      func()
 }
 
+func (hs *HandlerFactory) Init() {
+	if hs.LogLevel == nil {
+		hs.logLevel = logrus.InfoLevel
+	} else {
+		hs.logLevel = *hs.LogLevel
+	}
+}
+
+func (hs *HandlerFactory) SetLogLevel(logLevel logrus.Level) {
+	hs.logLevel = logLevel
+}
+
 func (hs *HandlerFactory) getFilePart(req *http.Request) (*multipartState, error) {
 	formParams := make(map[string]string)
 	ctx := req.Context()
@@ -368,14 +383,14 @@ 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)
+		l.Logf(hs.logLevel, "--> %s %s", req.Method, req.URL.Path)
 		startTime := time.Now()
 		status, err := handler(res, req)
 		durationMS := float64(time.Since(startTime)) / float64(time.Millisecond)
@@ -412,14 +427,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.logLevel, "<-- %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.logLevel, "<-- %s %s [%d] (%.2fms)", req.Method, req.URL.Path, status, durationMS)
 		}
 	}
 }

pkg/ffapi/handler_test.go

@@ -53,6 +53,7 @@ const configDir = "../../test/data/config"
 
 func newTestHandlerFactory(basePath string, basePathParams []*PathParam) *HandlerFactory {
 	return &HandlerFactory{
+		logLevel:              logrus.DebugLevel,
 		DefaultRequestTimeout: 5 * time.Second,
 		PassthroughHeaders: []string{
 			"X-Custom-Header",

pkg/ffapi/openapihandler_test.go

@@ -104,6 +104,7 @@ func TestOpenAPI3SwaggerUIDynamicPublicURL(t *testing.T) {
 func TestOpenAPIHandlerNonVersioned(t *testing.T) {
 	mux := mux.NewRouter()
 	hf := HandlerFactory{}
+	hf.Init()
 	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)
 		}
 

pkg/httpserver/httpserver.go

@@ -127,7 +127,7 @@ 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,
@@ -137,7 +137,7 @@ func (hs *httpServer) createServer(ctx context.Context, r *mux.Router) (srv *htt
 		ConnContext: func(newCtx context.Context, c net.Conn) context.Context {
 			l := log.L(ctx).WithField("req", fftypes.ShortID())
 			newCtx = log.WithLogger(newCtx, l)
-			l.Debugf("New HTTP connection: remote=%s local=%s", c.RemoteAddr().String(), c.LocalAddr().String())
+			l.Tracef("New HTTP connection: remote=%s local=%s", c.RemoteAddr().String(), c.LocalAddr().String())
 			return newCtx
 		},
 	}

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)
+	MsgMissingLogLevel                             = ffe("FF00257", "Missing log level", http.StatusBadRequest)
 )

pkg/log/log.go

@@ -1,4 +1,4 @@
-// Copyright © 2022 Kaleido, Inc.
+// Copyright © 2022 - 2025 Kaleido, Inc.
 //
 // SPDX-License-Identifier: Apache-2.0
 //
@@ -40,6 +40,7 @@ func WithLogger(ctx context.Context, logger *logrus.Entry) context.Context {
 	return context.WithValue(ctx, ctxLogKey{}, logger)
 }
 
+// Deprecated: Use WithLogFields instead.
 // WithLogField adds the specified field to the logger in the context
 func WithLogField(ctx context.Context, key, value string) context.Context {
 	if len(value) > 61 {
@@ -48,6 +49,37 @@ func WithLogField(ctx context.Context, key, value string) context.Context {
 	return WithLogger(ctx, loggerFromContext(ctx).WithField(key, value))
 }
 
+// WithLogFields adds the specified fields to the logger in the context for structured logging. The key-value pairs must be provided in pairs.
+func WithLogFields(ctx context.Context, keyValues ...string) context.Context {
+	if len(keyValues)%2 != 0 {
+		panic("odd number of key-value entry fields provided, cannot determine key-value pairs")
+	}
+
+	entry := loggerFromContext(ctx)
+	fields := logrus.Fields{}
+	for i := 0; i < len(keyValues); i += 2 {
+		key := keyValues[i]
+		value := keyValues[i+1]
+		if len(value) > 61 {
+			value = value[0:61] + "..."
+		}
+		fields[key] = value
+	}
+	return WithLogger(ctx, entry.WithFields(fields))
+}
+
+// WithFields adds the specified, structured fields to the logger in the context
+func WithFields(ctx context.Context, fields map[string]string) context.Context {
+	entryFields := logrus.Fields{}
+	for key, value := range fields {
+		if len(value) > 61 {
+			value = value[0:61] + "..."
+		}
+		entryFields[key] = value
+	}
+	return WithLogger(ctx, loggerFromContext(ctx).WithFields(entryFields))
+}
+
 // LoggerFromContext returns the logger for the current context, or no logger if there is no context
 func loggerFromContext(ctx context.Context) *logrus.Entry {
 	logger := ctx.Value(ctxLogKey{})