From 8a18837dd0f827399001d9a402a5511de26e05d5 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Thu, 9 Nov 2023 08:23:51 +0400 Subject: [PATCH] Add JSON format for logging (#3689) --- .github/ISSUE_TEMPLATE/bug.yml | 6 ++-- .github/ISSUE_TEMPLATE/chore.yml | 3 +- Taskfile.yml | 14 --------- cmd/ferretdb/main.go | 24 ++++++++------ ferretdb/ferretdb.go | 2 +- integration/setup/startup.go | 2 +- internal/util/debug/debug.go | 18 +++++++++-- internal/util/logging/buffer_test.go | 3 +- internal/util/logging/logging.go | 31 ++++++++++--------- website/docs/configuration/flags.md | 5 --- .../{logging.md => observability.md} | 25 ++++++++++----- website/docs/quickstart-guide/deb.md | 2 +- website/docs/quickstart-guide/docker.md | 2 +- website/docs/quickstart-guide/rpm.md | 2 +- 14 files changed, 76 insertions(+), 63 deletions(-) rename website/docs/configuration/{logging.md => observability.md} (53%) diff --git a/.github/ISSUE_TEMPLATE/bug.yml b/.github/ISSUE_TEMPLATE/bug.yml index 6b5627228d2a..5d348b3bf328 100644 --- a/.github/ISSUE_TEMPLATE/bug.yml +++ b/.github/ISSUE_TEMPLATE/bug.yml @@ -34,8 +34,8 @@ body: description: | For example: - **OS**: Ubuntu 22.04 x86_64 - - **Deployment**: Docker using `ghcr.io/ferretdb/ferretdb:1.0.0` image - - **Deployment details**: Docker version 23.0.5 + - **Deployment**: Docker using `ghcr.io/ferretdb/ferretdb:1.15.0` image + - **Deployment details**: Docker version 24.0.6 value: | - OS: - Deployment: @@ -65,6 +65,6 @@ body: attributes: label: What did you see instead? description: > - Please include FerretDB [logs](https://docs.ferretdb.io/configuration/logging/). + Please include FerretDB [logs](https://docs.ferretdb.io/configuration/observability/). validations: required: true diff --git a/.github/ISSUE_TEMPLATE/chore.yml b/.github/ISSUE_TEMPLATE/chore.yml index a3b37692259a..83d08dd3c09d 100644 --- a/.github/ISSUE_TEMPLATE/chore.yml +++ b/.github/ISSUE_TEMPLATE/chore.yml @@ -30,7 +30,8 @@ body: label: Definition of Done description: What should be done to consider this issue done? List everything that applies. value: | - - all handlers updated; + - handler updated; + - all backends updated; - unit tests added/updated; - integration/compatibility tests added/updated; - spot refactorings done; diff --git a/Taskfile.yml b/Taskfile.yml index 15bc91d70e3d..3a3bc5c6b0f7 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -347,20 +347,6 @@ tasks: --postgresql-url='postgres://username@127.0.0.1:5432/ferretdb?search_path=' --test-records-dir=tmp/records - run-old: - desc: "Run FerretDB with old `pg` handler" - deps: [build-host] - cmds: - - > - bin/ferretdb{{exeExt}} - --listen-addr=:27017 - --proxy-addr=127.0.0.1:47017 - --mode=diff-normal - --handler=pg - --postgresql-url='postgres://username@127.0.0.1:5432/ferretdb?search_path=' - --postgresql-old=true - --test-records-dir=tmp/records - run-sqlite: desc: "Run FerretDB with `sqlite` backend" deps: [build-host] diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go index 6166ea0fce59..80538d60cf7e 100644 --- a/cmd/ferretdb/main.go +++ b/cmd/ferretdb/main.go @@ -74,8 +74,9 @@ var cli struct { kong.Plugins Log struct { - Level string `default:"${default_log_level}" help:"${help_log_level}"` - UUID bool `default:"false" help:"Add instance UUID to all log messages." negatable:""` + Level string `default:"${default_log_level}" help:"${help_log_level}"` + Format string `default:"console" help:"${help_log_format}" enum:"${enum_log_format}"` + UUID bool `default:"false" help:"Add instance UUID to all log messages." negatable:""` } `embed:"" prefix:"log-"` MetricsUUID bool `default:"false" help:"Add instance UUID to all metrics." negatable:""` @@ -107,7 +108,6 @@ var cli struct { //nolint:lll // some tags are long var postgreSQLFlags struct { PostgreSQLURL string `name:"postgresql-url" default:"postgres://127.0.0.1:5432/ferretdb" help:"PostgreSQL URL for 'postgresql' handler."` - PostgreSQLOld bool `name:"postgresql-old" default:"false" help:"Use old PostgreSQL handler."` } // The sqliteFlags struct represents flags that are used by the "sqlite" backend. @@ -154,16 +154,20 @@ var ( zap.ErrorLevel.String(), } + logFormats = []string{"console", "json"} + kongOptions = []kong.Option{ kong.Vars{ "default_log_level": defaultLogLevel().String(), "default_mode": clientconn.AllModes[0], - "help_log_level": fmt.Sprintf("Log level: '%s'.", strings.Join(logLevels, "', '")), - "help_mode": fmt.Sprintf("Operation mode: '%s'.", strings.Join(clientconn.AllModes, "', '")), - "help_handler": fmt.Sprintf("Backend handler: '%s'.", strings.Join(registry.Handlers(), "', '")), + "enum_log_format": strings.Join(logFormats, ","), + "enum_mode": strings.Join(clientconn.AllModes, ","), - "enum_mode": strings.Join(clientconn.AllModes, ","), + "help_handler": fmt.Sprintf("Backend handler: '%s'.", strings.Join(registry.Handlers(), "', '")), + "help_log_format": fmt.Sprintf("Log format: '%s'.", strings.Join(logFormats, "', '")), + "help_log_level": fmt.Sprintf("Log level: '%s'.", strings.Join(logLevels, "', '")), + "help_mode": fmt.Sprintf("Operation mode: '%s'.", strings.Join(clientconn.AllModes, "', '")), }, kong.DefaultEnvars("FERRETDB"), } @@ -221,7 +225,7 @@ func setupMetrics(stateProvider *state.Provider) prometheus.Registerer { } // setupLogger setups zap logger. -func setupLogger(stateProvider *state.Provider) *zap.Logger { +func setupLogger(stateProvider *state.Provider, format string) *zap.Logger { info := version.Get() startupFields := []zap.Field{ @@ -246,7 +250,7 @@ func setupLogger(stateProvider *state.Provider) *zap.Logger { log.Fatal(err) } - logging.Setup(level, logUUID) + logging.Setup(level, format, logUUID) l := zap.L() l.Info("Starting FerretDB "+info.Version+"...", startupFields...) @@ -311,7 +315,7 @@ func run() { metricsRegisterer := setupMetrics(stateProvider) - logger := setupLogger(stateProvider) + logger := setupLogger(stateProvider, cli.Log.Format) if _, err := maxprocs.Set(maxprocs.Logger(logger.Sugar().Debugf)); err != nil { logger.Sugar().Warnf("Failed to set GOMAXPROCS: %s.", err) diff --git a/ferretdb/ferretdb.go b/ferretdb/ferretdb.go index e02201ebe8a1..05c8f3938164 100644 --- a/ferretdb/ferretdb.go +++ b/ferretdb/ferretdb.go @@ -216,6 +216,6 @@ func init() { l = zap.DebugLevel } - logging.Setup(l, "") + logging.Setup(l, "console", "") logger = zap.L() } diff --git a/integration/setup/startup.go b/integration/setup/startup.go index 71398aa812b5..6cb55831732c 100644 --- a/integration/setup/startup.go +++ b/integration/setup/startup.go @@ -46,7 +46,7 @@ var exporter *otlptrace.Exporter // Startup initializes things that should be initialized only once. func Startup() { - logging.Setup(zap.DebugLevel, "") + logging.Setup(zap.DebugLevel, "console", "") // https://docs.github.com/en/actions/learn-github-actions/variables#default-environment-variables if t, _ := strconv.ParseBool(os.Getenv("RUNNER_DEBUG")); t { diff --git a/internal/util/debug/debug.go b/internal/util/debug/debug.go index 881e5b4e819b..e53f7c07762b 100644 --- a/internal/util/debug/debug.go +++ b/internal/util/debug/debug.go @@ -19,9 +19,11 @@ import ( "bytes" "context" _ "expvar" // for metrics + "fmt" "net" "net/http" _ "net/http/pprof" // for profiling + "slices" "text/template" "time" @@ -29,6 +31,7 @@ import ( "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" "go.uber.org/zap" + "golang.org/x/exp/maps" "github.com/FerretDB/FerretDB/internal/util/must" ) @@ -67,8 +70,8 @@ func RunHandler(ctx context.Context, addr string, r prometheus.Registerer, l *za @@ -94,7 +97,16 @@ func RunHandler(ctx context.Context, addr string, r prometheus.Registerer, l *za go func() { lis := must.NotFail(net.Listen("tcp", addr)) - l.Sugar().Infof("Starting debug server on http://%s/", lis.Addr()) + root := fmt.Sprintf("http://%s", lis.Addr()) + + l.Sugar().Infof("Starting debug server on %s ...", root) + + paths := maps.Keys(handlers) + slices.Sort(paths) + + for _, path := range paths { + l.Sugar().Infof("%s%s - %s", root, path, handlers[path]) + } if err := s.Serve(lis); err != http.ErrServerClosed { panic(err) diff --git a/internal/util/logging/buffer_test.go b/internal/util/logging/buffer_test.go index dca03796e426..638d1d1980dd 100644 --- a/internal/util/logging/buffer_test.go +++ b/internal/util/logging/buffer_test.go @@ -109,8 +109,9 @@ func TestCircularBuffer(t *testing.T) { }) } - Setup(zap.DebugLevel, "") + Setup(zap.DebugLevel, "console", "") logger := zap.L() + for n, tc := range []struct { addMsg string expected []string diff --git a/internal/util/logging/logging.go b/internal/util/logging/logging.go index 066f6b785b95..d44e47aa470a 100644 --- a/internal/util/logging/logging.go +++ b/internal/util/logging/logging.go @@ -25,27 +25,30 @@ import ( ) // Setup initializes logging with a given level. -func Setup(level zapcore.Level, uuid string) { +func Setup(level zapcore.Level, encoding, uuid string) { config := zap.Config{ Level: zap.NewAtomicLevelAt(level), Development: debugbuild.Enabled, DisableCaller: false, DisableStacktrace: false, Sampling: nil, - Encoding: "console", + Encoding: encoding, EncoderConfig: zapcore.EncoderConfig{ - TimeKey: "T", - LevelKey: "L", - NameKey: "N", - CallerKey: "C", - FunctionKey: zapcore.OmitKey, - MessageKey: "M", - StacktraceKey: "S", - LineEnding: zapcore.DefaultLineEnding, - EncodeLevel: zapcore.CapitalLevelEncoder, - EncodeTime: zapcore.ISO8601TimeEncoder, - EncodeDuration: zapcore.StringDurationEncoder, - EncodeCaller: zapcore.ShortCallerEncoder, + MessageKey: "M", + LevelKey: "L", + TimeKey: "T", + NameKey: "N", + CallerKey: "C", + FunctionKey: zapcore.OmitKey, + StacktraceKey: "S", + LineEnding: zapcore.DefaultLineEnding, + EncodeLevel: zapcore.CapitalLevelEncoder, + EncodeTime: zapcore.ISO8601TimeEncoder, + EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, + EncodeName: nil, + NewReflectedEncoder: nil, + ConsoleSeparator: "\t", }, OutputPaths: []string{"stderr"}, ErrorOutputPaths: []string{"stderr"}, diff --git a/website/docs/configuration/flags.md b/website/docs/configuration/flags.md index ad113df7a04e..cf05073c8702 100644 --- a/website/docs/configuration/flags.md +++ b/website/docs/configuration/flags.md @@ -54,11 +54,6 @@ Some default values are overridden in [our Docker image](../quickstart-guide/doc | Flag | Description | Environment Variable | Default Value | | ------------------ | ------------------------------- | ------------------------- | ------------------------------------ | | `--postgresql-url` | PostgreSQL URL for 'pg' handler | `FERRETDB_POSTGRESQL_URL` | `postgres://127.0.0.1:5432/ferretdb` | -| `--postgresql-old` | Use old PostgreSQL backend | `FERRETDB_POSTGRESQL_OLD` | `false` | - -The new PostgreSQL backend is now enabled by default. -The `--postgresql-old` flag enables the use of the old PostgreSQL backend. -It will be removed in the next release. FerretDB uses [pgx v5](https://github.com/jackc/pgx) library for connecting to PostgreSQL. Supported URL parameters are documented there: diff --git a/website/docs/configuration/logging.md b/website/docs/configuration/observability.md similarity index 53% rename from website/docs/configuration/logging.md rename to website/docs/configuration/observability.md index a4d281597d97..aefe006758db 100644 --- a/website/docs/configuration/logging.md +++ b/website/docs/configuration/observability.md @@ -1,13 +1,17 @@ --- sidebar_position: 3 -description: Logging +description: Observability --- -# Logging +# Observability -## Docker logs +## Logging -Logs from FerretDB running on Docker can be accessed through the container. +The log level and format can be adjusted by [configuration flags](flags.md#miscellaneous). + +Please note that the structured log format is not stable yet; field names and formatting of values might change in minor releases. + +### Docker logs If Docker was launched with [our quick local setup with Docker Compose](../quickstart-guide/docker.md#setup-with-docker-compose), the following command can be used to fetch the logs. @@ -28,7 +32,14 @@ CONTAINER ID IMAGE COMMAND CREATED $ docker logs my-ferretdb ``` -## Binary executable logs +### Binary executable logs + +FerretDB writes logs to the standard error (`stderr`) stream. + +## Metrics + +FerretDB exposes metrics in Prometheus format on the debug handler on `http://127.0.0.1:8088/debug/metrics` by default. +There is no need to use an external exporter. +The host and port can be changed with [`--debug-addr` flag](flags.md#interfaces). -FerretDB writes logs to the standard error (`stderr`) stream but does not retain them. -Refer to the [flags](flags.md#miscellaneous) to adjust the log level. +Please note that the set of metrics is not stable yet; metric and label names and formatting of values might change in minor releases. diff --git a/website/docs/quickstart-guide/deb.md b/website/docs/quickstart-guide/deb.md index 07e7236a3c65..d3c9e4f4c0ba 100644 --- a/website/docs/quickstart-guide/deb.md +++ b/website/docs/quickstart-guide/deb.md @@ -34,4 +34,4 @@ You have to do it manually by running `ferretdb` binary with the [correct flags] Find out more about: -- [getting logs](../configuration/logging.md#binary-executable-logs). +- [getting logs](../configuration/observability.md#binary-executable-logs). diff --git a/website/docs/quickstart-guide/docker.md b/website/docs/quickstart-guide/docker.md index e4e185219437..0a3e0d9323cf 100644 --- a/website/docs/quickstart-guide/docker.md +++ b/website/docs/quickstart-guide/docker.md @@ -83,7 +83,7 @@ You can improve that setup by: Find out more about: -- [getting logs](../configuration/logging.md#docker-logs). +- [getting logs](../configuration/observability.md#docker-logs). ### SQLite Setup with Docker Compose diff --git a/website/docs/quickstart-guide/rpm.md b/website/docs/quickstart-guide/rpm.md index c65c23bdd025..8b7c2918771b 100644 --- a/website/docs/quickstart-guide/rpm.md +++ b/website/docs/quickstart-guide/rpm.md @@ -33,4 +33,4 @@ You have to do it manually by running `ferretdb` binary with the [correct flags] Find out more about: -- [getting logs](../configuration/logging.md#binary-executable-logs). +- [getting logs](../configuration/observability.md#binary-executable-logs).