From a19eea965f9657bdff50ec45c322844365f6e1a3 Mon Sep 17 00:00:00 2001 From: Christine Dodrill Date: Thu, 8 Jul 2021 14:39:45 -0400 Subject: [PATCH] tstest/integration/vms: use an in-process logcatcher (#2360) This adapts the existing in-process logcatcher from tstest/integration into a public type and uses it on the side of testcontrol. This also fixes a bug in the Alpine Linux OpenRC unit that makes every value in `/etc/default/tailscaled` exported into tailscaled's environment, a-la systemd [Service].EnviromentFile. Signed-off-by: Christine Dodrill --- cmd/tailscaled/tailscaled.openrc | 2 + tstest/integration/integration.go | 95 ++++++++++++++++++++++++++ tstest/integration/integration_test.go | 86 +---------------------- tstest/integration/vms/nixos_test.go | 16 ++++- tstest/integration/vms/vms_test.go | 35 +++++++--- 5 files changed, 137 insertions(+), 97 deletions(-) diff --git a/cmd/tailscaled/tailscaled.openrc b/cmd/tailscaled/tailscaled.openrc index bc6936fa1..309d70f23 100755 --- a/cmd/tailscaled/tailscaled.openrc +++ b/cmd/tailscaled/tailscaled.openrc @@ -1,6 +1,8 @@ #!/sbin/openrc-run +set -a source /etc/default/tailscaled +set +a command="/usr/sbin/tailscaled" command_args="--state=/var/lib/tailscale/tailscaled.state --port=$PORT --socket=/var/run/tailscale/tailscaled.sock $FLAGS" diff --git a/tstest/integration/integration.go b/tstest/integration/integration.go index 025cb31e6..b6bb1cd3c 100644 --- a/tstest/integration/integration.go +++ b/tstest/integration/integration.go @@ -9,8 +9,14 @@ package integration import ( + "bytes" "crypto/rand" "crypto/tls" + "encoding/json" + "fmt" + "io" + "io/ioutil" + "log" "net" "net/http" "net/http/httptest" @@ -24,9 +30,11 @@ "testing" "time" + "go4.org/mem" "tailscale.com/derp" "tailscale.com/derp/derphttp" "tailscale.com/net/stun/stuntest" + "tailscale.com/smallzstd" "tailscale.com/tailcfg" "tailscale.com/types/key" "tailscale.com/types/logger" @@ -160,3 +168,90 @@ func RunDERPAndSTUN(t testing.TB, logf logger.Logf, ipAddress string) (derpMap * return m } + +// LogCatcher is a minimal logcatcher for the logtail upload client. +type LogCatcher struct { + mu sync.Mutex + logf logger.Logf + buf bytes.Buffer + gotErr error + reqs int +} + +// UseLogf makes the logcatcher implementation use a given logf function +// to dump all logs to. +func (lc *LogCatcher) UseLogf(fn logger.Logf) { + lc.mu.Lock() + defer lc.mu.Unlock() + lc.logf = fn +} + +func (lc *LogCatcher) logsContains(sub mem.RO) bool { + lc.mu.Lock() + defer lc.mu.Unlock() + return mem.Contains(mem.B(lc.buf.Bytes()), sub) +} + +func (lc *LogCatcher) numRequests() int { + lc.mu.Lock() + defer lc.mu.Unlock() + return lc.reqs +} + +func (lc *LogCatcher) logsString() string { + lc.mu.Lock() + defer lc.mu.Unlock() + return lc.buf.String() +} + +func (lc *LogCatcher) ServeHTTP(w http.ResponseWriter, r *http.Request) { + var body io.Reader = r.Body + if r.Header.Get("Content-Encoding") == "zstd" { + var err error + body, err = smallzstd.NewDecoder(body) + if err != nil { + log.Printf("bad caught zstd: %v", err) + http.Error(w, err.Error(), 400) + return + } + } + bodyBytes, _ := ioutil.ReadAll(body) + + type Entry struct { + Logtail struct { + ClientTime time.Time `json:"client_time"` + ServerTime time.Time `json:"server_time"` + Error struct { + BadData string `json:"bad_data"` + } `json:"error"` + } `json:"logtail"` + Text string `json:"text"` + } + var jreq []Entry + var err error + if len(bodyBytes) > 0 && bodyBytes[0] == '[' { + err = json.Unmarshal(bodyBytes, &jreq) + } else { + var ent Entry + err = json.Unmarshal(bodyBytes, &ent) + jreq = append(jreq, ent) + } + + lc.mu.Lock() + defer lc.mu.Unlock() + lc.reqs++ + if lc.gotErr == nil && err != nil { + lc.gotErr = err + } + if err != nil { + fmt.Fprintf(&lc.buf, "error from %s of %#q: %v\n", r.Method, bodyBytes, err) + } else { + for _, ent := range jreq { + fmt.Fprintf(&lc.buf, "%s\n", strings.TrimSpace(ent.Text)) + if lc.logf != nil { + lc.logf("%s", strings.TrimSpace(ent.Text)) + } + } + } + w.WriteHeader(200) // must have no content, but not a 204 +} diff --git a/tstest/integration/integration_test.go b/tstest/integration/integration_test.go index bd3e01acf..d77c29e58 100644 --- a/tstest/integration/integration_test.go +++ b/tstest/integration/integration_test.go @@ -23,7 +23,6 @@ "path/filepath" "regexp" "runtime" - "strings" "sync" "sync/atomic" "testing" @@ -32,7 +31,6 @@ "go4.org/mem" "tailscale.com/ipn/ipnstate" "tailscale.com/safesocket" - "tailscale.com/smallzstd" "tailscale.com/tailcfg" "tailscale.com/tstest" "tailscale.com/tstest/integration/testcontrol" @@ -40,7 +38,6 @@ ) var ( - verboseLogCatcher = flag.Bool("verbose-log-catcher", false, "verbose log catcher logging") verboseTailscaled = flag.Bool("verbose-tailscaled", false, "verbose tailscaled logging") ) @@ -146,7 +143,6 @@ func TestOneNodeUp_Auth(t *testing.T) { } d1.MustCleanShutdown(t) - } func TestTwoNodes(t *testing.T) { @@ -294,7 +290,7 @@ type testEnv struct { t testing.TB Binaries *Binaries - LogCatcher *logCatcher + LogCatcher *LogCatcher LogCatcherServer *httptest.Server Control *testcontrol.Server @@ -323,7 +319,7 @@ func newTestEnv(t testing.TB, bins *Binaries, opts ...testEnvOpt) *testEnv { t.Skip("not tested/working on Windows yet") } derpMap := RunDERPAndSTUN(t, logger.Discard, "127.0.0.1") - logc := new(logCatcher) + logc := new(LogCatcher) control := &testcontrol.Server{ DERPMap: derpMap, } @@ -596,84 +592,6 @@ func (n *testNode) MustStatus(tb testing.TB) *ipnstate.Status { return st } -// logCatcher is a minimal logcatcher for the logtail upload client. -type logCatcher struct { - mu sync.Mutex - buf bytes.Buffer - gotErr error - reqs int -} - -func (lc *logCatcher) logsContains(sub mem.RO) bool { - lc.mu.Lock() - defer lc.mu.Unlock() - return mem.Contains(mem.B(lc.buf.Bytes()), sub) -} - -func (lc *logCatcher) numRequests() int { - lc.mu.Lock() - defer lc.mu.Unlock() - return lc.reqs -} - -func (lc *logCatcher) logsString() string { - lc.mu.Lock() - defer lc.mu.Unlock() - return lc.buf.String() -} - -func (lc *logCatcher) ServeHTTP(w http.ResponseWriter, r *http.Request) { - var body io.Reader = r.Body - if r.Header.Get("Content-Encoding") == "zstd" { - var err error - body, err = smallzstd.NewDecoder(body) - if err != nil { - log.Printf("bad caught zstd: %v", err) - http.Error(w, err.Error(), 400) - return - } - } - bodyBytes, _ := ioutil.ReadAll(body) - - type Entry struct { - Logtail struct { - ClientTime time.Time `json:"client_time"` - ServerTime time.Time `json:"server_time"` - Error struct { - BadData string `json:"bad_data"` - } `json:"error"` - } `json:"logtail"` - Text string `json:"text"` - } - var jreq []Entry - var err error - if len(bodyBytes) > 0 && bodyBytes[0] == '[' { - err = json.Unmarshal(bodyBytes, &jreq) - } else { - var ent Entry - err = json.Unmarshal(bodyBytes, &ent) - jreq = append(jreq, ent) - } - - lc.mu.Lock() - defer lc.mu.Unlock() - lc.reqs++ - if lc.gotErr == nil && err != nil { - lc.gotErr = err - } - if err != nil { - fmt.Fprintf(&lc.buf, "error from %s of %#q: %v\n", r.Method, bodyBytes, err) - } else { - for _, ent := range jreq { - fmt.Fprintf(&lc.buf, "%s\n", strings.TrimSpace(ent.Text)) - if *verboseLogCatcher { - fmt.Fprintf(os.Stderr, "%s\n", strings.TrimSpace(ent.Text)) - } - } - } - w.WriteHeader(200) // must have no content, but not a 204 -} - // trafficTrap is an HTTP proxy handler to note whether any // HTTP traffic tries to leave localhost from tailscaled. We don't // expect any, so any request triggers a failure. diff --git a/tstest/integration/vms/nixos_test.go b/tstest/integration/vms/nixos_test.go index f0962fe4d..f2cc7e07a 100644 --- a/tstest/integration/vms/nixos_test.go +++ b/tstest/integration/vms/nixos_test.go @@ -144,6 +144,9 @@ # Use the Tailscale package we just assembled. package = testTailscale; }; + + # Override TS_LOG_TARGET to our private logcatcher. + systemd.services.tailscaled.environment."TS_LOG_TARGET" = "{{.LogTarget}}"; }` func copyUnit(t *testing.T, bins *integration.Binaries) { @@ -160,8 +163,8 @@ func copyUnit(t *testing.T, bins *integration.Binaries) { } } -func makeNixOSImage(t *testing.T, d Distro, cdir string, bins *integration.Binaries) string { - copyUnit(t, bins) +func (h Harness) makeNixOSImage(t *testing.T, d Distro, cdir string) string { + copyUnit(t, h.bins) dir := t.TempDir() fname := filepath.Join(dir, d.name+".nix") fout, err := os.Create(fname) @@ -170,7 +173,13 @@ func makeNixOSImage(t *testing.T, d Distro, cdir string, bins *integration.Binar } tmpl := template.Must(template.New("base.nix").Parse(nixosConfigTemplate)) - err = tmpl.Execute(fout, struct{ BinPath string }{BinPath: bins.Dir}) + err = tmpl.Execute(fout, struct { + BinPath string + LogTarget string + }{ + BinPath: h.bins.Dir, + LogTarget: h.loginServerURL, + }) if err != nil { t.Fatal(err) } @@ -204,6 +213,7 @@ func makeNixOSImage(t *testing.T, d Distro, cdir string, bins *integration.Binar } cmd.Env = append(os.Environ(), "NIX_PATH=nixpkgs="+d.url) cmd.Dir = outpath + t.Logf("running %s %#v", "nixos-generate", cmd.Args) if err := cmd.Run(); err != nil { t.Fatalf("error while making NixOS image for %s: %v", d.name, err) } diff --git a/tstest/integration/vms/vms_test.go b/tstest/integration/vms/vms_test.go index 189e405ad..911222418 100644 --- a/tstest/integration/vms/vms_test.go +++ b/tstest/integration/vms/vms_test.go @@ -126,7 +126,7 @@ func TestDownloadImages(t *testing.T) { t.Parallel() - fetchDistro(t, distro, bins) + (Harness{bins: bins}).fetchDistro(t, distro) }) } } @@ -242,7 +242,7 @@ func fetchFromS3(t *testing.T, fout *os.File, d Distro) bool { // fetchDistro fetches a distribution from the internet if it doesn't already exist locally. It // also validates the sha256 sum from a known good hash. -func fetchDistro(t *testing.T, resultDistro Distro, bins *integration.Binaries) string { +func (h Harness) fetchDistro(t *testing.T, resultDistro Distro) string { t.Helper() cdir, err := os.UserCacheDir() @@ -252,7 +252,11 @@ func fetchDistro(t *testing.T, resultDistro Distro, bins *integration.Binaries) cdir = filepath.Join(cdir, "tailscale", "vm-test") if strings.HasPrefix(resultDistro.name, "nixos") { - return makeNixOSImage(t, resultDistro, cdir, bins) + var imagePath string + t.Run("nix-build", func(t *testing.T) { + imagePath = h.makeNixOSImage(t, resultDistro, cdir) + }) + return imagePath } qcowPath := filepath.Join(cdir, "qcow2", resultDistro.sha256sum) @@ -448,7 +452,7 @@ func mkSeed(t *testing.T, d Distro, sshKey, hostURL, tdir string, port int) { // mkVM makes a KVM-accelerated virtual machine and prepares it for introduction // to the testcontrol server. The function it returns is for killing the virtual // machine when it is time for it to die. -func mkVM(t *testing.T, n int, d Distro, sshKey, hostURL, tdir string, bins *integration.Binaries) { +func (h Harness) mkVM(t *testing.T, n int, d Distro, sshKey, hostURL, tdir string) { t.Helper() cdir, err := os.UserCacheDir() @@ -463,7 +467,7 @@ func mkVM(t *testing.T, n int, d Distro, sshKey, hostURL, tdir string, bins *int t.Fatal(err) } - mkLayeredQcow(t, tdir, d, fetchDistro(t, d, bins)) + mkLayeredQcow(t, tdir, d, h.fetchDistro(t, d)) mkSeed(t, d, sshKey, hostURL, tdir, port) driveArg := fmt.Sprintf("file=%s,if=virtio", filepath.Join(tdir, d.name+".qcow2")) @@ -600,6 +604,7 @@ func TestVMIntegrationEndToEnd(t *testing.T) { mux := http.NewServeMux() mux.Handle("/", cs) + mux.Handle("/c/", &integration.LogCatcher{}) // This handler will let the virtual machines tell the host information about that VM. // This is used to maintain a list of port->IP address mappings that are known to be @@ -677,7 +682,7 @@ func TestVMIntegrationEndToEnd(t *testing.T) { } defer ramsem.Release(int64(distro.mem)) - mkVM(t, n, distro, string(pubkey), loginServer, dir, bins) + h.mkVM(t, n, distro, string(pubkey), loginServer, dir) var ipm ipMapping t.Run("wait-for-start", func(t *testing.T) { @@ -703,7 +708,6 @@ func TestVMIntegrationEndToEnd(t *testing.T) { func (h Harness) testDistro(t *testing.T, d Distro, ipm ipMapping) { signer := h.signer - bins := h.bins loginServer := h.loginServerURL t.Helper() @@ -741,7 +745,7 @@ func (h Harness) testDistro(t *testing.T, d Distro, ipm ipMapping) { if err != nil { t.Fatal(err) } - copyBinaries(t, d, cli, bins) + h.copyBinaries(t, d, cli) timeout := 30 * time.Second @@ -887,7 +891,8 @@ func runTestCommands(t *testing.T, timeout time.Duration, cli *ssh.Client, batch } } -func copyBinaries(t *testing.T, d Distro, conn *ssh.Client, bins *integration.Binaries) { +func (h Harness) copyBinaries(t *testing.T, d Distro, conn *ssh.Client) { + bins := h.bins if strings.HasPrefix(d.name, "nixos") { return } @@ -917,6 +922,12 @@ func copyBinaries(t *testing.T, d Distro, conn *ssh.Client, bins *integration.Bi copyFile(t, cli, "../../../cmd/tailscaled/tailscaled.service", "/etc/systemd/system/tailscaled.service") } + fout, err := cli.OpenFile("/etc/default/tailscaled", os.O_WRONLY|os.O_APPEND) + if err != nil { + t.Fatalf("can't append to defaults for tailscaled: %v", err) + } + fmt.Fprintf(fout, "\n\nTS_LOG_TARGET=%s\n", h.loginServerURL) + t.Log("tailscale installed!") } @@ -1027,7 +1038,11 @@ func (h *Harness) makeTestNode(t *testing.T, bins *integration.Binaries, control fmt.Sprintf("--socks5-server=localhost:%d", port), ) - cmd.Env = append(os.Environ(), "NOTIFY_SOCKET="+filepath.Join(dir, "notify_socket")) + cmd.Env = append( + os.Environ(), + "NOTIFY_SOCKET="+filepath.Join(dir, "notify_socket"), + "TS_LOG_TARGET="+h.loginServerURL, + ) err = cmd.Start() if err != nil {