rc: fix LogLevel in _config being ignored

Before this change setting LogLevel in the _config parameter of an rc
call had no effect as both the log functions and the log handler only
looked at the global log level.

The context aware log functions now use the log level from the config
in the context, and the log handler lets a log level in the context
which differs from the global one override its own level. This means
an rc call can be made more or less verbose than the rest of rclone
with, for example

    "_config": {"LogLevel": "DEBUG"}

This applies to the logs made with the context aware log functions, so
not to those made by the backends which still use the global log level.

Note that a config copied into a context no longer follows later
changes to the global log level.

docs/content/rc.md

@@ -480,6 +480,16 @@ Or flat:
 If you wish to check the `_config` assignment has worked properly then
 calling `options/local` will show what the value got set to.
 
+Setting `LogLevel` sets the log level for the logs made by the rc call
+only, for example to debug a single call.
+
+```json
+"_config":{"LogLevel": "DEBUG"}
+```
+
+Note that not all of rclone's logs support this yet. In particular the
+backends log at the global log level.
+
 ### Setting filter flags with _filter
 
 If you wish to set filters for the duration of an rc call only then

fs/log.go

@@ -183,9 +183,7 @@ func logPrintf(ctx context.Context, level LogLevel, o any, text string, args ...
 }
 
 func logLevelPrintf(ctx context.Context, level LogLevel, o any, text string, args ...any) {
-	// This uses the global log level, not the one in ctx, as the
-	// log handler filters on the global log level.
-	if GetConfig(context.TODO()).LogLevel >= level {
+	if GetConfig(ctx).LogLevel >= level {
 		logPrintf(ctx, level, o, text, args...)
 	}
 }

fs/log/slog.go

@@ -258,11 +258,17 @@ func (h *OutputHandler) setFormatFlags(bitMask logFormat) {
 }
 
 // Enabled returns whether this logger is enabled for this level.
-func (h *OutputHandler) Enabled(_ context.Context, level slog.Level) bool {
+//
+// A log level in the config in ctx which differs from the global one
+// overrides the level of the handler.
+func (h *OutputHandler) Enabled(ctx context.Context, level slog.Level) bool {
 	minLevel := slog.LevelInfo
 	if h.opts.Level != nil {
 		minLevel = h.opts.Level.Level()
 	}
+	if ctxLevel := fs.GetConfig(ctx).LogLevel; ctxLevel != fs.GetConfig(context.Background()).LogLevel {
+		minLevel = fs.LogLevelToSlog(ctxLevel)
+	}
 	return level >= minLevel
 }
 

fs/log/slog_test.go

@@ -140,6 +140,16 @@ func TestEnabled(t *testing.T) {
 	opts := &slog.HandlerOptions{Level: slog.LevelDebug}
 	h2 := NewOutputHandler(&bytes.Buffer{}, opts, 0)
 	assert.True(t, h2.Enabled(context.Background(), slog.LevelDebug))
+
+	// A log level in the config in the context which differs from
+	// the global one overrides the level of the handler
+	ctx, ci := fs.AddConfig(context.Background())
+	assert.False(t, h.Enabled(ctx, slog.LevelDebug))
+	ci.LogLevel = fs.LogLevelDebug
+	assert.True(t, h.Enabled(ctx, slog.LevelDebug))
+	ci.LogLevel = fs.LogLevelError
+	assert.False(t, h.Enabled(ctx, slog.LevelInfo))
+	assert.True(t, h.Enabled(ctx, slog.LevelError))
 }
 
 // Test clearFormatFlags and setFormatFlags bitwise ops.

fs/log_test.go

@@ -196,3 +196,31 @@ func TestLogCtx(t *testing.T) {
 	InfofCtx(groupCtx, nil, "dropped")
 	assert.Equal(t, "", buf.String())
 }
+
+// The log level in the config in the context overrides the global one
+func TestLogCtxLogLevel(t *testing.T) {
+	var buf bytes.Buffer
+	oldLogger := logger
+	defer func() { logger = oldLogger }()
+	SetLogger(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
+	ci := GetConfig(context.Background())
+	oldLogLevel := ci.LogLevel
+	ci.LogLevel = LogLevelNotice
+	defer func() { ci.LogLevel = oldLogLevel }()
+
+	// More verbose than the global log level
+	ctx, ctxCi := AddConfig(context.Background())
+	ctxCi.LogLevel = LogLevelDebug
+	DebugfCtx(ctx, nil, "debug")
+	assert.Contains(t, buf.String(), `"msg":"debug"`)
+	buf.Reset()
+	Debugf(nil, "dropped")
+	assert.Equal(t, "", buf.String())
+
+	// Less verbose than the global log level
+	ctxCi.LogLevel = LogLevelError
+	LogfCtx(ctx, nil, "dropped")
+	assert.Equal(t, "", buf.String())
+	ErrorfCtx(ctx, nil, "error")
+	assert.Contains(t, buf.String(), `"msg":"error"`)
+}

fs/rc/jobs/job_test.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"log/slog"
 	"runtime"
 	"testing"
 	"time"
@@ -11,6 +12,7 @@ import (
 	"github.com/rclone/rclone/fs"
 	"github.com/rclone/rclone/fs/accounting"
 	"github.com/rclone/rclone/fs/filter"
+	"github.com/rclone/rclone/fs/log"
 	"github.com/rclone/rclone/fs/rc"
 	"github.com/rclone/rclone/fstest/testy"
 	"github.com/stretchr/testify/assert"
@@ -308,6 +310,34 @@ func TestExecuteJobWithConfig(t *testing.T) {
 	assert.NotEqual(t, 42*fs.Mebi, ci.BufferSize)
 }
 
+// Check LogLevel in _config sets the log level for the logs of the call
+func TestExecuteJobWithConfigLogLevel(t *testing.T) {
+	ctx := context.Background()
+	require.Less(t, fs.GetConfig(ctx).LogLevel, fs.LogLevelDebug)
+	var logs []string
+	log.Handler.SetOutput(func(level slog.Level, text string) {
+		logs = append(logs, text)
+	})
+	defer log.Handler.ResetOutput()
+	jobFn := func(ctx context.Context, in rc.Params) (rc.Params, error) {
+		fs.DebugfCtx(ctx, nil, "debug from job")
+		return nil, nil
+	}
+
+	_, _, err := NewJob(ctx, jobFn, rc.Params{})
+	require.NoError(t, err)
+	assert.Empty(t, logs)
+
+	_, _, err = NewJob(ctx, jobFn, rc.Params{
+		"_config": rc.Params{
+			"LogLevel": "DEBUG",
+		},
+	})
+	require.NoError(t, err)
+	require.Len(t, logs, 1)
+	assert.Contains(t, logs[0], "debug from job")
+}
+
 // NewJob must mark the context as a remote control (rc) request, including for
 // asynchronous jobs whose context is detached
 func TestNewJobMarksRCRequest(t *testing.T) {

fs/sync/sync_test.go

@@ -2793,7 +2793,7 @@ func TestSyncConcurrentTruncate(t *testing.T) {
 // Test that sync replaces dir modtimes in dst if they've changed
 func testSyncReplaceDirModTime(t *testing.T, copyEmptySrcDirs bool) {
 	accounting.GlobalStats().ResetCounters()
-	ctx, _ := fs.AddConfig(context.Background())
+	ctx, ci := fs.AddConfig(context.Background())
 	r := fstest.NewRun(t)
 
 	file1 := r.WriteFile("file1", "file1", t2)
@@ -2812,10 +2812,7 @@ func testSyncReplaceDirModTime(t *testing.T, copyEmptySrcDirs bool) {
 
 	// set logging
 	// (this checks log output as DirModtime operations do not yet have stats, and r.CheckDirectoryModTimes also does not tell us what actions were taken)
-	oldLogLevel := fs.GetConfig(context.Background()).LogLevel
-	defer func() { fs.GetConfig(context.Background()).LogLevel = oldLogLevel }() // reset to old val after test
-	// need to do this as fs.Infof only respects the globalConfig
-	fs.GetConfig(context.Background()).LogLevel = fs.LogLevelInfo
+	ci.LogLevel = fs.LogLevelInfo
 
 	// First run
 	accounting.GlobalStats().ResetCounters()
@@ -2902,7 +2899,7 @@ func TestSyncSetDirModTimeOnce(t *testing.T) {
 // Run the same sync twice, ensure no action is taken the second time
 func testNothingToTransfer(t *testing.T, copyEmptySrcDirs bool) {
 	accounting.GlobalStats().ResetCounters()
-	ctx, _ := fs.AddConfig(context.Background())
+	ctx, ci := fs.AddConfig(context.Background())
 	r := fstest.NewRun(t)
 	file1 := r.WriteFile("sub dir/hello world", "hello world", t1)
 	file2 := r.WriteFile("sub dir2/very/very/very/very/very/nested/subdir/hello world", "hello world", t1)
@@ -2917,10 +2914,7 @@ func testNothingToTransfer(t *testing.T, copyEmptySrcDirs bool) {
 
 	// set logging
 	// (this checks log output as DirModtime operations do not yet have stats, and r.CheckDirectoryModTimes also does not tell us what actions were taken)
-	oldLogLevel := fs.GetConfig(context.Background()).LogLevel
-	defer func() { fs.GetConfig(context.Background()).LogLevel = oldLogLevel }() // reset to old val after test
-	// need to do this as fs.Infof only respects the globalConfig
-	fs.GetConfig(context.Background()).LogLevel = fs.LogLevelInfo
+	ci.LogLevel = fs.LogLevelInfo
 
 	accounting.GlobalStats().ResetCounters()
 	ctx = predictDstFromLogger(ctx)