diff --git a/cmd/root.go b/cmd/root.go index 8c79cd0..8a71914 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -145,6 +145,13 @@ func init() { PlaceHolder(ioerrorFailCondition). EnumsVar(&failConditions, ioerrorFailCondition, negativeFailCondition, errorFailCondition, idmismatchFailCondition) + pApp.Flag("log-requests", "Controls whether the Benchmark requests are logged. Requests are logged into the file specified by --log-requests-path flag. Disabled by default."). + Default("false").BoolVar(&benchmark.RequestLogEnabled) + + pApp.Flag("log-requests-path", "Specifies path to the file, where the request logs will be logged. If the file exists, the logs will be appended to the file. "+ + "If the file does not exist, the file will be created."). + Default(dnsbench.DefaultRequestLogPath).StringVar(&benchmark.RequestLogPath) + pApp.Arg("queries", "Queries to issue. It can be a local file referenced using @, for example @data/2-domains. "+ "It can also be resource accessible using HTTP, like https://raw.githubusercontent.com/Tantalor93/dnspyre/master/data/1000-domains, in that "+ "case, the file will be downloaded and saved in-memory. "+ diff --git a/docs/index.md b/docs/index.md index a75fef0..297f90f 100644 --- a/docs/index.md +++ b/docs/index.md @@ -86,6 +86,11 @@ Flags: Supported options are 'ioerror' (fail if there is at least 1 IO error), 'negative' (fail if there is at least 1 negative DNS answer), 'error' (fail if there is at least 1 error DNS response), 'idmismatch' (fail there is at least 1 ID mismatch between DNS request and response). + --[no-]log-requests Controls whether the Benchmark requests are logged. Requests are logged into the file specified by + --log-requests-path flag. Disabled by default. + --log-requests-path="requests.log" + Specifies path to the file, where the request logs will be logged. If the file exists, the logs will be + appended to the file. If the file does not exist, the file will be created. --[no-]version Show application version. Args: diff --git a/go.mod b/go.mod index c0830ea..51c1206 100644 --- a/go.mod +++ b/go.mod @@ -44,6 +44,8 @@ require ( github.com/rivo/uniseg v0.4.7 // indirect github.com/xhit/go-str2duration/v2 v2.1.0 // indirect go.uber.org/mock v0.4.0 // indirect + go.uber.org/multierr v1.11.0 // indirect + go.uber.org/zap v1.27.0 // indirect golang.org/x/crypto v0.22.0 // indirect golang.org/x/exp v0.0.0-20231006140011-7918f672742d // indirect golang.org/x/image v0.13.0 // indirect diff --git a/go.sum b/go.sum index 0090142..d35fa02 100644 --- a/go.sum +++ b/go.sum @@ -124,8 +124,12 @@ go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= go.uber.org/mock v0.4.0 h1:VcM4ZOtdbR4f6VXfiOpwpVJDL6lCReaZ6mw31wqh7KU= go.uber.org/mock v0.4.0/go.mod h1:a6FSlNadKUHUa9IP5Vyt1zh4fC7uAwxMutEAscFbkZc= +go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0= +go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= go.uber.org/ratelimit v0.3.1 h1:K4qVE+byfv/B3tC+4nYWP7v/6SimcO7HzHekoMNBma0= go.uber.org/ratelimit v0.3.1/go.mod h1:6euWsTB6U/Nb3X++xEUXA8ciPJvr19Q/0h1+oDcJhRk= +go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8= +go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= diff --git a/pkg/dnsbench/benchmark.go b/pkg/dnsbench/benchmark.go index 226de86..e05db96 100644 --- a/pkg/dnsbench/benchmark.go +++ b/pkg/dnsbench/benchmark.go @@ -8,6 +8,7 @@ import ( "errors" "fmt" "io" + "log" "math/rand" "net" "net/http" @@ -57,6 +58,9 @@ const ( // DefaultEdns0BufferSize default EDNS0 buffer size according to the http://www.dnsflagday.net/2020/ DefaultEdns0BufferSize = 1232 + + // DefaultRequestLogPath is a default path to the file, where the requests will be logged. + DefaultRequestLogPath = "requests.log" ) // Benchmark is representation of runnable DNS benchmark scenario. @@ -179,6 +183,13 @@ type Benchmark struct { // These data sources can be combined, for example "google.com @data/2-domains https://raw.githubusercontent.com/Tantalor93/dnspyre/master/data/2-domains". Queries []string + // RequestLogEnabled controls whether the Benchmark requests will be logged. Requests are logged into the file specified by Benchmark.RequestLogPath field. + RequestLogEnabled bool + + // RequestLogPath specifies file where the request logs will be logged. If the file does not exist, it is created. + // If it exists, the request logs are appended to the file. + RequestLogPath string + // Writer used for writing benchmark execution logs and results. Default is os.Stdout. Writer io.Writer @@ -248,11 +259,24 @@ func (b *Benchmark) prepare() error { } } + if b.RequestLogEnabled { + b.RequestLogPath = DefaultRequestLogPath + } + return nil } // Run executes benchmark, if benchmark is unable to start the error is returned, otherwise array of results from parallel benchmark goroutines is returned. func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { + if b.RequestLogEnabled { + file, err := os.OpenFile(b.RequestLogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644) + if err != nil { + return nil, err + } + defer file.Close() + log.SetOutput(file) + } + color.NoColor = !b.Color if err := b.prepare(); err != nil { @@ -366,7 +390,7 @@ func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { var err error wg.Add(1) - go func(st *ResultStats) { + go func(workerID uint32, st *ResultStats) { defer func() { wg.Done() }() @@ -433,30 +457,30 @@ func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { } var resp *dns.Msg - m := dns.Msg{} - m.RecursionDesired = b.Recurse + req := dns.Msg{} + req.RecursionDesired = b.Recurse - m.Question = make([]dns.Question, 1) + req.Question = make([]dns.Question, 1) question := dns.Question{Name: q, Qtype: qt, Qclass: dns.ClassINET} - m.Question[0] = question + req.Question[0] = question if b.useQuic { - m.Id = 0 + req.Id = 0 } else { - m.Id = uint16(rando.Uint32()) + req.Id = uint16(rando.Uint32()) } if b.Edns0 > 0 { - m.SetEdns0(b.Edns0, false) + req.SetEdns0(b.Edns0, false) } if ednsOpt := b.EdnsOpt; len(ednsOpt) > 0 { - addEdnsOpt(&m, ednsOpt) + addEdnsOpt(&req, ednsOpt) } if b.DNSSEC { - edns0 := m.IsEdns0() + edns0 := req.IsEdns0() if edns0 == nil { - m.SetEdns0(DefaultEdns0BufferSize, false) - edns0 = m.IsEdns0() + req.SetEdns0(DefaultEdns0BufferSize, false) + edns0 = req.IsEdns0() } edns0.SetDo(true) } @@ -464,9 +488,13 @@ func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { start := time.Now() reqTimeoutCtx, cancel := context.WithTimeout(ctx, b.RequestTimeout) - resp, err = query(reqTimeoutCtx, b.Server, &m) + resp, err = query(reqTimeoutCtx, b.Server, &req) cancel() - st.record(&m, resp, err, start, time.Since(start)) + dur := time.Since(start) + if b.RequestLogEnabled { + b.logRequest(workerID, req, resp, err, dur) + } + st.record(&req, resp, err, start, dur) if incrementBar { bar.Add(1) @@ -474,7 +502,7 @@ func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { } } } - }(st) + }(w, st) } wg.Wait() @@ -482,6 +510,48 @@ func (b *Benchmark) Run(ctx context.Context) ([]*ResultStats, error) { return stats, nil } +func (b *Benchmark) logRequest(workerID uint32, req dns.Msg, resp *dns.Msg, err error, dur time.Duration) { + rcode := "" + respid := "" + respflags := "" + if resp != nil { + rcode = dns.RcodeToString[resp.Rcode] + respid = fmt.Sprint(resp.Id) + respflags = getFlags(resp) + } + log.Printf("worker:[%v] reqid:[%d] qname:[%s] qtype:[%s] respid:[%s] rcode:[%s] respflags:[%s] err:[%v] duration:[%v]", + workerID, req.Id, req.Question[0].Name, dns.TypeToString[req.Question[0].Qtype], respid, rcode, respflags, err, dur) +} + +func getFlags(resp *dns.Msg) string { + respflags := "" + if resp.Response { + respflags += "qr" + } + if resp.Authoritative { + respflags += " aa" + } + if resp.Truncated { + respflags += " tc" + } + if resp.RecursionDesired { + respflags += " rd" + } + if resp.RecursionAvailable { + respflags += " ra" + } + if resp.Zero { + respflags += " z" + } + if resp.AuthenticatedData { + respflags += " ad" + } + if resp.CheckingDisabled { + respflags += " cd" + } + return respflags +} + func addEdnsOpt(m *dns.Msg, ednsOpt string) { o := m.IsEdns0() if o == nil { diff --git a/pkg/dnsbench/benchmark_api_test.go b/pkg/dnsbench/benchmark_api_test.go index d84d5b8..b2df8f8 100644 --- a/pkg/dnsbench/benchmark_api_test.go +++ b/pkg/dnsbench/benchmark_api_test.go @@ -1,6 +1,7 @@ package dnsbench_test import ( + "bufio" "bytes" "context" "crypto/tls" @@ -12,6 +13,7 @@ import ( "net/http" "net/http/httptest" "os" + "regexp" "strconv" "testing" "time" @@ -1279,6 +1281,128 @@ func TestBenchmark_Run_DoQ_truncated(t *testing.T) { assert.Equal(t, int64(2), rs[1].Counters.Truncated, "there should be truncated messages") } +type requestLog struct { + worker int + requestid int + qname string + qtype string + respid int + rcode string + respflags string + err string + duration time.Duration +} + +func TestBenchmark_Requestlog(t *testing.T) { + requestLogPath := t.TempDir() + "/requests.log" + + s := NewServer(dnsbench.UDPTransport, nil, func(w dns.ResponseWriter, r *dns.Msg) { + ret := new(dns.Msg) + ret.SetReply(r) + ret.Answer = append(ret.Answer, A("example.org. IN A 127.0.0.1")) + + // wait some time to actually have some observable duration + time.Sleep(time.Millisecond * 500) + + w.WriteMsg(ret) + }) + defer s.Close() + + buf := bytes.Buffer{} + bench := dnsbench.Benchmark{ + Queries: []string{"example.org"}, + Types: []string{"A", "AAAA"}, + Server: s.Addr, + TCP: false, + Concurrency: 2, + Count: 1, + Probability: 1, + WriteTimeout: 1 * time.Second, + ReadTimeout: 3 * time.Second, + ConnectTimeout: 1 * time.Second, + RequestTimeout: 5 * time.Second, + Rcodes: true, + Recurse: true, + Writer: &buf, + RequestLogEnabled: true, + RequestLogPath: requestLogPath, + } + + ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) + defer cancel() + rs, err := bench.Run(ctx) + + require.NoError(t, err, "expected no error from benchmark run") + assertResult(t, rs) + + requestLogFile, err := os.Open(requestLogPath) + require.NoError(t, err) + + requestLogs := parseRequestLogs(t, requestLogFile) + + workerIds := map[int]int{} + qtypes := map[string]int{} + + for _, v := range requestLogs { + workerIds[v.worker]++ + qtypes[v.qtype]++ + + assert.Equal(t, "example.org.", v.qname) + assert.NotZero(t, v.requestid) + assert.NotZero(t, v.respid) + assert.Equal(t, "NOERROR", v.rcode) + assert.Equal(t, "qr rd", v.respflags) + assert.Equal(t, "", v.err) + assert.NotZero(t, v.duration) + } + assert.Equal(t, map[int]int{0: 2, 1: 2}, workerIds) + assert.Equal(t, map[string]int{"AAAA": 2, "A": 2}, qtypes) +} + +func parseRequestLogs(t *testing.T, reader io.Reader) []requestLog { + pattern := `.*worker:\[(.*)\] reqid:\[(.*)\] qname:\[(.*)\] qtype:\[(.*)\] respid:\[(.*)\] rcode:\[(.*)\] respflags:\[(.*)\] err:\[(.*)\] duration:\[(.*)\]$` + regex := regexp.MustCompile(pattern) + scanner := bufio.NewScanner(reader) + var requestLogs []requestLog + for scanner.Scan() { + line := scanner.Text() + + matches := regex.FindStringSubmatch(line) + + workerID, err := strconv.Atoi(matches[1]) + require.NoError(t, err) + + requestID, err := strconv.Atoi(matches[2]) + require.NoError(t, err) + + qname := matches[3] + qtype := matches[4] + + respID, err := strconv.Atoi(matches[5]) + require.NoError(t, err) + + rcode := matches[6] + respflags := matches[7] + errstr := matches[8] + + dur, err := time.ParseDuration(matches[9]) + require.NoError(t, err) + + requestLogs = append(requestLogs, requestLog{ + worker: workerID, + requestid: requestID, + qname: qname, + qtype: qtype, + respid: respID, + rcode: rcode, + respflags: respflags, + err: errstr, + duration: dur, + }) + } + return requestLogs +} + func assertResult(t *testing.T, rs []*dnsbench.ResultStats) { if assert.Len(t, rs, 2, "Run(ctx) rstats") { rs0 := rs[0] diff --git a/pkg/dnsbench/benchmark_test.go b/pkg/dnsbench/benchmark_test.go index 80c6acd..1dd5cc7 100644 --- a/pkg/dnsbench/benchmark_test.go +++ b/pkg/dnsbench/benchmark_test.go @@ -10,10 +10,11 @@ import ( func TestBenchmark_prepare(t *testing.T) { tests := []struct { - name string - benchmark Benchmark - wantServer string - wantErr bool + name string + benchmark Benchmark + wantServer string + wantRequestLogPath string + wantErr bool }{ { name: "server - IPv4", @@ -100,6 +101,12 @@ func TestBenchmark_prepare(t *testing.T) { benchmark: Benchmark{Server: "8.8.8.8", EdnsOpt: "65518:test"}, wantErr: true, }, + { + name: "request log - default path", + benchmark: Benchmark{Server: "8.8.8.8", RequestLogEnabled: true}, + wantServer: "8.8.8.8:53", + wantRequestLogPath: DefaultRequestLogPath, + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -108,6 +115,7 @@ func TestBenchmark_prepare(t *testing.T) { require.Equal(t, tt.wantErr, err != nil) if !tt.wantErr { assert.Equal(t, tt.wantServer, tt.benchmark.Server) + assert.Equal(t, tt.wantRequestLogPath, tt.wantRequestLogPath) } }) }