diff --git a/pkg/dbsql/crud.go b/pkg/dbsql/crud.go index f9a928d2..514bce49 100644 --- a/pkg/dbsql/crud.go +++ b/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 } diff --git a/pkg/dbsql/database.go b/pkg/dbsql/database.go index df0434d2..1019a561 100644 --- a/pkg/dbsql/database.go +++ b/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 { diff --git a/pkg/eventstreams/eventstreams.go b/pkg/eventstreams/eventstreams.go index 443d627e..3792a6a4 100644 --- a/pkg/eventstreams/eventstreams.go +++ b/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, diff --git a/pkg/ffapi/apiserver.go b/pkg/ffapi/apiserver.go index 846a45bd..23e2aed9 100644 --- a/pkg/ffapi/apiserver.go +++ b/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,9 @@ func (as *apiServer[T]) routeHandler(hf *HandlerFactory, route *Route) http.Hand 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]) handlerFactory() *HandlerFactory { 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 @@ 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 != "" { + 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 { diff --git a/pkg/ffapi/apiserver_config.go b/pkg/ffapi/apiserver_config.go index 01c71879..30d472c3 100644 --- a/pkg/ffapi/apiserver_config.go +++ b/pkg/ffapi/apiserver_config.go @@ -22,9 +22,10 @@ import ( ) var ( - ConfMonitoringServerEnabled = "enabled" - ConfMonitoringServerMetricsPath = "metricsPath" - ConfMonitoringServerLivenessPath = "livenessPath" + 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") } diff --git a/pkg/ffapi/handler.go b/pkg/ffapi/handler.go index a9b91cbd..360411c3 100644 --- a/pkg/ffapi/handler.go +++ b/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) } } } diff --git a/pkg/ffapi/handler_test.go b/pkg/ffapi/handler_test.go index ebae6253..fc2fc256 100644 --- a/pkg/ffapi/handler_test.go +++ b/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", diff --git a/pkg/ffapi/openapihandler_test.go b/pkg/ffapi/openapihandler_test.go index 630f4a2f..6fdf46f9 100644 --- a/pkg/ffapi/openapihandler_test.go +++ b/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", diff --git a/pkg/ffresty/ffresty.go b/pkg/ffresty/ffresty.go index 71c09fb8..8a949a5a 100644 --- a/pkg/ffresty/ffresty.go +++ b/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) } diff --git a/pkg/httpserver/httpserver.go b/pkg/httpserver/httpserver.go index 5b68608d..f2aaa6cd 100644 --- a/pkg/httpserver/httpserver.go +++ b/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 }, } diff --git a/pkg/i18n/en_base_error_messages.go b/pkg/i18n/en_base_error_messages.go index 9acb5425..9db84d55 100644 --- a/pkg/i18n/en_base_error_messages.go +++ b/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) ) diff --git a/pkg/log/log.go b/pkg/log/log.go index 9c7c7c3d..34579bea 100644 --- a/pkg/log/log.go +++ b/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{}) diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index 2bb66e3f..5526dd23 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -1,4 +1,4 @@ -// Copyright © 2022 Kaleido, Inc. +// Copyright © 2022 - 2025 Kaleido, Inc. // // SPDX-License-Identifier: Apache-2.0 // @@ -30,7 +30,7 @@ func TestLogContext(t *testing.T) { } func TestLogContextLimited(t *testing.T) { - ctx := WithLogField(context.Background(), "myfield", "0123456789012345678901234567890123456789012345678901234567890123456789") + ctx := WithLogFields(context.Background(), "myfield", "0123456789012345678901234567890123456789012345678901234567890123456789") assert.Equal(t, "0123456789012345678901234567890123456789012345678901234567890...", L(ctx).Data["myfield"]) } @@ -82,3 +82,24 @@ func TestSetFormattingJSONEnabled(t *testing.T) { L(context.Background()).Infof("JSON logs") } + +func TestWithFields(t *testing.T) { + ctx := WithFields(context.Background(), map[string]string{ + "myfield": "myvalue", + "myfield2": "myvalue2", + }) + assert.Equal(t, "myvalue", L(ctx).Data["myfield"]) + assert.Equal(t, "myvalue2", L(ctx).Data["myfield2"]) +} + +func TestWithLogFields(t *testing.T) { + ctx := WithLogFields(context.Background(), "myfield", "myvalue", "myfield2", "myvalue2") + assert.Equal(t, "myvalue", L(ctx).Data["myfield"]) + assert.Equal(t, "myvalue2", L(ctx).Data["myfield2"]) +} + +func TestWithLogFieldsOddNumberOfFields(t *testing.T) { + assert.Panics(t, func() { + WithLogFields(context.Background(), "myfield", "myvalue", "myfield2") + }) +} \ No newline at end of file diff --git a/pkg/metric/metric.go b/pkg/metric/metric.go index 9fa48257..8de7ccbb 100644 --- a/pkg/metric/metric.go +++ b/pkg/metric/metric.go @@ -59,7 +59,10 @@ type MetricsRegistry interface { // GetHTTPMetricsInstrumentationsMiddlewareForSubsystem returns the HTTP middleware of a subsystem that used predefined HTTP metrics GetHTTPMetricsInstrumentationsMiddlewareForSubsystem(ctx context.Context, subsystem string) (func(next http.Handler) http.Handler, error) + // MustRegisterCollector allows for registering a customer collector within the metrics registry, outside of the manager/subsystem context MustRegisterCollector(collector prometheus.Collector) + // GetGatherer returns the gatherer of the metrics registry, allowing for programmatic metrics exporting + GetGatherer() prometheus.Gatherer } type FireflyDefaultLabels struct { @@ -209,3 +212,7 @@ func (pmr *prometheusMetricsRegistry) GetHTTPMetricsInstrumentationsMiddlewareFo func (pmr *prometheusMetricsRegistry) MustRegisterCollector(collector prometheus.Collector) { pmr.registerer.MustRegister(collector) } + +func (pmr *prometheusMetricsRegistry) GetGatherer() prometheus.Gatherer { + return pmr.registry +} diff --git a/pkg/wsserver/wsconn.go b/pkg/wsserver/wsconn.go index bb51d870..c160130b 100644 --- a/pkg/wsserver/wsconn.go +++ b/pkg/wsserver/wsconn.go @@ -48,7 +48,7 @@ type WebSocketCommandMessage struct { func newConnection(bgCtx context.Context, server *webSocketServer, conn *ws.Conn) *webSocketConnection { id := fftypes.NewUUID().String() wsc := &webSocketConnection{ - ctx: log.WithLogField(bgCtx, "wsc", id), + ctx: log.WithLogFields(bgCtx, "wsc", id), id: id, server: server, conn: conn,