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>
The block-write and block-read tests are both flaky,
because each assumes it can get a normal read/write
completed within 10ms. This isn’t always true.
We can’t increase the timeouts, because that slows down the test.
However, we don’t need to issue a regular read/write for this test.
The immediately preceding tests already test this code,
using a far more generous timeout.
Remove the extraneous read/write.
This drops the failure rate from 1 per 20,000 to undetectable
on my machine.
While we’re here, fix a typo in a debug print statement.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Without the continue, we might overwrite our current meta
with a zero meta.
Log the error, so that we can check for anything unexpected.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Currently, comments in resolv.conf cause our parser to fail,
with error messages like:
ParseIP("192.168.0.100 # comment"): unexpected character (at " # comment")
Fix that.
Noticed while looking through logs.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
We were missing an argument here.
Also, switch to %q, in case anything weird
is happening with these strings.
Updates tailscale/corp#461
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
When this happens, it is incredibly noisy in the logs.
It accounts for about a third of all remaining
"unexpected" log lines from a recent investigation.
It's not clear that we know how to fix this,
we have a functioning workaround,
and we now have a (cheap and efficient) metric for this
that we can use for measurements.
So reduce the logging to approximately once per minute.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This limits the output to a single IP address.
RELNOTE=tailscale ip now has a -1 flag (TODO: update docs to use it)
Fixes#1921
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
One of the most common "unexpected" log lines is:
"network state changed, but stringification didn't"
One way that this can occur is if an interesting interface
(non-Tailscale, has interesting IP address)
gains or loses an uninteresting IP address (link local or loopback).
The fact that the interface is interesting is enough for EqualFiltered
to inspect it. The fact that an IP address changed is enough for
EqualFiltered to declare that the interfaces are not equal.
But the State.String method reasonably declines to print any
uninteresting IP addresses. As a result, the network state appears
to have changed, but the stringification did not.
The String method is correct; nothing interesting happened.
This change fixes this by adding an IP address filter to EqualFiltered
in addition to the interface filter. This lets the network monitor
ignore the addition/removal of uninteresting IP addresses.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Linux-only for now, to avoid having to figure out why
powershell doesn't like my shell scripting. (Not that I blame it.)
That'll be enough to catch most regressions.
Fixes#1083
Co-authored-by: Aaron Klotz <aaron@tailscale.com>
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The Windows BOOL type is an int32. We were using a bool,
which is a one byte wide. This could be responsible for the
ERROR_INVALID_PARAMETER errors we were seeing for calls to
WinHttpGetProxyForUrl.
We manually checked all other existing Windows syscalls
for similar mistakes and did not find any.
Updates #879
Co-authored-by: Aaron Klotz <aaron@tailscale.com>
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
There are lots of lines in the logs of the form:
portmapper: unexpected PMP probe response: {OpCode:128 ResultCode:3
SecondsSinceEpoch:NNN MappingValidSeconds:0 InternalPort:0
ExternalPort:0 PublicAddr:0.0.0.0}
ResultCode 3 here means a network failure, e.g. the NAT box itself has
not obtained a DHCP lease. This is not an indication that something
is wrong in the Tailscale client, so use different wording here
to reflect that. Keep logging, so that we can analyze and debug
the reasons that PMP probes fail.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
In rare circumstances (tailscale/corp#3016), the PublicKey
and Endpoints can diverge.
This by itself doesn't cause any harm, but our early exit
in response did, because it prevented us from recovering from it.
Remove the early exit.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
endpoint.discoKey is protected by endpoint.mu.
endpoint.sendDiscoMessage was reading it without holding the lock.
This showed up in a CI failure and is readily reproducible locally.
The fix is in two parts.
First, for Conn.enqueueCallMeMaybe, eliminate the one-line helper method endpoint.sendDiscoMessage; call Conn.sendDiscoMessage directly.
This makes it more natural to read endpoint.discoKey in a context
in which endpoint.mu is already held.
Second, for endpoint.sendDiscoPing, explicitly pass the disco key
as an argument. Again, this makes it easier to read endpoint.discoKey
in a context in which endpoint.mu is already held.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
I believe that this should eliminate the flakiness.
If GitHub CI manages to be even slower that can be believed
(and I can believe a lot at this point),
then we should roll this back and make some more invasive changes.
Updates #654Fixes#3247 (I hope)
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
We can do the "maybe delete" check unilaterally:
In the case of an insert, both oldDiscoKey
and ep.discoKey will be the zero value.
And since we don't use pi again, we can skip
giving it a name, which makes scoping clearer.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
In DeviceConfig, we did not close r after calling FromUAPI.
If FromUAPI returned early due to an error, then it might
not have read all the data that IpcGetOperation wanted to write.
As a result, IpcGetOperation could hang, as in #3220.
We were also closing the wrong end of the pipe after IpcSetOperation
in ReconfigDevice.
To ensure that we get all available information to diagnose
such a situation, include all errors anytime something goes wrong.
This should fix the immediate crashing problem in #3220.
We'll then need to figure out why IpcGetOperation was failing.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
github.com/go-multierror/multierror served us well.
But we need a few feature from it (implement Is),
and it's not worth maintaining a fork of such a small module.
Instead, I did a clean room implementation inspired by its API.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
There are a few remaining uses of testing.AllocsPerRun:
Two in which we only log the number of allocations,
and one in which dynamically calculate the allocations
target based on a different AllocsPerRun run.
This also allows us to tighten the "no allocs"
test in wgengine/filter.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
testing.AllocsPerRun measures the total allocations performed
by the entire program while repeatedly executing a function f.
If some unrelated part of the rest of the program happens to
allocate a lot during that period, you end up with a test failure.
Ideally, the rest of the program would be silent while
testing.AllocsPerRun executes.
Realistically, that is often unachievable.
AllocsPerRun attempts to mitigate this by setting GOMAXPROCS to 1,
but that doesn't prevent other code from running;
it only makes it less likely.
You can also mitigate this by passing a large iteration count to
AllocsPerRun, but that is unreliable and needlessly expensive.
Unlike most of package testing, AllocsPerRun doesn't use any
toolchain magic, so we can just write a replacement.
One wild idea is to change how we count mallocs.
Instead of using runtime.MemStats, turn on memory profiling with a
memprofilerate of 1. Discard all samples from the profile whose stack
does not contain testing.AllocsPerRun. Count the remaining samples to
determine the number of mallocs.
That's fun, but overkill.
Instead, this change adds a simple API that attempts to get f to
run at least once with a target number of allocations.
This is useful when you know that f should allocate consistently.
We can then assume that any iterations with too many allocations
are probably due to one-time costs or background noise.
This suits most uses of AllocsPerRun.
Ratcheting tests tend to be significantly less flaky,
because they are biased towards success.
They can also be faster, because they can exit early,
once success has been reached.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The fully qualified name of the type is thisPkg.tname,
so write the args like that too.
Suggested-by: Joe Tsai <joetsai@digital-static.net>
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
And in the process, fix a bug:
The fmt formatting was being applied by writef,
not fmt.Sprintf, thus emitting a MISSING string.
And there's no guarantee that fmt will be imported
in the generated code.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Change from a single-case type switch to a type assertion
with an early return.
That exposes that the name arg to gen is unneeded.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This is a package for shared utilities used in doing codegen programs.
The inaugural API is for writing gofmt'd code to a file.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
LocalBackend.Shutdown's docs say:
> The backend can no longer be used after Shutdown returns.
Nevertheless, TestStateMachine blithely calls Shutdown, talks some smack,
and continues on, expecting things to work. Other uses of Shutdown
in the codebase are as intended.
Things mostly kinda work anyway, except that the wgengine.Engine has been
shut down, so calls to Reconfig fail. Those get logged:
> local.go:603: wgengine status error: engine closing; no status
but otherwise ignored.
However, the Reconfig failure caused one fewer call to pause/unpause
than normal. Now the assertCalls lines match the equivalent ones
earlier in the test.
I don't see an obvious correct replacement for Shutdown in the context
of this test; I'm not sure entirely what it is trying to accomplish.
It is possible that many of the tests remaining after the prior call
to Shutdown are now extraneous. They don't harm anything, though,
so err on the side of safety and leave them for now.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Use helpers and variadic functions to make the call sites
a lot easier to read, since they occur a lot.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Concurrent calls to LocalBackend.setWgengineStatus
could result in some of the status updates being dropped.
This was exacerbated by 92077ae78c,
which increases the probability of concurrent status updates,
causing test failures (tailscale/corp#2579).
It's going to take a bit of work to fix this test.
The ipnlocal state machine is difficult to reason about,
particularly in the face of concurrency.
We could fix the test trivially by throwing a new mutex around
setWgengineStatus to serialize calls to it,
but I'd like to at least try to do better than cosmetics.
In the meantime, commit the test.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
We don't want to force ourselves to update the DERP list
every time we want to cut a new release.
Having an outdated DERP list on release branches is OK.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Spelling out the command to run for every type
means that changing the command makes for a large, repetitive diff.
Stop doing that.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
These "weird" port lines show up in logs frequently.
They're the result of uninteresting races,
and they're not actionable. Remove the noise.
Remove the isLoopbackAddr case to placate staticcheck.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
On about 1 out of 500 runs, TestSendFreeze failed:
derp_test.go:416: bob: unexpected message type derp.PeerGoneMessage
Closing alice before bob created a race.
If bob closed promptly, the test passed.
If bob closed slowly, and alice's disappearance caused
bob to receive a PeerGoneMessage before closing, the test failed.
Deflake the test by closing bob first.
With this fix, the test passed 12,000 times locally.
Fixes#2668
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This is useful for manual performance testing
of networks with many nodes.
I imagine it'll grow more knobs over time.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The number of peers we have will be pretty stable across time.
Allocate roughly the right slice size.
This reduces memory usage when there are many peers.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Two optimizations.
Use values instead of pointers.
We were using pointers to make track the "peer in progress" easier.
It's not too hard to do it manually, though.
Make two passes through the data, so that we can size our
return value accurately from the beginning.
This is cheap enough compared to the allocation,
which grows linearly in the number of peers,
that it is worth doing.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The netmaps can get really large.
Printing, processing, and uploading them is expensive.
Only print the header on an ongoing basis.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The number of packet filters can grow very large,
so this log entry can be very large.
We can get the packet filter server-side,
so reduce verbosity here to just the number of filters present.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
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>
Scanning log lines is a frequent source of allocations.
Pre-allocate a re-usable buffer.
This still doesn't help when there are giant log lines.
Those will still be problematic from an iOS memory perspective.
For more on that, see https://github.com/tailscale/corp/issues/2423.
(For those who cannot follow that link, it is a discussion
of particular problematic types of log lines for
particular categories of customers. The "categories of customers"
part is the reason that it is a private issue.)
There is also a latent bug here. If we ever encounter
a log line longer than bufio.MaxScanTokenSize,
then bufio.Scan will return an error,
and we'll truncate the file and discard the rest of the log.
That's not good, but bufio.MaxScanTokenSize is really big,
so it probably doesn't matter much in practice now.
Unfortunately, it does prevent us from easily capping the potential
memory usage here, on pain of losing log entries.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Prior to Go 1.16, iOS used GOOS=darwin,
so we had to distinguish macOS from iOS during GOARCH.
We now require Go 1.16 in our go.mod, so we can simplify.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Now that we have the easier-to-parse go:build build tags,
it is straightforward to simplify them. Yay.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
rsc.io/goversion is really expensive.
Running version.ReadExe on tailscaled on darwin
allocates 47k objects, almost 11mb.
All we want is the module info. For that, all we need to do
is scan through the binary looking for the magic start/end strings
and then grab the bytes in between them.
We can do that easily and quickly with nothing but a 64k buffer.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This was the proximate cause of #2579.
#2582 is a deeper fix, but this will remain
as a footgun, so may as well fix it too.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
This is a simplified rate limiter geared for exactly our needs:
A fast, mono.Time-based rate limiter for use in tstun.
It was generated by stripping down the x/time/rate rate limiter
to just our needs and switching it to use mono.Time.
It removes one time.Now call per packet.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
magicsock makes multiple calls to Now per packet.
Move to mono.Now. Changing some of the calls to
use package mono has a cascading effect,
causing non-per-packet call sites to also switch.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
There's a call to Now once per packet.
Move to mono.Now.
Though the current implementation provides high precision,
we document it to be coarse, to preserve the ability
to switch to a coarse monotonic time later.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Package mono provides a fast monotonic time.
Its primary advantage is that it is fast:
It is approximately twice as fast as time.Now.
This is because time.Now uses two clock calls,
one for wall time and one for monotonic time.
We ask for the current time 4-6 times per network packet.
At ~50ns per call to time.Now, that's enough to show
up in CPU profiles.
Package mono is a first step towards addressing that.
It is designed to be a near drop-in replacement for package time.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Go 1.17 switches to a register ABI on amd64 platforms.
Part of that switch is that go and defer calls use an argument-less
closure, which allocates. This means that we have an extra
alloc in some DNS work. That's unfortunate but not a showstopper,
and I don't see a clear path to fixing it.
The other performance benefits from the register ABI will all
but certainly outweigh this extra alloc.
Fixes#2545
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The handoff between tstun.Wrap's Read and poll methods
is one of the per-packet hotspots. It shows up in pprof.
Making outbound buffered increases throughput.
It is hard to measure exactly how much, because the numbers
are highly variable, but I'd estimate it at about 1%,
using the best observed max throughput across three runs.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The handoff between tstun.Wrap's Read and poll methods
is one of the per-packet hotspots. It shows up in pprof.
Making outbound buffered increases throughput.
It is hard to measure exactly how much, because the numbers
are highly variable, but I'd estimate it at about 1%,
using the best observed max throughput across three runs.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Filch doesn't like having multiple processes competing
for the same log files (#937).
Parallel integration tests were all using the same log files.
Add a TS_LOGS_DIR env var that the integration test can use
to use separate log files per test.
Fixes#2269
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
Instead of logging lsof execution failures to stdout,
incorporate them into the returned error.
While we're here, make it clear that the file
success case always returns a nil error.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
The maximum unix domain socket path length on darwin is 104 bytes,
including the trailing NUL.
On my machine, the path created by some newly added tests (6eecf3c9)
was too long, resulting in cryptic test failures.
Shorten the names of the tests, and add a check to make
the diagnosis easier next time.
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>
