Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix issue 57 - errors on VCL reload because of duplicated counters #70

Merged
merged 2 commits into from Jan 27, 2021
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
240 changes: 240 additions & 0 deletions test/scrape/6.5.1.json
Expand Up @@ -1952,6 +1952,246 @@
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.happy": {
"description": "Happy health probes",
"flag": "b",
"format": "b",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.bereq_hdrbytes": {
"description": "Request header bytes",
"flag": "c",
"format": "B",
"value": 6901
},
"VBE.reload_20210114_155148_19902.default.bereq_bodybytes": {
"description": "Request body bytes",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.beresp_hdrbytes": {
"description": "Response header bytes",
"flag": "c",
"format": "B",
"value": 5637
},
"VBE.reload_20210114_155148_19902.default.beresp_bodybytes": {
"description": "Response body bytes",
"flag": "c",
"format": "B",
"value": 44
},
"VBE.reload_20210114_155148_19902.default.pipe_hdrbytes": {
"description": "Pipe request header bytes",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.pipe_out": {
"description": "Piped bytes to backend",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.pipe_in": {
"description": "Piped bytes from backend",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.conn": {
"description": "Concurrent connections used",
"flag": "g",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.req": {
"description": "Backend requests sent",
"flag": "c",
"format": "i",
"value": 27
},
"VBE.reload_20210114_155148_19902.default.unhealthy": {
"description": "Fetches not attempted due to backend being unhealthy",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.busy": {
"description": "Fetches not attempted due to backend being busy",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail": {
"description": "Connections failed",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_eacces": {
"description": "Connections failed with EACCES or EPERM",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_eaddrnotavail": {
"description": "Connections failed with EADDRNOTAVAIL",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_econnrefused": {
"description": "Connections failed with ECONNREFUSED",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_enetunreach": {
"description": "Connections failed with ENETUNREACH",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_etimedout": {
"description": "Connections failed ETIMEDOUT",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.fail_other": {
"description": "Connections failed for other reason",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_155148_19902.default.helddown": {
"description": "Connection opens not attempted",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.happy": {
"description": "Happy health probes",
"flag": "b",
"format": "b",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.bereq_hdrbytes": {
"description": "Request header bytes",
"flag": "c",
"format": "B",
"value": 6901
},
"VBE.reload_20210114_160902_21476.default.bereq_bodybytes": {
"description": "Request body bytes",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.beresp_hdrbytes": {
"description": "Response header bytes",
"flag": "c",
"format": "B",
"value": 5637
},
"VBE.reload_20210114_160902_21476.default.beresp_bodybytes": {
"description": "Response body bytes",
"flag": "c",
"format": "B",
"value": 44
},
"VBE.reload_20210114_160902_21476.default.pipe_hdrbytes": {
"description": "Pipe request header bytes",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.pipe_out": {
"description": "Piped bytes to backend",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.pipe_in": {
"description": "Piped bytes from backend",
"flag": "c",
"format": "B",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.conn": {
"description": "Concurrent connections used",
"flag": "g",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.req": {
"description": "Backend requests sent",
"flag": "c",
"format": "i",
"value": 27
},
"VBE.reload_20210114_160902_21476.default.unhealthy": {
"description": "Fetches not attempted due to backend being unhealthy",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.busy": {
"description": "Fetches not attempted due to backend being busy",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail": {
"description": "Connections failed",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_eacces": {
"description": "Connections failed with EACCES or EPERM",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_eaddrnotavail": {
"description": "Connections failed with EADDRNOTAVAIL",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_econnrefused": {
"description": "Connections failed with ECONNREFUSED",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_enetunreach": {
"description": "Connections failed with ENETUNREACH",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_etimedout": {
"description": "Connections failed ETIMEDOUT",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.fail_other": {
"description": "Connections failed for other reason",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.reload_20210114_160902_21476.default.helddown": {
"description": "Connection opens not attempted",
"flag": "c",
"format": "i",
"value": 0
},
"VBE.boot.default.helddown": {
"description": "Connection opens not attempted",
"flag": "c",
Expand Down
36 changes: 36 additions & 0 deletions varnish.go
Expand Up @@ -15,6 +15,11 @@ import (
"github.com/prometheus/client_golang/prometheus"
)

const (
vbeReload = "VBE.reload_"
vbeReloadLength = len(vbeReload)
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can do this inline in findMostRecentVbeReloadPrefix, no need to make this globals constant.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, it was maybe and excessive attempt of optimization on my side. :D
Done: feb6172

)

var (
DescCache = &descCache{
descs: make(map[string]*prometheus.Desc),
Expand Down Expand Up @@ -88,7 +93,13 @@ func ScrapeVarnishFrom(buf []byte, ch chan<- prometheus.Metric) ([]byte, error)
countersJSON = metricsJSON
}

mostRecentVbeReloadPrefix := findMostRecentVbeReloadPrefix(countersJSON)

for vName, raw := range countersJSON {

if isOutdatedVbe(vName, mostRecentVbeReloadPrefix) {
continue
}
if vName == "timestamp" {
continue
}
Expand Down Expand Up @@ -212,6 +223,31 @@ func executeVarnishstat(varnishstatExe string, params ...string) (*bytes.Buffer,
return buf, cmd.Run()
}

// Returns the most recent prefix for 'VBE.reload_' stats. Empty until first reload.
// 'VBE.reload_2019-08-29T100458' as by varnish_reload_vcl in 4.1+
// 'VBE.reload_20191014_091124_78599' as by varnishreload in 6+
func findMostRecentVbeReloadPrefix(countersJSON map[string]interface{}) string {
var mostRecentVbeReloadPrefix string
for vName, _ := range countersJSON {
// Checking only the required ".happy" stat
if strings.HasPrefix(vName, vbeReload) && strings.HasSuffix(vName, ".happy") {
dotAfterPrefixIndex := vbeReloadLength + strings.Index(vName[vbeReloadLength:], ".")
vbeReloadPrefix := vName[:dotAfterPrefixIndex]
if strings.Compare(vbeReloadPrefix, mostRecentVbeReloadPrefix) > 0 {
mostRecentVbeReloadPrefix = vbeReloadPrefix
}
}
}
return mostRecentVbeReloadPrefix
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is only one set on reload_ entries, this function will return the only ones timestamp and that will then be (unintentionally?) ignored in ScrapeVarnishFrom. Did you intend this, I assume letting the one go through is ok, if its ok to let one of many through as well.

Suggested change
var mostRecentVbeReloadPrefix string
for vName, _ := range countersJSON {
// Checking only the required ".happy" stat
if strings.HasPrefix(vName, vbeReload) && strings.HasSuffix(vName, ".happy") {
dotAfterPrefixIndex := vbeReloadLength + strings.Index(vName[vbeReloadLength:], ".")
vbeReloadPrefix := vName[:dotAfterPrefixIndex]
if strings.Compare(vbeReloadPrefix, mostRecentVbeReloadPrefix) > 0 {
mostRecentVbeReloadPrefix = vbeReloadPrefix
}
}
}
return mostRecentVbeReloadPrefix
mostRecentVbeReloadPrefix := ""
numReloadedPrefix := 0
for vName, _ := range countersJSON {
// Checking only the required ".happy" stat
if strings.HasPrefix(vName, vbeReload) && strings.HasSuffix(vName, ".happy") {
numReloadedPrefix++
dotAfterPrefixIndex := vbeReloadLength + strings.Index(vName[vbeReloadLength:], ".")
vbeReloadPrefix := vName[:dotAfterPrefixIndex]
if strings.Compare(vbeReloadPrefix, mostRecentVbeReloadPrefix) > 0 {
mostRecentVbeReloadPrefix = vbeReloadPrefix
}
}
}
if numReloadedPrefix <= 1 {
return ""
}
return mostRecentVbeReloadPrefix

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is only one set on reload_ entries, this function will return the only ones timestamp

Correct

and that will then be (unintentionally?) ignored in ScrapeVarnishFrom.

I don't think this is true. ScrapeVarnishFrom will use isOutdatedVbe to determine that the VBE counters are not, in fact, outdated, so they won't be skipped (this should be covered by the current VCL version test case of Test_IsOutdatedVbe).

Let me know if I missed something!

}

// Returns true if the given 'VBE.' statistic refers to an outdated VCL version
func isOutdatedVbe(vName string, mostRecentVbeReloadPrefix string) bool {
return len(mostRecentVbeReloadPrefix) > 0 &&
strings.HasPrefix(vName, "VBE.") &&
!strings.HasPrefix(vName, mostRecentVbeReloadPrefix)
}

// varnishVersion

type varnishVersion struct {
Expand Down
65 changes: 65 additions & 0 deletions varnish_test.go
Expand Up @@ -192,6 +192,71 @@ func Test_VarnishMetrics(t *testing.T) {
}
}

func Test_FindMostRecentVbeReloadPrefix(t *testing.T) {
type testConfig struct {
varnishCounters map[string]interface{}
expectedMostRecentVbeReloadPrefix string
}

for _, testConfig := range []testConfig{
// Varnish <= 4.0 has no duplicated stats on reload
{map[string]interface{}{
"VBE.default(127.0.0.1,,8080).happy": "any",
}, ""},
// Varnish 4.1 or later, not yet reloaded
{map[string]interface{}{
"VBE.boot.default.happy": "any",
}, ""},
// Varnish 4.1, reloaded 2 times
{map[string]interface{}{
"VBE.boot.default.happy": "any",
"VBE.reload_2019-08-29T100458.default.happy": "any",
"VBE.reload_2019-08-29T100459.default.happy": "any",
}, "VBE.reload_2019-08-29T100459"},
// Varnish 6+, reloaded 2 times
{map[string]interface{}{
"VBE.boot.default.happy": "any",
"VBE.reload_20191016_072034_54500.default.happy": "any",
"VBE.reload_20191016_072034_54501.default.happy": "any",
}, "VBE.reload_20191016_072034_54501"},
} {
computedMostRecentVbeReloadPrefix := findMostRecentVbeReloadPrefix(testConfig.varnishCounters)
t.Logf("Varnish counters: %s\n", testConfig.varnishCounters)
t.Logf(" expected most recent prefix : '%s'\n", testConfig.expectedMostRecentVbeReloadPrefix)
t.Logf(" computed most recent prefix : '%s'\n", computedMostRecentVbeReloadPrefix)

if computedMostRecentVbeReloadPrefix != testConfig.expectedMostRecentVbeReloadPrefix {
t.Fatalf("mostRecentVbeReloadPrefix %q != %q", computedMostRecentVbeReloadPrefix, testConfig.expectedMostRecentVbeReloadPrefix)
}
}
}

func Test_IsOutdatedVbe(t *testing.T) {
type testConfig struct {
vName string
mostRecentVbeReloadPrefix string
expectedIsOutdatedVbe bool
}

for _, testConfig := range []testConfig{
{"MGT.uptime", "", false}, // not VBE
{"MGT.uptime", "VBE.reload_20191016_072034_54500", false}, // not VBE
{"VBE.boot.default.conn", "", false}, // VCL not yet reloaded
{"VBE.boot.default.conn", "VBE.reload_20191016_072034_54500", true}, // VCL reloaded, 'boot' is now outdated
{"VBE.reload_20191016_072034_54500.default.conn", "VBE.reload_20191016_072034_54500", false}, // current VCL version
{"VBE.reload_20191016_072034_54499.default.conn", "VBE.reload_20191016_072034_54500", true}, // previous VCL version
} {
computedIsOutdatedVbe := isOutdatedVbe(testConfig.vName, testConfig.mostRecentVbeReloadPrefix)
t.Logf("'%s', '%s'\n", testConfig.vName, testConfig.mostRecentVbeReloadPrefix)
t.Logf(" expected outdated : %t\n", testConfig.expectedIsOutdatedVbe)
t.Logf(" computed outdated : %t\n", computedIsOutdatedVbe)

if computedIsOutdatedVbe != testConfig.expectedIsOutdatedVbe {
t.Fatalf("outdatedVbe %t != %t", computedIsOutdatedVbe, testConfig.expectedIsOutdatedVbe)
}
}
}

type testCollector struct {
filepath string
t *testing.T
Expand Down