Skip to content

Commit

Permalink
Added debug logs for series lookup issues (#110)
Browse files Browse the repository at this point in the history 
This should help users debug issues caused by misconfiguration.
  • Loading branch information
@jkohen
jkohen authored Mar 23, 2019
1 parent 2c9a7c7 commit 3c176b3
Show file tree
Hide file tree
Showing 2 changed files with 213 additions and 30 deletions.
4 changes: 4 additions & 0 deletions retrieval/series_cache.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -335,6 +335,7 @@ func (c *seriesCache) refresh(ctx context.Context, ref uint64) error {
if target == nil {
ctx, _ = tag.New(ctx, tag.Insert(keyReason, "target_not_found"))
stats.Record(ctx, droppedSeries.M(1))
level.Debug(c.logger).Log("msg", "target not found", "labels", entry.lset)
return nil
}
// Remove target labels and __name__ label.
Expand All @@ -349,13 +350,15 @@ func (c *seriesCache) refresh(ctx context.Context, ref uint64) error {
if len(finalLabels) > maxLabelCount {
ctx, _ = tag.New(ctx, tag.Insert(keyReason, "too_many_labels"))
stats.Record(ctx, droppedSeries.M(1))
level.Debug(c.logger).Log("msg", "too many labels", "labels", entry.lset)
return nil
}

resource, ok := c.getResource(target.DiscoveredLabels, target.Labels)
if !ok {
ctx, _ = tag.New(ctx, tag.Insert(keyReason, "unknown_resource"))
stats.Record(ctx, droppedSeries.M(1))
level.Debug(c.logger).Log("msg", "unknown resource", "labels", target.Labels)
return nil
}
var (
Expand All @@ -382,6 +385,7 @@ func (c *seriesCache) refresh(ctx context.Context, ref uint64) error {
if metadata == nil {
ctx, _ = tag.New(ctx, tag.Insert(keyReason, "metadata_not_found"))
stats.Record(ctx, droppedSeries.M(1))
level.Debug(c.logger).Log("msg", "metadata not found", "metric_name", metricName)
return nil
}
}
Expand Down
239 changes: 209 additions & 30 deletions retrieval/series_cache_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,15 +14,19 @@ limitations under the License.
package retrieval

import (
"bytes"
"context"
"fmt"
"io/ioutil"
"os"
"path/filepath"
"strconv"
"strings"
"testing"
"time"

"github.com/Stackdriver/stackdriver-prometheus-sidecar/targets"
"github.com/go-kit/kit/log"
promlabels "github.com/prometheus/prometheus/pkg/labels"
"github.com/prometheus/prometheus/pkg/textparse"
"github.com/prometheus/prometheus/scrape"
Expand All @@ -43,7 +47,14 @@ func TestScrapeCache_GarbageCollect(t *testing.T) {
// Initialize the series cache with "empty" target and metadata maps.
// The series we use below have no job, instance, and __name__ labels set, which
// will result in those empty lookup keys.
c := newSeriesCache(nil, dir, nil, nil,
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
c := newSeriesCache(logger, dir, nil, nil,
targetMap{"/": &targets.Target{}},
metadataMap{"//": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge}},
[]ResourceMap{
Expand All @@ -67,12 +78,12 @@ func TestScrapeCache_GarbageCollect(t *testing.T) {
// We should be able to read them all.
for i := 1; i <= 7; i++ {
entry, ok, err := c.get(ctx, uint64(i))
if !ok {
t.Fatalf("entry with ref %d not found", i)
}
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !ok {
t.Fatalf("entry with ref %d not found", i)
}
if !entry.lset.Equals(labels.FromStrings("a", strconv.Itoa(i))) {
t.Fatalf("unexpected label set for ref %d: %s", i, entry.lset)
}
Expand Down Expand Up @@ -105,21 +116,21 @@ func TestScrapeCache_GarbageCollect(t *testing.T) {
t.Fatal(err)
}
for i := 1; i < 2; i++ {
if entry, ok, err := c.get(ctx, uint64(i)); ok {
t.Fatalf("unexpected cache entry %d: %s", i, entry.lset)
} else if err != nil {
if entry, ok, err := c.get(ctx, uint64(i)); err != nil {
t.Fatalf("unexpected error: %s", err)
} else if ok {
t.Fatalf("unexpected cache entry %d: %s", i, entry.lset)
}
}
// We should be able to read them all.
for i := 3; i <= 7; i++ {
entry, ok, err := c.get(ctx, uint64(i))
if !ok {
t.Fatalf("label set with ref %d not found", i)
}
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !ok {
t.Fatalf("label set with ref %d not found", i)
}
if !entry.lset.Equals(labels.FromStrings("a", strconv.Itoa(i))) {
t.Fatalf("unexpected label set for ref %d: %s", i, entry.lset)
}
Expand Down Expand Up @@ -153,20 +164,20 @@ func TestScrapeCache_GarbageCollect(t *testing.T) {
// Only series 4 and 7 should be left.
for i := 1; i <= 7; i++ {
if i != 4 && i != 7 {
if entry, ok, err := c.get(ctx, uint64(i)); ok {
t.Fatalf("unexpected cache entry %d: %s", i, entry.lset)
} else if err != nil {
if entry, ok, err := c.get(ctx, uint64(i)); err != nil {
t.Fatalf("unexpected error: %s", err)
} else if ok {
t.Fatalf("unexpected cache entry %d: %s", i, entry.lset)
}
continue
}
entry, ok, err := c.get(ctx, uint64(i))
if !ok {
t.Fatalf("entry with ref %d not found", i)
}
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !ok {
t.Fatalf("entry with ref %d not found", i)
}
if !entry.lset.Equals(labels.FromStrings("a", strconv.Itoa(i))) {
t.Fatalf("unexpected label set for ref %d: %s", i, entry.lset)
}
Expand All @@ -182,32 +193,43 @@ func TestSeriesCache_Refresh(t *testing.T) {
}
targetMap := targetMap{}
metadataMap := metadataMap{}
c := newSeriesCache(nil, "", nil, nil, targetMap, metadataMap, resourceMaps, "", false)
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
c := newSeriesCache(logger, "", nil, nil, targetMap, metadataMap, resourceMaps, "", false)

ctx, cancel := context.WithCancel(context.Background())
defer cancel()

// Query unset reference.
entry, ok, err := c.get(ctx, 1)
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}
const refId = 1
entry, ok, err := c.get(ctx, refId)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}

// Set a series but the metadata and target getters won't have sufficient information for it.
if err := c.set(ctx, 1, labels.FromStrings("__name__", "metric1", "job", "job1", "instance", "inst1"), 5); err != nil {
if err := c.set(ctx, refId, labels.FromStrings("__name__", "metric1", "job", "job1", "instance", "inst1"), 5); err != nil {
t.Fatalf("unexpected error: %s", err)
}
// We should still not receive anything.
entry, ok, err = c.get(ctx, 1)
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
if !strings.Contains(logBuffer.String(), "target not found") {
t.Errorf("expected error \"target not found\", got: %v", logBuffer)
}
// We should still not receive anything.
entry, ok, err = c.get(ctx, refId)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}

// Populate the getters with data.
targetMap["job1/inst1"] = &targets.Target{
Expand All @@ -218,15 +240,158 @@ func TestSeriesCache_Refresh(t *testing.T) {

// Hack the timestamp of the last update to be sufficiently in the past that a refresh
// will be triggered.
c.entries[1].lastRefresh = time.Now().Add(-2 * refreshInterval)
c.entries[refId].lastRefresh = time.Now().Add(-2 * refreshInterval)

// Now another get should trigger a refresh, which now finds data.
entry, ok, err = c.get(ctx, 1)
entry, ok, err = c.get(ctx, refId)
if entry == nil || !ok || err != nil {
t.Errorf("expected metadata but got none, error: %s", err)
}
}

func TestSeriesCache_RefreshTooManyLabels(t *testing.T) {
resourceMaps := []ResourceMap{
{
Type: "resource2",
LabelMap: map[string]labelTranslation{"__resource_a": constValue("resource_a")},
},
}
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
targetMap := targetMap{
"job1/inst1": &targets.Target{
Labels: promlabels.FromStrings("job", "job1", "instance", "inst1"),
DiscoveredLabels: promlabels.FromStrings("__resource_a", "resource2_a"),
},
}
metadataMap := metadataMap{
"job1/inst1/metric1": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge, Metric: "metric1"},
}
c := newSeriesCache(logger, "", nil, nil, targetMap, metadataMap, resourceMaps, "", false)

ctx, cancel := context.WithCancel(context.Background())
defer cancel()

const refId = 1
lset := labels.FromStrings("__name__", "metric1", "job", "job1", "instance", "inst1")
for i := 0; i <= maxLabelCount; i++ {
lset = append(lset, labels.Label{fmt.Sprintf("label%d", i), "x"})
}
// Set will trigger a refresh.
if err := c.set(ctx, refId, lset, 5); err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !strings.Contains(logBuffer.String(), "too many labels") {
t.Errorf("expected error \"too many labels\", got: %v", logBuffer)
}

// Get shouldn't find data because of the previous error.
entry, ok, err := c.get(ctx, refId)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}
}

func TestSeriesCache_RefreshUnknownResource(t *testing.T) {
resourceMaps := []ResourceMap{
{
Type: "resource2",
LabelMap: map[string]labelTranslation{"__resource_a": constValue("resource_a")},
},
}
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
targetMap := targetMap{
"job1/inst1": &targets.Target{
Labels: promlabels.FromStrings("job", "job1", "instance", "inst1"),
DiscoveredLabels: promlabels.FromStrings("__unknown_resource", "resource2_a"),
},
}
metadataMap := metadataMap{
"job1/inst1/metric1": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge, Metric: "metric1"},
}
c := newSeriesCache(logger, "", nil, nil, targetMap, metadataMap, resourceMaps, "", false)

ctx, cancel := context.WithCancel(context.Background())
defer cancel()

const refId = 1
// Set will trigger a refresh.
if err := c.set(ctx, refId, labels.FromStrings("__name__", "metric1", "job", "job1", "instance", "inst1"), 5); err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !strings.Contains(logBuffer.String(), "unknown resource") {
t.Errorf("expected error \"unknown resource\", got: %v", logBuffer)
}

// Get shouldn't find data because of the previous error.
entry, ok, err := c.get(ctx, refId)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}
}

func TestSeriesCache_RefreshMetadataNotFound(t *testing.T) {
resourceMaps := []ResourceMap{
{
Type: "resource2",
LabelMap: map[string]labelTranslation{"__resource_a": constValue("resource_a")},
},
}
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
targetMap := targetMap{
"job1/inst1": &targets.Target{
Labels: promlabels.FromStrings("job", "job1", "instance", "inst1"),
DiscoveredLabels: promlabels.FromStrings("__resource_a", "resource2_a"),
},
}
metadataMap := metadataMap{}
c := newSeriesCache(logger, "", nil, nil, targetMap, metadataMap, resourceMaps, "", false)

ctx, cancel := context.WithCancel(context.Background())
defer cancel()

const refId = 1
// Set will trigger a refresh.
if err := c.set(ctx, refId, labels.FromStrings("__name__", "metric1", "job", "job1", "instance", "inst1"), 5); err != nil {
t.Fatalf("unexpected error: %s", err)
}
if !strings.Contains(logBuffer.String(), "metadata not found") {
t.Errorf("expected error \"metadata not found\", got: %v", logBuffer)
}

// Get shouldn't find data because of the previous error.
entry, ok, err := c.get(ctx, refId)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
if ok || entry != nil {
t.Fatalf("unexpected series entry found: %v", entry)
}
}

func TestSeriesCache_Filter(t *testing.T) {
resourceMaps := []ResourceMap{
{
Expand All @@ -244,7 +409,14 @@ func TestSeriesCache_Filter(t *testing.T) {
metadataMap := metadataMap{
"job1/inst1/metric1": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge, Metric: "metric1"},
}
c := newSeriesCache(nil, "", []*promlabels.Matcher{
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
c := newSeriesCache(logger, "", []*promlabels.Matcher{
&promlabels.Matcher{Type: promlabels.MatchEqual, Name: "a", Value: "a1"},
&promlabels.Matcher{Type: promlabels.MatchEqual, Name: "b", Value: "b1"},
}, nil, targetMap, metadataMap, resourceMaps, "", false)
Expand Down Expand Up @@ -292,7 +464,14 @@ func TestSeriesCache_RenameMetric(t *testing.T) {
"job1/inst1/metric1": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge, Metric: "metric1"},
"job1/inst1/metric2": &scrape.MetricMetadata{Type: textparse.MetricTypeGauge, Metric: "metric2"},
}
c := newSeriesCache(nil, "", nil,
logBuffer := &bytes.Buffer{}
defer func() {
if logBuffer.Len() > 0 {
t.Log(logBuffer.String())
}
}()
logger := log.NewLogfmtLogger(logBuffer)
c := newSeriesCache(logger, "", nil,
map[string]string{"metric2": "metric3"},
targetMap, metadataMap, resourceMaps, "", false)

Expand Down

0 comments on commit 3c176b3

Please sign in to comment.