Print logs while waiting for cloud deployment

4 files changed, 97 insertions, 18 deletions

diff --git a/client/go/cmd/deploy.go b/client/go/cmd/deploy.go
index 2789a74d9ac..9bf59187778 100644
--- a/client/go/cmd/deploy.go
+++ b/client/go/cmd/deploy.go
@@ -13,11 +13,13 @@ import (
 )
 
 const (
-	zoneFlag = "zone"
+	zoneFlag     = "zone"
+	logLevelFlag = "log-level"
 )
 
 var (
-	zoneArg string
+	zoneArg     string
+	logLevelArg string
 )
 
 func init() {
@@ -25,6 +27,7 @@ func init() {
 	rootCmd.AddCommand(prepareCmd)
 	rootCmd.AddCommand(activateCmd)
 	deployCmd.PersistentFlags().StringVarP(&zoneArg, zoneFlag, "z", "dev.aws-us-east-1c", "The zone to use for deployment")
+	deployCmd.PersistentFlags().StringVarP(&logLevelArg, logLevelFlag, "l", "error", `Log level for Vespa logs. Must be "error", "warning", "info" or "debug"`)
 }
 
 var deployCmd = &cobra.Command{
diff --git a/client/go/cmd/helpers.go b/client/go/cmd/helpers.go
index a541f2d363a..3493a4b32a8 100644
--- a/client/go/cmd/helpers.go
+++ b/client/go/cmd/helpers.go
@@ -147,7 +147,7 @@ func getTarget() vespa.Target {
 		if err != nil {
 			fatalErrHint(err, "Deployment to cloud requires a certificate. Try 'vespa cert'")
 		}
-		return vespa.CloudTarget(deployment, kp, apiKey)
+		return vespa.CloudTarget(deployment, kp, apiKey, vespa.LogOptions{Writer: stdout, Level: vespa.LogLevel(logLevelArg)})
 	}
 	fatalErrHint(fmt.Errorf("Invalid target: %s", targetType), "Valid targets are 'local', 'cloud' or an URL")
 	return nil
diff --git a/client/go/vespa/target.go b/client/go/vespa/target.go
index ada2b2151b2..065471d2a1e 100644
--- a/client/go/vespa/target.go
+++ b/client/go/vespa/target.go
@@ -4,9 +4,12 @@ import (
 	"crypto/tls"
 	"encoding/json"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"net/http"
 	"net/url"
+	"sort"
+	"strconv"
 	"time"
 
 	"github.com/vespa-engine/vespa/client/go/util"
@@ -45,6 +48,12 @@ type Target interface {
 	DiscoverServices(timeout time.Duration, runID int64) error
 }
 
+// LogOptions configures the log output to produce when waiting for services.
+type LogOptions struct {
+	Writer io.Writer
+	Level  int
+}
+
 type customTarget struct {
 	targetType string
 	baseURL    string
@@ -74,7 +83,7 @@ func (s *Service) Wait(timeout time.Duration) (int, error) {
 		return 0, err
 	}
 	okFunc := func(status int, response []byte) (bool, error) { return status/100 == 2, nil }
-	return wait(okFunc, req, &s.certificate, timeout)
+	return wait(okFunc, func() *http.Request { return req }, &s.certificate, timeout)
 }
 
 func (s *Service) Description() string {
@@ -145,7 +154,7 @@ func (t *customTarget) DiscoverServices(timeout time.Duration, runID int64) erro
 		converged = resp.Converged
 		return converged, nil
 	}
-	if _, err := wait(convergedFunc, req, nil, timeout); err != nil {
+	if _, err := wait(convergedFunc, func() *http.Request { return req }, nil, timeout); err != nil {
 		return err
 	}
 	if !converged {
@@ -160,6 +169,7 @@ type cloudTarget struct {
 	deployment Deployment
 	keyPair    tls.Certificate
 	apiKey     []byte
+	logOptions LogOptions
 
 	queryURL    string
 	documentURL string
@@ -206,8 +216,15 @@ func (t *cloudTarget) waitForRun(signer *RequestSigner, runID int64, timeout tim
 	if err != nil {
 		return err
 	}
-	if err := signer.SignRequest(req); err != nil {
-		return err
+	lastID := int64(-1)
+	requestFunc := func() *http.Request {
+		q := req.URL.Query()
+		q.Set("after", strconv.FormatInt(lastID, 10))
+		req.URL.RawQuery = q.Encode()
+		if err := signer.SignRequest(req); err != nil {
+			panic(err)
+		}
+		return req
 	}
 	jobSuccessFunc := func(status int, response []byte) (bool, error) {
 		if status/100 != 2 {
@@ -217,6 +234,9 @@ func (t *cloudTarget) waitForRun(signer *RequestSigner, runID int64, timeout tim
 		if err := json.Unmarshal(response, &resp); err != nil {
 			return false, nil
 		}
+		if t.logOptions.Writer != nil {
+			lastID = t.printLog(resp, lastID)
+		}
 		if resp.Active {
 			return false, nil
 		}
@@ -225,10 +245,32 @@ func (t *cloudTarget) waitForRun(signer *RequestSigner, runID int64, timeout tim
 		}
 		return true, nil
 	}
-	_, err = wait(jobSuccessFunc, req, &t.keyPair, timeout)
+	_, err = wait(jobSuccessFunc, requestFunc, &t.keyPair, timeout)
 	return err
 }
 
+func (t *cloudTarget) printLog(response jobResponse, last int64) int64 {
+	if response.LastID == 0 {
+		return last
+	}
+	var msgs []logMessage
+	for step, stepMsgs := range response.Log {
+		for _, msg := range stepMsgs {
+			if step == "copyVespaLogs" && LogLevel(msg.Type) > t.logOptions.Level {
+				continue
+			}
+			msgs = append(msgs, msg)
+		}
+	}
+	sort.Slice(msgs, func(i, j int) bool { return msgs[i].At < msgs[j].At })
+	for _, msg := range msgs {
+		tm := time.Unix(msg.At/1000, (msg.At%1000)*1000)
+		fmtTime := tm.Format("15:04:05")
+		fmt.Fprintf(t.logOptions.Writer, "[%s] %-7s %s\n", fmtTime, msg.Type, msg.Message)
+	}
+	return response.LastID
+}
+
 func (t *cloudTarget) discoverEndpoints(signer *RequestSigner, timeout time.Duration) error {
 	deploymentURL := fmt.Sprintf("%s/application/v4/tenant/%s/application/%s/instance/%s/environment/%s/region/%s",
 		t.cloudAPI,
@@ -256,7 +298,7 @@ func (t *cloudTarget) discoverEndpoints(signer *RequestSigner, timeout time.Dura
 		endpointURL = resp.Endpoints[0].URL
 		return true, nil
 	}
-	if _, err = wait(endpointFunc, req, &t.keyPair, timeout); err != nil {
+	if _, err = wait(endpointFunc, func() *http.Request { return req }, &t.keyPair, timeout); err != nil {
 		return err
 	}
 	if endpointURL == "" {
@@ -278,13 +320,28 @@ func CustomTarget(baseURL string) Target {
 }
 
 // CloudTarget creates a Target for the Vespa Cloud platform.
-func CloudTarget(deployment Deployment, keyPair tls.Certificate, apiKey []byte) Target {
+func CloudTarget(deployment Deployment, keyPair tls.Certificate, apiKey []byte, logOptions LogOptions) Target {
 	return &cloudTarget{
 		cloudAPI:   defaultCloudAPI,
 		targetType: cloudTargetType,
 		deployment: deployment,
 		keyPair:    keyPair,
 		apiKey:     apiKey,
+		logOptions: logOptions,
+	}
+}
+
+// LogLevel returns an int representing a named log level.
+func LogLevel(name string) int {
+	switch name {
+	case "error":
+		return 0
+	case "warning":
+		return 1
+	case "info":
+		return 2
+	default: // everything else, e.g. debug
+		return 3
 	}
 }
 
@@ -296,18 +353,28 @@ type deploymentResponse struct {
 	Endpoints []deploymentEndpoint `json:"endpoints"`
 }
 
+type serviceConvergeResponse struct {
+	Converged bool `json:"converged"`
+}
+
 type jobResponse struct {
-	Active bool   `json:"active"`
-	Status string `json:"status"`
+	Active bool                    `json:"active"`
+	Status string                  `json:"status"`
+	Log    map[string][]logMessage `json:"log"`
+	LastID int64                   `json:"lastId"`
 }
 
-type serviceConvergeResponse struct {
-	Converged bool `json:"converged"`
+type logMessage struct {
+	At      int64  `json:"at"`
+	Type    string `json:"type"`
+	Message string `json:"message"`
 }
 
 type responseFunc func(status int, response []byte) (bool, error)
 
-func wait(fn responseFunc, req *http.Request, certificate *tls.Certificate, timeout time.Duration) (int, error) {
+type requestFunc func() *http.Request
+
+func wait(fn responseFunc, reqFn requestFunc, certificate *tls.Certificate, timeout time.Duration) (int, error) {
 	if certificate != nil {
 		util.ActiveHttpClient.UseCertificate(*certificate)
 	}
@@ -319,7 +386,7 @@ func wait(fn responseFunc, req *http.Request, certificate *tls.Certificate, time
 	deadline := time.Now().Add(timeout)
 	loopOnce := timeout == 0
 	for time.Now().Before(deadline) || loopOnce {
-		response, httpErr = util.HttpDo(req, 10*time.Second, "")
+		response, httpErr = util.HttpDo(reqFn(), 10*time.Second, "")
 		if httpErr == nil {
 			statusCode = response.StatusCode
 			body, err := ioutil.ReadAll(response.Body)
diff --git a/client/go/vespa/target_test.go b/client/go/vespa/target_test.go
index 213b2d93cf8..f4875587593 100644
--- a/client/go/vespa/target_test.go
+++ b/client/go/vespa/target_test.go
@@ -1,6 +1,7 @@
 package vespa
 
 import (
+	"bytes"
 	"crypto/tls"
 	"fmt"
 	"net/http"
@@ -28,7 +29,11 @@ func (v *mockVespaApi) mockVespaHandler(w http.ResponseWriter, req *http.Request
 		if v.deploymentConverged {
 			response = `{"active": false, "status": "success"}`
 		} else {
-			response = `{"active": true, "status": "running"}`
+			response = `{"active": true, "status": "running",
+                         "lastId": 42,
+                         "log": {"deployReal": [{"at": 1631707708431,
+                                                 "type": "info",
+                                                 "message": "Deploying platform version 7.465.17 and application version 1.0.2 ..."}]}}`
 		}
 		w.Write([]byte(response))
 	case "/application/v2/tenant/default/application/default/environment/prod/region/default/instance/default/serviceconverge":
@@ -94,13 +99,15 @@ func TestCloudTargetWait(t *testing.T) {
 	apiKey, err := CreateAPIKey()
 	assert.Nil(t, err)
 
+	var logWriter bytes.Buffer
 	target := CloudTarget(
 		Deployment{
 			Application: ApplicationID{Tenant: "t1", Application: "a1", Instance: "i1"},
 			Zone:        ZoneID{Environment: "dev", Region: "us-north-1"},
 		},
 		x509KeyPair,
-		apiKey)
+		apiKey,
+		LogOptions{Writer: &logWriter})
 	if ct, ok := target.(*cloudTarget); ok {
 		ct.cloudAPI = srv.URL
 	} else {
@@ -120,6 +127,8 @@ func TestCloudTargetWait(t *testing.T) {
 
 	assertServiceWait(t, 500, target, "query")
 	assertServiceWait(t, 500, target, "document")
+
+	assert.Equal(t, "[14:08:28] info    Deploying platform version 7.465.17 and application version 1.0.2 ...\n", logWriter.String())
 }
 
 func assertServiceURL(t *testing.T, url string, target Target, service string) {