We often need both a log function and a context.
We can do this by adding the log function as a context value.
This commit adds helper glue to make that easy.
It is designed to allow incremental adoption.
Updates tailscale/corp#3138
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Fix regression from 19c3e6cc9e
which made the locking coarser.
Found while debugging #2245, which ended up looking like a tswin/Windows
issue where Crawshaw had blocked cmd.exe's output.
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
Upstream wireguard-go renamed the interface method
from CreateEndpoint to ParseEndpoint.
I updated the log call site but not the allowlist.
Signed-off-by: Josh Bleecher Snyder <josharian@gmail.com>
- Switch to our own simpler token bucket, since x/time/rate is missing
necessary stuff (can't provide your own time func; can't check the
current bucket contents) and it's overkill anyway.
- Add tests that actually include advancing time.
- Don't remove the rate limit on a message until there's enough room to
print at least two more of them. When we do, we'll also print how
many we dropped, as a contextual reminder that some were previously
lost. (This is more like how the Linux kernel does it.)
- Reformat the [RATE LIMITED] messages to be shorter, and to not
corrupt original message. Instead, we print the message, then print
its format string.
- Use %q instead of \"%s\", for more accurate parsing later, if the
format string contained quotes.
Fixes#1772
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
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>
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>
