Commit Graph

45 Commits (5e9e57ecf531f26692413ecddebfa6172550dd44)

Author SHA1 Message Date
Brad Fitzpatrick a04f1ff9e6 logtail: default to 2s log flush delay on all platforms
Per chat. This is close enough to realtime but massively reduces
number of HTTP requests. (which you can verify with
TS_DEBUG_LOGTAIL_WAKES and watching tailscaled run at start)

By contrast, this is set to 2 minutes on mobile.

Change-Id: Id737c7924d452de5c446df3961f5e94a43a33f1f
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Brad Fitzpatrick a315336287 logtail: change batched upload mechanism to not use CPU when idle
The mobile implementation had a 2 minute ticker going all the time
to do a channel send. Instead, schedule it as needed based on activity.

Then we can be actually idle for long periods of time.

Updates #3363

Change-Id: I0dba4150ea7b94f74382fbd10db54a82f7ef6c29
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Joe Tsai 3af0d4d0f2
logtail: always record timestamps in UTC (#5732)
Upstream optimizations to the Go time package will make
unmarshaling of time.Time 3-6x faster. See:
* https://go.dev/cl/425116
* https://go.dev/cl/425197
* https://go.dev/cl/429862

The last optimization avoids a []byte -> string allocation
if the timestamp string less than than 32B.
Unfortunately, the presence of a timezone breaks that optimization.
Drop recording of timezone as this is non-essential information.

Most of the performance gains is upon unmarshal,
but there is also a slight performance benefit to
not marshaling the timezone as well.

Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2 years ago
Joe Tsai c321363d2c
logtail: support a copy ID (#5851)
The copy ID operates similar to a CC in email where
a message is sent to both the primary ID and also the copy ID.
A given log message is uploaded once, but the log server
records it twice for each ID.

Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2 years ago
Josh Soref d4811f11a0 all: fix spelling mistakes
Signed-off-by: Josh Soref <2119212+jsoref@users.noreply.github.com>
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
Joe Tsai 21cd402204
logtail: do not log when backing off (#5485) 2 years ago
Brad Fitzpatrick 4950fe60bd syncs, all: move to using Go's new atomic types instead of ours
Fixes #5185

Change-Id: I850dd532559af78c3895e2924f8237ccc328449d
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Brad Fitzpatrick 5381437664 logtail, net/portmapper, wgengine/magicsock: use fmt.Appendf
Fixes #5206

Change-Id: I490bb92e774ce7c044040537e2cd864fcf1dbe5a
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Brad Fitzpatrick 48e73e147a logtail,logpolicy: tweak minor cosmetic things
Just reading the code again in prep for some alloc reductions.

Change-Id: I065226ea794b7ec7144c2b15942d35131c9313a8
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
2 years ago
Brad Fitzpatrick 02e580c1d2 logtail: use http.NewRequestWithContext
Saves some allocs. Not hot, but because we can now.

And a const instead of a var.

Change-Id: Ieb2b64534ed38051c36b2c0aa2e82739d9d0e015
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 years ago
Mihai Parparita 3222bce02d logtail: add instance metadata to the entry logtail
Allows instances that are running with the same machine ID (due to
cloning) to be distinguished.

Also adds sequence numbers to detect duplicates.

For tailscale/corp#5244

Signed-off-by: Mihai Parparita <mihai@tailscale.com>
3 years ago
Brad Fitzpatrick 9f1dd716e8 tailcfg, logtail: provide Debug bit to disable logtail
For people running self-hosted control planes who want a global
opt-out knob instead of running their own logcatcher.

Change-Id: I7f996c09f45850ff77b58bfd5a535e197971725a
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 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
Brad Fitzpatrick 5f529d1359 logtail: add Logger.PrivateID accessor
For the control plane to use.

Change-Id: I0f02321fc4fa3a41c3ece3b51eee729ea9770905
Signed-off-by: Brad Fitzpatrick <bradfitz@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 5d9ab502f3 logtail: don't strip verbose level on upload
For analysis of log spam.

Bandwidth is ~unchanged from had we not stripped the "[vN] " from
text; it just gets restructed intot he new "v":N, field.  I guess it
adds one byte.

Updates #1548

Change-Id: Ie00a4e0d511066a33d10dc38d765d92b0b044697
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 years ago
Josh Bleecher Snyder 9fe5ece833 logtail: cap the buffer size in encodeText
This started as an attempt to placate GitHub's code scanner,
but it's also probably generally a good idea.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
Brad Fitzpatrick 40e2b312b6 ipn/ipnserver, logpolicy: move Windows disk logging up earlier
This moves the Windows-only initialization of the filelogger into
logpolicy. Previously we only did it when babysitting the tailscaled
subprocess, but this meant that log messages from the service itself
never made it to disk. Examples that weren't logged to disk:

* logtail unable to dial out,
* DNS flush messages from the service
* svc.ChangeRequest messages (#3581)

This is basically the same fix as #3571 but staying in the Logf type,
and avoiding build-tagged file (which wasn't quite a goal, but
happened and seemed nice)

Fixes #3570

Co-authored-by: Aaron Klotz <aaron@tailscale.com>
Change-Id: Iacd80c4720b7218365ec80ae143339d030842702
3 years ago
Brad Fitzpatrick 3b541c833e util/clientmetric, logtail: log metric changes
Updates #3307

Change-Id: I1399ebd786f6ff7defe6e11c0eb651144c071574
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
3 years ago
Josh Bleecher Snyder 0c038b477f logtail: add a re-usable buffer for uploads
This avoids a per-upload alloc (which in practice
often means per-log-line), up to 4k.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
Josh Bleecher Snyder 278e7de9c9 logtail: always send a json array
The code goes to some effort to send a single JSON object
when there's only a single line and a JSON array when there
are multiple lines.

It makes the code more complex and more expensive;
when we add a second line, we have to use a second buffer
to duplicate the first one after adding a leading square brackets.

The savings come to two bytes. Instead, always send an array.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
Josh Bleecher Snyder 0373ba36f3 logtail: fix typo in comment
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
3 years ago
David Crawshaw 1606ef5219 logtail: print panics from previous runs on stderr
Signed-off-by: David Crawshaw <crawshaw@tailscale.com>
3 years ago
Josh Bleecher Snyder bb8ce48a6b logtail: allow changing log level concurrently
When tailscaled starts up, these lines run:

func run() error {
	// ...
	pol := logpolicy.New("tailnode.log.tailscale.io")
	pol.SetVerbosityLevel(args.verbose)
	// ...
}

If there are old log entries present, they immediate start getting uploaded. This races with the call to pol.SetVerbosityLevel.

This manifested itself as a test failure in tailscale.com/tstest/integration
when run with -race:

WARNING: DATA RACE
Read at 0x00c0001bc970 by goroutine 24:
  tailscale.com/logtail.(*Logger).Write()
      /Users/josh/t/corp/oss/logtail/logtail.go:517 +0x27c
  log.(*Logger).Output()
      /Users/josh/go/ts/src/log/log.go:184 +0x2b8
  log.Printf()
      /Users/josh/go/ts/src/log/log.go:323 +0x94
  tailscale.com/logpolicy.newLogtailTransport.func1()
      /Users/josh/t/corp/oss/logpolicy/logpolicy.go:509 +0x36c
  net/http.(*Transport).dial()
      /Users/josh/go/ts/src/net/http/transport.go:1168 +0x238
  net/http.(*Transport).dialConn()
      /Users/josh/go/ts/src/net/http/transport.go:1606 +0x21d0
  net/http.(*Transport).dialConnFor()
      /Users/josh/go/ts/src/net/http/transport.go:1448 +0xe4

Previous write at 0x00c0001bc970 by main goroutine:
  tailscale.com/logtail.(*Logger).SetVerbosityLevel()
      /Users/josh/t/corp/oss/logtail/logtail.go:131 +0x98
  tailscale.com/logpolicy.(*Policy).SetVerbosityLevel()
      /Users/josh/t/corp/oss/logpolicy/logpolicy.go:463 +0x60
  main.run()
      /Users/josh/t/corp/oss/cmd/tailscaled/tailscaled.go:178 +0x50
  main.main()
      /Users/josh/t/corp/oss/cmd/tailscaled/tailscaled.go:163 +0x71c

Goroutine 24 (running) created at:
  net/http.(*Transport).queueForDial()
      /Users/josh/go/ts/src/net/http/transport.go:1417 +0x4d8
  net/http.(*Transport).getConn()
      /Users/josh/go/ts/src/net/http/transport.go:1371 +0x5b8
  net/http.(*Transport).roundTrip()
      /Users/josh/go/ts/src/net/http/transport.go:585 +0x7f4
  net/http.(*Transport).RoundTrip()
      /Users/josh/go/ts/src/net/http/roundtrip.go:17 +0x30
  net/http.send()
      /Users/josh/go/ts/src/net/http/client.go:251 +0x4f0
  net/http.(*Client).send()
      /Users/josh/go/ts/src/net/http/client.go:175 +0x148
  net/http.(*Client).do()
      /Users/josh/go/ts/src/net/http/client.go:717 +0x1d0
  net/http.(*Client).Do()
      /Users/josh/go/ts/src/net/http/client.go:585 +0x358
  tailscale.com/logtail.(*Logger).upload()
      /Users/josh/t/corp/oss/logtail/logtail.go:367 +0x334
  tailscale.com/logtail.(*Logger).uploading()
      /Users/josh/t/corp/oss/logtail/logtail.go:289 +0xec


Rather than complicate the logpolicy API,
allow the verbosity to be adjusted concurrently.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
4 years ago
Brad Fitzpatrick b4cf837d8a logtail: use link monitor to determine when to retry after upload failure
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
4 years ago
Brad Fitzpatrick c0cdca6d06 cmd/tailscaled, logtail: share link monitor from wgengine to logtail
Part of overall effort to clean up, unify, use link monitoring more,
and make Tailscale quieter when all networks are down. This is especially
bad on macOS where we can get killed for not being polite it seems.
(But we should be polite in any case)

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
4 years ago
Brad Fitzpatrick 57dd247376 cmd/tailscaled, logpolicy, logtail: support log levels
Log levels can now be specified with "[v1] " or "[v2] " substrings
that are then stripped and filtered at the final logger. This follows
our existing "[unexpected]" etc convention and doesn't require a
wholesale reworking of our logging at the moment.

cmd/tailscaled then gets a new --verbose=N flag to take a log level
that controls what gets logged to stderr (and thus systemd, syslog,
etc). Logtail is unaffected by --verbose.

This commit doesn't add annotations to any existing log prints. That
is in the next commit.

Updates #924
Updates #282

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
4 years ago
Brad Fitzpatrick d97ee12179 logtail, logpolicy: remove an unidiomatic use of an interface 4 years ago
Josh Bleecher Snyder 3a7402aa2d logtail: help the server be more efficient
Add content length hints to headers.
The server can use these hints to more efficiently select buffers.

Stop attempting to compress tiny requests.
The bandwidth savings are negligible (and sometimes negative!),
and it makes extra work for the server.

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
4 years ago
Josh Bleecher Snyder 883a11f2a8 logtail: fix typo in comment
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
4 years ago
Brad Fitzpatrick dd97111d06 backoff: update to Go style, document a bit, make 30s explicit
Also, bit of behavior change: on non-nil err but expired context,
don't reset the consecutive failure count. I don't think the old
behavior was intentional.

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
4 years ago
Elias Naur bca9fe35ba logtail: return correct write size from logger.Write
Signed-off-by: Elias Naur <mail@eliasnaur.com>
4 years ago
Avery Pennarun 6f590f5b52 logtail: we missed a case for the backoff timer.
We want to run bo.Backoff() after every upload, regardless. If
upload==true but err!=nil, we weren't backing off, which caused some
very-high-throughput log upload retries in bad network conditions.

Updates #282.

Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
5 years ago
Avery Pennarun 08acb502e5 Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.

This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.

To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.

Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
5 years ago
Brad Fitzpatrick c726c1eec9 logtail: add const DefaultHost with default server name 5 years ago
Brad Fitzpatrick 996bf9cae7 logtail: don't send a User-Agent
Just useless bytes on the wire. Especially with HTTP/1.

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago
Brad Fitzpatrick e71a7c7a2c logtail: read to EOF on chunked response
We'll be fixing the server so this won't trigger in practice,
but it demos the connection reuse problem.

Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago
Brad Fitzpatrick fcb6a34f4b logtail: reduce allocations encoding text
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
5 years ago
David Crawshaw 6ddbcab71e logtail: rename the unused CheckLogs to DrainLogs
Its semantics has changed slightly, this will let us use it to
drive batched logging in special circumstances.

Signed-off-by: David Crawshaw <crawshaw@tailscale.com>
5 years ago
Brad Fitzpatrick 8f9fa6a842 logtail: minor style/simplification changes 5 years ago
David Anderson 8380d8575a logtail: remove unused code from old sentinel logic.
Signed-off-by: David Anderson <dave@natulte.net>
5 years ago
David Anderson be6bcd59cd logtail: don't pass in nil contexts.
Signed-off-by: David Anderson <dave@natulte.net>
5 years ago
David Anderson 250dfc9016 logtail: remove unused struct fields.
Signed-off-by: David Anderson <dave@natulte.net>
5 years ago
Earl Lee a8d8b8719a Move Linux client & common packages into a public repo. 5 years ago