Merge pull request #244 from Tantalor93/requestlog

introduce request log

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 @<file-path>, 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. "+

docs/failoncondition.md

@@ -4,8 +4,6 @@ layout: default
 parent: Examples
 ---
 
-
-
 # Fail on condition
 v3.1.0
 {: .label .label-yellow }

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:

docs/requestlog.md

@@ -0,0 +1,36 @@
+---
+title: Request logging
+layout: default
+parent: Examples
+---
+
+# Request logging
+v3.2.0
+{: .label .label-yellow }
+*dnspyre* can also log all DNS requests it produces. Request logging can be enabled by running *dnspyre* with flag `--log-requests`
+
+```
+dnspyre --server 8.8.8.8 google.com -n 5 --log-requests
+```
+
+The request logs will be by default available in file `requests.log`. The log file path can be configured using `--log-requests-path`.
+If the file does not exist, it is created. If it exists, the logs are appended.
+
+```
+dnspyre --server 8.8.8.8 google.com -n 5 --log-requests --log-requests-path /tmp/requests.log
+```
+
+The request logs look like this:
+```
+2024/04/28 21:45:14 worker:[0] reqid:[37449] qname:[google.com.] qtype:[A] respid:[37449] rcode:[NOERROR] respflags:[qr rd ra] err:[<nil>] duration:[75.875086ms]
+2024/04/28 21:45:14 worker:[0] reqid:[34625] qname:[google.com.] qtype:[A] respid:[34625] rcode:[NOERROR] respflags:[qr rd ra] err:[<nil>] duration:[15.643628ms]
+2024/04/28 21:45:14 worker:[0] reqid:[798] qname:[google.com.] qtype:[A] respid:[798] rcode:[NOERROR] respflags:[qr rd ra] err:[<nil>] duration:[12.087964ms]
+2024/04/28 21:45:14 worker:[0] reqid:[54943] qname:[google.com.] qtype:[A] respid:[54943] rcode:[NOERROR] respflags:[qr rd ra] err:[<nil>] duration:[12.975761ms]
+2024/04/28 21:45:14 worker:[0] reqid:[509] qname:[google.com.] qtype:[A] respid:[509] rcode:[NOERROR] respflags:[qr rd ra] err:[<nil>] duration:[11.784968ms]
+```
+You can see:
+* which worker executed the request (`worker`)
+* what was the request and response ID (`reqid` and `respid`)
+* what domain was queried and what type (`qname` and `qtype`)
+* what were the DNS response flags (`respflags`)
+* roundtrip duration (`duration`)

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,55 +457,101 @@ 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)
 						}
 
 						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)
 						}
 					}
 				}
 			}
-		}(st)
+		}(w, st)
 	}
 
 	wg.Wait()
 
 	return stats, nil
 }
 
+func (b *Benchmark) logRequest(workerID uint32, req dns.Msg, resp *dns.Msg, err error, dur time.Duration) {
+	rcode := "<nil>"
+	respid := "<nil>"
+	respflags := "<nil>"
+	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 {

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, "<nil>", 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]