Commit Graph

37 Commits (4f05cf685e51ebedbdf3c3978bfec2da60a59acb)

Author SHA1 Message Date
Brad Fitzpatrick ecc1d6907b types/logger: add TestLogger
We have this in another repo and I wanted it here too.

Updates #cleanup

Change-Id: If93dc73f11eaaada5024acf2a885a153b88db5a0
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
1 year ago
Brad Fitzpatrick 590c693b96 types/logger: add AsJSON
Printing out JSON representation things in log output is pretty common.

Updates #cleanup

Change-Id: Ife2d2e321a18e6e1185efa8b699a23061ac5e5a4
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
1 year ago
Andrew Dunham d1146dc701 ipn/ipnlocal: rate-limit diagnose logs in bugreport
We can log too quickly for logtail to catch up, even when we opt out of
log rate-limiting. When the user passes the --diagnose flag to
bugreport, we use a token bucket to control how many logs per second are
printed and sleep until we're able to write more.

Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
Change-Id: If27672d66b621b589280bd0fe228de367ffcbd8f
2 years ago
Will Norris 71029cea2d all: update copyright and license headers
This updates all source files to use a new standard header for copyright
and license declaration.  Notably, copyright no longer includes a date,
and we now use the standard SPDX-License-Identifier header.

This commit was done almost entirely mechanically with perl, and then
some minimal manual fixes.

Updates #6865

Signed-off-by: Will Norris <will@tailscale.com>
2 years ago
Andrew Dunham b1867457a6
doctor: add package for running in-depth healthchecks; use in bugreport (#5413)
Change-Id: Iaa4e5b021a545447f319cfe8b3da2bd3e5e5782b
Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
2 years ago
Eng Zer Jun f0347e841f refactor: move from io/ioutil to io and os packages
The io/ioutil package has been deprecated as of Go 1.16 [1]. This commit
replaces the existing io/ioutil functions with their new definitions in
io and os packages.

Reference: https://golang.org/doc/go1.16#ioutil
Signed-off-by: Eng Zer Jun <engzerjun@gmail.com>
2 years ago
Brad Fitzpatrick 74674b110d envknob: support changing envknobs post-init
Updates #5114

Change-Id: Ia423fc7486e1b3f3180a26308278be0086fae49b
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Josh Bleecher Snyder 0868329936 all: use any instead of interface{}
My favorite part of generics.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
Josh Bleecher Snyder 66f5aa6814 types/logger: add more reserved top level field names
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
Brad Fitzpatrick 84138450a4 types/logger, logtail: add mechanism to do structured JSON logs
e.g. the change to ipnlocal in this commit ultimately logs out:

{"logtail":{"client_time":"2022-02-17T20:40:30.511381153-08:00","server_time":"2022-02-18T04:40:31.057771504Z"},"type":"Hostinfo","val":{"GoArch":"amd64","Hostname":"tsdev","IPNVersion":"1.21.0-date.20220107","OS":"linux","OSVersion":"Debian 11.2 (bullseye); kernel=5.10.0-10-amd64"},"v":1}

Change-Id: I668646b19aeae4a2fed05170d7b279456829c844
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 years ago
Brad Fitzpatrick 41fd4eab5c envknob: add new package for all the strconv.ParseBool(os.Getenv(..))
A new package can also later record/report which knobs are checked and
set. It also makes the code cleaner & easier to grep for env knobs.

Change-Id: Id8a123ab7539f1fadbd27e0cbeac79c2e4f09751
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 years ago
Josh Bleecher Snyder deb2f5e793 types/logger: add Context and related helpers
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>
3 years ago
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