ipn/ipnlocal: add logging and locking to c2n /update (#9290)

Log some progress info to make updates more debuggable. Also, track
whether an active update is already started and return an error if
a concurrent update is attempted.

Some planned future PRs:
* add JSON output to `tailscale update`
* use JSON output from `tailscale update` to provide a more detailed
  status of in-progress update (stage, download progress, etc)

Updates #6907

Signed-off-by: Andrew Lytvynov <awly@tailscale.com>

clientupdate/clientupdate.go

@@ -128,8 +128,8 @@ func NewUpdater(args Arguments) (*Updater, error) {
 			return nil, err
 		}
 	}
-	if args.PkgsAddr == "" {
+	if up.Arguments.PkgsAddr == "" {
-		args.PkgsAddr = "https://pkgs.tailscale.com"
+		up.Arguments.PkgsAddr = "https://pkgs.tailscale.com"
 	}
 	return &up, nil
 }

ipn/ipnlocal/c2n.go

@@ -4,6 +4,7 @@
 package ipnlocal
 
 import (
+	"bytes"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -14,6 +15,7 @@
 	"path/filepath"
 	"runtime"
 	"strconv"
+	"strings"
 	"time"
 
 	"tailscale.com/clientupdate"
@@ -38,7 +40,15 @@ func (b *LocalBackend) handleC2N(w http.ResponseWriter, r *http.Request) {
 		body, _ := io.ReadAll(r.Body)
 		w.Write(body)
 	case "/update":
-		b.handleC2NUpdate(w, r)
+		switch r.Method {
+		case http.MethodGet:
+			b.handleC2NUpdateGet(w, r)
+		case http.MethodPost:
+			b.handleC2NUpdatePost(w, r)
+		default:
+			http.Error(w, "bad method", http.StatusMethodNotAllowed)
+			return
+		}
 	case "/logtail/flush":
 		if r.Method != "POST" {
 			http.Error(w, "bad method", http.StatusMethodNotAllowed)
@@ -111,37 +121,27 @@ func (b *LocalBackend) handleC2N(w http.ResponseWriter, r *http.Request) {
 	}
 }
 
-func (b *LocalBackend) handleC2NUpdate(w http.ResponseWriter, r *http.Request) {
+func (b *LocalBackend) handleC2NUpdateGet(w http.ResponseWriter, r *http.Request) {
-	// TODO(bradfitz): add some sort of semaphore that prevents two concurrent
+	b.logf("c2n: GET /update received")
-	// updates, or if one happened in the past 5 minutes, or something.
 
-	// GET returns the current status, and POST actually begins an update.
+	res := b.newC2NUpdateResponse()
-	if r.Method != "GET" && r.Method != "POST" {
+	res.Started = b.c2nUpdateStarted()
-		http.Error(w, "bad method", http.StatusMethodNotAllowed)
-		return
-	}
 
-	// If NewUpdater does not return an error, we can update the installation.
+	w.Header().Set("Content-Type", "application/json")
-	// Exception: When version.IsMacSysExt returns true, we don't support that
+	json.NewEncoder(w).Encode(res)
-	// yet. TODO(cpalmer, #6995): Implement it.
+}
-	//
-	// Note that we create the Updater solely to check for errors; we do not
-	// invoke it here. For this purpose, it is ok to pass it a zero Arguments.
-	prefs := b.Prefs().AutoUpdate()
-	_, err := clientupdate.NewUpdater(clientupdate.Arguments{})
-	res := tailcfg.C2NUpdateResponse{
-		Enabled:   envknob.AllowsRemoteUpdate() || prefs.Apply,
-		Supported: err == nil && !version.IsMacSysExt(),
-	}
 
+func (b *LocalBackend) handleC2NUpdatePost(w http.ResponseWriter, r *http.Request) {
+	b.logf("c2n: POST /update received")
+	res := b.newC2NUpdateResponse()
 	defer func() {
+		if res.Err != "" {
+			b.logf("c2n: POST /update failed: %s", res.Err)
+		}
 		w.Header().Set("Content-Type", "application/json")
 		json.NewEncoder(w).Encode(res)
 	}()
 
-	if r.Method == "GET" {
-		return
-	}
 	if !res.Enabled {
 		res.Err = "not enabled"
 		return
@@ -151,6 +151,18 @@ func (b *LocalBackend) handleC2NUpdate(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	// Check if update was already started, and mark as started.
+	if !b.trySetC2NUpdateStarted() {
+		res.Err = "update already started"
+		return
+	}
+	defer func() {
+		// Clear the started flag if something failed.
+		if res.Err != "" {
+			b.setC2NUpdateStarted(false)
+		}
+	}()
+
 	cmdTS, err := findCmdTailscale()
 	if err != nil {
 		res.Err = fmt.Sprintf("failed to find cmd/tailscale binary: %v", err)
@@ -172,22 +184,64 @@ func (b *LocalBackend) handleC2NUpdate(w http.ResponseWriter, r *http.Request) {
 		res.Err = "cmd/tailscale version mismatch"
 		return
 	}
+
 	cmd := exec.Command(cmdTS, "update", "--yes")
+	buf := new(bytes.Buffer)
+	cmd.Stdout = buf
+	cmd.Stderr = buf
+	b.logf("c2n: running %q", strings.Join(cmd.Args, " "))
 	if err := cmd.Start(); err != nil {
 		res.Err = fmt.Sprintf("failed to start cmd/tailscale update: %v", err)
 		return
 	}
 	res.Started = true
 
-	// TODO(bradfitz,andrew): There might be a race condition here on Windows:
+	// Run update asynchronously and respond that it started.
-	// * We start the update process.
+	go func() {
-	// * tailscale.exe copies itself and kicks off the update process
+		if err := cmd.Wait(); err != nil {
-	// * msiexec stops this process during the update before the selfCopy exits(?)
+			b.logf("c2n: update command failed: %v, output: %s", err, buf)
-	// * This doesn't return because the process is dead.
+		} else {
+			b.logf("c2n: update complete")
+		}
+		b.setC2NUpdateStarted(false)
+	}()
+}
+
+func (b *LocalBackend) newC2NUpdateResponse() tailcfg.C2NUpdateResponse {
+	// If NewUpdater does not return an error, we can update the installation.
+	// Exception: When version.IsMacSysExt returns true, we don't support that
+	// yet. TODO(cpalmer, #6995): Implement it.
 	//
-	// This seems fairly unlikely, but worth checking.
+	// Note that we create the Updater solely to check for errors; we do not
-	defer cmd.Wait()
+	// invoke it here. For this purpose, it is ok to pass it a zero Arguments.
-	return
+	prefs := b.Prefs().AutoUpdate()
+	_, err := clientupdate.NewUpdater(clientupdate.Arguments{})
+	return tailcfg.C2NUpdateResponse{
+		Enabled:   envknob.AllowsRemoteUpdate() || prefs.Apply,
+		Supported: err == nil && !version.IsMacSysExt(),
+	}
+}
+
+func (b *LocalBackend) c2nUpdateStarted() bool {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.c2nUpdateStatus.started
+}
+
+func (b *LocalBackend) setC2NUpdateStarted(v bool) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	b.c2nUpdateStatus.started = v
+}
+
+func (b *LocalBackend) trySetC2NUpdateStarted() bool {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	if b.c2nUpdateStatus.started {
+		return false
+	}
+	b.c2nUpdateStatus.started = true
+	return true
 }
 
 // findCmdTailscale looks for the cmd/tailscale that corresponds to the

ipn/ipnlocal/local.go

@@ -240,6 +240,8 @@ type LocalBackend struct {
 	directFileRoot          string
 	directFileDoFinalRename bool // false on macOS, true on several NAS platforms
 	componentLogUntil       map[string]componentLogState
+	// c2nUpdateStatus is the status of c2n-triggered client update.
+	c2nUpdateStatus updateStatus
 
 	// ServeConfig fields. (also guarded by mu)
 	lastServeConfJSON   mem.RO              // last JSON that was parsed into serveConfig
@@ -268,6 +270,10 @@ type LocalBackend struct {
 	clock       tstime.Clock
 }
 
+type updateStatus struct {
+	started bool
+}
+
 // clientGen is a func that creates a control plane client.
 // It's the type used by LocalBackend.SetControlClientGetterForTesting.
 type clientGen func(controlclient.Options) (controlclient.Client, error)

tailcfg/c2ntypes.go

@@ -39,7 +39,7 @@ type C2NSSHUsernamesResponse struct {
 // its Tailscale installation.
 type C2NUpdateResponse struct {
 	// Err is the error message, if any.
-	Err string
+	Err string `json:",omitempty"`
 
 	// Enabled indicates whether the user has opted in to updates triggered from
 	// control.