diff --git a/control/controlclient/auto_test.go b/control/controlclient/auto_test.go index 96c8239af..0ad0b5cc3 100644 --- a/control/controlclient/auto_test.go +++ b/control/controlclient/auto_test.go @@ -12,7 +12,6 @@ import ( "encoding/json" "fmt" "io/ioutil" - "log" "net/http" "net/http/cookiejar" "net/http/httptest" @@ -55,46 +54,72 @@ func TestControlBasics(t *testing.T) { c.postAuthURL(t, "foo@tailscale.com", status.New) } +// A function with the same semantics as t.Run(), but which doesn't rearrange +// the logs by creating a new sub-t.Logf, and doesn't support parallelism. +// This makes it possible to actually figure out what happened by looking +// at the logs. +func runSub(t *testing.T, name string, fn func(t *testing.T)) { + t.Helper() + t.Logf("\n") + t.Logf("\n\n--- Starting: %v\n\n", name) + defer func() { + if t.Failed() { + t.Logf("\n\n--- FAILED: %v\n\n", name) + } else { + t.Logf("\n\n--- PASS: %v\n\n", name) + } + }() + + fn(t) +} + +func fatal(t *testing.T, args ...interface{}) { + t.Fatal("FAILED: ", fmt.Sprint(args...)) +} + +func fatalf(t *testing.T, s string, args ...interface{}) { + t.Fatalf("FAILED: "+s, args...) +} + func TestControl(t *testing.T) { - log.SetFlags(log.Ltime | log.Lshortfile) s := newServer(t) defer s.close() c1 := s.newClient(t, "c1") - t.Run("authorize first tailscale.com client", func(t *testing.T) { + runSub(t, "authorize first tailscale.com client", func(t *testing.T) { const loginName = "testuser1@tailscale.com" c1.checkNoStatus(t) c1.loginAs(t, loginName) c1.waitStatus(t, stateAuthenticated) status := c1.waitStatus(t, stateSynchronized) if got, want := status.New.NetMap.MachineStatus, tailcfg.MachineUnauthorized; got != want { - t.Errorf("MachineStatus=%v, want %v", got, want) + fatalf(t, "MachineStatus=%v, want %v", got, want) } c1.checkNoStatus(t) affectedPeers, err := s.control.AuthorizeMachine(c1.mkey, c1.nkey) if err != nil { - t.Fatal(err) + fatal(t, err) } status = c1.status(t) if got := status.New.Persist.LoginName; got != loginName { - t.Errorf("LoginName=%q, want %q", got, loginName) + fatalf(t, "LoginName=%q, want %q", got, loginName) } if got := status.New.Persist.Provider; got != "google" { - t.Errorf("Provider=%q, want google", got) + fatalf(t, "Provider=%q, want google", got) } if len(affectedPeers) != 1 || affectedPeers[0] != c1.id { - t.Errorf("authorization should notify the node being authorized (%v), got: %v", c1.id, affectedPeers) + fatalf(t, "authorization should notify the node being authorized (%v), got: %v", c1.id, affectedPeers) } if peers := status.New.NetMap.Peers; len(peers) != 0 { - t.Errorf("peers=%v, want none", peers) + fatalf(t, "peers=%v, want none", peers) } if userID := status.New.NetMap.User; userID == 0 { - t.Errorf("NetMap.User is missing") + fatalf(t, "NetMap.User is missing") } else { profile := status.New.NetMap.UserProfiles[userID] if profile.LoginName != loginName { - t.Errorf("NetMap user LoginName=%q, want %q", profile.LoginName, loginName) + fatalf(t, "NetMap user LoginName=%q, want %q", profile.LoginName, loginName) } } c1.checkNoStatus(t) @@ -102,7 +127,7 @@ func TestControl(t *testing.T) { c2 := s.newClient(t, "c2") - t.Run("authorize second tailscale.io client", func(t *testing.T) { + runSub(t, "authorize second tailscale.io client", func(t *testing.T) { c2.loginAs(t, "testuser2@tailscale.com") c2.waitStatus(t, stateAuthenticated) c2.waitStatus(t, stateSynchronized) @@ -114,16 +139,16 @@ func TestControl(t *testing.T) { // there will sometimes be a spurious map update. affectedPeers, err := s.control.AuthorizeMachine(c2.mkey, c2.nkey) if err != nil { - t.Fatal(err) + fatal(t, err) } status := c2.waitStatus(t, stateSynchronized) c1Status := c1.waitStatus(t, stateSynchronized) if len(affectedPeers) != 2 { - t.Errorf("affectedPeers=%v, want two entries", affectedPeers) + fatalf(t, "affectedPeers=%v, want two entries", affectedPeers) } if want := []tailcfg.NodeID{c1.id, c2.id}; !nodeIDsEqual(affectedPeers, want) { - t.Errorf("affectedPeers=%v, want %v", affectedPeers, want) + fatalf(t, "affectedPeers=%v, want %v", affectedPeers, want) } c1NetMap := c1Status.New.NetMap @@ -132,15 +157,15 @@ func TestControl(t *testing.T) { t.Error("wrong number of peers") } else { if c2NetMap.Peers[0].Key != c1.nkey { - t.Errorf("c2 has wrong peer key %v, want %v", c2NetMap.Peers[0].Key, c1.nkey) + fatalf(t, "c2 has wrong peer key %v, want %v", c2NetMap.Peers[0].Key, c1.nkey) } if c1NetMap.Peers[0].Key != c2.nkey { - t.Errorf("c1 has wrong peer key %v, want %v", c1NetMap.Peers[0].Key, c2.nkey) + fatalf(t, "c1 has wrong peer key %v, want %v", c1NetMap.Peers[0].Key, c2.nkey) } } if t.Failed() { - t.Errorf("client1 network map:\n%s", c1Status.New.NetMap) - t.Errorf("client2 network map:\n%s", status.New.NetMap) + fatalf(t, "client1 network map:\n%s", c1Status.New.NetMap) + fatalf(t, "client2 network map:\n%s", status.New.NetMap) } c1.checkNoStatus(t) @@ -151,7 +176,7 @@ func TestControl(t *testing.T) { // The two domains should never affect one another. c3 := s.newClient(t, "c3") - t.Run("authorize first onmicrosoft client", func(t *testing.T) { + runSub(t, "authorize first onmicrosoft client", func(t *testing.T) { c3.loginAs(t, "testuser1@tailscale.onmicrosoft.com") c3.waitStatus(t, stateAuthenticated) c3Status := c3.waitStatus(t, stateSynchronized) @@ -161,10 +186,10 @@ func TestControl(t *testing.T) { netMap := c3Status.New.NetMap if netMap.NodeKey != c3.nkey { - t.Errorf("netMap.NodeKey=%v, want %v", netMap.NodeKey, c3.nkey) + fatalf(t, "netMap.NodeKey=%v, want %v", netMap.NodeKey, c3.nkey) } if len(netMap.Peers) != 0 { - t.Errorf("netMap.Peers=%v, want none", netMap.Peers) + fatalf(t, "netMap.Peers=%v, want none", netMap.Peers) } c1.checkNoStatus(t) @@ -174,7 +199,7 @@ func TestControl(t *testing.T) { c4 := s.newClient(t, "c4") - t.Run("authorize second onmicrosoft client", func(t *testing.T) { + runSub(t, "authorize second onmicrosoft client", func(t *testing.T) { c4.loginAs(t, "testuser2@tailscale.onmicrosoft.com") c4.waitStatus(t, stateAuthenticated) c3Status := c3.waitStatus(t, stateSynchronized) @@ -186,22 +211,22 @@ func TestControl(t *testing.T) { c2.checkNoStatus(t) if len(c3NetMap.Peers) != 1 { - t.Errorf("wrong number of c3 peers: %d", len(c3NetMap.Peers)) + fatalf(t, "wrong number of c3 peers: %d", len(c3NetMap.Peers)) } else if len(c4NetMap.Peers) != 1 { - t.Errorf("wrong number of c4 peers: %d", len(c4NetMap.Peers)) + fatalf(t, "wrong number of c4 peers: %d", len(c4NetMap.Peers)) } else { if c3NetMap.Peers[0].Key != c4.nkey || c4NetMap.Peers[0].Key != c3.nkey { t.Error("wrong peer key") } } if t.Failed() { - t.Errorf("client3 network map:\n%s", c3NetMap) - t.Errorf("client4 network map:\n%s", c4NetMap) + fatalf(t, "client3 network map:\n%s", c3NetMap) + fatalf(t, "client4 network map:\n%s", c4NetMap) } }) var c1NetMap *NetworkMap - t.Run("update c1 and c2 endpoints", func(t *testing.T) { + runSub(t, "update c1 and c2 endpoints", func(t *testing.T) { c1Endpoints := []string{"172.16.1.5:12345", "4.4.4.4:4444"} c1.checkNoStatus(t) c1.UpdateEndpoints(1234, c1Endpoints) @@ -211,13 +236,13 @@ func TestControl(t *testing.T) { c2.checkNoStatus(t) if c1NetMap.LocalPort != 1234 { - t.Errorf("c1 netmap localport=%d, want 1234", c1NetMap.LocalPort) + fatalf(t, "c1 netmap localport=%d, want 1234", c1NetMap.LocalPort) } if len(c2NetMap.Peers) != 1 { - t.Fatalf("wrong peer count: %d", len(c2NetMap.Peers)) + fatalf(t, "wrong peer count: %d", len(c2NetMap.Peers)) } if got := c2NetMap.Peers[0].Endpoints; !hasStringsSuffix(got, c1Endpoints) { - t.Errorf("c2 peer endpoints=%v, want %v", got, c1Endpoints) + fatalf(t, "c2 peer endpoints=%v, want %v", got, c1Endpoints) } c3.checkNoStatus(t) c4.checkNoStatus(t) @@ -228,16 +253,16 @@ func TestControl(t *testing.T) { c2NetMap = c2.status(t).New.NetMap if c1NetMap.LocalPort != 1234 { - t.Errorf("c1 netmap localport=%d, want 1234", c1NetMap.LocalPort) + fatalf(t, "c1 netmap localport=%d, want 1234", c1NetMap.LocalPort) } if c2NetMap.LocalPort != 9876 { - t.Errorf("c2 netmap localport=%d, want 9876", c2NetMap.LocalPort) + fatalf(t, "c2 netmap localport=%d, want 9876", c2NetMap.LocalPort) } if got := c2NetMap.Peers[0].Endpoints; !hasStringsSuffix(got, c1Endpoints) { - t.Errorf("c2 peer endpoints=%v, want suffix %v", got, c1Endpoints) + fatalf(t, "c2 peer endpoints=%v, want suffix %v", got, c1Endpoints) } if got := c1NetMap.Peers[0].Endpoints; !hasStringsSuffix(got, c2Endpoints) { - t.Errorf("c1 peer endpoints=%v, want suffix %v", got, c2Endpoints) + fatalf(t, "c1 peer endpoints=%v, want suffix %v", got, c2Endpoints) } c1.checkNoStatus(t) @@ -248,23 +273,23 @@ func TestControl(t *testing.T) { allZeros, err := wgcfg.ParseCIDR("0.0.0.0/0") if err != nil { - t.Fatal(err) + fatal(t, err) } - t.Run("route all traffic via client 1", func(t *testing.T) { + runSub(t, "route all traffic via client 1", func(t *testing.T) { aips := []wgcfg.CIDR{} aips = append(aips, c1NetMap.Addresses...) aips = append(aips, allZeros) affectedPeers, err := s.control.SetAllowedIPs(c1.nkey, aips) if err != nil { - t.Fatal(err) + fatal(t, err) } c2Status := c2.status(t) c2NetMap := c2Status.New.NetMap if want := []tailcfg.NodeID{c2.id}; !nodeIDsEqual(affectedPeers, want) { - t.Errorf("affectedPeers=%v, want %v", affectedPeers, want) + fatalf(t, "affectedPeers=%v, want %v", affectedPeers, want) } _ = c2NetMap @@ -275,7 +300,7 @@ func TestControl(t *testing.T) { } } if !foundAllZeros { - t.Errorf("client2 peer does not contain %s: %v", allZeros, c2NetMap.Peers[0].AllowedIPs) + fatalf(t, "client2 peer does not contain %s: %v", allZeros, c2NetMap.Peers[0].AllowedIPs) } c1.checkNoStatus(t) @@ -283,15 +308,15 @@ func TestControl(t *testing.T) { c4.checkNoStatus(t) }) - t.Run("remove route all traffic", func(t *testing.T) { + runSub(t, "remove route all traffic", func(t *testing.T) { affectedPeers, err := s.control.SetAllowedIPs(c1.nkey, c1NetMap.Addresses) if err != nil { - t.Fatal(err) + fatal(t, err) } c2NetMap := c2.status(t).New.NetMap if want := []tailcfg.NodeID{c2.id}; !nodeIDsEqual(affectedPeers, want) { - t.Errorf("affectedPeers=%v, want %v", affectedPeers, want) + fatalf(t, "affectedPeers=%v, want %v", affectedPeers, want) } foundAllZeros := false @@ -301,7 +326,7 @@ func TestControl(t *testing.T) { } } if foundAllZeros { - t.Errorf("client2 peer still contains %s: %v", allZeros, c2NetMap.Peers[0].AllowedIPs) + fatalf(t, "client2 peer still contains %s: %v", allZeros, c2NetMap.Peers[0].AllowedIPs) } c1.checkNoStatus(t) @@ -309,7 +334,7 @@ func TestControl(t *testing.T) { c4.checkNoStatus(t) }) - t.Run("refresh client key", func(t *testing.T) { + runSub(t, "refresh client key", func(t *testing.T) { oldKey := c1.nkey c1.Login(nil, LoginInteractive) @@ -318,24 +343,24 @@ func TestControl(t *testing.T) { c1.waitStatus(t, stateAuthenticated) status = c1.waitStatus(t, stateSynchronized) if status.New.Err != "" { - t.Fatal(status.New.Err) + fatal(t, status.New.Err) } c1NetMap := status.New.NetMap c1.nkey = c1NetMap.NodeKey if c1.nkey == oldKey { - t.Errorf("new key is the same as the old key: %s", oldKey) + fatalf(t, "new key is the same as the old key: %s", oldKey) } c2NetMap := c2.status(t).New.NetMap if len(c2NetMap.Peers) != 1 || c2NetMap.Peers[0].Key != c1.nkey { - t.Errorf("c2 peer: %v, want new node key %v", c1.nkey, c2NetMap.Peers[0].Key) + fatalf(t, "c2 peer: %v, want new node key %v", c1.nkey, c2NetMap.Peers[0].Key) } c3.checkNoStatus(t) c4.checkNoStatus(t) }) - t.Run("set hostinfo", func(t *testing.T) { + runSub(t, "set hostinfo", func(t *testing.T) { c3.UpdateEndpoints(9876, []string{"1.2.3.4:3333"}) c4.UpdateEndpoints(9876, []string{"5.6.7.8:1111"}) c3.waitStatus(t, stateSynchronized) @@ -348,14 +373,14 @@ func TestControl(t *testing.T) { c3.waitStatus(t, stateSynchronized) c4NetMap := c4.status(t).New.NetMap if len(c4NetMap.Peers) != 1 { - t.Fatalf("wrong number of peers: %v", c4NetMap.Peers) + fatalf(t, "wrong number of peers: %v", c4NetMap.Peers) } peer := c4NetMap.Peers[0] if !peer.KeepAlive { - t.Errorf("peer KeepAlive=false, want true") + fatalf(t, "peer KeepAlive=false, want true") } if peer.Hostinfo.OS != "linux" { - t.Errorf("peer OS is not linux: %v", peer.Hostinfo) + fatalf(t, "peer OS is not linux: %v", peer.Hostinfo) } c4.SetHostinfo(&tailcfg.Hostinfo{ @@ -365,24 +390,24 @@ func TestControl(t *testing.T) { c3NetMap := c3.status(t).New.NetMap c4NetMap = c4.status(t).New.NetMap if len(c3NetMap.Peers) != 1 { - t.Fatalf("wrong number of peers: %v", c3NetMap.Peers) + fatalf(t, "wrong number of peers: %v", c3NetMap.Peers) } if len(c4NetMap.Peers) != 1 { - t.Fatalf("wrong number of peers: %v", c4NetMap.Peers) + fatalf(t, "wrong number of peers: %v", c4NetMap.Peers) } peer = c3NetMap.Peers[0] if peer.KeepAlive { - t.Errorf("peer KeepAlive=true, want false") + fatalf(t, "peer KeepAlive=true, want false") } if peer.Hostinfo.OS != "iOS" { - t.Errorf("peer OS is not iOS: %v", peer.Hostinfo) + fatalf(t, "peer OS is not iOS: %v", peer.Hostinfo) } peer = c4NetMap.Peers[0] if peer.KeepAlive { - t.Errorf("peer KeepAlive=true, want false") + fatalf(t, "peer KeepAlive=true, want false") } if peer.Hostinfo.OS != "linux" { - t.Errorf("peer OS is not linux: %v", peer.Hostinfo) + fatalf(t, "peer OS is not linux: %v", peer.Hostinfo) } }) @@ -408,15 +433,15 @@ func TestLoginInterrupt(t *testing.T) { c.waitStatus(t, stateSynchronized) t.Logf("authorizing: %v %v %v %v\n", s, s.control, c.mkey, c.nkey) if _, err := s.control.AuthorizeMachine(c.mkey, c.nkey); err != nil { - t.Fatal(err) + fatal(t, err) } status := c.waitStatus(t, stateSynchronized) if got, want := status.New.NetMap.MachineStatus, tailcfg.MachineAuthorized; got != want { - t.Errorf("MachineStatus=%v, want %v", got, want) + fatalf(t, "MachineStatus=%v, want %v", got, want) } origAddrs := status.New.NetMap.Addresses if len(origAddrs) == 0 { - t.Errorf("Addresses empty, want something") + fatalf(t, "Addresses empty, want something") } c.Logout() @@ -431,63 +456,63 @@ func TestLoginInterrupt(t *testing.T) { authURL2 := status.New.URL if authURL == authURL2 { - t.Errorf("auth URLs match for subsequent logins: %s", authURL) + fatalf(t, "auth URLs match for subsequent logins: %s", authURL) } // Direct auth URL visit is not enough because our cookie is no longer fresh. req, err := http.NewRequest("GET", authURL2, nil) if err != nil { - t.Fatal(err) + fatal(t, err) } req.Header.Add("Content-Type", "application/x-www-form-urlencoded") resp, err := c.httpc.Do(req.WithContext(c.ctx)) if err != nil { - t.Fatal(err) + fatal(t, err) } b, err := ioutil.ReadAll(resp.Body) if err != nil { - t.Fatal(err) + fatal(t, err) } resp.Body.Close() if i := bytes.Index(b, []byte("
header b = b[i:] } if !bytes.Contains(b, []byte("