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 all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
240 changes: 240 additions & 0 deletions test/scrape/6.5.1.json
Original file line number Diff line number Diff line change
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
35 changes: 35 additions & 0 deletions varnish.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,10 @@ import (
"github.com/prometheus/client_golang/prometheus"
)

const (
vbeReload = "VBE.reload_"
)

var (
DescCache = &descCache{
descs: make(map[string]*prometheus.Desc),
Expand Down Expand Up @@ -88,7 +92,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 +222,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 := len(vbeReload) + strings.Index(vName[len(vbeReload):], ".")
vbeReloadPrefix := vName[:dotAfterPrefixIndex]
if strings.Compare(vbeReloadPrefix, mostRecentVbeReloadPrefix) > 0 {
mostRecentVbeReloadPrefix = vbeReloadPrefix
}
}
}
return mostRecentVbeReloadPrefix
}

// 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
Original file line number Diff line number Diff line change
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