diff options
| -rw-r--r-- | CHANGELOG.adoc | 9 | ||||
| -rw-r--r-- | lib/dns/answer.go | 44 | ||||
| -rw-r--r-- | lib/dns/answer_test.go | 74 | ||||
| -rw-r--r-- | lib/dns/answers.go | 13 | ||||
| -rw-r--r-- | lib/dns/answers_test.go | 26 | ||||
| -rw-r--r-- | lib/dns/caches.go | 45 | ||||
| -rw-r--r-- | lib/dns/caches_test.go | 24 | ||||
| -rw-r--r-- | lib/dns/request.go | 7 | ||||
| -rw-r--r-- | lib/dns/server.go | 188 |
9 files changed, 207 insertions, 223 deletions
diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index 24f1d833..6d647edf 100644 --- a/CHANGELOG.adoc +++ b/CHANGELOG.adoc @@ -38,6 +38,15 @@ Legend, [#v0_61_0] == pakakeh.go v0.61.0 (2026-xx-xx) +**lib/dns: print the answer TTL in DebugLevelCache** + +The log level cache changed to the following format, + + ... {MSG_ID QNAME TYPE TTL} ... + +where MSG_ID is the message ID, QNAME is the question name, TYPE is the +type of question, and TTL is the time-to-live of the answer. + **🌼 lib/dns: simplify log message for DebugLevelCache** For each logged request, there should be one line of response logged, diff --git a/lib/dns/answer.go b/lib/dns/answer.go index dc81e359..fd5c431d 100644 --- a/lib/dns/answer.go +++ b/lib/dns/answer.go @@ -5,6 +5,7 @@ package dns import ( "container/list" + "fmt" "strings" "time" ) @@ -14,8 +15,8 @@ type Answer struct { // el contains pointer to the cache in LRU. el *list.Element - // msg contains the unpacked DNS message. - msg *Message + // Message contains the unpacked DNS message. + Message *Message // QName contains DNS question name, a copy of msg.Question.Name. QName string @@ -34,6 +35,9 @@ type Answer struct { // RClass contains record class, a copy of msg.Question.Class. RClass RecordClass + + // TTL contains the first TTL on RR Answer. + TTL uint32 } // newAnswer create new answer from Message. @@ -42,10 +46,10 @@ type Answer struct { func newAnswer(msg *Message, isLocal bool) (an *Answer) { an = &Answer{ // Trim the dot at the end for Message that is come from zone. - QName: strings.TrimSuffix(msg.Question.Name, `.`), - RType: msg.Question.Type, - RClass: msg.Question.Class, - msg: msg, + QName: strings.TrimSuffix(msg.Question.Name, `.`), + RType: msg.Question.Type, + RClass: msg.Question.Class, + Message: msg, } if isLocal { return @@ -53,12 +57,24 @@ func newAnswer(msg *Message, isLocal bool) (an *Answer) { var at = time.Now().Unix() an.ReceivedAt = at an.AccessedAt = at + if len(msg.Answer) != 0 { + an.TTL = msg.Answer[0].TTL + } return } +func (an *Answer) String() string { + var id uint16 + if an.Message != nil { + id = an.Message.Header.ID + } + return fmt.Sprintf(`{%d %s %s %d}`, id, an.QName, + RecordTypeNames[an.RType], an.TTL) +} + // clear the answer fields. func (an *Answer) clear() { - an.msg = nil + an.Message = nil an.el = nil } @@ -69,14 +85,14 @@ func (an *Answer) clear() { func (an *Answer) get() (packet []byte) { an.updateTTL() - packet = make([]byte, len(an.msg.packet)) - copy(packet, an.msg.packet) + packet = make([]byte, len(an.Message.packet)) + copy(packet, an.Message.packet) return } // update the answer with new message. func (an *Answer) update(nu *Answer) { - if nu == nil || nu.msg == nil { + if nu == nil || nu.Message == nil { return } @@ -85,8 +101,8 @@ func (an *Answer) update(nu *Answer) { an.AccessedAt = nu.AccessedAt } - an.msg = nu.msg - nu.msg = nil + an.Message = nu.Message + an.TTL = nu.TTL } // updateTTL decrease the answer TTLs based on time when message received. @@ -96,6 +112,6 @@ func (an *Answer) updateTTL() { } an.AccessedAt = time.Now().Unix() - var ttl = uint32(an.AccessedAt - an.ReceivedAt) - an.msg.SubTTL(ttl) + an.TTL = uint32(an.AccessedAt - an.ReceivedAt) + an.Message.SubTTL(an.TTL) } diff --git a/lib/dns/answer_test.go b/lib/dns/answer_test.go index f21c14c5..6147917f 100644 --- a/lib/dns/answer_test.go +++ b/lib/dns/answer_test.go @@ -54,10 +54,10 @@ func TestNewAnswer(t *testing.T) { msg: msg1, isLocal: true, exp: &Answer{ - QName: "test", - RType: 1, - RClass: 1, - msg: msg1, + QName: "test", + RType: 1, + RClass: 1, + Message: msg1, }, expQName: "test", expRType: 1, @@ -67,10 +67,10 @@ func TestNewAnswer(t *testing.T) { desc: "With non local message", msg: msg1, exp: &Answer{ - QName: "test", - RType: 1, - RClass: 1, - msg: msg1, + QName: "test", + RType: 1, + RClass: 1, + Message: msg1, }, expQName: "test", expRType: 1, @@ -99,7 +99,7 @@ func TestNewAnswer(t *testing.T) { test.Assert(t, "newAnswer.QName", c.expQName, got.QName) test.Assert(t, "newAnswer.RType", c.expRType, got.RType) test.Assert(t, "newAnswer.RClass", c.expRClass, got.RClass) - test.Assert(t, "newAnswer.msg", c.expMsg, got.msg) + test.Assert(t, "newAnswer.Message", c.expMsg, got.Message) } } @@ -110,8 +110,8 @@ func TestAnswerClear(t *testing.T) { Value: 1, } an = &Answer{ - msg: msg, - el: el, + Message: msg, + el: el, } expMsg *Message @@ -120,7 +120,7 @@ func TestAnswerClear(t *testing.T) { an.clear() - test.Assert(t, "answer.msg", expMsg, an.msg) + test.Assert(t, "answer.Message", expMsg, an.Message) test.Assert(t, "answer.el", expEl, an.el) } @@ -212,12 +212,10 @@ func TestAnswerGet(t *testing.T) { func TestAnswerUpdate(t *testing.T) { type testCase struct { - an *Answer - nu *Answer - expMsg *Message - desc string - expReceivedAt int64 - expAccessedAt int64 + an *Answer + nu *Answer + exp *Answer + desc string } var ( @@ -242,41 +240,47 @@ func TestAnswerUpdate(t *testing.T) { an: &Answer{ ReceivedAt: 1, AccessedAt: 1, - msg: msg1, + Message: msg1, + }, + exp: &Answer{ + ReceivedAt: 1, + AccessedAt: 1, + Message: msg1, }, - expReceivedAt: 1, - expAccessedAt: 1, - expMsg: msg1, }, { desc: "With local answer", an: &Answer{ ReceivedAt: 0, AccessedAt: 0, - msg: msg1, + Message: msg1, }, nu: &Answer{ ReceivedAt: at, AccessedAt: at, - msg: msg2, + Message: msg2, + }, + exp: &Answer{ + ReceivedAt: 0, + AccessedAt: 0, + Message: msg2, }, - expReceivedAt: 0, - expAccessedAt: 0, - expMsg: nil, }, { desc: "With non local answer", an: &Answer{ ReceivedAt: 1, AccessedAt: 1, - msg: msg1, + Message: msg1, }, nu: &Answer{ ReceivedAt: at, AccessedAt: at, - msg: msg2, + Message: msg2, + }, + exp: &Answer{ + ReceivedAt: at, + AccessedAt: at, + Message: msg2, }, - expReceivedAt: at, - expAccessedAt: at, - expMsg: nil, }} for _, c = range cases { @@ -284,10 +288,6 @@ func TestAnswerUpdate(t *testing.T) { c.an.update(c.nu) - test.Assert(t, "ReceivedAt", c.expReceivedAt, c.an.ReceivedAt) - test.Assert(t, "AccessedAt", c.expAccessedAt, c.an.AccessedAt) - if c.nu != nil { - test.Assert(t, "c.nu.msg", c.expMsg, c.nu.msg) - } + test.Assert(t, "ReceivedAt", c.exp, c.an) } } diff --git a/lib/dns/answers.go b/lib/dns/answers.go index a29fdf86..412002d1 100644 --- a/lib/dns/answers.go +++ b/lib/dns/answers.go @@ -15,7 +15,7 @@ func newAnswers(an *Answer) (ans *answers) { ans = &answers{ v: make([]*Answer, 0, 1), } - if an != nil && an.msg != nil { + if an != nil && an.Message != nil { ans.v = append(ans.v, an) } return @@ -54,10 +54,9 @@ func (ans *answers) remove(rtype RecordType, rclass RecordClass) { } // upsert update or insert new answer to list. -// If new answer is updated, it will return the old answer. -// If new answer is inserted, it will return nil instead. -func (ans *answers) upsert(nu *Answer) (an *Answer) { - if nu == nil || nu.msg == nil { +// It return the new inserted answer or update answer. +func (ans *answers) upsert(nu *Answer) (an *Answer, isInsert bool) { + if nu == nil || nu.Message == nil { return } an, _ = ans.get(nu.RType, nu.RClass) @@ -65,6 +64,8 @@ func (ans *answers) upsert(nu *Answer) (an *Answer) { an.update(nu) } else { ans.v = append(ans.v, nu) + an = nu + isInsert = true } - return + return an, isInsert } diff --git a/lib/dns/answers_test.go b/lib/dns/answers_test.go index 77912fa7..96418779 100644 --- a/lib/dns/answers_test.go +++ b/lib/dns/answers_test.go @@ -34,11 +34,11 @@ func TestNewAnswers(t *testing.T) { }, { desc: "With valid answer", an: &Answer{ - msg: &Message{}, + Message: &Message{}, }, expLen: 1, expV: []*Answer{{ - msg: &Message{}, + Message: &Message{}, }}, }} @@ -188,26 +188,26 @@ func TestAnswersUpdate(t *testing.T) { an1 = &Answer{ RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 1, }, }, } an2 = &Answer{ - RType: 2, - RClass: 1, - msg: &Message{}, + RType: 2, + RClass: 1, + Message: &Message{}, } an3 = &Answer{ - RType: 1, - RClass: 2, - msg: &Message{}, + RType: 1, + RClass: 2, + Message: &Message{}, } an4 = &Answer{ RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 2, }, @@ -247,9 +247,9 @@ func TestAnswersUpdate(t *testing.T) { exp: &answers{ v: []*Answer{ { - RType: 1, - RClass: 1, - msg: an4.msg, + RType: 1, + RClass: 1, + Message: an4.Message, }, an2, an3, diff --git a/lib/dns/caches.go b/lib/dns/caches.go index 3d4d5142..e6d5f58f 100644 --- a/lib/dns/caches.go +++ b/lib/dns/caches.go @@ -109,7 +109,7 @@ func (c *Caches) ExternalLoad(r io.Reader) (answers []*Answer, err error) { return nil, fmt.Errorf("%s: %w", logp, err) } for _, answer = range answers { - _ = c.upsert(answer) + c.upsert(answer) } return answers, nil } @@ -198,7 +198,7 @@ func (c *Caches) ExternalSave(w io.Writer) (n int, err error) { item = &cachesFileV1{ ReceivedAt: answer.ReceivedAt, AccessedAt: answer.AccessedAt, - Packet: answer.msg.packet, + Packet: answer.Message.packet, } err = enc.Encode(item) if err != nil { @@ -225,7 +225,7 @@ func (c *Caches) ExternalSearch(re *regexp.Regexp) (listMsg []*Message) { for dname, ans = range c.external { if re.MatchString(dname) { for _, an = range ans.v { - listMsg = append(listMsg, an.msg) + listMsg = append(listMsg, an.Message) } } } @@ -270,10 +270,10 @@ out: return nil } an = &Answer{ - msg: msg, + Message: msg, } - _ = an.msg.AddAuthority(zone.soaRecord()) - an.msg.SetResponseCode(RCodeErrName) + _ = an.Message.AddAuthority(zone.soaRecord()) + an.Message.SetResponseCode(RCodeErrName) } return an } @@ -303,7 +303,7 @@ func (c *Caches) InternalPopulate(msgs []*Message, from string) { for _, msg = range msgs { an = newAnswer(msg, isLocal) - inserted = c.upsert(an) + _, inserted = c.upsert(an) if inserted { n++ } @@ -382,7 +382,7 @@ func (c *Caches) InternalRemoveRecord(rr *ResourceRecord) (rrOut *ResourceRecord if an.RClass != rr.Class { continue } - rrOut, err = an.msg.RemoveAnswer(rr) + rrOut, err = an.Message.RemoveAnswer(rr) break } return rrOut, err @@ -437,7 +437,7 @@ func (c *Caches) internalUpsertRecord(rr *ResourceRecord) (err error) { return nil } - return an.msg.AddAnswer(rr) + return an.Message.AddAnswer(rr) } // prune old, external answers that have access time less or equal than @@ -460,7 +460,7 @@ func (c *Caches) prune(exp int64) (listAnswer []*Answer) { } if c.debug&DebugLevelCache != 0 { - log.Printf(`dns: - 0:%s`, answer.msg.Question.String()) + log.Printf(`dns: - 0:%s`, answer.Message.Question.String()) } next = el.Next() @@ -531,15 +531,12 @@ func (c *Caches) read(r io.Reader) (answers []*Answer, err error) { // // If the answer is inserted it will return true, otherwise it will return // false. -func (c *Caches) upsert(nu *Answer) (inserted bool) { - if nu == nil || nu.msg == nil { - return +func (c *Caches) upsert(nu *Answer) (an *Answer, inserted bool) { + if nu == nil || nu.Message == nil { + return nil, false } - var ( - answers *answers - an *Answer - ) + var answers *answers c.Lock() defer c.Unlock() @@ -550,11 +547,9 @@ func (c *Caches) upsert(nu *Answer) (inserted bool) { answers = newAnswers(nu) c.internal[nu.QName] = answers inserted = true + an = nu } else { - an = answers.upsert(nu) - if an == nil { - inserted = true - } + an, inserted = answers.upsert(nu) } } else { answers = c.external[nu.QName] @@ -562,11 +557,9 @@ func (c *Caches) upsert(nu *Answer) (inserted bool) { answers = newAnswers(nu) c.external[nu.QName] = answers inserted = true + an = nu } else { - an = answers.upsert(nu) - if an == nil { - inserted = true - } + an, inserted = answers.upsert(nu) } if inserted { // Push the new answer to LRU if new answer is @@ -575,7 +568,7 @@ func (c *Caches) upsert(nu *Answer) (inserted bool) { } } - return inserted + return an, inserted } // worker for pruning unused caches. diff --git a/lib/dns/caches_test.go b/lib/dns/caches_test.go index 3dc64fbd..d166f349 100644 --- a/lib/dns/caches_test.go +++ b/lib/dns/caches_test.go @@ -26,7 +26,7 @@ func TestCachesQuery(t *testing.T) { QName: "test", RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 1, }, @@ -37,7 +37,7 @@ func TestCachesQuery(t *testing.T) { QName: "test", RType: 2, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 2, }, @@ -48,7 +48,7 @@ func TestCachesQuery(t *testing.T) { QName: "test", RType: 3, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 3, }, @@ -113,7 +113,7 @@ func TestCachesPrune(t *testing.T) { QName: "test", RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 1, }, @@ -125,7 +125,7 @@ func TestCachesPrune(t *testing.T) { QName: "test", RType: 2, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 2, }, @@ -137,7 +137,7 @@ func TestCachesPrune(t *testing.T) { QName: "test", RType: 3, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 3, }, @@ -193,7 +193,7 @@ func TestCaches_ExternalSave(t *testing.T) { srv.Caches.init(0, 0, 0) - _ = srv.Caches.upsert(answer) + srv.Caches.upsert(answer) n, err = srv.Caches.ExternalSave(&w) if err != nil { @@ -202,7 +202,7 @@ func TestCaches_ExternalSave(t *testing.T) { test.Assert(t, "Caches.ExternalSave", 1, n) - msg, err = UnpackMessage(answer.msg.packet) + msg, err = UnpackMessage(answer.Message.packet) if err != nil { t.Fatal(err) } @@ -237,7 +237,7 @@ func TestCachesUpsert(t *testing.T) { QName: "test", RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 1, }, @@ -249,7 +249,7 @@ func TestCachesUpsert(t *testing.T) { QName: "test", RType: 1, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 3, }, @@ -261,7 +261,7 @@ func TestCachesUpsert(t *testing.T) { QName: "test", RType: 2, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 2, }, @@ -273,7 +273,7 @@ func TestCachesUpsert(t *testing.T) { QName: "test", RType: 2, RClass: 1, - msg: &Message{ + Message: &Message{ Header: MessageHeader{ ID: 4, }, diff --git a/lib/dns/request.go b/lib/dns/request.go index 7bfacd28..dd1b0925 100644 --- a/lib/dns/request.go +++ b/lib/dns/request.go @@ -4,6 +4,7 @@ package dns import ( + "fmt" "io" "log" "time" @@ -44,6 +45,12 @@ func newRequest() (req *request) { return req } +func (req *request) String() string { + return fmt.Sprintf(`{%d %s %s}`, req.message.Header.ID, + req.message.Question.Name, + RecordTypeNames[req.message.Question.Type]) +} + // error set the request message as an error. func (req *request) error(rcode ResponseCode) { var err error diff --git a/lib/dns/server.go b/lib/dns/server.go index 005a28b0..ca2baa5b 100644 --- a/lib/dns/server.go +++ b/lib/dns/server.go @@ -66,18 +66,21 @@ const ( // // Following the prefix is // -// SOURCE FWD-NAME NS MSG-ID:QUESTION ELAPSED TOTAL_Q AVG_ELAPSED +// SOURCE FWD_NAME NS {MSG_ID QNAME TYPE TTL} ELAPSED TOTAL_Q AVG_ELAPSED // // where each field is, in order, -// - source of connection (UDP, TCP, DoH, or DoT), -// - forwarder name (for example, UDP-0 if request handled by the -// first parent name server using UDP) or "-" if its from cache, -// - parent name server address for forwarded query or "-" if its from -// cache, -// - message-ID and question separated by ":", -// - elapsed time, -// - total query per-forwarder, and -// - average elapsed time +// - SOURCE: source of connection (UDP, TCP, DoH, or DoT) +// - FWD_NAME: forwarder name (for example, UDP-0 means request handled by +// the first parent name server using UDP) or "-" if its from cache +// - NS: parent name server address for forwarded query or "-" if its from +// cache +// - MSG_ID: message ID +// - QNAME: the question +// - TYPE: type of question +// - TTL: time to live of the answer, 0 if its log is request +// - ELAPSED: elapsed time +// - TOTAL_Q: total query per-forwarder +// - AVG_ELAPSED: average elapsed time per-forwarder type Server struct { HostsFiles map[string]*HostsFile Caches Caches @@ -591,10 +594,8 @@ func (srv *Server) processRequest() { } if srv.opts.Debug&DebugLevelCache != 0 { - log.Printf(`> %s - - %d:%s - - -`, - connTypeNames[req.kind], - req.message.Header.ID, - req.message.Question.String()) + log.Printf(`> %s - - %s - - -`, + connTypeNames[req.kind], req.String()) } an = srv.Caches.query(req.message) @@ -608,17 +609,16 @@ func (srv *Server) processRequest() { } default: if srv.opts.Debug&DebugLevelCache != 0 { - log.Printf(`* %s - - %d:%s - - -: no active forwarders`, + log.Printf(`* %s - - %s - - -: no active forwarders`, connTypeNames[req.kind], - req.message.Header.ID, - req.message.Question.String()) + req.String()) } req.error(RCodeErrServer) } continue } - if an.msg.IsExpired() { + if an.Message.IsExpired() { switch { case srv.hasForwarders(): if req.kind == connTypeTCP { @@ -629,60 +629,51 @@ func (srv *Server) processRequest() { default: if srv.opts.Debug&DebugLevelCache != 0 { - log.Printf(`* %s - - %d:%s - - -: answer is expired and no active forwarders`, + log.Printf(`* %s - - %s - - -: answer is expired and no active forwarders`, connTypeNames[req.kind], - req.message.Header.ID, - req.message.Question.String()) + req.String()) } req.error(RCodeErrServer) } continue } - an.msg.SetID(req.message.Header.ID) + an.Message.SetID(req.message.Header.ID) an.updateTTL() - res = an.msg + res = an.Message _, err = req.writer.Write(res.packet) if err != nil { - log.Printf(`! %s - - %d:%s - - -: %s`, - connTypeNames[req.kind], - req.message.Header.ID, - req.message.Question.String(), err) + log.Printf(`! %s - - %s - - -: %s`, + connTypeNames[req.kind], an.String(), err) continue } if srv.opts.Debug&DebugLevelCache != 0 { - log.Printf(`< %s - - %d:%s - - -`, connTypeNames[req.kind], - res.Header.ID, res.Question.String()) + log.Printf(`< %s - - %s - - -`, + connTypeNames[req.kind], an.String()) } } } -func (srv *Server) processResponse(req *request, res *Message) (inserted bool, err error) { +func (srv *Server) processResponse(req *request, res *Message) (an *Answer, inserted bool, err error) { if !isResponseValid(req, res) { req.error(RCodeErrServer) - return false, nil + return nil, false, errors.New(`invalid response`) } - var an *Answer - _, err = req.writer.Write(res.packet) if err != nil { - return false, err + return nil, false, err } if res.Header.RCode != 0 { - if srv.opts.Debug&DebugLevelDNS != 0 { - err = errors.New(`response has error code ` + rcodeNames[res.Header.RCode]) - } - return false, err + err = errors.New(`response has error code ` + rcodeNames[res.Header.RCode]) + return nil, false, err } if res.Header.IsTC { - if srv.opts.Debug&DebugLevelDNS != 0 { - err = errors.New(`response truncated`) - } - return false, err + err = errors.New(`response truncated`) + return nil, false, err } if res.Header.ANCount == 0 { // Ignore empty answers. @@ -694,16 +685,14 @@ func (srv *Server) processResponse(req *request, res *Message) (inserted bool, e // Once they connect to Y again, any request to MY.Y will not // be possible because rescached caches contains empty answer // for MY.Y. - if srv.opts.Debug&DebugLevelDNS != 0 { - err = errors.New(`empty RR answer`) - } - return false, err + err = errors.New(`empty RR answer`) + return nil, false, err } an = newAnswer(res, false) - inserted = srv.Caches.upsert(an) + an, inserted = srv.Caches.upsert(an) - return inserted, nil + return an, inserted, nil } func (srv *Server) startAllForwarders() { @@ -790,11 +779,9 @@ func (srv *Server) dohForwarder(tag, nameserver string) { } res, err = forwarder.Query(req.message) if err != nil { - log.Printf(`! %s %s %s %d:%s: forward failed %s`, + log.Printf(`! %s %s %s %s - - -: forward failed %s`, connTypeNames[req.kind], - tag, nameserver, - req.message.Header.ID, - req.message.Question.String(), + tag, nameserver, req.String(), err) if !errors.Is(err, errInvalidMessage) { isRunning = false @@ -802,34 +789,28 @@ func (srv *Server) dohForwarder(tag, nameserver string) { continue } - isInserted, err := srv.processResponse(req, res) + an, isInserted, err := srv.processResponse(req, res) elapsed := time.Since(req.startAt) totalElapsed += int64(elapsed) totalQuery++ avgElapsed := time.Duration(totalElapsed / totalQuery) if err != nil { - log.Printf(`! %s %s %s %d:%s %v %d %v: %s`, + log.Printf(`! %s %s %s %s %v %d %v: %s`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, req.String(), elapsed, totalQuery, avgElapsed, err) continue } if srv.opts.Debug&DebugLevelCache != 0 { if isInserted { - log.Printf(`+ %s %s %s %d:%s %v %d %v`, + log.Printf(`+ %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } else { - log.Printf(`# %s %s %s %d:%s %v %d %v`, + log.Printf(`# %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } } @@ -902,11 +883,9 @@ func (srv *Server) tlsForwarder(tag, nameserver string) { res, err = forwarder.Query(req.message) if err != nil { - log.Printf(`! %s %s %s %d:%s: forward failed %s`, + log.Printf(`! %s %s %s %s - - -: forward failed %s`, connTypeNames[req.kind], - logp, tag, - req.message.Header.ID, - req.message.Question.String(), + logp, tag, req.String(), err) if !errors.Is(err, errInvalidMessage) { isRunning = false @@ -914,34 +893,29 @@ func (srv *Server) tlsForwarder(tag, nameserver string) { continue } - isInserted, err := srv.processResponse(req, res) + an, isInserted, err := srv.processResponse(req, res) elapsed := time.Since(req.startAt) totalElapsed += int64(elapsed) totalQuery++ avgElapsed := time.Duration(totalElapsed / totalQuery) if err != nil { - log.Printf(`! %s %s %s %d:%s %v %d %v: %s`, + log.Printf(`! %s %s %s %s %v %d %v: %s`, connTypeNames[req.kind], tag, nameserver, - res.Header.ID, - res.Question.String(), + req.String(), elapsed, totalQuery, avgElapsed, err) continue } if srv.opts.Debug&DebugLevelCache != 0 { if isInserted { - log.Printf(`+ %s %s %s %d:%s %v %d %v`, + log.Printf(`+ %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } else { - log.Printf(`# %s %s %s %d:%s %v %d %v`, + log.Printf(`# %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } } @@ -1006,42 +980,34 @@ func (srv *Server) tcpForwarder(tag, nameserver string) { res, err = cl.Query(req.message) cl.Close() if err != nil { - log.Printf(`! %s %s %s %d:%s: forward failed %s`, + log.Printf(`! %s %s %s %s - - -: forward failed %s`, connTypeNames[req.kind], - tag, nameserver, - req.message.Header.ID, - req.message.Question.String(), err) + tag, nameserver, req.String(), err) continue } - isInserted, err := srv.processResponse(req, res) + an, isInserted, err := srv.processResponse(req, res) elapsed := time.Since(req.startAt) totalElapsed += int64(elapsed) totalQuery++ avgElapsed := time.Duration(totalElapsed / totalQuery) if err != nil { - log.Printf(`! %s %s %s %d:%s %v %d %v: %s`, + log.Printf(`! %s %s %s %s %v %d %v: %s`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, req.String(), elapsed, totalQuery, avgElapsed, err) continue } if srv.opts.Debug&DebugLevelCache != 0 { if isInserted { - log.Printf(`+ %s %s %s %d:%s %v %d %v`, + log.Printf(`+ %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } else { - log.Printf(`# %s %s %s %d:%s: %v %d %v`, + log.Printf(`# %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } } @@ -1116,11 +1082,9 @@ func (srv *Server) udpForwarder(tag, nameserver string) { res, err = forwarder.Query(req.message) if err != nil { - log.Printf(`! %s %s %s %d:%s: forward failed %s`, + log.Printf(`! %s %s %s %s - - -: forward failed %s`, connTypeNames[req.kind], - tag, nameserver, - req.message.Header.ID, - req.message.Question.String(), + tag, nameserver, req.String(), err) if !errors.Is(err, errInvalidMessage) { isRunning = false @@ -1128,34 +1092,28 @@ func (srv *Server) udpForwarder(tag, nameserver string) { continue } - isInserted, err := srv.processResponse(req, res) + an, isInserted, err := srv.processResponse(req, res) elapsed := time.Since(req.startAt) totalElapsed += int64(elapsed) totalQuery++ avgElapsed := time.Duration(totalElapsed / totalQuery) if err != nil { - log.Printf(`! %s %s %s %d:%s %v %d %v: %s`, + log.Printf(`! %s %s %s %s %v %d %v: %s`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, req.String(), elapsed, totalQuery, avgElapsed, err) continue } if srv.opts.Debug&DebugLevelCache != 0 { if isInserted { - log.Printf(`+ %s %s %s %d:%s %v %d %v`, + log.Printf(`+ %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } else { - log.Printf(`# %s %s %s %d:%s %v %d %v`, + log.Printf(`# %s %s %s %s %v %d %v`, connTypeNames[req.kind], - tag, nameserver, - res.Header.ID, - res.Question.String(), + tag, nameserver, an.String(), elapsed, totalQuery, avgElapsed) } } |
