feat: add `query-log-path` configuration #25710

devanbenz · 2024-12-26T20:11:45Z

This PR adds the ability for an admin to define 'query-log-path' as a configuration item field.

A new configuration option is created

[data]
# Setting a logging path will enable query logging
query-log-path = "/var/influx/query.log"

This will enable query logging.

Logged queries example:

{"level":"info","ts":1735248393.084461,"msg":"Executing query","query":"SHOW DATABASES"}
{"level":"info","ts":1735248395.092188,"msg":"Executing query","query":"SHOW DATABASES"}
{"level":"info","ts":1735248398.58039,"msg":"Executing query","query":"SELECT * FROM stress.autogen.m0 LIMIT 20"}

query/executor_test.go

davidby-influx

Did not look at the tests

etc/config.sample.toml

query/executor.go

davidby-influx

Quick review (didn't look at tests) on this, treating it like a draft PR, per your request.

coordinator/points_writer.go

davidby-influx · 2025-01-07T00:46:55Z

query/executor.go

+// WatcherInterface is used for any file watch functionality using fsnotify
+type WatcherInterface interface {
+	Event() chan fsnotify.Event
+	Error() chan error


Is there a direction on this channel?

davidby-influx · 2025-01-07T00:50:07Z

query/executor.go

+			e.Logger.Debug("received file event", zap.String("event", event.Name))
+
+			if event.Op == fsnotify.Remove || event.Op == fsnotify.Rename {
+				e.mu.Lock()


perhaps toss this block into a lambda and use defer mu.Unlock()? That protects against future additional return paths.

davidby-influx · 2025-01-07T00:55:05Z

query/executor.go

+		case err, ok := <-w.Error():
+			closeErr := w.Close()
+			if closeErr != nil {
+				return fmt.Errorf("failed to close watcher: %w", closeErr)


We don't want to throw away the first error. Use errors.Join to get the original error and the Close error.

davidby-influx · 2025-01-07T00:58:05Z

query/file_log_watcher.go

+	return f.fsWatcher.Events
+}
+
+func (f *FileLogWatcher) Error() chan error {


channel direction?

query/file_log_watcher.go

davidby-influx · 2025-01-07T01:07:05Z

query/file_log_watcher.go

+	logFile, err := os.OpenFile(f.path, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0644)
+	if err != nil {
+		f.logger.Error("failed to open log file", zap.Error(err), zap.String("path", f.path))
+		return nil


return err ??

davidby-influx · 2025-01-07T01:08:51Z

query/file_log_watcher.go

+	existingCore := f.logger.Core()
+	encoder, err := l.NewEncoder(f.formatterConfig)
+	if err != nil {
+		return err


Do we want to Close the file here? If this isn't a fatal error for the database we should probably close the file to avoid leaking the handle.

davidby-influx · 2025-01-07T01:09:15Z

query/file_log_watcher.go

+	f.logger = zap.New(newCore)
+
+	if err := f.fsWatcher.Add(f.path); err != nil {
+		return err


Same as above. What needs to be cleaned up here, if anything?

davidby-influx · 2025-01-07T01:12:03Z

query/file_log_watcher.go

+}
+
+func (f *FileLogWatcher) Close() error {
+	if err := f.currFile.Sync(); err != nil {


Do we need mutex protection here?

We should always close the file, even if the sync fails.

We should close the fsWatcher even if the sync or close fails

errors.Join is your friend.

davidby-influx · 2025-01-07T23:04:32Z

query/executor_test.go

+
+	for time.Now().Before(deadline) {
+		if mockWatcher.ChangeEvents.Load() == 1 {
+			break


Are you breaking here, or running out the deadline?

davidby-influx

Some changes for debugging the CI problem, some general changes

davidby-influx · 2025-01-07T23:14:14Z

query/executor_test.go

+	require.Equal(t, uint64(1), mockWatcher.ChangeEvents.Load())
+	require.Equal(t, uint64(1), mockWatcher.RemovedPaths.Load())
+
+	err = mockWatcher.Close()


This is already in the defer above. Move the require.NoError into a lambda for the defer.

davidby-influx · 2025-01-07T23:15:06Z

query/executor_test.go

+	require.Equal(t, uint64(1), mockWatcher.ChangeEvents.Load())
+	require.Equal(t, uint64(1), mockWatcher.RemovedPaths.Load())
+
+	err = mockWatcher.Close()


As above, the Close is already in the defer. Move the require.NoError into a lambda in the defer

Oops yeah meant to adjust that. Going to move to the lambdas as per your comment

davidby-influx · 2025-01-07T23:34:39Z

query/executor_test.go

+		Op:   fsnotify.Remove,
+	}
+
+	for time.Now().Before(deadline) {


Perhaps use time.After instead of a loop?

Good call I'll try that out

davidby-influx · 2025-01-07T23:35:44Z

query/executor_test.go

+
+	for time.Now().Before(deadline) {
+		if mockWatcher.ChangeEvents.Load() == 1 {
+			break


Set a bool variable here to see if this is the loop exit or the ChangeEvents.Load is

This PR adds the ability for an admin to define 'query-log-path' as a configuration item field. A new configuration option is created ```toml [data] query-log-path = "/var/influx/query.log" ``` This will enable query logging being written to a log file on disk. Logged queries example: ``` {"level":"info","ts":1735248393.084461,"msg":"Executing query","query":"SHOW DATABASES"} {"level":"info","ts":1735248395.092188,"msg":"Executing query","query":"SHOW DATABASES"} {"level":"info","ts":1735248398.58039,"msg":"Executing query","query":"SELECT * FROM stress.autogen.m0 LIMIT 20"} ```

gwossum · 2025-01-09T22:54:29Z

query/file_log_watcher.go

+	// FileWatcher is not meant to be used with interactive shell sessions so
+	// console as a logging format will not be supported.
+	if format == "console" {
+		logger.Error("unknown logging format", zap.String("format", format), zap.String("path", path))


console isn't an unknown logging format. It's an unsupported format for query logging.

gwossum · 2025-01-09T22:58:37Z

query/file_log_watcher.go

+		format = "logfmt"
+	}
+
+	logFile, err := os.OpenFile(path, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0644)


Generally it's better to use a permission of 0666 and let the system's umask value get the permissions the admin really wants (source: lots of headaches). It's likely the admin might want the file to be group writable for the external log rotation to work properly. Hard coding 0644 here might cause issues with said log rotation.

gwossum · 2025-01-09T23:01:44Z

cmd/influxd/run/server.go

@@ -487,6 +487,16 @@ func (s *Server) Open() error {
 		// so it only logs as is appropriate.
 		s.QueryExecutor.TaskManager.Logger = s.Logger
 	}
+	if s.config.Data.QueryLogPath != "" {
+		path := s.config.Data.QueryLogPath
+		flw := query.NewFileLogWatcher(s.QueryExecutor, path, s.Logger, s.config.Logging.Format)


Either query.NewFileLogWatcher is misnamed, or QueryExecutor.WithLogWriter is misnamed. It looks like the wrong thing is getting passed around.

gwossum · 2025-01-09T23:03:37Z

query/executor.go

+	}
+}
+
+func (e *Executor) WithLogWriter(w WatcherInterface, ctx context.Context) {


ctx should be the first parameter. From the docs:

The Context should be the first parameter, typically named ctx.

gwossum · 2025-01-09T23:08:20Z

query/file_log_watcher.go

+	// FileWatcher is not meant to be used with interactive shell sessions so
+	// console as a logging format will not be supported.
+	if format == "console" {
+		logger.Error("unknown logging format", zap.String("format", format), zap.String("path", path))


I feel like it would be cleaner for NewFileLogWatcher to return an additional error value and not take the logger object in. The caller should log the error returned.

Stylistically, a function that on error only returns nil feels like it should be left in the world of C.

gwossum · 2025-01-09T23:09:03Z

cmd/influxd/run/server.go

+		if flw != nil {
+			s.QueryExecutor.WithLogWriter(flw, context.Background())
+		} else {
+			s.Logger.Error("error creating log writer", zap.String("path", path))


Yeah, if NewFileLogWatcher returned an error, you could log the error right here instead of this generic log message.

gwossum · 2025-01-09T23:10:42Z

logger/logger.go

@@ -65,7 +65,7 @@ func newEncoder(format string) (zapcore.Encoder, error) {
 	}
 }

-func newEncoderConfig() zapcore.EncoderConfig {
+func NewEncoderConfig() zapcore.EncoderConfig {


I can't find any uses of NewEncodingConfig outside of the logger package. Is there a reason to change it to public?

gwossum · 2025-01-09T23:15:35Z

query/executor.go

@@ -289,6 +306,94 @@ func (e *Executor) WithLogger(log *zap.Logger) {
 	e.TaskManager.Logger = e.Logger
 }

+func startFileLogWatcher(w WatcherInterface, e *Executor, ctx context.Context) error {


startFileLogWatcher made me think this was going to spawn a goroutine, but it doesn't. It's the body of a goroutine. Maybe either doFileLogWatch or simply fileLogWatch?

gwossum · 2025-01-09T23:17:31Z

query/executor.go

@@ -242,6 +257,8 @@ type Executor struct {

 	// expvar-based stats.
 	stats *Statistics
+
+	mu sync.Mutex


I would not put mu at the bottom of the struct. A developer going into this code might miss mu and not lock appropriately.

My preference is to put mu above all the members that it will protect, along with a comment that mu protects all following members. Members that don't require protection can go above mu.

gwossum · 2025-01-09T23:27:05Z

@devanbenz The hardest part of this, IMO, is correctly handling the fsnotify events. It would be great to have some tests that actually exercise that functionality.

gwossum · 2025-01-09T23:33:32Z

@devanbenz You might even consider just using the real thing for all the tests instead of the mocked interface. Use testing.T.TempDir() to create a temp directory to drop the log files into. To check the contents, slurp the log files in with io.ReadAll and a regex or even a simple strings.Contains to check for the expected statement in the logs. You could then get rid of the complexity of the interface and deal directly with the real object.

gwossum · 2025-01-09T23:50:20Z

@devanbenz The more I think about it, the more I like getting rid of the mock. I'm interested in how the fsnotify behaves when:

influxd creates a log new file.
influxd appends to an existing log file.
A log rotator renames the current log.
A log rotator renames the current log and then starts a new log file.
Make sure we don't have other fsnotify related issues during normal operation.

devanbenz · 2025-01-10T14:33:03Z

@devanbenz The more I think about it, the more I like getting rid of the mock. I'm interested in how the fsnotify behaves when:

influxd creates a log new file.

influxd appends to an existing log file.

A log rotator renames the current log.

A log rotator renames the current log and then starts a new log file.

Make sure we don't have other fsnotify related issues during normal operation.

This makes sense to me. I'm usually under the mindset to not "test" third party libraries but I could foresee this being an exception to that since its correctness is core to the changes. Do you think I should get rid of the interface and just make everything concrete as well?

gwossum · 2025-01-10T19:02:46Z

cmd/influxd/run/server.go

+		flw := query.NewFileLogWatcher(s.QueryExecutor, path, s.Logger, s.config.Logging.Format)
+		if flw != nil {
+			s.QueryExecutor.WithLogWriter(flw, context.Background())


@devan I had an idea last night on how to make this way more flexible and reusable.

First, change QueryExecutor.WithLogWriter(*FileLogWatcher) to QueryExecutor.WithQueryLogger(*zap.Logger). By taking a *zap.Logger, we have way more flexibility in how queries can be logged. It will also decouple log rotation logic from the QueryExecutor if the code ends up being split between OSS and Enterprise.

Second, change query.NewFileLogWatcher(...) *FileLogWatcher to query.NewRotatableLogger(...) (*zap.Logger, error) (or logger.NewRotatableLogger...). This logger can then be used anywhere we need a log file that can be rotated by an external log rotator without making changes to the client code using the logger. Note: The goroutine to watch the signal channel will keep the references to the required data so it won't be garbage collected.

gwossum · 2025-01-10T19:04:37Z

Adding this comment from slack for posterity:

I think we've taken the wrong approach on handling log rotation. I reviewed the logrotate config files on my system and did some research on how major packages handle it. Most packages handle log rotation by listening for a signal (e.g. SIGHUP or SIGUSR1) and reopening logs when the signal is received. logrotate is then configured to send the signal to the process when it rotates logs.

Here's a couple of examples from package docs describing reopening log files on SIGHUP:

PostgreSQL Log Maintenance

Hashicorp Vault SIGHUP Behavior

devanbenz force-pushed the db/459/query-loggin branch from a440193 to 410241e Compare December 30, 2024 16:56

devanbenz marked this pull request as ready for review December 30, 2024 16:56

devanbenz commented Dec 30, 2024

View reviewed changes

query/executor_test.go Outdated Show resolved Hide resolved

davidby-influx reviewed Dec 31, 2024

View reviewed changes

devanbenz marked this pull request as draft December 31, 2024 16:04

davidby-influx assigned devanbenz Dec 31, 2024

davidby-influx added 1.x area/logging area/queries labels Dec 31, 2024

devanbenz force-pushed the db/459/query-loggin branch from 86d496e to a4a995f Compare January 6, 2025 23:36

davidby-influx requested changes Jan 7, 2025

View reviewed changes

davidby-influx reviewed Jan 7, 2025

View reviewed changes

davidby-influx requested changes Jan 7, 2025

View reviewed changes

devanbenz force-pushed the db/459/query-loggin branch from 2109d11 to efcf13c Compare January 8, 2025 20:18

devanbenz added 2 commits January 8, 2025 15:01

feat: Adds a mutex protection for file log watcher Close()

a059c07

feat: remove mutex that was not needed

28b5807

devanbenz marked this pull request as ready for review January 8, 2025 21:11

gwossum reviewed Jan 9, 2025

View reviewed changes

gwossum reviewed Jan 10, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add `query-log-path` configuration #25710

feat: add `query-log-path` configuration #25710

devanbenz commented Dec 26, 2024 •

edited

Loading

davidby-influx left a comment

davidby-influx left a comment

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

davidby-influx left a comment

davidby-influx Jan 7, 2025

davidby-influx Jan 7, 2025

devanbenz Jan 8, 2025

davidby-influx Jan 7, 2025

devanbenz Jan 8, 2025

davidby-influx Jan 7, 2025

devanbenz Jan 8, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum Jan 9, 2025

gwossum commented Jan 9, 2025

gwossum commented Jan 9, 2025

gwossum commented Jan 9, 2025

devanbenz commented Jan 10, 2025 •

edited

Loading

gwossum Jan 10, 2025

gwossum commented Jan 10, 2025

feat: add query-log-path configuration #25710

Are you sure you want to change the base?

feat: add query-log-path configuration #25710

Conversation

devanbenz commented Dec 26, 2024 • edited Loading

davidby-influx left a comment

Choose a reason for hiding this comment

davidby-influx left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidby-influx left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gwossum commented Jan 9, 2025

gwossum commented Jan 9, 2025

gwossum commented Jan 9, 2025

devanbenz commented Jan 10, 2025 • edited Loading

Choose a reason for hiding this comment

gwossum commented Jan 10, 2025

feat: add `query-log-path` configuration #25710

feat: add `query-log-path` configuration #25710

devanbenz commented Dec 26, 2024 •

edited

Loading

devanbenz commented Jan 10, 2025 •

edited

Loading