Repository: VictoriaMetrics/VictoriaMetrics
Pull request #1956 (2021-12-16 13:21:57)

vmagent: add error log for skipped data block when rejected by receiv…
…ing side

Previously, rejected data blocks were silently dropped - only metrics were updated.
From operational perspective, having an additional logging for such cases is preferable.

https://github.com/VictoriaMetrics/VictoriaMetrics/issues/1911

Signed-off-by: hagen1778 <roman@victoriametrics.com>

-------------------

Log example:
```
2021-12-16T13:21:38.742Z        error   app/vmagent/remotewrite/client.go:306   sending a block with size 14682 bytes to "1:secret-url" was rejected (skipping the block): status code 400; response body: remoteAddr: "127.0.0.1:52196"; requestURI: /api/v1/writez; unsupported path requested: "/api/v1/writez"
```

codecov[bot]: # [Codecov](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics) Report
> Merging [#1956](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics) (9a0a442) into [master](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/commit/eaf82fe41109f20f26c015416d3445bc32e13920?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics) (eaf82fe) will **decrease** coverage by `0.12%`.
> The diff coverage is `n/a`.

[![Impacted file tree graph](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956/graphs/tree.svg?width=650&height=150&src=pr&token=YND8dYVcXn&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics)](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics)

```diff
@@            Coverage Diff             @@
##           master    #1956      +/-   ##
==========================================
- Coverage   60.72%   60.60%   -0.13%     
==========================================
  Files         237      237              
  Lines       39906    39906              
==========================================
- Hits        24234    24185      -49     
- Misses      14069    14122      +53     
+ Partials     1603     1599       -4     
```


| [Impacted Files](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics) | Coverage Δ | |
|---|---|---|
| [lib/mergeset/block\_stream\_reader.go](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics#diff-bGliL21lcmdlc2V0L2Jsb2NrX3N0cmVhbV9yZWFkZXIuZ28=) | `50.24% <0.00%> (-11.95%)` | :arrow_down: |
| [lib/mergeset/table.go](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics#diff-bGliL21lcmdlc2V0L3RhYmxlLmdv) | `65.63% <0.00%> (-2.33%)` | :arrow_down: |
| [lib/bloomfilter/filter.go](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics#diff-bGliL2Jsb29tZmlsdGVyL2ZpbHRlci5nbw==) | `98.00% <0.00%> (-2.00%)` | :arrow_down: |
| [app/vmselect/promql/aggr\_incremental.go](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics#diff-YXBwL3Ztc2VsZWN0L3Byb21xbC9hZ2dyX2luY3JlbWVudGFsLmdv) | `85.24% <0.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics). Last update [eaf82fe...9a0a442](https://codecov.io/gh/VictoriaMetrics/VictoriaMetrics/pull/1956?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=VictoriaMetrics).


Patch:
diff --git a/app/vmagent/remotewrite/client.go b/app/vmagent/remotewrite/client.go
index 5a4f5ea53..0493758b8 100644
--- a/app/vmagent/remotewrite/client.go
+++ b/app/vmagent/remotewrite/client.go
@@ -295,6 +295,17 @@ again:
 	}
 	metrics.GetOrCreateCounter(fmt.Sprintf(`vmagent_remotewrite_requests_total{url=%q, status_code="%d"}`, c.sanitizedURL, statusCode)).Inc()
 	if statusCode == 409 || statusCode == 400 {
+		body, err := ioutil.ReadAll(resp.Body)
+		_ = resp.Body.Close()
+		l := logger.WithThrottler("remoteWriteRejected", 5*time.Second)
+		if err != nil {
+			l.Errorf("sending a block with size %d bytes to %q was rejected (skipping the block): status code %d; "+
+				"failed to read response body: %s",
+				len(block), c.sanitizedURL, statusCode, err)
+		} else {
+			l.Errorf("sending a block with size %d bytes to %q was rejected (skipping the block): status code %d; response body: %s",
+				len(block), c.sanitizedURL, statusCode, string(body))
+		}
 		// Just drop block on 409 and 400 status codes like Prometheus does.
 		// See https://github.com/VictoriaMetrics/VictoriaMetrics/issues/873
 		// and https://github.com/VictoriaMetrics/VictoriaMetrics/issues/1149
diff --git a/lib/logger/throttler.go b/lib/logger/throttler.go
new file mode 100644
index 000000000..da1e9edab
--- /dev/null
+++ b/lib/logger/throttler.go
@@ -0,0 +1,72 @@
+package logger
+
+import (
+	"sync"
+	"time"
+)
+
+var (
+	logThrottlerRegistryMu = sync.Mutex{}
+	logThrottlerRegistry   = make(map[string]*LogThrottler)
+)
+
+// WithThrottler returns a logger throttled by time - only one message in throttle duration will be logged.
+//
+// New logger is created only once for each unique name passed.
+// The function is thread-safe.
+func WithThrottler(name string, throttle time.Duration) *LogThrottler {
+	logThrottlerRegistryMu.Lock()
+	defer logThrottlerRegistryMu.Unlock()
+
+	lt, ok := logThrottlerRegistry[name]
+	if ok {
+		return lt
+	}
+
+	lt = newLogThrottler(throttle)
+	lt.warnF = Warnf
+	lt.errorF = Errorf
+	logThrottlerRegistry[name] = lt
+	return lt
+}
+
+// LogThrottler is a logger, which throttles log messages passed to Warnf and Errorf.
+//
+// LogThrottler must be created via WithThrottler() call.
+type LogThrottler struct {
+	ch chan struct{}
+
+	warnF  func(format string, args ...interface{})
+	errorF func(format string, args ...interface{})
+}
+
+func newLogThrottler(throttle time.Duration) *LogThrottler {
+	lt := &LogThrottler{
+		ch: make(chan struct{}, 1),
+	}
+	go func() {
+		for {
+			<-lt.ch
+			time.Sleep(throttle)
+		}
+	}()
+	return lt
+}
+
+// Errorf logs error message.
+func (lt *LogThrottler) Errorf(format string, args ...interface{}) {
+	select {
+	case lt.ch <- struct{}{}:
+		lt.errorF(format, args...)
+	default:
+	}
+}
+
+// Warnf logs warn message.
+func (lt *LogThrottler) Warnf(format string, args ...interface{}) {
+	select {
+	case lt.ch <- struct{}{}:
+		lt.warnF(format, args...)
+	default:
+	}
+}


Test patch:
diff --git a/lib/logger/throttler_test.go b/lib/logger/throttler_test.go
new file mode 100644
index 000000000..53f3c81a6
--- /dev/null
+++ b/lib/logger/throttler_test.go
@@ -0,0 +1,40 @@
+package logger
+
+import (
+	"testing"
+	"time"
+)
+
+func TestLoggerWithThrottler(t *testing.T) {
+	lName := "test"
+	lThrottle := 50 * time.Millisecond
+
+	lt := WithThrottler(lName, lThrottle)
+	var i int
+	lt.warnF = func(format string, args ...interface{}) {
+		i++
+	}
+
+	lt.Warnf("")
+	lt.Warnf("")
+	lt.Warnf("")
+
+	if i != 1 {
+		t.Fatalf("expected logger will be throttled to 1; got %d instead", i)
+	}
+
+	time.Sleep(lThrottle * 2) // wait to throttle to fade off
+	// the same logger supposed to be return for the same name
+	WithThrottler(lName, lThrottle).Warnf("")
+	if i != 2 {
+		t.Fatalf("expected logger to have 2 iterations; got %d instead", i)
+	}
+
+	logThrottlerRegistryMu.Lock()
+	registeredN := len(logThrottlerRegistry)
+	logThrottlerRegistryMu.Unlock()
+
+	if registeredN != 1 {
+		t.Fatalf("expected only 1 logger to be registered; got %d", registeredN)
+	}
+}