resolver: less debug #2475
resolver: less debug #2475
Conversation
kolyshkin
force-pushed
the
resolver-debug
branch
2 times, most recently
from
8b72ab8
to
999e703
Compare
| @@ -452,9 +449,6 @@ func (r *resolver) ServeDNS(w dns.ResponseWriter, query *dns.Msg) { | |||
| logrus.Warnf("[resolver] connect failed: %s", err) | |||
| continue | |||
| } | |||
| queryType := dns.TypeToString[query.Question[0].Qtype] | |||
| logrus.Debugf("[resolver] query %s (%s) from %s, forwarding to %s:%s", name, queryType, | |||
| extConn.LocalAddr().String(), proto, extDNS.IPStr) | |||
There was a problem hiding this comment.
Wondering if we still have some debugging about this case (I know this has sometimes been useful when debugging if requests are actually forwarded, and if so, to which DNS)
There was a problem hiding this comment.
Well, tcpdump for the rescue.
| r.backend.HandleQueryResp(h.Name, ip) | ||
| } | ||
| } | ||
| if resp.Answer == nil || answers == 0 { | ||
| logrus.Debugf("[resolver] external DNS %s:%s did not return any %s records for %q", proto, extDNS.IPStr, queryType, name) |
Lack of caching is an issue, too, but I think it's entirely separate one (also much more complicated) |
|
@kolyshkin is there a way to ratelimit these logs |
Doesn't seem like logrus implements it out of the box, but could possibly be implemented; sirupsen/logrus#560 sirupsen/logrus#304 |
@arkodg in fact some logs are already rate-limited; see #1062. But in this case it does not make sense to rate-limit the logs, since every line provide different information (different names or IPs), so if you try to rate-limit, you'll end up seeing only some of them, which does not make sense. IOW, it makes sense to rate-limit a warning message like Or maybe I don't quite understand your proposal; can you elaborate? |
|
@kolyshkin I'm just very reluctant to delete these logs Can we add a compile time parameter / global |
@arkodg I don't see any value in logging every DNS request (and I guess most of this info is easy to obtain using tcpdump/wireshark).
Yes but IMHO this will look ugly. OK let me try it. |
Observed lots of debug messages from resolver (and associated high CPU usage because of lots of logging) when debug logging is turned on. Here is some data from a real system: > $ journalctl -u docker --since="2019-10-21 21:00:00" --until="2019-10-21 22:00:00" | wc -l > 188621 > $ journalctl -u docker --since="2019-10-21 21:00:00" --until="2019-10-21 22:00:00" | grep -E 'Name To resolve: |\[resolver\] ' | wc -l > 186319 So, it was about 200000 lines logger for just one hour, and about 99% of that are from resolver. While this might be the peculiarity of a particular setup, the number of such messages still seem way too excessive. Remove the ones that are not errors. In case those are needed, one have to recompile this package with debug_log build tag. Signed-off-by: Kir Kolyshkin <[email protected]>
Use more `debugf` in places that look definitely like developer's debug which is most probably useless to an end user. Promote some debug errors that looks more like warnings to use Warnf rather than Debugf. Signed-off-by: Kir Kolyshkin <[email protected]>
kolyshkin
force-pushed
the
resolver-debug
branch
from
999e703
to
0f20b88
Compare
|
@arkodg I have modified this PR according to your comments; please take another look |
|
@arkodg PTAL |
|
Note we have migrated this codebase over to github.com/moby/moby/libnetwork. |
Observed lots of debug messages from resolver (and associated high CPU
usage, part of which was because of excessive logging) when debug logging
is turned on. Here is some data from a real system:
So, it was almost 200000 lines logger for just one hour, and about 99% of that
are from resolver. While this might be the peculiarity of a particular setup,
the number of such messages still seem way too excessive.
Remove the ones that appear very often and are not errors.