From fbe728c9aa03a325c2733c214412f9071faba5ed Mon Sep 17 00:00:00 2001 From: Stanislav Chzhen Date: Mon, 18 Nov 2024 20:57:15 +0300 Subject: [PATCH] all: imp code --- internal/home/dns.go | 4 +-- internal/querylog/decode.go | 61 +++++++++++++++++++------------- internal/querylog/decode_test.go | 14 ++++---- internal/querylog/search.go | 2 +- 4 files changed, 46 insertions(+), 35 deletions(-) diff --git a/internal/home/dns.go b/internal/home/dns.go index 23130cce..a25fc75e 100644 --- a/internal/home/dns.go +++ b/internal/home/dns.go @@ -531,7 +531,7 @@ func closeDNSServer() { if Context.stats != nil { err := Context.stats.Close() if err != nil { - log.Debug("closing stats: %s", err) + log.Error("closing stats: %s", err) } } @@ -539,7 +539,7 @@ func closeDNSServer() { // TODO(s.chzhen): Pass context. err := Context.queryLog.Shutdown(context.TODO()) if err != nil { - log.Debug("closing query log: %s", err) + log.Error("closing query log: %s", err) } } diff --git a/internal/querylog/decode.go b/internal/querylog/decode.go index b1993941..fa57d158 100644 --- a/internal/querylog/decode.go +++ b/internal/querylog/decode.go @@ -223,7 +223,12 @@ func (l *queryLog) decodeVTokenAndAddRule( vToken, err := dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext(ctx, "decodeResultRuleKey", "key", key, slogutil.KeyError, err) + l.logger.DebugContext( + ctx, + "decoding result rule key", + "key", key, + slogutil.KeyError, err, + ) } return newRules, nil @@ -239,11 +244,13 @@ func (l *queryLog) decodeVTokenAndAddRule( // decodeResultRules parses the dec's tokens into logEntry ent interpreting it // as a slice of the result rules. func (l *queryLog) decodeResultRules(ctx context.Context, dec *json.Decoder, ent *logEntry) { + const msgPrefix = "decoding result rules" + for { delimToken, err := dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext(ctx, "decodeResultRules", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -254,7 +261,7 @@ func (l *queryLog) decodeResultRules(ctx context.Context, dec *json.Decoder, ent } else if d != '[' { l.logger.DebugContext( ctx, - "decodeResultRules", + msgPrefix, slogutil.KeyError, unexpectedDelimiterError(d), ) } @@ -262,7 +269,7 @@ func (l *queryLog) decodeResultRules(ctx context.Context, dec *json.Decoder, ent err = l.decodeResultRuleToken(ctx, dec, ent) if err != nil { if err != io.EOF && !errors.Is(err, ErrEndOfToken) { - l.logger.DebugContext(ctx, "decodeResultRules", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; rule token", slogutil.KeyError, err) } return @@ -313,11 +320,13 @@ func (l *queryLog) decodeResultRuleToken( // rewrites currently has the highest priority along the entire filtering // pipeline. func (l *queryLog) decodeResultReverseHosts(ctx context.Context, dec *json.Decoder, ent *logEntry) { + const msgPrefix = "decoding result reverse hosts" + for { itemToken, err := dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext(ctx, "decodeResultReverseHosts", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -333,7 +342,7 @@ func (l *queryLog) decodeResultReverseHosts(ctx context.Context, dec *json.Decod l.logger.DebugContext( ctx, - "decodeResultReverseHosts", + msgPrefix, slogutil.KeyError, unexpectedDelimiterError(v), ) @@ -367,11 +376,13 @@ func (l *queryLog) decodeResultReverseHosts(ctx context.Context, dec *json.Decod // decodeResultIPList parses the dec's tokens into logEntry ent interpreting it // as the result IP addresses list. func (l *queryLog) decodeResultIPList(ctx context.Context, dec *json.Decoder, ent *logEntry) { + const msgPrefix = "decoding result ip list" + for { itemToken, err := dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext(ctx, "decodeResultIPList", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -387,7 +398,7 @@ func (l *queryLog) decodeResultIPList(ctx context.Context, dec *json.Decoder, en l.logger.DebugContext( ctx, - "decodeResultIPList", + msgPrefix, slogutil.KeyError, unexpectedDelimiterError(v), ) @@ -412,6 +423,8 @@ func (l *queryLog) decodeResultDNSRewriteResultKey( dec *json.Decoder, ent *logEntry, ) { + const msgPrefix = "decoding result dns rewrite result key" + var err error switch key { @@ -420,11 +433,7 @@ func (l *queryLog) decodeResultDNSRewriteResultKey( vToken, err = dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext( - ctx, - "decodeResultDNSRewriteResultKey", - slogutil.KeyError, err, - ) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -452,11 +461,7 @@ func (l *queryLog) decodeResultDNSRewriteResultKey( // decoding and correct the values. err = dec.Decode(&ent.Result.DNSRewriteResult.Response) if err != nil { - l.logger.DebugContext( - ctx, - "decodeResultDNSRewriteResultKey response", - slogutil.KeyError, err, - ) + l.logger.DebugContext(ctx, msgPrefix+"; response", slogutil.KeyError, err) } ent.parseDNSRewriteResultIPs() @@ -472,11 +477,13 @@ func (l *queryLog) decodeResultDNSRewriteResult( dec *json.Decoder, ent *logEntry, ) { + const msgPrefix = "decoding result dns rewrite result" + for { key, err := parseKeyToken(dec) if err != nil { if err != io.EOF && !errors.Is(err, ErrEndOfToken) { - l.logger.DebugContext(ctx, "decodeResultDNSRewriteResult", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -550,13 +557,15 @@ func parseKeyToken(dec *json.Decoder) (key string, err error) { // decodeResult decodes a token of "Result" type to logEntry struct. func (l *queryLog) decodeResult(ctx context.Context, dec *json.Decoder, ent *logEntry) { + const msgPrefix = "decoding result" + defer translateResult(ent) for { key, err := parseKeyToken(dec) if err != nil { if err != io.EOF && !errors.Is(err, ErrEndOfToken) { - l.logger.DebugContext(ctx, "decodeResult", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -582,7 +591,7 @@ func (l *queryLog) decodeResult(ctx context.Context, dec *json.Decoder, ent *log } if err = handler(val, ent); err != nil { - l.logger.DebugContext(ctx, "decodeResult handler", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; handler", slogutil.KeyError, err) return } @@ -701,6 +710,8 @@ func (l *queryLog) resultDecHandler( // decodeLogEntry decodes string str to logEntry ent. func (l *queryLog) decodeLogEntry(ctx context.Context, ent *logEntry, str string) { + const msgPrefix = "decoding log entry" + dec := json.NewDecoder(strings.NewReader(str)) dec.UseNumber() @@ -708,7 +719,7 @@ func (l *queryLog) decodeLogEntry(ctx context.Context, ent *logEntry, str string keyToken, err := dec.Token() if err != nil { if err != io.EOF { - l.logger.DebugContext(ctx, "decodeLogEntry err", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; token", slogutil.KeyError, err) } return @@ -720,8 +731,8 @@ func (l *queryLog) decodeLogEntry(ctx context.Context, ent *logEntry, str string key, ok := keyToken.(string) if !ok { - err = fmt.Errorf("decodeLogEntry: keyToken is %T (%[1]v) and not string", keyToken) - l.logger.DebugContext(ctx, "decodeLogEntry", slogutil.KeyError, err) + err = fmt.Errorf("%s: keyToken is %T (%[2]v) and not string", msgPrefix, keyToken) + l.logger.DebugContext(ctx, msgPrefix, slogutil.KeyError, err) return } @@ -743,7 +754,7 @@ func (l *queryLog) decodeLogEntry(ctx context.Context, ent *logEntry, str string } if err = handler(val, ent); err != nil { - l.logger.DebugContext(ctx, "decodeLogEntry handler", slogutil.KeyError, err) + l.logger.DebugContext(ctx, msgPrefix+"; handler", slogutil.KeyError, err) return } diff --git a/internal/querylog/decode_test.go b/internal/querylog/decode_test.go index f4a2e5cf..8344479f 100644 --- a/internal/querylog/decode_test.go +++ b/internal/querylog/decode_test.go @@ -121,11 +121,11 @@ func TestDecodeLogEntry(t *testing.T) { }, { name: "bad_filter_id_old_rule", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3,"FilterID":1.5},"Elapsed":837429}`, - want: `level=DEBUG msg="decodeResult handler" err="strconv.ParseInt: parsing \"1.5\": invalid syntax"`, + want: `level=DEBUG msg="decoding result; handler" err="strconv.ParseInt: parsing \"1.5\": invalid syntax"`, }, { name: "bad_is_filtered", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":trooe,"Reason":3},"Elapsed":837429}`, - want: `level=DEBUG msg="decodeLogEntry err" err="invalid character 'o' in literal true (expecting 'u')"`, + want: `level=DEBUG msg="decoding log entry; token" err="invalid character 'o' in literal true (expecting 'u')"`, }, { name: "bad_elapsed", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3},"Elapsed":-1}`, @@ -137,7 +137,7 @@ func TestDecodeLogEntry(t *testing.T) { }, { name: "bad_time", log: `{"IP":"127.0.0.1","T":"12/09/1998T15:00:00.000000+05:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3},"Elapsed":837429}`, - want: `level=DEBUG msg="decodeLogEntry handler" err="parsing time \"12/09/1998T15:00:00.000000+05:00\" as \"2006-01-02T15:04:05Z07:00\": cannot parse \"12/09/1998T15:00:00.000000+05:00\" as \"2006\""`, + want: `level=DEBUG msg="decoding log entry; handler" err="parsing time \"12/09/1998T15:00:00.000000+05:00\" as \"2006-01-02T15:04:05Z07:00\": cannot parse \"12/09/1998T15:00:00.000000+05:00\" as \"2006\""`, }, { name: "bad_host", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":6,"QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3},"Elapsed":837429}`, @@ -157,7 +157,7 @@ func TestDecodeLogEntry(t *testing.T) { }, { name: "very_bad_client_proto", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"dog","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3},"Elapsed":837429}`, - want: `level=DEBUG msg="decodeLogEntry handler" err="invalid client proto: \"dog\""`, + want: `level=DEBUG msg="decoding log entry; handler" err="invalid client proto: \"dog\""`, }, { name: "bad_answer", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":0.9,"Result":{"IsFiltered":true,"Reason":3},"Elapsed":837429}`, @@ -165,7 +165,7 @@ func TestDecodeLogEntry(t *testing.T) { }, { name: "very_bad_answer", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3},"Elapsed":837429}`, - want: `level=DEBUG msg="decodeLogEntry handler" err="illegal base64 data at input byte 61"`, + want: `level=DEBUG msg="decoding log entry; handler" err="illegal base64 data at input byte 61"`, }, { name: "bad_rule", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3,"Rule":false},"Elapsed":837429}`, @@ -177,11 +177,11 @@ func TestDecodeLogEntry(t *testing.T) { }, { name: "bad_reverse_hosts", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3,"ReverseHosts":[{}]},"Elapsed":837429}`, - want: `level=DEBUG msg=decodeResultReverseHosts err="unexpected delimiter: \"{\""`, + want: `level=DEBUG msg="decoding result reverse hosts" err="unexpected delimiter: \"{\""`, }, { name: "bad_ip_list", log: `{"IP":"127.0.0.1","T":"2020-11-25T18:55:56.519796+03:00","QH":"an.yandex.ru","QT":"A","QC":"IN","CP":"","Answer":"Qz+BgAABAAEAAAAAAmFuBnlhbmRleAJydQAAAQABwAwAAQABAAAACgAEAAAAAA==","Result":{"IsFiltered":true,"Reason":3,"ReverseHosts":["example.net"],"IPList":[{}]},"Elapsed":837429}`, - want: `level=DEBUG msg=decodeResultIPList err="unexpected delimiter: \"{\""`, + want: `level=DEBUG msg="decoding result ip list" err="unexpected delimiter: \"{\""`, }} for _, tc := range testCases { diff --git a/internal/querylog/search.go b/internal/querylog/search.go index 4a066887..153d81a4 100644 --- a/internal/querylog/search.go +++ b/internal/querylog/search.go @@ -75,7 +75,7 @@ func (l *queryLog) searchMemory( l.logger.ErrorContext( ctx, "enriching memory record", - "time", e.Time, + "at", e.Time, "client_ip", e.IP, "client_id", e.ClientID, slogutil.KeyError, err,