Commit Graph

25 Commits (6d43cbc32517660cf9f4a08c1e8574c411452c63)

Author SHA1 Message Date
Brad Fitzpatrick 8a4dffee07 types/logger: fix deadlock RateLimitedFn reentrancy
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>
3 years ago
Josh Bleecher Snyder 78d4c561b5 types/logger: add key grinder stats lines to rate-limiting exemption list
Updates #1749

Co-authored-by: Brad Fitzpatrick <bradfitz@tailscale.com>
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
4 years ago
Josh Bleecher Snyder f116a4c44f types/logger: fix rate limiter allowlist
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>
4 years ago
Avery Pennarun 19c3e6cc9e types/logger: rate limited: more hysteresis, better messages.
- 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>
4 years ago
Josh Bleecher Snyder 1e28207a15 types/logger: fix rateFree interaction with verbosity prefixes
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>
4 years ago
David Anderson 78338ac029 types/logger: trim spaces from the rate-limited example message.
Signed-off-by: David Anderson <danderson@tailscale.com>
4 years ago
Josh Bleecher Snyder 2d837f79dc wgengine/magicsock: close test loggers once we're done with them
This is a big hammer approach to helping with #1132.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
4 years ago
Smitty 2bf49ddf90 Provide example when format string is rate limited
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>
4 years ago
Josh Bleecher Snyder 1e4604f60e wgengine: quiet some wireguard-go logging
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>
4 years ago
Smitty f0b0a62873 Clarify that raw format strings are intentional
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>
4 years ago
Brad Fitzpatrick 8b904b1493 types/logger: fix LogOnChange to pass through format/args to underlying logger
So they don't get interpretted as a format pattern or get rate-limited away
in the wrong way.
4 years ago
Brad Fitzpatrick 0ea51872c9 types/logger: add rateFreePrefix rate-limiting-exempt log format prefixes
Per conversation with @danderson.
4 years ago
Dmytro Shynkevych c12d87c54b
Fix concurrency issues in controlclient, ipn, types/logger (#456)
Signed-Off-By: Dmytro Shynkevych <dmytro@tailscale.com>
5 years ago
Brad Fitzpatrick dd6b96ba68 types/logger: add TS_DEBUG_LOG_RATE knob to easily turn off rate limiting 5 years ago
Avery Pennarun af9328c1b7 log rate limiting: reformat limiter messages, and use nonempty burst size.
- 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>
5 years ago
Wendi Yu bb55694c95
wgengine: log node IDs when peers are added/removed (#381)
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>
5 years ago
Brad Fitzpatrick fe97bedf67 types/logger: add ArgWriter 5 years ago
Brad Fitzpatrick 8eda667aa1 types/logger: simplify mutex locking in rate-limited logger
Updates #365

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago
David Anderson 48b1e85e8a types/logger: fix deadlock in the burst case.
Fixes #365.

Signed-off-by: David Anderson <danderson@tailscale.com>
5 years ago
Wendi Yu 0c69b4e00d
Implement rate limiting on log messages (#356)
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>
5 years ago
Brad Fitzpatrick 45f2b53aca all: remove unnecessary trailing newlines in format patterns for consistency
And document on logger.Logf that it's unnecessary.
5 years ago
David Anderson 96b2f20c5b types/logger: add Discard helper. 5 years ago
Brad Fitzpatrick 946df89fa6 types/logger: add adapters for Logf to std Logger/Writer 5 years ago
Brad Fitzpatrick 3988ddc85d types/logger: add WithPrefix, use it in two places
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago
Brad Fitzpatrick 2896be60db Move "logger" package to under types, now that we have it.
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago