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 <xe@tailscale.com>

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"

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 @@ import (
 	"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
+}

tstest/integration/integration_test.go

@@ -23,7 +23,6 @@ import (
 	"path/filepath"
 	"regexp"
 	"runtime"
-	"strings"
 	"sync"
 	"sync/atomic"
 	"testing"
@@ -32,7 +31,6 @@ import (
 	"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 @@ import (
 )
 
 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.

tstest/integration/vms/nixos_test.go

@@ -144,6 +144,9 @@ in {
     # 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 {
+func (h Harness) makeNixOSImage(t *testing.T, d Distro, cdir string) string {
-	copyUnit(t, bins)
+	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)
 	}

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 {