Skip to content

V
varnishapi
Commit 7147cd55 authored by Geoff Simmons's avatar Geoff Simmons
Browse files
Options

Comprehensive refactoring of the Log package, adding Cursor and Query. 

VSLQ_Dispatch() is a powerful tool for the C API, but the restrictions
and overhead involved with the C/Go bridge make it too unwieldy to use.
Too much synchronization becomes necessary for a low-level API like
this. The cgocall overhead becomes excessive.

It seems to be difficult, perhaps impossible, to implement callbacks
without creating many objects on the Go heap. Since many objects from
the log are created in hot code, this puts excessive pressure on the
Go garbage collector.

This version uses low-level log read operations, excusively VSL_Next()
and related functions. The C/Go bridge is much smaller and simpler. It
should be possible to create the objects for log data on the Go stack.

The Cursor and Query interfaces reflect the underlying VSL interface
more faithfully. Distinct Cursors are safe for concurrent reads (as
for struct VSL_cursor from the VSL interface).

This means that grouping and VSL queries will have to re-implemented
in Go.
parent 85332d75
Hide whitespace changes
Inline Side-by-side
Showing with 2860 additions and 1080 deletions
pkg/log/cursor.go 0 → 100644
View file @ 7147cd55
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
package log
/*
#cgo pkg-config: varnishapi
#include <stdio.h>
#include <vapi/vsl.h>
*/
import "C"
import "errors"
// A Cursor is used to advance through the records in a Varnish
// log. It can be created from an attached instance of Log with
// NewCursor(), to read from a live Varnish instance, or with
// Log.NewCursorFile(), to read from a binary log file (as produced by
// varnishlog -w).
//
// A Cursor can in turn be used to create a Query object for reading
// aggregated log transactions. Or you can use Cursor's Next() method
// to read disaggregated Records directly from the log (equivalent to
// reading raw transactions via a Query). The results of intermingled
// reads via Next() and via a Query created from the same Cursor are
// undefined.
//
// Distinct Cursors may be used to read a log concurrently. Concurrent
// reads with the same Cursor are not safe.
//
// Because they are low-level operations used frequently in hot code,
// the Cursor methods have no error checking. So it is vital to
// observe these two rules:
//
// The Cursor methods will panic if applied to a nil Cursor, or to a
// Cursor that has not been initialized through one of the New*
// functions.
//
// Call Next() before using one of the methods that read data from the
// log record to which a Cursor is concurrently pointing (Match(),
// Tag(), VXID(), Payload(), Client(), Backend() or Record()). The
// results of calling one of these methods before Next() are
// undefined, and may lead to panic.
type Cursor struct {
cursor *C.struct_VSL_cursor
log *Log
}
// NewCursor creates a Cursor to read from a live Varnish log. Fails
// if the Log object is not attached to a log.
func (log *Log) NewCursor() (*Cursor, error) {
if err := log.checkNil(); err != nil {
return nil, err
}
if log.vsm == nil {
return nil, errors.New("Not attached to a Varnish log")
}
if log.vsm.VSM == nil {
panic("VSM handle is nil")
}
C.VSL_ResetError(log.vsl)
cursor := C.VSL_CursorVSM(log.vsl, (*C.struct_vsm)(log.vsm.VSM),
log.vsmopts)
if cursor == nil {
return nil, log
}
return &Cursor{cursor: cursor, log: log}, nil
}
// NewCursorFile creates a Cursor to read from a binary log file,
// created by varnishlog -w.
func (log *Log) NewCursorFile(path string) (*Cursor, error) {
if err := log.checkNil(); err != nil {
return nil, err
}
C.VSL_ResetError(log.vsl)
cursor := C.VSL_CursorFile(log.vsl, C.CString(path), 0)
if cursor == nil {
return nil, log
}
return &Cursor{cursor: cursor, log: log}, nil
}
// Delete releases native resources associated with the Cursor. You
// should always call Delete when you're done with a Cursor, otherwise
// there is a a risk of resource leakage. It is wise to schedule
// invocation with defer after successfully creating a Cursor with one
// of the New*() functions.
func (c *Cursor) Delete() {
if c == nil || c.cursor == nil {
// return silently in the nil case
return
}
C.VSL_DeleteCursor(c.cursor)
c.cursor = nil
}
// Next advances the Cursor to the next Record in the log. It returns
// a Status to indicate an error condition, the end of the log (EOF or
// EOL), or that there are more records in the log.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Next() Status {
return Status(C.VSL_Next(c.cursor))
}
// Match returns true if the record at which the Cursor is currently
// pointing should be included, according to the include/exclude
// filters set for the Log object with which the Cursor was created.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Match() bool {
return C.VSL_Match(c.log.vsl, c.cursor) == 1
}
// Tag returns the Tag of the record at which the Cursor is currently
// pointing.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Tag() Tag {
return c.cursor.rec.tag()
}
// VXID returns the VXID of the record at which the Cursor is
// currently pointing.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) VXID() uint32 {
return c.cursor.rec.vxid()
}
// Payload returns the payload (message content) of the record at
// which the Cursor is currently pointing.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Payload() []byte {
return c.cursor.rec.payload()
}
// Client returns true if the record at which the Cursor is currently
// pointing belongs to a client transaction.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Client() bool {
return c.cursor.rec.client()
}
// Backend returns true if the record at which the Cursor is currently
// pointing belongs to a backend transaction.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Backend() bool {
return c.cursor.rec.backend()
}
// Record returns structured data for the record at which the Cursor
// is currently pointing.
//
// Panics if Cursor is nil, or if was not initialized with one of the
// New* functions.
func (c *Cursor) Record() Record {
rec := Record{
Tag: c.cursor.rec.tag(),
VXID: uint(c.cursor.rec.vxid()),
Payload: string(c.cursor.rec.payload()),
}
switch {
case c.cursor.rec.backend():
rec.Type = Backend
case c.cursor.rec.client():
rec.Type = Client
default:
rec.Type = None
}
return rec
}
pkg/log/log.h → pkg/log/cursor_e2e_test.go
View file @ 7147cd55
// +build e2e
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
......@@ -26,93 +28,117 @@
* SUCH DAMAGE.
*/
#ifndef _LOG_H_INCLUDED
#define _LOG_H_INCLUDED
#include <stdio.h>
#include <vapi/vsl.h>
int dispatch(struct VSLQ *vslq, uint64_t key);
// Necessary because the field name is a go keyword.
static inline enum VSL_transaction_e
txtype(struct VSL_transaction *tx)
{
return tx->type;
}
// The rest are necessary due to the use of macros.
static inline int
slt_max()
{
return SLT__MAX;
}
static inline unsigned
vxid(struct VSL_cursor *c)
{
return (VSL_ID(c->rec.ptr));
}
static inline enum VSL_tag_e
tag(struct VSL_cursor *c)
{
return (VSL_TAG(c->rec.ptr));
}
static inline const char *
cdata(struct VSL_cursor *c)
{
return (VSL_CDATA(c->rec.ptr));
}
static inline int
len(struct VSL_cursor *c)
{
// Subtracting one because Go doesn't need the terminating null.
return (VSL_LEN(c->rec.ptr) - 1);
// This test is only run if go test is invoked with a -tags option
// that includes "e2e". It requires that two instances of Varnish are
// running: a default instance (varnishd invoked without the -n
// option), and an instance named "gotest" (varnishd -n "gotest").
package log
import (
"net/http"
"testing"
)
func TestNewCursor(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
return
}
c, err := l.NewCursor()
if err != nil {
t.Fatal("NewCursor():", err)
return
}
defer c.Delete()
ln := New()
defer ln.Release()
if err := ln.Attach("gotest"); err != nil {
t.Fatal("Attach(gotest):", err)
return
}
cn, err := ln.NewCursor()
if err != nil {
t.Fatal("NewCursor() for gotest:", err)
return
}
defer cn.Delete()
}
static inline int
client(struct VSL_cursor *c)
{
return (VSL_CLIENT(c->rec.ptr));
func TestE2ECursor(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
return
}
c, err := l.NewCursor()
if err != nil {
t.Fatal("NewCursor():", err)
return
}
defer c.Delete()
client := &http.Client{}
req, err := http.NewRequest("GET", url("/uncacheable"), nil)
if err != nil {
t.Fatal("/uncacheable Request", err)
}
req.Close = true
stopChan := make(chan bool)
respChan := make(chan bool)
go func() {
sent := false
for {
select {
case <-stopChan:
return
default:
_, err := client.Do(req)
if err != nil {
t.Fatal("GET request:", err)
return
}
if !sent {
respChan <- true
sent = true
}
}
}
}()
<-respChan
var recs []testRec
for i := 0; i < 100; i++ {
status := c.Next()
vxid := c.VXID()
tag := c.Tag()
payload := c.Payload()
backend := c.Backend()
client := c.Client()
rec := testRec{
vxid: int(vxid),
tag: Tag(tag).String(),
payload: string(payload),
}
if backend {
rec.rectype = 'b'
} else if client {
rec.rectype = 'c'
} else {
rec.rectype = '-'
}
recs = append(recs, rec)
if status == EOL {
break
}
}
stopChan <- true
t.Logf("read %d records", len(recs))
t.Log(recs)
}
static inline int
backend(struct VSL_cursor *c)
{
return (VSL_BACKEND(c->rec.ptr));
}
static inline int
binary(enum VSL_tag_e tag)
{
return (VSL_tagflags[tag] & SLT_F_BINARY);
}
static inline int
unsafe(enum VSL_tag_e tag)
{
return (VSL_tagflags[tag] & SLT_F_UNSAFE);
}
static inline unsigned
vsl_opt_batch()
{
return VSL_COPT_BATCH;
}
static inline unsigned
vsl_opt_tail()
{
return VSL_COPT_TAIL;
}
static inline unsigned
vsl_opt_tailstop()
{
return VSL_COPT_TAILSTOP;
}
#endif
pkg/log/cursor_test.go 0 → 100644
View file @ 7147cd55
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
package log
import "testing"
func TestNewCursorFile(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
}
defer c.Delete()
if _, err := l.NewCursorFile(failPath); err == nil {
t.Error("Expected NewCursorFile(nonexistent) to fail")
}
var n *Log
if _, err := n.NewCursorFile(testFile); err == nil {
t.Error("Expected nil.NewCursorFile() to fail")
}
uninit := &Log{}
if _, err := uninit.NewCursorFile(testFile); err == nil {
t.Error("Expected uninitiailized.NewCursorFile() to fail")
}
}
func TestDelete(t *testing.T) {
// don't panic if the Cursor is nil or uninitialized
var c *Cursor
c.Delete()
uninit := &Cursor{}
uninit.Delete()
}
func TestNext(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
status := c.Next()
// XXX change the status constant, this is vcl_more
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
}
var expFirstRec = testRec{
vxid: 0,
tag: "Backend_health",
rectype: '-',
payload: "boot.test Still healthy 4---X-RH 1 1 1 0.000402 0.000484 HTTP/1.1 204 No Content",
}
func TestTag(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
status := c.Next()
// XXX
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
tag := c.Tag()
if tag.String() != expFirstRec.tag {
t.Errorf("Tag() want=%v got=%v\n", expFirstRec.tag,
tag.String())
}
}
func TestVXID(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
status := c.Next()
// XXX
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
vxid := c.VXID()
if vxid != uint32(expFirstRec.vxid) {
t.Errorf("VXID() want=%v got=%v\n", expFirstRec.vxid, vxid)
}
}
func TestBackend(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
status := c.Next()
// XXX
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
backend := c.Backend()
if backend != (expFirstRec.rectype == rune(Backend)) {
t.Errorf("Backend() want=%v got=%v\n",
expFirstRec.rectype == rune(Backend), backend)
}
}
func TestClient(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
}
defer c.Delete()
status := c.Next()
// XXX
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
client := c.Client()
if client != (expFirstRec.rectype == rune(Client)) {
t.Errorf("Client() want=%v got=%v\n",
expFirstRec.rectype == rune(Client), client)
}
}
func TestPayload(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
status := c.Next()
// XXX
if status != More {
t.Errorf("Next() status want=More got=%d\n", uint8(status))
}
payload := c.Payload()
if string(payload) != expFirstRec.payload {
t.Errorf("Payload() want=%v got=%v\n", expFirstRec.payload,
payload)
}
}
func TestNextFileAll(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
for _, rec := range expRawLog {
status := c.Next()
if status == EOF {
return
}
// XXX should be More
if status != More {
t.Fatal("Next() unexpected status:", status)
return
}
vxid := c.VXID()
if vxid != uint32(rec.vxid) {
t.Errorf("VXID want=%v got=%v\n", rec.vxid, vxid)
}
tag := c.Tag()
if tag.String() != rec.tag {
t.Errorf("Tag() want=%v got=%v\n", rec.tag,
tag.String())
}
payload := c.Payload()
if string(payload) != rec.payload {
t.Errorf("Payload() want=%v got=%v\n", rec.payload,
string(payload))
}
backend := c.Backend()
if backend && rec.rectype != 'b' {
t.Errorf("Backend() want=%v got=b\n", rec.rectype)
}
client := c.Client()
if client && rec.rectype != 'c' {
t.Errorf("Client() want=%v got=c\n", rec.rectype)
}
}
}
func TestNextFileConcurrent(t *testing.T) {
l := New()
defer l.Release()
c1, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c1.Delete()
c2, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c2.Delete()
for _, rec := range expRawLog {
status1 := c1.Next()
status2 := c2.Next()
if status1 != status2 {
t.Errorf("Next() differing status: %v %v\n", status1,
status2)
}
if status1 == EOF {
return
}
// XXX
if status1 != More {
t.Fatal("Next() unexpected status:", status1)
return
}
cursors := [2]*Cursor{c1, c2}
for _, c := range cursors {
vxid := c.VXID()
if vxid != uint32(rec.vxid) {
t.Errorf("VXID want=%v got=%v\n", rec.vxid,
vxid)
}
tag := c.Tag()
if tag.String() != rec.tag {
t.Errorf("Tag() want=%v got=%v\n", rec.tag,
tag.String())
}
payload := c.Payload()
if string(payload) != rec.payload {
t.Errorf("Payload() want=%v got=%v\n",
rec.payload, string(payload))
}
backend := c.Backend()
if backend && rec.rectype != 'b' {
t.Errorf("Backend() want=%v got=b\n",
rec.rectype)
}
client := c.Client()
if client && rec.rectype != 'c' {
t.Errorf("Client() want=%v got=c\n",
rec.rectype)
}
}
}
}
func BenchmarkNextFileOne(b *testing.B) {
for i := 0; i < b.N; i++ {
b.StopTimer()
b.ReportAllocs()
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
b.Fatal("NewCursorFile(bin.log):", err)
}
b.StartTimer()
status := c.Next()
b.StopTimer()
if status != More {
b.Fatalf("Next() status want=More got=%d\n",
uint8(status))
}
c.Delete()
}
}
pkg/log/e2e_test.go
View file @ 7147cd55
......@@ -32,12 +32,10 @@
// that includes "e2e". It requires that two instances of Varnish are
// running: a default instance (varnishd invoked without the -n
// option), and an instance named "gotest" (varnishd -n "gotest").
package log
import (
"net/http"
"strconv"
"strings"
"testing"
"time"
)
......@@ -97,409 +95,3 @@ func TestAttachInstance(t *testing.T) {
"non-existent instance")
}
}
var tx2recType = map[TxType]RecordType{
Sess: Client,
Req: Client,
BeReq: Backend,
}
const (
undefLen int = int(^uint(0) >> 1)
txTypeUndef TxType = TxUnknown
txReasonUndef Reason = ReasonUnknown
txLevelUndef uint = ^uint(0)
txVXIDUndef uint32 = ^uint32(0)
recTypeUndef RecordType = RecordType(0)
recTagUndef string = "undefined tag string"
recVXIDUndef uint = ^uint(0)
recPayloadUndef string = "undefined payload string"
)
type expRec struct {
tag string
payload string
}
type expTx struct {
typ TxType
reason Reason
level uint
vxid uint32
pvxid uint32
recs []expRec
}
type expTxLen struct {
expRecs int
tx expTx
}
type expTxGrp struct {
expTx int
txGrp []expTxLen
}
var expDefaultRead = map[TxType]expTxGrp{
BeReq: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: undefLen,
tx: expTx{
typ: BeReq,
reason: Fetch,
level: 1,
vxid: txVXIDUndef,
pvxid: txVXIDUndef,
recs: nil,
}}},
},
Req: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: undefLen,
tx: expTx{
typ: Req,
reason: RxReq,
level: 1,
vxid: txVXIDUndef,
pvxid: txVXIDUndef,
recs: nil,
}}},
},
Sess: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: 5,
tx: expTx{
typ: Sess,
reason: HTTP1,
level: 1,
vxid: txVXIDUndef,
pvxid: 0,
recs: []expRec{
{
tag: "Begin",
payload: "sess 0 HTTP/1",
},
{
tag: "SessOpen",
payload: recPayloadUndef,
},
{
tag: "Link",
payload: recPayloadUndef,
},
{
tag: "SessClose",
payload: recPayloadUndef,
},
{
tag: "End",
payload: "",
},
}},
}},
},
}
func checkRec(t *testing.T, rec Record, expRec expRec) {
if expRec.tag != recTagUndef && rec.Tag.String() != expRec.tag {
t.Errorf("record tag want=%v got=%s", expRec.tag, rec.Tag)
}
if expRec.payload != recPayloadUndef && rec.Payload != expRec.payload {
t.Errorf("record payload want=%v got=%s", expRec.payload,
rec.Payload)
}
}
func checkTx(t *testing.T, tx Tx, expTxLen expTxLen) {
expTx := expTxLen.tx
if expTx.typ != txTypeUndef && expTx.typ != tx.Type {
t.Errorf("tx.Type want=%v got=%v", expTx.typ, tx.Type)
}
if expTx.reason != txReasonUndef && expTx.reason != tx.Reason {
t.Errorf("tx.Reason want=%v got=%v", expTx.reason, tx.Reason)
}
if expTx.level != txLevelUndef && expTx.level != tx.Level {
t.Errorf("tx.Level want=%v got=%v", expTx.level, tx.Level)
}
if expTx.vxid != txVXIDUndef && expTx.vxid != tx.VXID {
t.Errorf("tx.VXID want=%v got=%v", expTx.vxid, tx.VXID)
}
if expTx.pvxid != txVXIDUndef && expTx.pvxid != tx.ParentVXID {
t.Errorf("tx.ParentVXID want=%v got=%v", expTx.pvxid,
tx.ParentVXID)
}
if expTxLen.expRecs != undefLen && expTxLen.expRecs != len(tx.Records) {
t.Errorf("number of records want=%v got=%v", expTxLen.expRecs,
len(tx.Records))
}
if tx.Records == nil || len(tx.Records) < 1 {
t.Fatal("tx has no records:", tx)
return
}
if tx.Type == TxRaw {
if len(tx.Records) != 1 {
t.Errorf("tx type raw number of records want=1 got=%v",
len(tx.Records))
}
if tx.Records[0].VXID != uint(tx.VXID) {
t.Errorf("record VXID want=%v got=%v", uint(tx.VXID),
tx.Records[0].VXID)
}
} else {
// These conditions always hold for the records in a
// non-raw transaction.
if tx.Records[0].Tag.String() != "Begin" {
t.Errorf("tx first record tag want=Begin got=%s",
tx.Records[0].Tag)
}
lastIdx := len(tx.Records) - 1
if tx.Records[lastIdx].Tag.String() != "End" {
t.Errorf("tx last record tag want=End got=%s",
tx.Records[lastIdx].Tag)
}
if tx.Records[lastIdx].Payload != "" {
t.Errorf("tx last record tag want=%q got=%q", "",
tx.Records[lastIdx].Payload)
}
expType, ok := tx2recType[tx.Type]
if !ok {
t.Fatal("tx2recType no value for", tx.Type)
t.FailNow()
return
}
for _, rec := range tx.Records {
if rec.Type != expType {
t.Errorf("record type want=%c got=%c", expType,
rec.Type)
}
if rec.VXID != uint(tx.VXID) {
t.Errorf("record VXID want=%v got=%v",
uint(tx.VXID), rec.VXID)
}
}
}
if expTx.recs != nil {
for i, rec := range tx.Records {
checkRec(t, rec, expTx.recs[i])
}
}
}
func checkTxGrp(t *testing.T, txGrp []Tx, expTxGrp expTxGrp) {
if expTxGrp.expTx != undefLen && len(txGrp) != expTxGrp.expTx {
t.Fatalf("number of tx in group got=%v want=%v",
len(txGrp), expTxGrp.expTx)
return
}
for i, tx := range txGrp {
checkTx(t, tx, expTxGrp.txGrp[i])
}
}
func checkBereq(t *testing.T, tx Tx, req http.Request) {
if tx.Type != BeReq {
t.Fatalf("checkBereq() tx.Type want=BeReq got=%s", tx.Type)
t.FailNow()
return
}
for _, rec := range tx.Records {
if rec.Tag.String() != "BereqURL" {
continue
}
if rec.Payload != req.URL.Path {
t.Errorf("bereq URL want=%v got=%v", req.URL.Path,
rec.Payload)
}
break
}
}
func checkReqResp(t *testing.T, tx Tx, req http.Request, resp http.Response) {
if tx.Type != Req {
t.Fatalf("checkReqResp() tx.Type want=Req got=%s", tx.Type)
t.FailNow()
return
}
respHdr := make(http.Header)
for _, rec := range tx.Records {
switch rec.Tag.String() {
case "ReqMethod":
if rec.Payload != req.Method {
t.Errorf("request method want=%v got=%v",
req.Method, rec.Payload)
}
case "ReqURL":
if rec.Payload != req.URL.Path {
t.Errorf("request URL want=%v got=%v",
req.URL.Path, rec.Payload)
}
case "ReqProtocol":
if rec.Payload != req.Proto {
t.Errorf("request protocol want=%v got=%v",
req.Proto, rec.Payload)
}
case "ReqHeader":
if !strings.HasPrefix(rec.Payload, "Host:") {
continue
}
host := rec.Payload[len("Host: "):]
if host != req.Host {
t.Errorf("request Host want=%v got=%v",
req.Host, host)
}
case "RespProtocol":
if rec.Payload != resp.Proto {
t.Errorf("response protocol want=%v got=%v",
resp.Proto, rec.Payload)
}
case "RespStatus":
expStatus := strconv.FormatInt(int64(resp.StatusCode),
10)
if rec.Payload != expStatus {
t.Errorf("response status want=%d got=%v",
resp.StatusCode, rec.Payload)
}
case "RespReason":
expReason := resp.Status[4:]
if rec.Payload != expReason {
t.Errorf("response reason want=%v got=%v",
expReason, rec.Payload)
}
case "RespHeader":
colonIdx := strings.Index(rec.Payload, ": ")
if colonIdx < 0 {
t.Fatal("cannot parse response header:",
rec.Payload)
continue
}
hdr := rec.Payload[:colonIdx]
val := rec.Payload[colonIdx+2:]
respHdr.Set(hdr, val)
default:
continue
}
}
// http.Response apparently removes the Connection header, but
// sets its Close field to true if it was present and set to
// "close".
if resp.Close {
conn := respHdr.Get("Connection")
if conn != "close" {
t.Errorf("response Connection:close not found")
}
if conn != "" {
respHdr.Del("Connection")
}
}
// Won't worry about multiple values for a header
if len(resp.Header) != len(respHdr) {
t.Errorf("response headers want=%v got=%v", len(resp.Header),
len(respHdr))
return
}
for h, _ := range resp.Header {
if respHdr.Get(h) != resp.Header.Get(h) {
t.Errorf("response header %v want=%v got=%v", h,
resp.Header.Get(h), respHdr.Get(h))
}
}
}
const target = "http://localhost:8080"
func url(path string) string {
return target + path
}
func TestE2EDefaultRead(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
}
var status Status
var txGrps [][]Tx
rdHndlr := func(txGrp []Tx, rdstatus Status) bool {
switch rdstatus {
case More:
txGrps = append(txGrps, txGrp)
if len(txGrps) == 3 {
return false
}
return true
default:
status = rdstatus
return false
}
}
stopChan := make(chan bool)
readFailed := false
go func() {
err := l.Read(rdHndlr, nil)
if err != nil {
t.Fatal("Read(): " + err.Error())
readFailed = true
}
stopChan <- true
}()
client := &http.Client{}
req, err := http.NewRequest("GET", url("/uncacheable"), nil)
if err != nil {
t.Fatal("/uncacheable Request", err)
}
req.Close = true
resp, err := client.Do(req)
if err != nil {
t.Fatal("/uncacheable Response", err)
}
<-stopChan
if readFailed {
return
}
if status != Stopped {
t.Errorf("End read status want=%v got=%v", Stopped, status)
}
if len(txGrps) != 3 {
t.Errorf("number of tx groups want=3 got=%v", len(txGrps))
}
for _, txGrp := range txGrps {
tx := txGrp[0]
checkTxGrp(t, txGrp, expDefaultRead[tx.Type])
if tx.Type == BeReq {
checkBereq(t, tx, *req)
}
if tx.Type == Req {
checkReqResp(t, tx, *req, *resp)
}
}
}
func TestStartAtHead(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
}
if err := l.StartAtHead(true); err != nil {
t.Error("StartAtHead(true):", err)
}
if err := l.StartAtHead(false); err != nil {
t.Error("StartAtHead(false):", err)
}
var n *Log
if err := n.StartAtHead(true); err == nil {
t.Error("expected nil.StartAtHead() to fail")
}
uninit := new(Log)
if err := uninit.StartAtHead(true); err == nil {
t.Error("expected uninitialized.StartAtHead() to fail")
}
}
pkg/log/log.go
View file @ 7147cd55
......@@ -32,7 +32,38 @@ package log
/*
#cgo pkg-config: varnishapi
#include "log.h"
#include <stdio.h>
#include <vapi/vsl.h>
int
slt_max()
{
return SLT__MAX;
}
unsigned
vsl_opt_batch()
{
return VSL_COPT_BATCH;
}
unsigned
vsl_opt_tail()
{
return VSL_COPT_TAIL;
}
unsigned
vsl_opt_tailstop()
{
return VSL_COPT_TAILSTOP;
}
int
nonprintable(enum VSL_tag_e tag)
{
return (VSL_tagflags[tag] & (SLT_F_BINARY | SLT_F_UNSAFE));
}
*/
import "C"
......@@ -41,12 +72,7 @@ import (
"errors"
"fmt"
"os"
"regexp"
"sync"
"sync/atomic"
"time"
"unsafe"
)
// TxType is a classifier for a log transaction, indicating if it is
......@@ -189,6 +215,14 @@ const (
Session = Grouping(C.VSL_g_session)
)
// Str2Grp maps strings to Grouping constants.
var Str2Grp = map[string]Grouping{
"raw": GRaw,
"vxid": VXID,
"request": Request,
"session": Session,
}
// RecordType is a classifier for the data in a Record, indicating if
// it is part of the log for a client request/response, a backend
// request/repsonse, or neither. Corresponds to the indicator 'b',
......@@ -233,13 +267,7 @@ func initTags() []string {
return tags
}
var (
tags = initTags()
nonprint = regexp.MustCompile("[^[:print:]]")
mapCtr = uint64(0)
cbMap = make(map[uint64]ReadHandler)
cbLock sync.RWMutex
)
var tags = initTags()
// A Tag is a classifier for the contents of a Record's payload,
// corresponding to the second column of default varnishlog
......@@ -262,6 +290,14 @@ func (tag Tag) String() string {
return tags[tag]
}
// Nonprintable returns true if log payloads of the type indicated by
// the tag may contain non-printable characters. If Nonprintable()
// returns false (which is the case for most tags), you can assume
// that the log payload contains only printable ASCII characters.
func (tag Tag) Nonprintable() bool {
return C.nonprintable(uint32(tag)) != 0
}
// A Record in the Varnish log, corresponding to a line of output from
// the varnishlog utility. Instances of this type are contained in the
// Tx objects returned by Read() operations, and form the bulk of log
......@@ -341,10 +377,6 @@ type Log struct {
vsl *C.struct_VSL_data
vsm *vsm.VSM
vsmopts C.unsigned
cursor *C.struct_VSL_cursor
grp C.enum_VSL_grouping_e
query *C.char
rdLock sync.Mutex
}
// New returns a new and initialized instance of Log. Log instances
......@@ -361,9 +393,9 @@ func New() *Log {
return nil
}
log.vsm = nil
log.vsmopts = C.vsl_opt_batch() | C.vsl_opt_tail()
log.grp = C.VSL_g_vxid
log.query = nil
log.vsmopts = C.vsl_opt_tail()
// log.grp = C.VSL_g_vxid
// log.query = nil
return log
}
......@@ -391,9 +423,6 @@ func (log *Log) Release() {
if log == nil || log.vsl == nil {
return
}
if log.cursor != nil {
C.VSL_DeleteCursor(log.cursor)
}
if log.vsm != nil {
// ignoring nil check errors
_ = log.vsm.Destroy()
......@@ -452,129 +481,9 @@ func (log *Log) Attach(name string) error {
if log.vsm.VSM == nil {
panic("VSM handle is nil")
}
C.VSL_ResetError(log.vsl)
log.cursor = C.VSL_CursorVSM(log.vsl, (*C.struct_vsm)(log.vsm.VSM),
log.vsmopts)
if log.cursor == nil {
return log
}
return nil
}
// AttachFile attaches the client for reading from the binary log file
// located at path, as written by varnishlog -w.
//
// Returns nil if no file at that path is readable by the current
// process, if it is not a regular file, or if the native interface
// cannot successfully attach to the file.
func (log *Log) AttachFile(path string) error {
if err := log.checkNil(); err != nil {
return err
}
info, err := os.Stat(path)
if err != nil {
return err
}
if !info.Mode().IsRegular() {
return errors.New(path + " is not a regular file")
}
log.cursor = C.VSL_CursorFile(log.vsl, C.CString(path), 0)
if log.cursor == nil {
return log
}
return nil
}
func quote(s string) string {
return fmt.Sprintf("%q", s)
}
// StartAtHead determines whether log reads from a live Varnish
// instance begin at the current head or tail of the ring buffer that
// forms the Varnish log. Set true to start at the head, false to
// start at the tail. Starting at the head has the effect of the -d
// option for varnishlog(1).
//
// By default, live log reads begin at the tail.
//
// StartAtHead has no effect on reads from a binary log file -- the
// log file is read from beginning to end.
func (log *Log) StartAtHead(head bool) error {
if err := log.checkNil(); err != nil {
return err
}
if head {
log.vsmopts &= ^(C.vsl_opt_tail())
return nil
}
log.vsmopts |= C.vsl_opt_tail()
return nil
}
//export publish
func publish(trans unsafe.Pointer, key uint64) C.int {
txn := (*[1 << 30]*C.struct_VSL_transaction)(unsafe.Pointer(trans))
if txn[0] == nil {
return 0
}
cbLock.RLock()
cb, ok := cbMap[key]
cbLock.RUnlock()
if !ok {
panic("unmapped read handler")
}
var gtxn []Tx
status := C.int(0)
for i := 0; txn[i] != nil; i++ {
var tx Tx
vtx := txn[i]
tx.Type = TxType(C.txtype(vtx))
tx.VXID = uint32(vtx.vxid)
tx.ParentVXID = uint32(vtx.vxid_parent)
tx.Reason = Reason(vtx.reason)
tx.Level = uint(vtx.level)
for {
status = C.int(C.VSL_Next(vtx.c))
if status <= 0 {
break
}
tag := C.tag(vtx.c)
if tag < 0 || int(tag) >= len(tags) {
panic("tag index out of range")
}
var rec Record
rec.Tag = Tag(tag)
rec.Payload = C.GoStringN(C.cdata(vtx.c), C.len(vtx.c))
if C.unsafe(tag) != 0 || C.binary(tag) != 0 {
nonprint.ReplaceAllStringFunc(rec.Payload,
quote)
}
switch {
case C.backend(vtx.c) != 0:
rec.Type = Backend
case C.client(vtx.c) != 0:
rec.Type = Client
default:
rec.Type = None
}
rec.VXID = uint(C.vxid(vtx.c))
tx.Records = append(tx.Records, rec)
}
gtxn = append(gtxn, tx)
}
if status < 0 {
cb(nil, Status(status))
return status
}
if cb(gtxn, More) {
return 0
}
return C.int(Stopped)
}
// Status classifies the current state of a log read sequence. A value
// of this type is passed to the ReadHandler used by the Read method.
type Status int8
......@@ -602,13 +511,9 @@ const (
// reached (there are currently no new log data).
EOL = Status(C.vsl_end)
// More indicates that there are transactions pending during a
// log read.
More = Status(C.vsl_more + 1)
// Stopped indicates that the read handler has returned false,
// to stop log reads.
Stopped = More + 1
// More indicates that there are more records to be read from
// the log.
More = Status(C.vsl_more)
)
// String returns a string describing the Status.
......@@ -628,8 +533,6 @@ func (status Status) String() string {
return "End of log"
case More:
return "More log transactions are pending"
case Stopped:
return "Read stopped by handler"
default:
panic("invalid status")
}
......@@ -643,141 +546,3 @@ func (status Status) String() string {
func (status Status) Error() string {
return status.String()
}
// ReadHandler is the type of a callback function that is passed to
// the Read method, and is invoked while the log is being read.
//
// When the log read has aggregated a group of transactions, they are
// passed to the handler as a slice of Tx objects. The second
// argument of type Status is log.More in this case.
//
// When the log read encounters an error or end condition (end of log
// or end of file), then it passes a Status in the second argument to
// indicate the condition. The first argument (the slice) is nil in
// this case.
//
// The handler returns true or false to signal whether the log read
// should continue. If the handler returns false, it is invoked one
// more time with the Status set to Stopped, and nil for the
// transaction slice, and the Read method finishes.
//
// All of the data passed into the paramters of the handler (the slice
// of Tx and the Status) were allocated as local variables during the
// execution of Read. They go out of scope (and hence are eligible for
// garbage collection) when the handler finishes execution.
type ReadHandler func([]Tx, Status) bool
// EOLHandler is the type of a function that is passed to the Read
// method. It is executed when the end-of-log condition is encountered
// while the log of a live Varnish instance is being read during the
// execution of Read. This means that the end of the log buffer has
// been reached, and there are currently no new transactions.
//
// If the handler returns true, then log reads are continued in the
// Read invocation. If it returns false, then log reads are ended, and
// Read finishes.
//
// If nil is passed to Read as the handler, then a default EOLHandler
// is executed that sleeps for 10 milliseconds (as is done by default
// for the log tools in the Varnish distribution), and returns true to
// continue reads.
//
// If you use your own implementation of an EOLHandler, it is strongly
// recommended to pause for a brief time (for example with
// Time.sleep). Otherwise, Read can become a busy-wait loop while
// there are no new log transactions, with heavy CPU consumption.
//
// If the Log is reading from a binary log file, then there is never
// an end-of-log condition -- the log read ends with status EOF. So no
// EOLHandler is executed, and the Read parameter can just as well be
// nil.
type EOLHandler func() bool
func defaultEOLHndlr() bool {
time.Sleep(10 * time.Millisecond)
return true
}
// Read reads from the currently attached log source, and invokes
// rdHndler with data from the log, as documented for ReadHandler.
//
// You can also pass in an EOLHandler that is executed when the log
// reaches the EOL condition reading from the log of a live Varnish
// instance, as documented above. If eolHndler is nil, then the
// default EOLHandler is used. The EOLHandler is never executed for
// reads from a binary log file.
//
// Note that the native read executed during Read is locked per Log
// object, because it is not safe for concurrency with the same
// internal handles. If Read is continuously reading from a live
// Varnish log, it will be locked the entire time. For concurrent
// Reads, initialize different Log instances that are attached
// separately to the log sources.
//
// Returns an error if rdHndlr is nil, if the Log object is not
// attached to a log source, or if the native library could not
// initialize the read.
//
// Example:
//
// // this callback will be passed to the Read method
// rdHndlr := func(txGrp []log.Tx, rdstatus log.Status) bool {
// // discontinue reads if the status is not log.More
// if rdstatus != log.More {
// return false
// }
// for i, tx := range txGrp {
// // do stuff with each transaction in the group ...
// }
// // return true to indicate that reads should continue
// return true
// }
//
// // assuming that vlog is an initialized Log object that is
// // attached to a log source
// err = vlog.Read(rdHndler, nil)
// if err != nil {
// // error handling ...
// }
func (log *Log) Read(rdHndlr ReadHandler, eolHndlr EOLHandler) error {
if err := log.checkNil(); err != nil {
return err
}
if log.vsm == nil && log.cursor == nil {
return errors.New("not attached to a log source")
}
if rdHndlr == nil {
return errors.New("callback is nil")
}
if eolHndlr == nil {
eolHndlr = defaultEOLHndlr
}
vslq := C.VSLQ_New(log.vsl, &log.cursor, log.grp, log.query)
if vslq == nil {
return log
}
defer C.VSLQ_Delete(&vslq)
key := atomic.AddUint64(&mapCtr, 1)
cbLock.Lock()
cbMap[key] = rdHndlr
cbLock.Unlock()
status := C.int(C.vsl_more)
log.rdLock.Lock()
for status == C.vsl_more {
status = C.dispatch(vslq, C.uint64_t(key))
if status == C.vsl_end && eolHndlr() {
status = C.vsl_more
}
}
rdHndlr(nil, Status(status))
log.rdLock.Unlock()
cbLock.Lock()
delete(cbMap, key)
cbLock.Unlock()
return nil
}
pkg/log/log_test.go
View file @ 7147cd55
......@@ -28,111 +28,7 @@
package log
import (
"bufio"
"errors"
"fmt"
"os"
"regexp"
"strconv"
"testing"
)
const (
testFile = "testdata/bin.log"
vxidLog = "testdata/vxid.log"
failPath = "ifAFileWithThisNameReallyExistsThenTestsFail"
)
type testRec struct {
vxid int
tag string
rectype rune
payload string
}
type testTx struct {
level uint
vxid uint32
txtype string
recs []testRec
}
var (
txline = regexp.MustCompile(`^(\*+)\s+<<\s+(\w+)\s+>>\s+(\d+)`)
recline = regexp.MustCompile(`^-+\s+(\d+)\s+(\w+)\s+([b|c|-])\s+(.*)$`)
begin = regexp.MustCompile(`^\w+\s+(\d+)\s+(\S+)$`)
)
func scrapeLog(file string) ([]testTx, error) {
var txn []testTx
f, err := os.Open(file)
if err != nil {
return nil, err
}
lines := bufio.NewScanner(f)
TX:
for lines.Scan() {
flds := txline.FindStringSubmatch(lines.Text())
if flds == nil {
return nil, errors.New("Cannot parse tx line: " +
lines.Text())
}
txVxid, err := strconv.Atoi(flds[3])
if err != nil {
return nil, errors.New("Cannot parse vxid " +
flds[4] + " in tx line: " + lines.Text())
}
tx := testTx{}
tx.vxid = uint32(txVxid)
// NB: this works only for levels up to 3
tx.level = uint(len(flds[1]))
tx.txtype = flds[2]
for lines.Scan() {
// XXX: currently does not work for grouped txn
if lines.Text() == "" {
txn = append(txn, tx)
continue TX
}
flds = recline.FindStringSubmatch(lines.Text())
if flds == nil {
return nil, errors.New("Cannot parse record: " +
lines.Text())
}
rec := testRec{}
rec.vxid, err = strconv.Atoi(flds[1])
if err != nil {
return nil, errors.New("Cannot parse vxid " +
flds[1] + " in rec line: " +
lines.Text())
}
rec.tag = flds[2]
rec.rectype = rune(flds[3][0])
rec.payload = flds[4]
tx.recs = append(tx.recs, rec)
}
}
return txn, nil
}
var expVxidLog []testTx
func TestMain(m *testing.M) {
files := []string{testFile, vxidLog}
for _, file := range files {
if _, err := os.Stat(file); err != nil {
fmt.Fprintln(os.Stderr, "Cannot stat "+file+":", err)
os.Exit(1)
}
}
var err error
if expVxidLog, err = scrapeLog(vxidLog); err != nil {
fmt.Fprintln(os.Stderr, "Cannot parse "+vxidLog+":", err)
os.Exit(1)
}
os.Exit(m.Run())
}
import "testing"
var expTxTypeStr = map[TxType]string{
TxUnknown: "Unknown",
......@@ -176,7 +72,7 @@ func TestStatusString(t *testing.T) {
// Just make sure it doesn't panic, don't want tests to depend
// on specific values of the strings.
stati := [...]Status{
WriteErr, IOErr, Overrun, Abandoned, EOF, EOL, More, Stopped,
WriteErr, IOErr, Overrun, Abandoned, EOF, EOL, More,
}
for _, v := range stati {
_ = v.String()
......@@ -213,49 +109,6 @@ func TestNewRelease(t *testing.T) {
uninit.Release()
}
func TestAttachFile(t *testing.T) {
l := New()
defer l.Release()
err := l.AttachFile(failPath)
if err == nil {
t.Error("Expected AttachFile() to fail for " + failPath)
}
err = l.AttachFile(testFile)
if err != nil {
t.Fatal("Cannot attach to " + testFile + ": " + err.Error())
}
var n *Log
if err := n.AttachFile(testFile); err == nil {
t.Error("expected nil.AttachFile() to fail")
}
uninit := &Log{}
if err := uninit.AttachFile(testFile); err == nil {
t.Error("expected uninitialized.AttachFile() to fail")
}
}
func TestRead(t *testing.T) {
rdHndlr := func(txGrp []Tx, rdstatus Status) bool {
return false
}
var n *Log
if err := n.Read(rdHndlr, nil); err == nil {
t.Error("expected nil.Read() to fail")
}
uninit := &Log{}
if err := uninit.Read(rdHndlr, nil); err == nil {
t.Error("expected uninitialized.Read() to fail")
}
l := New()
defer l.Release()
if err := l.Read(rdHndlr, nil); err == nil {
t.Error("expected l.Read() before attach to fail")
}
}
func TestError(t *testing.T) {
// just make sure there is no panic for the nil or "no error" cases
var n *Log
......@@ -267,222 +120,3 @@ func TestError(t *testing.T) {
defer l.Release()
_ = l.Error()
}
func checkTxGroups(t *testing.T, txGrps [][]Tx, expTxn []testTx) {
if len(txGrps) != len(expTxn) {
t.Fatalf("number of transaction groups expected=%v got=%v",
len(expTxn), len(txGrps))
return
}
for i, txGrp := range txGrps {
if len(txGrp) != 1 {
t.Fatalf("transactions in group expected=1 got=%v",
len(txGrp))
}
tx := txGrp[0]
expTx := expTxn[i]
if tx.Level != expTx.level {
t.Errorf("tx Level expected=%v got=%v", expTx.level,
tx.Level)
}
if tx.VXID != expTx.vxid {
t.Errorf("tx VXID expected=%v got=%v", expTx.vxid,
tx.VXID)
}
if tx.Type.String() != expTx.txtype {
t.Errorf("tx Type expected=%v got=%v", expTx.txtype,
tx.Type.String())
}
if tx.Type != TxRaw {
if len(expTx.recs) == 0 {
t.Error("scraped tx has no records")
break
}
if expTx.recs[0].tag != "Begin" {
t.Error("scraped tx does not begin with Begin")
}
payload := expTx.recs[0].payload
flds := begin.FindStringSubmatch(payload)
if len(flds) != 3 {
t.Errorf("could not parse Begin: " + payload)
break
}
if tx.Reason.String() != flds[2] {
t.Errorf("tx reason expected=%v got=%s",
flds[2], tx.Reason)
}
// XXX test parent vxid in grouped txn
}
if len(tx.Records) != len(expTx.recs) {
t.Errorf("tx number of records expected=%v got=%v",
len(expTx.recs), len(tx.Records))
continue
}
for j, rec := range tx.Records {
expRec := expTx.recs[j]
if rec.VXID != uint(expRec.vxid) {
t.Errorf("rec vxid expected=%v got=%v",
expRec.vxid, rec.VXID)
}
if rec.Tag.String() != expRec.tag {
t.Errorf("rec tag expected=%v got=%s",
expRec.tag, rec.Tag)
}
if rune(rec.Type) != expRec.rectype {
t.Errorf("rec type expected=%v got=%v",
expRec.rectype, rune(rec.Type))
}
if len(rec.Payload) != len(expRec.payload) {
t.Errorf("rec payload length "+
"expected=%v got=%v",
len(expRec.payload), len(rec.Payload))
}
if rec.Payload != expRec.payload {
t.Errorf("rec payload expected='%v' got='%v'",
expRec.payload, rec.Payload)
}
}
}
}
func TestDefaultRead(t *testing.T) {
var txGrps [][]Tx
l := New()
defer l.Release()
err := l.AttachFile(testFile)
if err != nil {
t.Fatal("Cannot attach to " + testFile + ": " + err.Error())
}
// Test coverage for this case
if err := l.Read(nil, nil); err == nil {
t.Error("expected l.Read() with nil ReadHandler to fail")
}
var status Status
rdHndlr := func(txGrp []Tx, rdstatus Status) bool {
if rdstatus != More {
status = rdstatus
return false
}
txGrps = append(txGrps, txGrp)
return true
}
err = l.Read(rdHndlr, nil)
if err != nil {
t.Fatal("Read(): " + err.Error())
}
// More test coverage
if err := l.Read(rdHndlr, nil); err == nil {
t.Error("expected l.Read() with read already running to fail")
}
if status != Status(EOF) {
t.Errorf("expected EOF status got: %s", status.Error())
}
checkTxGroups(t, txGrps, expVxidLog)
}
func readHndl(txGrp []Tx, status Status, txGrps *[][]Tx, end *Status) bool {
if status != More {
*end = status
return false
}
*txGrps = append(*txGrps, txGrp)
return true
}
func TestConcurrentRead(t *testing.T) {
var txGrps1, txGrps2 [][]Tx
l1 := New()
defer l1.Release()
err := l1.AttachFile(testFile)
if err != nil {
t.Fatal("l1 attach to " + testFile + ": " + err.Error())
}
l2 := New()
defer l2.Release()
err = l2.AttachFile(testFile)
if err != nil {
t.Fatal("l2 attach to " + testFile + ": " + err.Error())
}
var endStatus1 Status
var endStatus2 Status
hndlr1 := func(txGrp []Tx, rdstatus Status) bool {
return readHndl(txGrp, rdstatus, &txGrps1, &endStatus1)
}
hndlr2 := func(txGrp []Tx, rdstatus Status) bool {
return readHndl(txGrp, rdstatus, &txGrps2, &endStatus2)
}
err1 := l1.Read(hndlr1, nil)
err2 := l2.Read(hndlr2, nil)
if err1 != nil {
t.Fatal("l1.Read(): " + err.Error())
}
if err2 != nil {
t.Fatal("l2.Read(): " + err.Error())
}
if endStatus1 != Status(EOF) {
t.Errorf("expected EOF status got: %s", endStatus1.Error())
}
if endStatus2 != Status(EOF) {
t.Errorf("expected EOF status got: %s", endStatus2.Error())
}
checkTxGroups(t, txGrps1, expVxidLog)
checkTxGroups(t, txGrps2, expVxidLog)
}
func BenchmarkReadFileOneTxGrp(b *testing.B) {
for i := 0; i < b.N; i++ {
b.StopTimer()
b.ReportAllocs()
l := New()
defer l.Release()
if err := l.AttachFile(testFile); err != nil {
b.Fatal("AttachFile():", err)
return
}
rdHndlr := func(txGrp []Tx, rdstatus Status) bool {
return false
}
b.StartTimer()
if err := l.Read(rdHndlr, nil); err != nil {
b.Fatal("Read():", err)
}
}
}
func BenchmarkReadFileAllTxGrps(b *testing.B) {
for i := 0; i < b.N; i++ {
b.StopTimer()
b.ReportAllocs()
l := New()
defer l.Release()
if err := l.AttachFile(testFile); err != nil {
b.Fatal("AttachFile():", err)
return
}
rdHndlr := func(txGrp []Tx, rdstatus Status) bool {
return true
}
b.StartTimer()
if err := l.Read(rdHndlr, nil); err != nil {
b.Fatal("Read():", err)
}
}
}
pkg/log/main_test.go 0 → 100644
View file @ 7147cd55
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
package log
import (
"bufio"
"errors"
"fmt"
"net/http"
"os"
"regexp"
"strconv"
"strings"
"testing"
)
const (
testFile = "testdata/bin.log"
vxidLog = "testdata/vxid.log"
rawLog = "testdata/raw.log"
failPath = "ifAFileWithThisNameReallyExistsThenTestsFail"
target = "http://localhost:8080"
)
type testRec struct {
vxid int
tag string
rectype rune
payload string
}
type testTx struct {
level uint
vxid uint32
txtype string
recs []testRec
}
var (
txline = regexp.MustCompile(`^(\*+)\s+<<\s+(\w+)\s+>>\s+(\d+)`)
recline = regexp.MustCompile(`^-+\s+(\d+)\s+(\w+)\s+([b|c|-])\s+(.*)$`)
begin = regexp.MustCompile(`^\w+\s+(\d+)\s+(\S+)$`)
rawLine = regexp.MustCompile(`^\s+(\d+)\s+(\w+)\s+([b|c|-])\s+(.*)$`)
expVxidLog []testTx
expRawLog []testRec
)
func url(path string) string {
return target + path
}
// XXX test helpers currently only work with vxid grouping
// Scrape a log file with transactional data written by varnishlog in
// verbose mode.
func scrapeLog(file string) ([]testTx, error) {
var txn []testTx
f, err := os.Open(file)
if err != nil {
return nil, err
}
lines := bufio.NewScanner(f)
TX:
for lines.Scan() {
flds := txline.FindStringSubmatch(lines.Text())
if flds == nil {
return nil, errors.New("Cannot parse tx line: " +
lines.Text())
}
txVxid, err := strconv.Atoi(flds[3])
if err != nil {
return nil, errors.New("Cannot parse vxid " +
flds[4] + " in tx line: " + lines.Text())
}
tx := testTx{}
tx.vxid = uint32(txVxid)
// NB: this works only for levels up to 3
tx.level = uint(len(flds[1]))
tx.txtype = flds[2]
for lines.Scan() {
// XXX: currently does not work for grouped txn
if lines.Text() == "" {
txn = append(txn, tx)
continue TX
}
flds = recline.FindStringSubmatch(lines.Text())
if flds == nil {
return nil, errors.New("Cannot parse record: " +
lines.Text())
}
rec := testRec{}
rec.vxid, err = strconv.Atoi(flds[1])
if err != nil {
return nil, errors.New("Cannot parse vxid " +
flds[1] + " in rec line: " +
lines.Text())
}
rec.tag = flds[2]
rec.rectype = rune(flds[3][0])
rec.payload = flds[4]
tx.recs = append(tx.recs, rec)
}
}
return txn, nil
}
// Scrape a log file with raw transactions written by varnishlog in
// verbose mode.
func scrapeRawLog(file string) ([]testRec, error) {
var testRecs []testRec
f, err := os.Open(file)
if err != nil {
return nil, err
}
defer f.Close()
lines := bufio.NewScanner(f)
for lines.Scan() {
flds := rawLine.FindStringSubmatch(lines.Text())
if flds == nil {
return nil, errors.New("Cannot parse line: " +
lines.Text())
}
vxid, err := strconv.Atoi(flds[1])
if err != nil {
return nil, errors.New("Cannot parse vxid " + flds[1] +
" in line: " + lines.Text())
}
rec := testRec{
vxid: vxid,
tag: flds[2],
rectype: rune(flds[3][0]),
payload: flds[4],
}
testRecs = append(testRecs, rec)
}
return testRecs, nil
}
func checkRecord(t *testing.T, rec Record, expRec testRec) {
if rec.VXID != uint(expRec.vxid) {
t.Errorf("rec vxid expected=%v got=%v", expRec.vxid, rec.VXID)
}
if rec.Tag.String() != expRec.tag {
t.Errorf("rec tag expected=%v got=%s", expRec.tag, rec.Tag)
}
if rune(rec.Type) != expRec.rectype {
t.Errorf("rec type expected=%v got=%v", expRec.rectype,
rune(rec.Type))
}
if len(rec.Payload) != len(expRec.payload) {
t.Errorf("rec payload length expected=%v got=%v",
len(expRec.payload), len(rec.Payload))
}
if rec.Payload != expRec.payload {
t.Errorf("rec payload expected='%v' got='%v'", expRec.payload,
rec.Payload)
}
}
func checkExpTx(t *testing.T, tx Tx, expTx testTx) {
if tx.Level != expTx.level {
t.Errorf("tx Level expected=%v got=%v", expTx.level, tx.Level)
}
if tx.VXID != expTx.vxid {
t.Errorf("tx VXID expected=%v got=%v", expTx.vxid, tx.VXID)
}
if tx.Type.String() != expTx.txtype {
t.Errorf("tx Type expected=%v got=%v", expTx.txtype,
tx.Type.String())
}
if tx.Type != TxRaw {
if len(expTx.recs) == 0 {
t.Error("scraped tx has no records")
return
}
if expTx.recs[0].tag != "Begin" {
t.Error("scraped tx does not begin with Begin")
}
payload := expTx.recs[0].payload
flds := begin.FindStringSubmatch(payload)
if len(flds) != 3 {
t.Errorf("could not parse Begin: " + payload)
return
}
if tx.Reason.String() != flds[2] {
t.Errorf("tx reason expected=%v got=%s", flds[2],
tx.Reason)
}
// XXX test parent vxid in grouped txn
}
if len(tx.Records) != len(expTx.recs) {
t.Errorf("tx number of records expected=%v got=%v",
len(expTx.recs), len(tx.Records))
return
}
for i, rec := range tx.Records {
expRec := expTx.recs[i]
checkRecord(t, rec, expRec)
}
}
func checkTxGroups(t *testing.T, txGrps [][]Tx, expTxn []testTx) {
if len(txGrps) != len(expTxn) {
t.Fatalf("number of transaction groups expected=%v got=%v",
len(expTxn), len(txGrps))
return
}
for i, txGrp := range txGrps {
if len(txGrp) != 1 {
t.Fatalf("transactions in group expected=1 got=%v",
len(txGrp))
}
checkExpTx(t, txGrp[0], expTxn[i])
}
}
func checkBereq(t *testing.T, tx Tx, req http.Request) {
if tx.Type != BeReq {
t.Fatalf("checkBereq() tx.Type want=BeReq got=%s", tx.Type)
t.FailNow()
return
}
for _, rec := range tx.Records {
if rec.Tag.String() != "BereqURL" {
continue
}
if rec.Payload != req.URL.Path {
t.Errorf("bereq URL want=%v got=%v", req.URL.Path,
rec.Payload)
}
break
}
}
func checkReqResp(t *testing.T, tx Tx, req http.Request, resp http.Response) {
if tx.Type != Req {
t.Fatalf("checkReqResp() tx.Type want=Req got=%s", tx.Type)
t.FailNow()
return
}
respHdr := make(http.Header)
for _, rec := range tx.Records {
switch rec.Tag.String() {
case "ReqMethod":
if rec.Payload != req.Method {
t.Errorf("request method want=%v got=%v",
req.Method, rec.Payload)
}
case "ReqURL":
if rec.Payload != req.URL.Path {
t.Errorf("request URL want=%v got=%v",
req.URL.Path, rec.Payload)
}
case "ReqProtocol":
if rec.Payload != req.Proto {
t.Errorf("request protocol want=%v got=%v",
req.Proto, rec.Payload)
}
case "ReqHeader":
if !strings.HasPrefix(rec.Payload, "Host:") {
continue
}
host := rec.Payload[len("Host: "):]
if host != req.Host {
t.Errorf("request Host want=%v got=%v",
req.Host, host)
}
case "RespProtocol":
if rec.Payload != resp.Proto {
t.Errorf("response protocol want=%v got=%v",
resp.Proto, rec.Payload)
}
case "RespStatus":
expStatus := strconv.FormatInt(int64(resp.StatusCode),
10)
if rec.Payload != expStatus {
t.Errorf("response status want=%d got=%v",
resp.StatusCode, rec.Payload)
}
case "RespReason":
expReason := resp.Status[4:]
if rec.Payload != expReason {
t.Errorf("response reason want=%v got=%v",
expReason, rec.Payload)
}
case "RespHeader":
colonIdx := strings.Index(rec.Payload, ": ")
if colonIdx < 0 {
t.Fatal("cannot parse response header:",
rec.Payload)
continue
}
hdr := rec.Payload[:colonIdx]
val := rec.Payload[colonIdx+2:]
respHdr.Set(hdr, val)
default:
continue
}
}
// http.Response apparently removes the Connection header, but
// sets its Close field to true if it was present and set to
// "close".
if resp.Close {
conn := respHdr.Get("Connection")
if conn != "close" {
t.Errorf("response Connection:close not found")
}
if conn != "" {
respHdr.Del("Connection")
}
}
// Won't worry about multiple values for a header
if len(resp.Header) != len(respHdr) {
t.Errorf("response headers want=%v got=%v", len(resp.Header),
len(respHdr))
return
}
for h := range resp.Header {
if respHdr.Get(h) != resp.Header.Get(h) {
t.Errorf("response header %v want=%v got=%v", h,
resp.Header.Get(h), respHdr.Get(h))
}
}
}
func TestMain(m *testing.M) {
files := []string{testFile, vxidLog, rawLog}
for _, file := range files {
if _, err := os.Stat(file); err != nil {
fmt.Fprintln(os.Stderr, "Cannot stat "+file+":", err)
os.Exit(1)
}
}
var err error
if expVxidLog, err = scrapeLog(vxidLog); err != nil {
fmt.Fprintln(os.Stderr, "Cannot parse "+vxidLog+":", err)
os.Exit(1)
}
if expRawLog, err = scrapeRawLog(rawLog); err != nil {
fmt.Fprintln(os.Stderr, "Cannot parse "+rawLog+":", err)
os.Exit(1)
}
os.Exit(m.Run())
}
pkg/log/query.go 0 → 100644
View file @ 7147cd55
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
package log
/*
#cgo pkg-config: varnishapi
#include <stdio.h>
#include <vapi/vsl.h>
*/
import "C"
import (
"errors"
"strconv"
"strings"
)
// A Query provides the means to read aggregated transactions from the
// log. A Query must be created from a Cursor using the NewQuery
// function.
type Query struct {
cursor *Cursor
incomplete map[uint32]*Tx
grp Grouping
}
var str2type = map[string]TxType{
"sess": Sess,
"req": Req,
"bereq": BeReq,
}
var str2reason = map[string]Reason{
"HTTP/1": HTTP1,
"rxreq": RxReq,
"esi": ESI,
"restart": Restart,
"pass": Pass,
"fetch": Fetch,
"bgfetch": BgFetch,
"pipe": Pipe,
}
func (c *Cursor) rawTxGrp() []Tx {
rec := c.Record()
return []Tx{Tx{
Type: TxRaw,
Reason: ReasonUnknown,
Level: 0,
VXID: uint32(rec.VXID),
ParentVXID: 0,
Records: []Record{rec},
}}
}
// NewQuery creates a Query from a Cursor. The Grouping argument indicates
// how transactions from the log should be aggregated: VXID, Request, Session
// or Raw grouping.
//
// XXX: request and session grouping not yet implement, nor are VSL
// queries
func (c *Cursor) NewQuery(grp Grouping, query string) (*Query, error) {
if c == nil || c.cursor == nil {
return nil, errors.New("Cursor is nil or uninitialized")
}
if err := c.log.checkNil(); err != nil {
return nil, err
}
txMap := make(map[uint32]*Tx)
return &Query{cursor: c, grp: grp, incomplete: txMap}, nil
}
// NextTxGroup returns the next group of transactions from the
// log. Transactions are aggregated according to the Grouping argument
// given in NewQuery().
//
// The Status return values indicates whether there was an error
// reading the log, whether there was an end condition (EOL or EOF),
// or if there are more transactions to be read from the log.
func (q *Query) NextTxGroup() ([]Tx, Status) {
for {
status := q.cursor.Next()
if status != More {
return nil, status
}
if q.grp == GRaw {
return q.cursor.rawTxGrp(), status
}
backend := q.cursor.Backend()
client := q.cursor.Client()
if !backend && !client {
continue
}
rec := q.cursor.Record()
vxid32 := uint32(rec.VXID)
incmplTx, exists := q.incomplete[vxid32]
if exists {
incmplTx.Records = append(incmplTx.Records, rec)
if rec.Tag == Tag(C.SLT_End) {
delete(q.incomplete, vxid32)
txGrp := []Tx{*incmplTx}
return txGrp, status
}
continue
}
tx := Tx{
VXID: vxid32,
Type: TxUnknown,
Reason: ReasonUnknown,
Level: 1,
Records: []Record{rec},
}
if rec.Tag == Tag(C.SLT_Begin) {
begin := strings.Split(rec.Payload, " ")
if txtype, exists := str2type[begin[0]]; exists {
tx.Type = txtype
}
if pvxid, err := strconv.Atoi(begin[1]); err != nil {
tx.ParentVXID = uint32(pvxid)
}
if reason, exists := str2reason[begin[2]]; exists {
tx.Reason = reason
}
}
q.incomplete[vxid32] = &tx
}
}
pkg/log/query_e2e_test.go 0 → 100644
View file @ 7147cd55
// +build e2e
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
// This test is only run if go test is invoked with a -tags option
// that includes "e2e". It requires that two instances of Varnish are
// running: a default instance (varnishd invoked without the -n
// option), and an instance named "gotest" (varnishd -n "gotest").
package log
import (
"net/http"
"testing"
)
// XXX remove the duplication with the test helpers in main_test.go
var tx2recType = map[TxType]RecordType{
Sess: Client,
Req: Client,
BeReq: Backend,
}
const (
undefLen int = int(^uint(0) >> 1)
txTypeUndef TxType = TxUnknown
txReasonUndef Reason = ReasonUnknown
txLevelUndef uint = ^uint(0)
txVXIDUndef uint32 = ^uint32(0)
recTypeUndef RecordType = RecordType(0)
recTagUndef string = "undefined tag string"
recVXIDUndef uint = ^uint(0)
recPayloadUndef string = "undefined payload string"
)
type expRec struct {
tag string
payload string
}
type expTx struct {
typ TxType
reason Reason
level uint
vxid uint32
pvxid uint32
recs []expRec
}
type expTxLen struct {
expRecs int
tx expTx
}
type expTxGrp struct {
expTx int
txGrp []expTxLen
}
var expDefaultRead = map[TxType]expTxGrp{
BeReq: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: undefLen,
tx: expTx{
typ: BeReq,
reason: Fetch,
level: 1,
vxid: txVXIDUndef,
pvxid: txVXIDUndef,
recs: nil,
}}},
},
Req: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: undefLen,
tx: expTx{
typ: Req,
reason: RxReq,
level: 1,
vxid: txVXIDUndef,
pvxid: txVXIDUndef,
recs: nil,
}}},
},
Sess: {
expTx: 1,
txGrp: []expTxLen{{
expRecs: 5,
tx: expTx{
typ: Sess,
reason: HTTP1,
level: 1,
vxid: txVXIDUndef,
pvxid: 0,
recs: []expRec{
{
tag: "Begin",
payload: "sess 0 HTTP/1",
},
{
tag: "SessOpen",
payload: recPayloadUndef,
},
{
tag: "Link",
payload: recPayloadUndef,
},
{
tag: "SessClose",
payload: recPayloadUndef,
},
{
tag: "End",
payload: "",
},
}},
}},
},
}
func checkRec(t *testing.T, rec Record, expRec expRec) {
if expRec.tag != recTagUndef && rec.Tag.String() != expRec.tag {
t.Errorf("record tag want=%v got=%s", expRec.tag, rec.Tag)
}
if expRec.payload != recPayloadUndef && rec.Payload != expRec.payload {
t.Errorf("record payload want=%v got=%s", expRec.payload,
rec.Payload)
}
}
func checkTx(t *testing.T, tx Tx, expTxLen expTxLen) {
expTx := expTxLen.tx
if expTx.typ != txTypeUndef && expTx.typ != tx.Type {
t.Errorf("tx.Type want=%v got=%v", expTx.typ, tx.Type)
}
if expTx.reason != txReasonUndef && expTx.reason != tx.Reason {
t.Errorf("tx.Reason want=%v got=%v", expTx.reason, tx.Reason)
}
if expTx.level != txLevelUndef && expTx.level != tx.Level {
t.Errorf("tx.Level want=%v got=%v", expTx.level, tx.Level)
}
if expTx.vxid != txVXIDUndef && expTx.vxid != tx.VXID {
t.Errorf("tx.VXID want=%v got=%v", expTx.vxid, tx.VXID)
}
if expTx.pvxid != txVXIDUndef && expTx.pvxid != tx.ParentVXID {
t.Errorf("tx.ParentVXID want=%v got=%v", expTx.pvxid,
tx.ParentVXID)
}
if expTxLen.expRecs != undefLen && expTxLen.expRecs != len(tx.Records) {
t.Errorf("number of records want=%v got=%v", expTxLen.expRecs,
len(tx.Records))
}
if tx.Records == nil || len(tx.Records) < 1 {
t.Fatal("tx has no records:", tx)
return
}
if tx.Type == TxRaw {
if len(tx.Records) != 1 {
t.Errorf("tx type raw number of records want=1 got=%v",
len(tx.Records))
}
if tx.Records[0].VXID != uint(tx.VXID) {
t.Errorf("record VXID want=%v got=%v", uint(tx.VXID),
tx.Records[0].VXID)
}
} else {
// These conditions always hold for the records in a
// non-raw transaction.
if tx.Records[0].Tag.String() != "Begin" {
t.Errorf("tx first record tag want=Begin got=%s",
tx.Records[0].Tag)
}
lastIdx := len(tx.Records) - 1
if tx.Records[lastIdx].Tag.String() != "End" {
t.Errorf("tx last record tag want=End got=%s",
tx.Records[lastIdx].Tag)
}
if tx.Records[lastIdx].Payload != "" {
t.Errorf("tx last record tag want=%q got=%q", "",
tx.Records[lastIdx].Payload)
}
expType, ok := tx2recType[tx.Type]
if !ok {
t.Fatal("tx2recType no value for", tx.Type)
t.FailNow()
return
}
for _, rec := range tx.Records {
if rec.Type != expType {
t.Errorf("record type want=%c got=%c", expType,
rec.Type)
}
if rec.VXID != uint(tx.VXID) {
t.Errorf("record VXID want=%v got=%v",
uint(tx.VXID), rec.VXID)
}
}
}
if expTx.recs != nil {
for i, rec := range tx.Records {
checkRec(t, rec, expTx.recs[i])
}
}
}
func checkTxGrp(t *testing.T, txGrp []Tx, expTxGrp expTxGrp) {
if expTxGrp.expTx != undefLen && len(txGrp) != expTxGrp.expTx {
t.Fatalf("number of tx in group got=%v want=%v",
len(txGrp), expTxGrp.expTx)
return
}
for i, tx := range txGrp {
checkTx(t, tx, expTxGrp.txGrp[i])
}
}
func TestAttachQuery(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
return
}
c, err := l.NewCursor()
if err != nil {
t.Fatal("NewCursor():", err)
return
}
defer c.Delete()
q, err := c.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
if q == nil {
t.Fatal("NewQuery() returned nil")
return
}
ln := New()
defer ln.Release()
if err := ln.Attach("gotest"); err != nil {
t.Fatal("Attach(gotest):", err)
return
}
cn, err := ln.NewCursor()
if err != nil {
t.Fatal("NewCursor() for gotest:", err)
return
}
defer cn.Delete()
qn, err := cn.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
if qn == nil {
t.Fatal("NewQuery() for gotest returned nil")
return
}
}
func TestE2EQueryRaw(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
return
}
c, err := l.NewCursor()
if err != nil {
t.Fatal("NewCursor():", err)
return
}
defer c.Delete()
q, err := c.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
client := &http.Client{}
req, err := http.NewRequest("GET", url("/uncacheable"), nil)
if err != nil {
t.Fatal("/uncacheable Request", err)
}
req.Close = true
stopChan := make(chan bool)
respChan := make(chan bool)
go func() {
sent := false
for {
select {
case <-stopChan:
return
default:
_, err := client.Do(req)
if err != nil {
t.Fatal("GET request:", err)
return
}
if !sent {
respChan <- true
sent = true
}
}
}
}()
<-respChan
var txGrps [][]Tx
for i := 0; i < 100; i++ {
txGrp, status := q.NextTxGroup()
txGrps = append(txGrps, txGrp)
if status == EOL {
break
}
}
stopChan <- true
t.Logf("read %d txGrps", len(txGrps))
t.Log(txGrps)
}
func TestE2EQueryVXID(t *testing.T) {
l := New()
defer l.Release()
if err := l.Attach(""); err != nil {
t.Fatal("Attach(default):", err)
return
}
c, err := l.NewCursor()
if err != nil {
t.Fatal("NewCursor():", err)
return
}
defer c.Delete()
q, err := c.NewQuery(VXID, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
var status Status
var txGrps [][]Tx
stopChan := make(chan bool)
go func() {
for len(txGrps) < 3 {
txGrp, txStatus := q.NextTxGroup()
status = txStatus
if txStatus == EOL {
continue
}
if txStatus != More {
break
}
txGrps = append(txGrps, txGrp)
}
stopChan <- true
}()
client := &http.Client{}
req, err := http.NewRequest("GET", url("/uncacheable"), nil)
if err != nil {
t.Fatal("/uncacheable Request", err)
}
req.Close = true
resp, err := client.Do(req)
if err != nil {
t.Fatal("/uncacheable Response", err)
}
<-stopChan
if status != More && status != EOL {
t.Error("Read status:", status)
}
if len(txGrps) != 3 {
t.Errorf("number of tx groups want=3 got=%v", len(txGrps))
}
for _, txGrp := range txGrps {
tx := txGrp[0]
checkTxGrp(t, txGrp, expDefaultRead[tx.Type])
if tx.Type == BeReq {
checkBereq(t, tx, *req)
}
if tx.Type == Req {
checkReqResp(t, tx, *req, *resp)
}
}
}
pkg/log/query_test.go 0 → 100644
View file @ 7147cd55
/*-
* Copyright (c) 2018 UPLEX Nils Goroll Systemoptimierung
* All rights reserved
*
* Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*/
package log
import "testing"
func TestNewQuery(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
q, err := c.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
if q == nil {
t.Fatal("NewQuery() returned nil")
return
}
var n *Cursor
if _, err := n.NewQuery(GRaw, ""); err == nil {
t.Error("Expected nil.NewQuery() to fail")
}
uninit := &Cursor{}
if _, err := uninit.NewQuery(GRaw, ""); err == nil {
t.Error("Expected uninitiailized.NewQuery() to fail")
}
}
var expFirstTx = testTx{
level: 0,
txtype: "Record",
vxid: 0,
recs: []testRec{expFirstRec},
}
func TestNextTxGroupRawOne(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
q, err := c.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
txn, status := q.NextTxGroup()
// XXX change the status constant, this is vsl_more
if status != More {
t.Errorf("NextTxGroup() status want=More got=%d\n",
uint8(status))
}
if len(txn) != 1 {
t.Errorf("len(Txn) from NextTxGroup want=1 got=%v\n",
len(txn))
}
tx := txn[0]
checkExpTx(t, tx, expFirstTx)
if tx.Reason != ReasonUnknown {
t.Errorf("tx Reason want=unknown got=%v\n", tx.Reason)
}
if tx.ParentVXID != 0 {
t.Errorf("tx ParentVXID want=0 got=%v\n", tx.ParentVXID)
}
}
func TestNextTxGroupRawAll(t *testing.T) {
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
q, err := c.NewQuery(GRaw, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
for _, rec := range expRawLog {
txn, status := q.NextTxGroup()
// XXX should be More
if status != More {
t.Errorf("NextTxGroup() status want=More got=%d\n",
uint8(status))
}
if len(txn) != 1 {
t.Errorf("len(Txn) from NextTxGroup want=1 got=%v\n",
len(txn))
}
tx := txn[0]
expTx := testTx{
level: 0,
txtype: "Record",
vxid: uint32(rec.vxid),
recs: []testRec{rec},
}
checkExpTx(t, tx, expTx)
if tx.Reason != ReasonUnknown {
t.Errorf("tx Reason want=unknown got=%v\n", tx.Reason)
}
if tx.ParentVXID != 0 {
t.Errorf("tx ParentVXID want=0 got=%v\n", tx.ParentVXID)
}
}
}
func TestNextTxGroupDefault(t *testing.T) {
var txGrps [][]Tx
l := New()
defer l.Release()
c, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c.Delete()
q, err := c.NewQuery(VXID, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
var status Status
for {
txn, rdstatus := q.NextTxGroup()
if rdstatus != More {
status = rdstatus
break
}
txGrps = append(txGrps, txn)
}
if status != Status(EOF) {
t.Errorf("expected EOF status got: %s", status.Error())
}
checkTxGroups(t, txGrps, expVxidLog)
}
func TestNextTxGroupConcurrent(t *testing.T) {
var txGrps1, txGrps2 [][]Tx
l := New()
defer l.Release()
c1, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c1.Delete()
q1, err := c1.NewQuery(VXID, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
c2, err := l.NewCursorFile(testFile)
if err != nil {
t.Fatal("NewCursorFile(bin.log):", err)
return
}
defer c2.Delete()
q2, err := c2.NewQuery(VXID, "")
if err != nil {
t.Fatal("NewQuery():", err)
return
}
for {
txGrp1, status1 := q1.NextTxGroup()
txGrp2, status2 := q2.NextTxGroup()
if status1 == EOF && status2 == EOF {
break
}
// XXX
if status1 != More {
t.Fatal("NextTxGroup() unexpected status:", status1)
return
}
if status2 != More {
t.Fatal("NextTxGroup() unexpected status:", status2)
return
}
txGrps1 = append(txGrps1, txGrp1)
txGrps2 = append(txGrps2, txGrp2)
}
checkTxGroups(t, txGrps1, expVxidLog)
checkTxGroups(t, txGrps2, expVxidLog)
}
pkg/log/testdata/raw.log 0 → 100644
View file @ 7147cd55
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000402 0.000484 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799278 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000373 0.000456 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000522 0.000472 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000414 0.000458 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799281 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000876 0.000562 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000485 0.000543 HTTP/1.1 204 No Content
1 Begin c sess 0 HTTP/1
1 SessOpen c 127.0.0.1 38018 a0 127.0.0.1 8080 1533799283.516383 28
1 Link c req 2 rxreq
3 Begin b bereq 2 fetch
3 Timestamp b Start: 1533799283.516577 0.000000 0.000000
3 BereqMethod b GET
3 BereqURL b /
3 BereqProtocol b HTTP/1.1
3 BereqHeader b Host: localhost:8080
3 BereqHeader b User-Agent: curl/7.52.1
3 BereqHeader b Accept: */*
3 BereqHeader b X-Forwarded-For: 127.0.0.1
3 BereqHeader b Accept-Encoding: gzip
3 BereqHeader b X-Varnish: 3
3 VCL_call b BACKEND_FETCH
3 VCL_return b fetch
3 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
3 BackendStart b 127.0.0.1 39659
3 Timestamp b Bereq: 1533799283.516785 0.000208 0.000208
3 Timestamp b Beresp: 1533799283.516958 0.000381 0.000174
3 BerespProtocol b HTTP/1.1
3 BerespStatus b 200
3 BerespReason b OK
3 BerespHeader b Server: testbackend.go
3 BerespHeader b Date: Thu, 09 Aug 2018 07:21:23 GMT
3 BerespHeader b Content-Length: 39
3 BerespHeader b Content-Type: text/html; charset=utf-8
3 TTL b RFC 120 10 0 1533799284 1533799284 1533799283 0 0 cacheable
3 VCL_call b BACKEND_RESPONSE
3 VCL_return b deliver
3 Storage b malloc s0
3 Fetch_Body b 3 length -
3 BackendReuse b 30 boot.test
3 Timestamp b BerespBody: 1533799283.517067 0.000490 0.000109
3 Length b 39
3 BereqAcct b 143 0 143 140 39 179
3 End b
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f814000 e=0.000000000 f=0x0
0 ExpKill - EXP_When p=0x7f471f814000 e=1533799413.516958475 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=129.999868870 f=0x0
2 Begin c req 1 rxreq
2 Timestamp c Start: 1533799283.516451 0.000000 0.000000
2 Timestamp c Req: 1533799283.516451 0.000000 0.000000
2 ReqStart c 127.0.0.1 38018 a0
2 ReqMethod c GET
2 ReqURL c /
2 ReqProtocol c HTTP/1.1
2 ReqHeader c Host: localhost:8080
2 ReqHeader c User-Agent: curl/7.52.1
2 ReqHeader c Accept: */*
2 ReqHeader c X-Forwarded-For: 127.0.0.1
2 VCL_call c RECV
2 VCL_return c hash
2 VCL_call c HASH
2 VCL_return c lookup
2 VCL_call c MISS
2 VCL_return c fetch
2 Link c bereq 3 fetch
2 Timestamp c Fetch: 1533799283.517071 0.000620 0.000620
2 RespProtocol c HTTP/1.1
2 RespStatus c 200
2 RespReason c OK
2 RespHeader c Server: testbackend.go
2 RespHeader c Date: Thu, 09 Aug 2018 07:21:23 GMT
2 RespHeader c Content-Length: 39
2 RespHeader c Content-Type: text/html; charset=utf-8
2 RespHeader c X-Varnish: 2
2 RespHeader c Age: 0
2 RespHeader c Via: 1.1 varnish (Varnish/6.0)
2 VCL_call c DELIVER
2 VCL_return c deliver
2 Timestamp c Process: 1533799283.517098 0.000647 0.000027
2 RespHeader c Accept-Ranges: bytes
2 RespHeader c Connection: keep-alive
2 Timestamp c Resp: 1533799283.517144 0.000693 0.000046
2 ReqAcct c 78 0 78 240 39 279
2 End c
1 SessClose c REM_CLOSE 0.001
1 End c
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000553 0.000546 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799284 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000322 0.000490 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000378 0.000462 HTTP/1.1 204 No Content
4 Begin c sess 0 HTTP/1
4 SessOpen c 127.0.0.1 38040 a0 127.0.0.1 8080 1533799286.395182 29
4 Link c req 5 rxreq
6 Begin b bereq 5 fetch
6 Timestamp b Start: 1533799286.395248 0.000000 0.000000
6 BereqMethod b GET
6 BereqURL b /esi
6 BereqProtocol b HTTP/1.1
6 BereqHeader b Host: localhost:8080
6 BereqHeader b User-Agent: curl/7.52.1
6 BereqHeader b Accept: */*
6 BereqHeader b X-Forwarded-For: 127.0.0.1
6 BereqHeader b Accept-Encoding: gzip
6 BereqHeader b X-Varnish: 6
6 VCL_call b BACKEND_FETCH
6 VCL_return b fetch
6 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
6 BackendStart b 127.0.0.1 39659
6 Timestamp b Bereq: 1533799286.395292 0.000044 0.000044
6 Timestamp b Beresp: 1533799286.395461 0.000213 0.000169
6 BerespProtocol b HTTP/1.1
6 BerespStatus b 200
6 BerespReason b OK
6 BerespHeader b Server: testbackend.go
6 BerespHeader b Date: Thu, 09 Aug 2018 07:21:26 GMT
6 BerespHeader b Content-Length: 151
6 BerespHeader b Content-Type: text/html; charset=utf-8
6 TTL b RFC 120 10 0 1533799286 1533799286 1533799286 0 0 cacheable
6 VCL_call b BACKEND_RESPONSE
6 VCL_return b deliver
6 Storage b malloc s0
6 Fetch_Body b 3 length -
6 ESI_xmlerror b WARN after 29 ESI 1.0 <esi:include> lacks final '/'
6 ESI_xmlerror b WARN after 91 ESI 1.0 <esi:include> lacks final '/'
6 BackendReuse b 30 boot.test
6 Timestamp b BerespBody: 1533799286.395530 0.000282 0.000069
6 Length b 151
6 BereqAcct b 146 0 146 141 151 292
6 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.121419907 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f8140c0 e=0.000000000 f=0x0
0 ExpKill - EXP_When p=0x7f471f8140c0 e=1533799416.395461082 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.121412277 f=0x0
8 Begin b bereq 7 fetch
8 Timestamp b Start: 1533799286.395623 0.000000 0.000000
8 BereqMethod b GET
8 BereqURL b /include1
8 BereqProtocol b HTTP/1.1
8 BereqHeader b Host: localhost:8080
8 BereqHeader b User-Agent: curl/7.52.1
8 BereqHeader b Accept: */*
8 BereqHeader b X-Forwarded-For: 127.0.0.1
8 BereqHeader b Accept-Encoding: gzip
8 BereqHeader b X-Varnish: 8
8 VCL_call b BACKEND_FETCH
8 VCL_return b fetch
8 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
8 BackendStart b 127.0.0.1 39659
8 Timestamp b Bereq: 1533799286.395660 0.000037 0.000037
8 Timestamp b Beresp: 1533799286.395740 0.000117 0.000080
8 BerespProtocol b HTTP/1.1
8 BerespStatus b 200
8 BerespReason b OK
8 BerespHeader b Server: testbackend.go
8 BerespHeader b Date: Thu, 09 Aug 2018 07:21:26 GMT
8 BerespHeader b Content-Length: 8
8 BerespHeader b Content-Type: text/plain; charset=utf-8
8 TTL b RFC 120 10 0 1533799286 1533799286 1533799286 0 0 cacheable
8 VCL_call b BACKEND_RESPONSE
8 VCL_return b deliver
8 Storage b malloc s0
8 Fetch_Body b 3 length -
8 ESI_xmlerror b No ESI processing, first char not '<'. (See feature esi_disable_xml_check)
8 BackendReuse b 30 boot.test
8 Timestamp b BerespBody: 1533799286.395784 0.000160 0.000043
8 Length b 8
8 BereqAcct b 151 0 151 140 8 148
8 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.121165037 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f814180 e=0.000000000 f=0x0
0 ExpKill - EXP_When p=0x7f471f814180 e=1533799416.395740271 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.121158123 f=0x0
7 Begin c req 5 esi
7 ReqURL c /include1
7 Timestamp c Start: 1533799286.395601 0.000000 0.000000
7 ReqStart c 127.0.0.1 38040 a0
7 ReqMethod c GET
7 ReqURL c /include1
7 ReqProtocol c HTTP/1.1
7 ReqHeader c Host: localhost:8080
7 ReqHeader c User-Agent: curl/7.52.1
7 ReqHeader c Accept: */*
7 ReqHeader c X-Forwarded-For: 127.0.0.1
7 VCL_call c RECV
7 VCL_return c hash
7 VCL_call c HASH
7 VCL_return c lookup
7 VCL_call c MISS
7 VCL_return c fetch
7 Link c bereq 8 fetch
7 Timestamp c Fetch: 1533799286.395787 0.000186 0.000186
7 RespProtocol c HTTP/1.1
7 RespStatus c 200
7 RespReason c OK
7 RespHeader c Server: testbackend.go
7 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
7 RespHeader c Content-Length: 8
7 RespHeader c Content-Type: text/plain; charset=utf-8
7 RespHeader c X-Varnish: 7
7 RespHeader c Age: 0
7 RespHeader c Via: 1.1 varnish (Varnish/6.0)
7 VCL_call c DELIVER
7 VCL_return c deliver
7 Timestamp c Process: 1533799286.395794 0.000194 0.000007
7 RespHeader c Accept-Ranges: bytes
7 Timestamp c Resp: 1533799286.395814 0.000213 0.000020
7 ReqAcct c 0 0 0 0 8 8
7 End c
10 Begin b bereq 9 fetch
10 Timestamp b Start: 1533799286.395890 0.000000 0.000000
10 BereqMethod b GET
10 BereqURL b /include2
10 BereqProtocol b HTTP/1.1
10 BereqHeader b Host: localhost:8080
10 BereqHeader b User-Agent: curl/7.52.1
10 BereqHeader b Accept: */*
10 BereqHeader b X-Forwarded-For: 127.0.0.1
10 BereqHeader b Accept-Encoding: gzip
10 BereqHeader b X-Varnish: 10
10 VCL_call b BACKEND_FETCH
10 VCL_return b fetch
10 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
10 BackendStart b 127.0.0.1 39659
10 Timestamp b Bereq: 1533799286.395925 0.000035 0.000035
10 Timestamp b Beresp: 1533799286.395999 0.000109 0.000074
10 BerespProtocol b HTTP/1.1
10 BerespStatus b 200
10 BerespReason b OK
10 BerespHeader b Server: testbackend.go
10 BerespHeader b Date: Thu, 09 Aug 2018 07:21:26 GMT
10 BerespHeader b Content-Length: 8
10 BerespHeader b Content-Type: text/plain; charset=utf-8
10 TTL b RFC 120 10 0 1533799286 1533799286 1533799286 0 0 cacheable
10 VCL_call b BACKEND_RESPONSE
10 VCL_return b deliver
10 Storage b malloc s0
10 Fetch_Body b 3 length -
10 ESI_xmlerror b No ESI processing, first char not '<'. (See feature esi_disable_xml_check)
10 BackendReuse b 30 boot.test
10 Timestamp b BerespBody: 1533799286.396033 0.000143 0.000034
10 Length b 8
10 BereqAcct b 152 0 152 140 8 148
10 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.120920181 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f814240 e=0.000000000 f=0x0
0 ExpKill - EXP_When p=0x7f471f814240 e=1533799416.395998716 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=127.120915174 f=0x0
9 Begin c req 5 esi
9 ReqURL c /include2
9 Timestamp c Start: 1533799286.395873 0.000000 0.000000
9 ReqStart c 127.0.0.1 38040 a0
9 ReqMethod c GET
9 ReqURL c /include2
9 ReqProtocol c HTTP/1.1
9 ReqHeader c Host: localhost:8080
9 ReqHeader c User-Agent: curl/7.52.1
9 ReqHeader c Accept: */*
9 ReqHeader c X-Forwarded-For: 127.0.0.1
9 VCL_call c RECV
9 VCL_return c hash
9 VCL_call c HASH
9 VCL_return c lookup
9 VCL_call c MISS
9 VCL_return c fetch
9 Link c bereq 10 fetch
9 Timestamp c Fetch: 1533799286.396036 0.000163 0.000163
9 RespProtocol c HTTP/1.1
9 RespStatus c 200
9 RespReason c OK
9 RespHeader c Server: testbackend.go
9 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
9 RespHeader c Content-Length: 8
9 RespHeader c Content-Type: text/plain; charset=utf-8
9 RespHeader c X-Varnish: 9
9 RespHeader c Age: 0
9 RespHeader c Via: 1.1 varnish (Varnish/6.0)
9 VCL_call c DELIVER
9 VCL_return c deliver
9 Timestamp c Process: 1533799286.396043 0.000171 0.000008
9 RespHeader c Accept-Ranges: bytes
9 Timestamp c Resp: 1533799286.396064 0.000191 0.000021
9 ReqAcct c 0 0 0 0 8 8
9 End c
5 Begin c req 4 rxreq
5 Timestamp c Start: 1533799286.395210 0.000000 0.000000
5 Timestamp c Req: 1533799286.395210 0.000000 0.000000
5 ReqStart c 127.0.0.1 38040 a0
5 ReqMethod c GET
5 ReqURL c /esi
5 ReqProtocol c HTTP/1.1
5 ReqHeader c Host: localhost:8080
5 ReqHeader c User-Agent: curl/7.52.1
5 ReqHeader c Accept: */*
5 ReqHeader c X-Forwarded-For: 127.0.0.1
5 VCL_call c RECV
5 VCL_return c hash
5 VCL_call c HASH
5 VCL_return c lookup
5 VCL_call c MISS
5 VCL_return c fetch
5 Link c bereq 6 fetch
5 Timestamp c Fetch: 1533799286.395534 0.000324 0.000324
5 RespProtocol c HTTP/1.1
5 RespStatus c 200
5 RespReason c OK
5 RespHeader c Server: testbackend.go
5 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
5 RespHeader c Content-Length: 151
5 RespHeader c Content-Type: text/html; charset=utf-8
5 RespHeader c X-Varnish: 5
5 RespHeader c Age: 0
5 RespHeader c Via: 1.1 varnish (Varnish/6.0)
5 VCL_call c DELIVER
5 VCL_return c deliver
5 Timestamp c Process: 1533799286.395545 0.000336 0.000012
5 RespHeader c Accept-Ranges: bytes
5 RespUnset c Content-Length: 151
5 RespHeader c Transfer-Encoding: chunked
5 RespHeader c Connection: keep-alive
5 Link c req 7 esi
5 Link c req 9 esi
5 Timestamp c Resp: 1533799286.396089 0.000880 0.000544
5 ReqAcct c 81 0 81 248 152 400
5 End c
4 SessClose c REM_CLOSE 0.001
4 End c
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000321 0.000427 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799287 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000477 0.000439 HTTP/1.1 204 No Content
32769 Begin c sess 0 HTTP/1
32769 SessOpen c 127.0.0.1 38054 a0 127.0.0.1 8080 1533799288.488951 26
32769 Link c req 32770 rxreq
32770 Begin c req 32769 rxreq
32770 Timestamp c Start: 1533799288.488980 0.000000 0.000000
32770 Timestamp c Req: 1533799288.488980 0.000000 0.000000
32770 ReqStart c 127.0.0.1 38054 a0
32770 ReqMethod c GET
32770 ReqURL c /
32770 ReqProtocol c HTTP/1.1
32770 ReqHeader c Host: localhost:8080
32770 ReqHeader c User-Agent: curl/7.52.1
32770 ReqHeader c Accept: */*
32770 ReqHeader c X-Forwarded-For: 127.0.0.1
32770 VCL_call c RECV
32770 VCL_return c hash
32770 VCL_call c HASH
32770 VCL_return c lookup
32770 Hit c 3 115.027978 10.000000 0.000000
32770 VCL_call c HIT
32770 VCL_return c deliver
32770 RespProtocol c HTTP/1.1
32770 RespStatus c 200
32770 RespReason c OK
32770 RespHeader c Server: testbackend.go
32770 RespHeader c Date: Thu, 09 Aug 2018 07:21:23 GMT
32770 RespHeader c Content-Length: 39
32770 RespHeader c Content-Type: text/html; charset=utf-8
32770 RespHeader c X-Varnish: 32770 3
32770 RespHeader c Age: 4
32770 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32770 VCL_call c DELIVER
32770 VCL_return c deliver
32770 Timestamp c Process: 1533799288.489031 0.000050 0.000050
32770 RespHeader c Accept-Ranges: bytes
32770 RespHeader c Connection: keep-alive
32770 Timestamp c Resp: 1533799288.489062 0.000082 0.000031
32770 ReqAcct c 78 0 78 246 39 285
32770 End c
32769 SessClose c REM_CLOSE 0.000
32769 End c
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000448 0.000441 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000381 0.000426 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799290 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000345 0.000406 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000364 0.000396 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000330 0.000379 HTTP/1.1 204 No Content
32771 Begin c sess 0 HTTP/1
32771 SessOpen c 127.0.0.1 38086 a0 127.0.0.1 8080 1533799293.001471 29
32771 Link c req 32772 rxreq
32773 Begin c req 32772 esi
32773 ReqURL c /include1
32773 Timestamp c Start: 1533799293.001589 0.000000 0.000000
32773 ReqStart c 127.0.0.1 38086 a0
32773 ReqMethod c GET
32773 ReqURL c /include1
32773 ReqProtocol c HTTP/1.1
32773 ReqHeader c Host: localhost:8080
32773 ReqHeader c User-Agent: curl/7.52.1
32773 ReqHeader c Accept: */*
32773 ReqHeader c X-Forwarded-For: 127.0.0.1
32773 VCL_call c RECV
32773 VCL_return c hash
32773 VCL_call c HASH
32773 VCL_return c lookup
32773 Hit c 8 113.394242 10.000000 0.000000
32773 VCL_call c HIT
32773 VCL_return c deliver
32773 RespProtocol c HTTP/1.1
32773 RespStatus c 200
32773 RespReason c OK
32773 RespHeader c Server: testbackend.go
32773 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
32773 RespHeader c Content-Length: 8
32773 RespHeader c Content-Type: text/plain; charset=utf-8
32773 RespHeader c X-Varnish: 32773 8
32773 RespHeader c Age: 6
32773 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32773 VCL_call c DELIVER
32773 VCL_return c deliver
32773 Timestamp c Process: 1533799293.001600 0.000010 0.000010
32773 RespHeader c Accept-Ranges: bytes
32773 Timestamp c Resp: 1533799293.001613 0.000024 0.000014
32773 ReqAcct c 0 0 0 0 8 8
32773 End c
32774 Begin c req 32772 esi
32774 ReqURL c /include2
32774 Timestamp c Start: 1533799293.001657 0.000000 0.000000
32774 ReqStart c 127.0.0.1 38086 a0
32774 ReqMethod c GET
32774 ReqURL c /include2
32774 ReqProtocol c HTTP/1.1
32774 ReqHeader c Host: localhost:8080
32774 ReqHeader c User-Agent: curl/7.52.1
32774 ReqHeader c Accept: */*
32774 ReqHeader c X-Forwarded-For: 127.0.0.1
32774 VCL_call c RECV
32774 VCL_return c hash
32774 VCL_call c HASH
32774 VCL_return c lookup
32774 Hit c 10 113.394501 10.000000 0.000000
32774 VCL_call c HIT
32774 VCL_return c deliver
32774 RespProtocol c HTTP/1.1
32774 RespStatus c 200
32774 RespReason c OK
32774 RespHeader c Server: testbackend.go
32774 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
32774 RespHeader c Content-Length: 8
32774 RespHeader c Content-Type: text/plain; charset=utf-8
32774 RespHeader c X-Varnish: 32774 10
32774 RespHeader c Age: 6
32774 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32774 VCL_call c DELIVER
32774 VCL_return c deliver
32774 Timestamp c Process: 1533799293.001666 0.000009 0.000009
32774 RespHeader c Accept-Ranges: bytes
32774 Timestamp c Resp: 1533799293.001682 0.000026 0.000016
32774 ReqAcct c 0 0 0 0 8 8
32774 End c
32772 Begin c req 32771 rxreq
32772 Timestamp c Start: 1533799293.001498 0.000000 0.000000
32772 Timestamp c Req: 1533799293.001498 0.000000 0.000000
32772 ReqStart c 127.0.0.1 38086 a0
32772 ReqMethod c GET
32772 ReqURL c /esi
32772 ReqProtocol c HTTP/1.1
32772 ReqHeader c Host: localhost:8080
32772 ReqHeader c User-Agent: curl/7.52.1
32772 ReqHeader c Accept: */*
32772 ReqHeader c X-Forwarded-For: 127.0.0.1
32772 VCL_call c RECV
32772 VCL_return c hash
32772 VCL_call c HASH
32772 VCL_return c lookup
32772 Hit c 6 113.393963 10.000000 0.000000
32772 VCL_call c HIT
32772 VCL_return c deliver
32772 RespProtocol c HTTP/1.1
32772 RespStatus c 200
32772 RespReason c OK
32772 RespHeader c Server: testbackend.go
32772 RespHeader c Date: Thu, 09 Aug 2018 07:21:26 GMT
32772 RespHeader c Content-Length: 151
32772 RespHeader c Content-Type: text/html; charset=utf-8
32772 RespHeader c X-Varnish: 32772 6
32772 RespHeader c Age: 6
32772 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32772 VCL_call c DELIVER
32772 VCL_return c deliver
32772 Timestamp c Process: 1533799293.001531 0.000033 0.000033
32772 RespHeader c Accept-Ranges: bytes
32772 RespUnset c Content-Length: 151
32772 RespHeader c Transfer-Encoding: chunked
32772 RespHeader c Connection: keep-alive
32772 Link c req 32773 esi
32772 Link c req 32774 esi
32772 Timestamp c Resp: 1533799293.001708 0.000210 0.000177
32772 ReqAcct c 81 0 81 254 152 406
32772 End c
32771 SessClose c REM_CLOSE 0.000
32771 End c
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799293 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000313 0.000363 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000356 0.000361 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000324 0.000352 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799296 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000367 0.000356 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000417 0.000371 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000788 0.000475 HTTP/1.1 204 No Content
11 Begin c sess 0 HTTP/1
11 SessOpen c 127.0.0.1 38124 a0 127.0.0.1 8080 1533799299.438098 27
11 Link c req 12 rxreq
13 Begin b bereq 12 fetch
13 Timestamp b Start: 1533799299.438194 0.000000 0.000000
13 BereqMethod b GET
13 BereqURL b /uncacheable
13 BereqProtocol b HTTP/1.1
13 BereqHeader b Host: localhost:8080
13 BereqHeader b User-Agent: curl/7.52.1
13 BereqHeader b Accept: */*
13 BereqHeader b X-Forwarded-For: 127.0.0.1
13 BereqHeader b Accept-Encoding: gzip
13 BereqHeader b X-Varnish: 13
13 VCL_call b BACKEND_FETCH
13 VCL_return b fetch
13 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
13 BackendStart b 127.0.0.1 39659
13 Timestamp b Bereq: 1533799299.438255 0.000061 0.000061
13 Timestamp b Beresp: 1533799299.438425 0.000231 0.000170
13 BerespProtocol b HTTP/1.1
13 BerespStatus b 200
13 BerespReason b OK
13 BerespHeader b Cache-Control: max-age=0
13 BerespHeader b Server: testbackend.go
13 BerespHeader b Date: Thu, 09 Aug 2018 07:21:39 GMT
13 BerespHeader b Content-Length: 41
13 BerespHeader b Content-Type: text/html; charset=utf-8
13 TTL b RFC 0 10 0 1533799299 1533799299 1533799299 0 0 cacheable
13 VCL_call b BACKEND_RESPONSE
13 TTL b VCL 120 10 0 1533799299 cacheable
13 TTL b VCL 120 10 0 1533799299 uncacheable
13 VCL_return b deliver
13 Storage b malloc Transient
13 Fetch_Body b 3 length -
13 BackendReuse b 30 boot.test
13 Timestamp b BerespBody: 1533799299.438481 0.000287 0.000057
13 Length b 41
13 BereqAcct b 155 0 155 166 41 207
13 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=114.078472137 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f814300 e=0.000000000 f=0x4
0 ExpKill - EXP_When p=0x7f471f814300 e=1533799429.438424826 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=114.078464270 f=0x0
12 Begin c req 11 rxreq
12 Timestamp c Start: 1533799299.438128 0.000000 0.000000
12 Timestamp c Req: 1533799299.438128 0.000000 0.000000
12 ReqStart c 127.0.0.1 38124 a0
12 ReqMethod c GET
12 ReqURL c /uncacheable
12 ReqProtocol c HTTP/1.1
12 ReqHeader c Host: localhost:8080
12 ReqHeader c User-Agent: curl/7.52.1
12 ReqHeader c Accept: */*
12 ReqHeader c X-Forwarded-For: 127.0.0.1
12 VCL_call c RECV
12 VCL_return c hash
12 VCL_call c HASH
12 VCL_return c lookup
12 VCL_call c MISS
12 VCL_return c fetch
12 Link c bereq 13 fetch
12 Timestamp c Fetch: 1533799299.438493 0.000364 0.000364
12 RespProtocol c HTTP/1.1
12 RespStatus c 200
12 RespReason c OK
12 RespHeader c Cache-Control: max-age=0
12 RespHeader c Server: testbackend.go
12 RespHeader c Date: Thu, 09 Aug 2018 07:21:39 GMT
12 RespHeader c Content-Length: 41
12 RespHeader c Content-Type: text/html; charset=utf-8
12 RespHeader c X-Varnish: 12
12 RespHeader c Age: 0
12 RespHeader c Via: 1.1 varnish (Varnish/6.0)
12 VCL_call c DELIVER
12 VCL_return c deliver
12 Timestamp c Process: 1533799299.438504 0.000376 0.000011
12 RespHeader c Accept-Ranges: bytes
12 RespHeader c Connection: keep-alive
12 Timestamp c Resp: 1533799299.438535 0.000407 0.000031
12 ReqAcct c 89 0 89 267 41 308
12 End c
11 SessClose c REM_CLOSE 0.001
11 End c
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799299 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000375 0.000450 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000485 0.000459 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000719 0.000524 HTTP/1.1 204 No Content
32775 Begin c sess 0 HTTP/1
32775 SessOpen c 127.0.0.1 38140 a0 127.0.0.1 8080 1533799301.686020 28
32775 Link c req 32776 rxreq
32777 Begin b bereq 32776 fetch
32777 Timestamp b Start: 1533799301.686114 0.000000 0.000000
32777 BereqMethod b GET
32777 BereqURL b /uncacheable
32777 BereqProtocol b HTTP/1.1
32777 BereqHeader b Host: localhost:8080
32777 BereqHeader b User-Agent: curl/7.52.1
32777 BereqHeader b Accept: */*
32777 BereqHeader b X-Forwarded-For: 127.0.0.1
32777 BereqHeader b Accept-Encoding: gzip
32777 BereqHeader b X-Varnish: 32777
32777 VCL_call b BACKEND_FETCH
32777 VCL_return b fetch
32777 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
32777 BackendStart b 127.0.0.1 39659
32777 Timestamp b Bereq: 1533799301.686184 0.000071 0.000071
32777 Timestamp b Beresp: 1533799301.686378 0.000264 0.000194
32777 BerespProtocol b HTTP/1.1
32777 BerespStatus b 200
32777 BerespReason b OK
32777 BerespHeader b Cache-Control: max-age=0
32777 BerespHeader b Server: testbackend.go
32777 BerespHeader b Date: Thu, 09 Aug 2018 07:21:41 GMT
32777 BerespHeader b Content-Length: 41
32777 BerespHeader b Content-Type: text/html; charset=utf-8
32777 TTL b RFC 0 10 0 1533799302 1533799302 1533799301 0 0 cacheable
32777 VCL_call b BACKEND_RESPONSE
32777 TTL b VCL 120 10 0 1533799302 cacheable
32777 TTL b VCL 120 10 0 1533799302 uncacheable
32777 VCL_return b deliver
32777 Storage b malloc Transient
32777 Fetch_Body b 3 length -
32777 BackendReuse b 30 boot.test
32777 Timestamp b BerespBody: 1533799301.686499 0.000386 0.000121
32777 Length b 41
32777 BereqAcct b 158 0 158 166 41 207
32777 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=111.830454588 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f212000 e=0.000000000 f=0x4
0 ExpKill - EXP_When p=0x7f471f212000 e=1533799431.686378002 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=111.830445766 f=0x0
32776 Begin c req 32775 rxreq
32776 Timestamp c Start: 1533799301.686047 0.000000 0.000000
32776 Timestamp c Req: 1533799301.686047 0.000000 0.000000
32776 ReqStart c 127.0.0.1 38140 a0
32776 ReqMethod c GET
32776 ReqURL c /uncacheable
32776 ReqProtocol c HTTP/1.1
32776 ReqHeader c Host: localhost:8080
32776 ReqHeader c User-Agent: curl/7.52.1
32776 ReqHeader c Accept: */*
32776 ReqHeader c X-Forwarded-For: 127.0.0.1
32776 VCL_call c RECV
32776 VCL_return c hash
32776 VCL_call c HASH
32776 VCL_return c lookup
32776 HitMiss c 13 117.752378
32776 VCL_call c MISS
32776 VCL_return c fetch
32776 Link c bereq 32777 fetch
32776 Timestamp c Fetch: 1533799301.686502 0.000456 0.000456
32776 RespProtocol c HTTP/1.1
32776 RespStatus c 200
32776 RespReason c OK
32776 RespHeader c Cache-Control: max-age=0
32776 RespHeader c Server: testbackend.go
32776 RespHeader c Date: Thu, 09 Aug 2018 07:21:41 GMT
32776 RespHeader c Content-Length: 41
32776 RespHeader c Content-Type: text/html; charset=utf-8
32776 RespHeader c X-Varnish: 32776
32776 RespHeader c Age: 0
32776 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32776 VCL_call c DELIVER
32776 VCL_return c deliver
32776 Timestamp c Process: 1533799301.686517 0.000470 0.000014
32776 RespHeader c Accept-Ranges: bytes
32776 RespHeader c Connection: keep-alive
32776 Timestamp c Resp: 1533799301.686549 0.000503 0.000033
32776 ReqAcct c 89 0 89 270 41 311
32776 End c
32775 SessClose c REM_CLOSE 0.001
32775 End c
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799302 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000315 0.000472 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000725 0.000535 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000369 0.000493 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799305 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000280 0.000440 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000331 0.000413 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000330 0.000392 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799308 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000319 0.000374 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000298 0.000355 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000378 0.000361 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799311 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000613 0.000424 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000355 0.000407 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000398 0.000405 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799314 1.0
0 Backend_health - boot.test Went sick 4---X-R- 0 1 1 0.000347 0.000405 HTTP/1.1 503 Service Unavailable
0 Backend_health - boot.test Still sick 4---X-R- 0 1 1 0.000404 0.000405 HTTP/1.1 503 Service Unavailable
0 Backend_health - boot.test Still sick 4---X-R- 0 1 1 0.000317 0.000405 HTTP/1.1 503 Service Unavailable
14 Begin c sess 0 HTTP/1
14 SessOpen c 127.0.0.1 38238 a0 127.0.0.1 8080 1533799317.220793 28
14 Link c req 15 rxreq
16 Begin b bereq 15 fetch
16 Timestamp b Start: 1533799317.220906 0.000000 0.000000
16 BereqMethod b GET
16 BereqURL b /uncacheable
16 BereqProtocol b HTTP/1.1
16 BereqHeader b Host: localhost:8080
16 BereqHeader b User-Agent: curl/7.52.1
16 BereqHeader b Accept: */*
16 BereqHeader b X-Forwarded-For: 127.0.0.1
16 BereqHeader b Accept-Encoding: gzip
16 BereqHeader b X-Varnish: 16
16 VCL_call b BACKEND_FETCH
16 VCL_return b fetch
16 FetchError b backend boot.test: unhealthy
16 Timestamp b Beresp: 1533799317.220936 0.000030 0.000030
16 Timestamp b Error: 1533799317.220939 0.000033 0.000003
16 BerespProtocol b HTTP/1.1
16 BerespStatus b 503
16 BerespReason b Service Unavailable
16 BerespReason b Backend fetch failed
16 BerespHeader b Date: Thu, 09 Aug 2018 07:21:57 GMT
16 BerespHeader b Server: Varnish
16 VCL_call b BACKEND_ERROR
16 BerespHeader b Content-Type: text/html; charset=utf-8
16 BerespHeader b Retry-After: 5
16 VCL_return b deliver
16 Storage b malloc Transient
16 Length b 279
16 BereqAcct b 0 0 0 0 0 0
16 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=96.295926332 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f8143c0 e=0.000000000 f=0x0
0 ExpKill - EXP_When p=0x7f471f8143c0 e=1533799317.220938921 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f8143c0 e=-0.000101566 f=0x0
0 ExpKill - EXP_Expired x=16 t=-0
0 ExpKill - EXP_expire p=0x7f471f814000 e=96.295915127 f=0x0
15 Begin c req 14 rxreq
15 Timestamp c Start: 1533799317.220823 0.000000 0.000000
15 Timestamp c Req: 1533799317.220823 0.000000 0.000000
15 ReqStart c 127.0.0.1 38238 a0
15 ReqMethod c GET
15 ReqURL c /uncacheable
15 ReqProtocol c HTTP/1.1
15 ReqHeader c Host: localhost:8080
15 ReqHeader c User-Agent: curl/7.52.1
15 ReqHeader c Accept: */*
15 ReqHeader c X-Forwarded-For: 127.0.0.1
15 VCL_call c RECV
15 VCL_return c hash
15 VCL_call c HASH
15 VCL_return c lookup
15 HitMiss c 32777 104.465555
15 VCL_call c MISS
15 VCL_return c fetch
15 Link c bereq 16 fetch
15 Timestamp c Fetch: 1533799317.221021 0.000198 0.000198
15 RespProtocol c HTTP/1.1
15 RespStatus c 503
15 RespReason c Backend fetch failed
15 RespHeader c Date: Thu, 09 Aug 2018 07:21:57 GMT
15 RespHeader c Server: Varnish
15 RespHeader c Content-Type: text/html; charset=utf-8
15 RespHeader c Retry-After: 5
15 RespHeader c X-Varnish: 15
15 RespHeader c Age: 0
15 RespHeader c Via: 1.1 varnish (Varnish/6.0)
15 VCL_call c DELIVER
15 VCL_return c deliver
15 Timestamp c Process: 1533799317.221040 0.000217 0.000019
15 RespHeader c Content-Length: 279
15 RespHeader c Connection: keep-alive
15 Timestamp c Resp: 1533799317.221071 0.000248 0.000031
15 ReqAcct c 89 0 89 247 279 526
15 End c
14 SessClose c REM_CLOSE 0.000
14 End c
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799317 1.0
0 Backend_health - boot.test Still sick 4---X-R- 0 1 1 0.000311 0.000405 HTTP/1.1 503 Service Unavailable
0 Backend_health - boot.test Still sick 4---X-R- 0 1 1 0.000325 0.000405 HTTP/1.1 503 Service Unavailable
0 Backend_health - boot.test Still sick 4---X-R- 0 1 1 0.000368 0.000405 HTTP/1.1 503 Service Unavailable
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799320 1.0
0 Backend_health - boot.test Back healthy 4---X-RH 1 1 1 0.000652 0.000466 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000610 0.000502 HTTP/1.1 204 No Content
32778 Begin c sess 0 HTTP/1
32778 SessOpen c 127.0.0.1 38272 a0 127.0.0.1 8080 1533799322.545473 27
32778 Link c req 32779 rxreq
32780 Begin b bereq 32779 fetch
32780 Timestamp b Start: 1533799322.545569 0.000000 0.000000
32780 BereqMethod b GET
32780 BereqURL b /uncacheable
32780 BereqProtocol b HTTP/1.1
32780 BereqHeader b Host: localhost:8080
32780 BereqHeader b User-Agent: curl/7.52.1
32780 BereqHeader b Accept: */*
32780 BereqHeader b X-Forwarded-For: 127.0.0.1
32780 BereqHeader b Accept-Encoding: gzip
32780 BereqHeader b X-Varnish: 32780
32780 VCL_call b BACKEND_FETCH
32780 VCL_return b fetch
32780 BackendOpen b 30 boot.test 127.0.0.1 39659 127.0.0.1 37230
32780 BackendStart b 127.0.0.1 39659
32780 Timestamp b Bereq: 1533799322.545640 0.000070 0.000070
32780 Timestamp b Beresp: 1533799322.545800 0.000231 0.000160
32780 BerespProtocol b HTTP/1.1
32780 BerespStatus b 200
32780 BerespReason b OK
32780 BerespHeader b Cache-Control: max-age=0
32780 BerespHeader b Server: testbackend.go
32780 BerespHeader b Date: Thu, 09 Aug 2018 07:22:02 GMT
32780 BerespHeader b Content-Length: 41
32780 BerespHeader b Content-Type: text/html; charset=utf-8
32780 TTL b RFC 0 10 0 1533799323 1533799323 1533799322 0 0 cacheable
32780 VCL_call b BACKEND_RESPONSE
32780 TTL b VCL 120 10 0 1533799323 cacheable
32780 TTL b VCL 120 10 0 1533799323 uncacheable
32780 VCL_return b deliver
32780 Storage b malloc Transient
32780 Fetch_Body b 3 length -
32780 BackendReuse b 30 boot.test
32780 Timestamp b BerespBody: 1533799322.545850 0.000281 0.000050
32780 Length b 41
32780 BereqAcct b 158 0 158 166 41 207
32780 End b
0 ExpKill - EXP_expire p=0x7f471f814000 e=90.971094608 f=0x0
0 ExpKill - EXP_Inbox flg=1e p=0x7f471f2120c0 e=0.000000000 f=0x4
0 ExpKill - EXP_When p=0x7f471f2120c0 e=1533799452.545800209 f=0x1e
0 ExpKill - EXP_expire p=0x7f471f814000 e=90.971087217 f=0x0
32779 Begin c req 32778 rxreq
32779 Timestamp c Start: 1533799322.545502 0.000000 0.000000
32779 Timestamp c Req: 1533799322.545502 0.000000 0.000000
32779 ReqStart c 127.0.0.1 38272 a0
32779 ReqMethod c GET
32779 ReqURL c /uncacheable
32779 ReqProtocol c HTTP/1.1
32779 ReqHeader c Host: localhost:8080
32779 ReqHeader c User-Agent: curl/7.52.1
32779 ReqHeader c Accept: */*
32779 ReqHeader c X-Forwarded-For: 127.0.0.1
32779 VCL_call c RECV
32779 VCL_return c hash
32779 VCL_call c HASH
32779 VCL_return c lookup
32779 HitMiss c 32777 99.140876
32779 VCL_call c MISS
32779 VCL_return c fetch
32779 Link c bereq 32780 fetch
32779 Timestamp c Fetch: 1533799322.545855 0.000353 0.000353
32779 RespProtocol c HTTP/1.1
32779 RespStatus c 200
32779 RespReason c OK
32779 RespHeader c Cache-Control: max-age=0
32779 RespHeader c Server: testbackend.go
32779 RespHeader c Date: Thu, 09 Aug 2018 07:22:02 GMT
32779 RespHeader c Content-Length: 41
32779 RespHeader c Content-Type: text/html; charset=utf-8
32779 RespHeader c X-Varnish: 32779
32779 RespHeader c Age: 0
32779 RespHeader c Via: 1.1 varnish (Varnish/6.0)
32779 VCL_call c DELIVER
32779 VCL_return c deliver
32779 Timestamp c Process: 1533799322.545867 0.000365 0.000012
32779 RespHeader c Accept-Ranges: bytes
32779 RespHeader c Connection: keep-alive
32779 Timestamp c Resp: 1533799322.545897 0.000396 0.000031
32779 ReqAcct c 89 0 89 270 41 311
32779 End c
32778 SessClose c REM_CLOSE 0.001
32778 End c
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000362 0.000467 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799323 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000319 0.000430 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000358 0.000412 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000584 0.000455 HTTP/1.1 204 No Content
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1533799326 1.0
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000317 0.000421 HTTP/1.1 204 No Content
0 Backend_health - boot.test Still healthy 4---X-RH 1 1 1 0.000343 0.000401 HTTP/1.1 204 No Content
pkg/log/log.c → pkg/log/vsl_int.go
View file @ 7147cd55
......@@ -26,19 +26,55 @@
* SUCH DAMAGE.
*/
#include "log.h"
#include "_cgo_export.h"
static int
dispatch_wrapped(struct VSL_data *vsl, struct VSL_transaction * const trans[],
void *priv)
{
(void) vsl;
return (publish((void *)trans, *((uint64_t *)priv)));
package log
/*
#cgo pkg-config: varnishapi
#include <stdio.h>
#include <vapi/vsl.h>
*/
import "C"
import "unsafe"
const (
identmask = ^uint32(3 << 30)
lenmask = uint32(0x0ffff)
clientmarker = uint32(1 << 30)
backendmarker = uint32(1 << 31)
maxRecLen = 4096
)
func (rec *C.struct_VSLC_ptr) tag() Tag {
ptr := (*uint32)(unsafe.Pointer(rec.ptr))
return Tag(uint8(*ptr >> 24))
}
func (rec *C.struct_VSLC_ptr) vxid() uint32 {
ptr := (*[2]uint32)(unsafe.Pointer(rec.ptr))
return ptr[1] & identmask
}
func (rec *C.struct_VSLC_ptr) length() uint32 {
ptr := (*uint32)(unsafe.Pointer(rec.ptr))
return *ptr & lenmask
}
func (rec *C.struct_VSLC_ptr) payload() []byte {
length := rec.length() - 1
ptr := (*[maxRecLen]byte)(unsafe.Pointer(uintptr(unsafe.Pointer(rec.ptr)) + 2*unsafe.Sizeof(*rec.ptr)))
b := ptr[:length]
bytes := make([]byte, length, length)
copy(bytes, b)
return bytes
}
func (rec *C.struct_VSLC_ptr) client() bool {
ptr := (*[2]uint32)(unsafe.Pointer(rec.ptr))
return ptr[1]&clientmarker != 0
}
int
dispatch(struct VSLQ *vslq, uint64_t key)
{
return VSLQ_Dispatch(vslq, dispatch_wrapped, (void *)&key);
func (rec *C.struct_VSLC_ptr) backend() bool {
ptr := (*[2]uint32)(unsafe.Pointer(rec.ptr))
return ptr[1]&backendmarker != 0
}
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment