Skip to content

Commit

Permalink
Fix issue 57 - errors on VCL reload because of duplicated counters
Browse files Browse the repository at this point in the history
  • Loading branch information
@LorenzoPeri
LorenzoPeri committed Jan 19, 2021
1 parent 0855dcb commit 6d3f0ae
Show file tree
Hide file tree
Showing 3 changed files with 341 additions and 0 deletions.
240 changes: 240 additions & 0 deletions test/scrape/6.5.1.json
View file
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
36 changes: 36 additions & 0 deletions varnish.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,11 @@ import (
"github.com/prometheus/client_golang/prometheus"
)

const (
vbeReload = "VBE.reload_"
vbeReloadLength = len(vbeReload)
)

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
}

// 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
View file
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

0 comments on commit 6d3f0ae

Please sign in to comment.