We log lines like this:
c.logf("[v1] magicsock: disco: %v->%v (%v, %v) sent %v", c.discoShort, dstDisco.ShortString(), dstKey.ShortString(), derpStr(dst.String()), disco.MessageSummary(m))
The leading [v1] causes it to get unintentionally rate limited.
Until we have a proper fix, work around it.
Fixes#1216
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
(cherry picked from commit 1e28207a15)
Here's an example log line in the new format:
[RATE LIMITED] format string "open-conn-track: timeout opening %v; no associated peer node" (example: "open-conn-track: timeout opening ([ip] => [ip]); no associated peer node")
This should make debugging logging issues a bit easier, and give more
context as to why something was rate limited. This change was proposed
in a comment on #1110.
Signed-off-by: Smitty <me@smitop.com>
The log lines that wireguard-go prints as it starts
and stops its worker routines are mostly noise.
They also happen after other work is completed,
which causes failures in some of the log testing packages.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This caused some confusion in issue #460, since usually raw format
strings aren't printed directly. Hopefully by directly logging that
they are intended to be raw format strings, this will be more clear.
Rate limited format strings now look like:
[RATE LIMITED] format string "control: sendStatus: %s: %v"
Closes#460.
Signed-off-by: Smitty <me@smitop.com>
The RusagePrefixLog is rarely useful, hasn't been useful in a long
time, is rarely the measurement we need, and is pretty spammy (and
syscall-heavy). Disable it by default. We can enable it when we're
debugging memory.
- Reformat the warning about a message being rate limited to print the
format string, rather than the formatted message. This helps give a
clue what "type" of message is being limited.
- Change the rate limit warning to be [RATE LIMITED] in all caps. This
uses less space on each line, plus is more noticeable.
- In tailscaled, change the frequency to be less often (once every 5
seconds per format string) but to allow bursts of up to 5 messages.
This greatly reduces the number of messages that are rate limited
during startup, but allows us to tighten the limit even further during
normal runtime.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
Also stop logging data sent/received from nodes we're not connected to (ie all those `x`s being logged in the `peers: ` line)
Signed-off-by: Wendi <wendi.yu@yahoo.ca>
Implement rate limiting on log messages
Addresses issue #317, where logs can get spammed with the same message
nonstop. Created a rate limiting closure on logging functions, which
limits the number of messages being logged per second based on format
string. To keep memory usage as constant as possible, the previous cache
purging at periodic time intervals has been replaced by an LRU that
discards the oldest string when the capacity of the cache is reached.
Signed-off-by: Wendi Yu <wendi.yu@yahoo.ca>
