vmalert: support logs suppressing during config reloads (#3973)

* vmalert: support logs suppressing during config reloads

The change is mostly required for ENT version of vmalert,
since it supports object-storage for config files.
Reading data from object storage could be time-consuming,
so vmalert emits logs to track the progress.

However, these logs are mostly needed on start or on
manual config reload. Printing these logs each time
`rule.configCheckInterval` is triggered would too verbose.
So the change allows to control logs emitting during
config reloads.

Now, logs are emitted during start up or when SIGHUP is receieved.
For periodicall config checks logs emitted by config pkg are suppressed.

Signed-off-by: hagen1778 <roman@victoriametrics.com>

* vmalert: review fixes

Signed-off-by: hagen1778 <roman@victoriametrics.com>

---------

Signed-off-by: hagen1778 <roman@victoriametrics.com>

app/vmalert/config/config.go

@@ -10,9 +10,9 @@ import (
 
 	"gopkg.in/yaml.v2"
 
+	"github.com/VictoriaMetrics/VictoriaMetrics/app/vmalert/config/log"
 	"github.com/VictoriaMetrics/VictoriaMetrics/app/vmalert/utils"
 	"github.com/VictoriaMetrics/VictoriaMetrics/lib/envtemplate"
-	"github.com/VictoriaMetrics/VictoriaMetrics/lib/logger"
 	"github.com/VictoriaMetrics/VictoriaMetrics/lib/promutils"
 )
 
@@ -199,9 +199,17 @@ func (r *Rule) Validate() error {
 // ValidateTplFn must validate the given annotations
 type ValidateTplFn func(annotations map[string]string) error
 
+// cLogger is a logger with support of logs suppressing.
+// it is used when logs emitted by config package needs
+// to be suppressed.
+var cLogger = &log.Logger{}
+
 // ParseSilent parses rule configs from given file patterns without emitting logs
 func ParseSilent(pathPatterns []string, validateTplFn ValidateTplFn, validateExpressions bool) ([]Group, error) {
-	files, err := readFromFS(pathPatterns, true)
+	cLogger.Suppress(true)
+	defer cLogger.Suppress(false)
+
+	files, err := readFromFS(pathPatterns)
 	if err != nil {
 		return nil, fmt.Errorf("failed to read from the config: %s", err)
 	}
@@ -210,7 +218,7 @@ func ParseSilent(pathPatterns []string, validateTplFn ValidateTplFn, validateExp
 
 // Parse parses rule configs from given file patterns
 func Parse(pathPatterns []string, validateTplFn ValidateTplFn, validateExpressions bool) ([]Group, error) {
-	files, err := readFromFS(pathPatterns, false)
+	files, err := readFromFS(pathPatterns)
 	if err != nil {
 		return nil, fmt.Errorf("failed to read from the config: %s", err)
 	}
@@ -219,7 +227,7 @@ func Parse(pathPatterns []string, validateTplFn ValidateTplFn, validateExpressio
 		return nil, fmt.Errorf("failed to parse %s: %s", pathPatterns, err)
 	}
 	if len(groups) < 1 {
-		logger.Warnf("no groups found in %s", strings.Join(pathPatterns, ";"))
+		cLogger.Warnf("no groups found in %s", strings.Join(pathPatterns, ";"))
 	}
 	return groups, nil
 }

app/vmalert/config/fs.go

@@ -4,9 +4,9 @@ import (
 	"fmt"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/VictoriaMetrics/VictoriaMetrics/app/vmalert/config/fslocal"
-	"github.com/VictoriaMetrics/VictoriaMetrics/lib/logger"
 )
 
 // FS represent a file system abstract for reading files.
@@ -36,10 +36,9 @@ var (
 // readFromFS returns an error if at least one FS failed to init.
 // The function can be called multiple times but each unique path
 // will be inited only once.
-// If silent == true, readFromFS will not emit any logs.
 //
 // It is allowed to mix different FS types in path list.
-func readFromFS(paths []string, silent bool) (map[string][]byte, error) {
+func readFromFS(paths []string) (map[string][]byte, error) {
 	var err error
 	result := make(map[string][]byte)
 	for _, path := range paths {
@@ -65,18 +64,19 @@ func readFromFS(paths []string, silent bool) (map[string][]byte, error) {
 			return nil, fmt.Errorf("failed to list files from %q", fs)
 		}
 
-		if !silent {
-			logger.Infof("found %d files to read from %q", len(list), fs)
-		}
+		cLogger.Infof("found %d files to read from %q", len(list), fs)
 
 		if len(list) < 1 {
 			continue
 		}
 
+		ts := time.Now()
 		files, err := fs.Read(list)
 		if err != nil {
 			return nil, fmt.Errorf("error while reading files from %q: %w", fs, err)
 		}
+		cLogger.Infof("finished reading %d files in %v from %q", len(list), time.Since(ts), fs)
+
 		for k, v := range files {
 			if _, ok := result[k]; ok {
 				return nil, fmt.Errorf("duplicate found for file name %q: file names must be unique", k)

app/vmalert/config/log/logger.go

@@ -0,0 +1,59 @@
+package log
+
+import (
+	"sync"
+
+	"github.com/VictoriaMetrics/VictoriaMetrics/lib/logger"
+)
+
+// Logger is using lib/logger for logging
+// but can be suppressed via Suppress method
+type Logger struct {
+	mu       sync.RWMutex
+	disabled bool
+}
+
+// Suppress whether to ignore message logging.
+// Once suppressed, logging continues to be ignored
+// until logger is un-suppressed.
+func (l *Logger) Suppress(v bool) {
+	l.mu.Lock()
+	l.disabled = v
+	l.mu.Unlock()
+}
+
+func (l *Logger) isDisabled() bool {
+	l.mu.RLock()
+	defer l.mu.RUnlock()
+	return l.disabled
+}
+
+// Errorf logs error message.
+func (l *Logger) Errorf(format string, args ...interface{}) {
+	if l.isDisabled() {
+		return
+	}
+	logger.Errorf(format, args...)
+}
+
+// Warnf logs warning message.
+func (l *Logger) Warnf(format string, args ...interface{}) {
+	if l.isDisabled() {
+		return
+	}
+	logger.Warnf(format, args...)
+}
+
+// Infof logs info message.
+func (l *Logger) Infof(format string, args ...interface{}) {
+	if l.isDisabled() {
+		return
+	}
+	logger.Infof(format, args...)
+}
+
+// Panicf logs panic message and panics.
+// Panicf can't be suppressed
+func (l *Logger) Panicf(format string, args ...interface{}) {
+	logger.Panicf(format, args...)
+}

app/vmalert/config/log/logger_test.go

@@ -0,0 +1,54 @@
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/VictoriaMetrics/VictoriaMetrics/lib/logger"
+)
+
+func TestOutput(t *testing.T) {
+	testOutput := &bytes.Buffer{}
+	logger.SetOutputForTests(testOutput)
+	defer logger.ResetOutputForTest()
+
+	log := &Logger{}
+
+	mustMatch := func(exp string) {
+		t.Helper()
+		if exp == "" {
+			if testOutput.String() != "" {
+				t.Errorf("expected output to be empty; got %q", testOutput.String())
+				return
+			}
+		}
+		if !strings.Contains(testOutput.String(), exp) {
+			t.Errorf("output %q should contain %q", testOutput.String(), exp)
+		}
+		fmt.Println(testOutput.String())
+		testOutput.Reset()
+	}
+
+	log.Warnf("foo")
+	mustMatch("foo")
+
+	log.Infof("info %d", 2)
+	mustMatch("info 2")
+
+	log.Errorf("error %s %d", "baz", 5)
+	mustMatch("error baz 5")
+
+	log.Suppress(true)
+
+	log.Warnf("foo")
+	mustMatch("")
+
+	log.Infof("info %d", 2)
+	mustMatch("")
+
+	log.Errorf("error %q %d", "baz", 5)
+	mustMatch("")
+
+}

app/vmalert/main.go

@@ -319,6 +319,7 @@ func configReload(ctx context.Context, m *manager, groupsCfg []config.Group, sig
 	// init reload metrics with positive values to improve alerting conditions
 	configSuccess.Set(1)
 	configTimestamp.Set(fasttime.UnixTimestamp())
+	parseFn := config.Parse
 	for {
 		select {
 		case <-ctx.Done():
@@ -330,7 +331,11 @@ func configReload(ctx context.Context, m *manager, groupsCfg []config.Group, sig
 			}
 			logger.Infof("SIGHUP received. Going to reload rules %q %s...", *rulePath, tmplMsg)
 			configReloads.Inc()
+			// allow logs emitting during manual config reload
+			parseFn = config.Parse
 		case <-configCheckCh:
+			// disable logs emitting during per-interval config reload
+			parseFn = config.ParseSilent
 		}
 		if err := notifier.Reload(); err != nil {
 			configReloadErrors.Inc()
@@ -345,7 +350,7 @@ func configReload(ctx context.Context, m *manager, groupsCfg []config.Group, sig
 			logger.Errorf("failed to load new templates: %s", err)
 			continue
 		}
-		newGroupsCfg, err := config.ParseSilent(*rulePath, validateTplFn, *validateExpressions)
+		newGroupsCfg, err := parseFn(*rulePath, validateTplFn, *validateExpressions)
 		if err != nil {
 			configReloadErrors.Inc()
 			configSuccess.Set(0)