verbose output for deploy, run, test (#80)

attest/attest.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/fxamacker/cbor/v2"
+	log "github.com/sirupsen/logrus"
 	"github.com/veraison/go-cose"
 )
 
@@ -91,27 +92,38 @@ func verifyCertChain(cert *x509.Certificate, cabundle [][]byte) error {
 }
 
 func Attest(attestation []byte) (*AttestationDoc, error) {
+	log.Debugf("\n* Verifying Attestation Document")
+	log.Debugf("\t* Creating sign1 from attestation bytes")
 	msg, err := createSign1(attestation)
 	if err != nil {
 		return nil, err
 	}
 
 	doc := &AttestationDoc{}
+	log.Debugf("\t* Unmarshalling cbor document")
 	err = cbor.Unmarshal(msg.Payload, doc)
 	if err != nil {
+		log.Errorf("Error unmarshalling cbor document: %v", err)
 		return nil, err
 	}
 
+	log.Debugf("\t* Generated attestation document")
+	log.Debugf("\t* Parsing x509 certificates")
 	cert, err := x509.ParseCertificate(doc.Certificate)
 	if err != nil {
 		return nil, err
 	}
 
+	log.Debugf("\t* Verifying signature")
 	if err := verifySignature(cert, msg); err != nil {
+		log.Errorf("Error verifying signature: %v", err)
 		return nil, err
 	}
 
+	log.Debugf("\t* Verifying certificate chain (Country: %s, Organization: %s, Locality: %s, Province: %s, Common Name: %s)",
+		cert.Issuer.Country, cert.Issuer.Organization, cert.Issuer.Locality, cert.Issuer.Province, cert.Issuer.CommonName)
 	if err := verifyCertChain(cert, doc.Cabundle); err != nil {
+		log.Errorf("Error verifying certificate chain: %v", err)
 		return nil, err
 	}
 

capetest/capetest.go

@@ -6,9 +6,8 @@ import (
 	"fmt"
 	"net/http"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/gorilla/websocket"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/capeprivacy/cli/attest"
 	"github.com/capeprivacy/cli/crypto"
@@ -48,7 +47,19 @@ func websocketDial(url string, insecure bool) (*websocket.Conn, *http.Response,
 		}
 	}
 
-	return websocket.DefaultDialer.Dial(url, nil)
+	str := fmt.Sprintf("* Dialing %s", url)
+	if insecure {
+		str += " (insecure)"
+	}
+
+	log.Debug(str)
+	c, r, err := websocket.DefaultDialer.Dial(url, nil)
+	if err != nil {
+		return nil, nil, err
+	}
+
+	log.Debugf("* Websocket connection established")
+	return c, r, nil
 }
 
 func CapeTest(testReq TestRequest, endpoint string, insecure bool) (*RunResults, error) {
@@ -77,6 +88,7 @@ func CapeTest(testReq TestRequest, endpoint string, insecure bool) (*RunResults,
 		AuthToken: testReq.AuthToken,
 		Nonce:     nonce,
 	}
+	log.Debug("> Start Request")
 	if err := conn.WriteJSON(startReq); err != nil {
 		return nil, err
 	}
@@ -86,6 +98,7 @@ func CapeTest(testReq TestRequest, endpoint string, insecure bool) (*RunResults,
 		return nil, err
 	}
 
+	log.Debug("< Attestation document")
 	doc, err := runAttestation(attestation.Message)
 	if err != nil {
 		return nil, err
@@ -101,10 +114,12 @@ func CapeTest(testReq TestRequest, endpoint string, insecure bool) (*RunResults,
 		return nil, err
 	}
 
+	log.Debug("> Encrypted function")
 	if err := conn.WriteMessage(websocket.BinaryMessage, encFn); err != nil {
 		return nil, err
 	}
 
+	log.Debug("> Encrypted input")
 	if err := conn.WriteMessage(websocket.BinaryMessage, encInput); err != nil {
 		return nil, err
 	}
@@ -113,6 +128,7 @@ func CapeTest(testReq TestRequest, endpoint string, insecure bool) (*RunResults,
 	if err := conn.ReadJSON(&res); err != nil {
 		return nil, err
 	}
+	log.Debug("< Test Response", res)
 
 	return &res, nil
 }

cmd/cape/cmd/deploy.go

@@ -9,12 +9,8 @@ import (
 	"io"
 	"net/http"
 	"os"
-	"os/signal"
 	"path/filepath"
-	"syscall"
-	"time"
 
-	"github.com/briandowns/spinner"
 	"github.com/gorilla/websocket"
 	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
@@ -89,7 +85,7 @@ func deploy(cmd *cobra.Command, args []string) error {
 		return err
 	}
 
-	fmt.Printf("Success! Deployed function to Cape\nFunction ID ➜ %s\n", dID)
+	log.Infof("Success! Deployed function to Cape\nFunction ID ➜ %s\n", dID)
 
 	return nil
 }
@@ -164,18 +160,8 @@ func Deploy(url string, functionInput string, functionName string, insecure bool
 
 func doDeploy(url string, name string, reader io.Reader, insecure bool) (string, error) {
 	endpoint := fmt.Sprintf("%s/v1/deploy", url)
-	s := spinner.New(spinner.CharSets[26], 300*time.Millisecond)
-	defer s.Stop()
-
-	c := make(chan os.Signal, 1)
-	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
-	go func() {
-		<-c
-		s.Stop()
-		os.Exit(1)
-	}()
-	s.Prefix = "Deploying function to Cape "
-	s.Start()
+
+	log.Info("Deploying function to Cape ...")
 
 	conn, res, err := websocketDial(endpoint, insecure)
 	if err != nil {
@@ -204,19 +190,23 @@ func doDeploy(url string, name string, reader io.Reader, insecure bool) (string,
 	}
 
 	req := DeployRequest{Nonce: nonce, AuthToken: token}
+	log.Debug("\n> Sending Nonce and Auth Token")
 	err = conn.WriteJSON(req)
 	if err != nil {
 		log.Error("error writing deploy request")
 		return "", err
 	}
 
+	log.Debug("* Waiting for attestation document...")
+
 	var msg Message
 	err = conn.ReadJSON(&msg)
 	if err != nil {
 		log.Error("error reading attestation doc")
 		return "", err
 	}
 
+	log.Debug("< Attestation document")
 	doc, err := attest.Attest(msg.Message)
 	if err != nil {
 		log.Error("error attesting")
@@ -235,15 +225,19 @@ func doDeploy(url string, name string, reader io.Reader, insecure bool) (string,
 		return "", err
 	}
 
+	log.Debug("\n> Deploying Encrypted Function")
 	err = writeFunction(conn, bytes.NewBuffer(ciphertext))
 	if err != nil {
 		return "", err
 	}
 
+	log.Debug("* Waiting for deploy response...")
+
 	resData := DeployResponse{}
 	if err := conn.ReadJSON(&resData); err != nil {
 		return "", err
 	}
+	log.Debugf("< Received Deploy Response %v", resData)
 
 	return resData.ID, nil
 }
@@ -255,13 +249,25 @@ func websocketDial(url string, insecure bool) (*websocket.Conn, *http.Response,
 		}
 	}
 
-	return websocket.DefaultDialer.Dial(url, nil)
+	str := fmt.Sprintf("* Dialing %s", url)
+	if insecure {
+		str += " (insecure)"
+	}
+
+	log.Debug(str)
+	c, r, err := websocket.DefaultDialer.Dial(url, nil)
+	if err != nil {
+		return nil, nil, err
+	}
+
+	log.Debugf("* Websocket connection established")
+	return c, r, nil
 }
 
 func writeFunction(conn *websocket.Conn, reader io.Reader) error {
 	writer, err := conn.NextWriter(websocket.BinaryMessage)
 	if err != nil {
-		log.Println("error getting writer for function")
+		log.Errorf("error getting writer for function: %v", err)
 		return err
 	}
 	defer writer.Close()
@@ -284,5 +290,8 @@ func getAuthToken() (string, error) {
 	if t == "" {
 		return "", fmt.Errorf("empty access token (did you run 'cape login'?): %v", err)
 	}
+
+	log.Debug("* Retrieved Auth Token")
+
 	return t, nil
 }

cmd/cape/cmd/root.go

@@ -15,14 +15,33 @@ import (
 var C config.Config
 
 var version = "unknown"
-
 var cfgFile string
 
+type PlainFormatter struct {
+}
+
+func (f *PlainFormatter) Format(entry *log.Entry) ([]byte, error) {
+	return []byte(fmt.Sprintf("%s\n", entry.Message)), nil
+}
+
 // rootCmd represents the base command when called without any subcommands
 var rootCmd = &cobra.Command{
 	Use:   "cape",
 	Short: "Cape command",
 	Long:  `Cape commandline tool`,
+	PersistentPreRunE: func(cmd *cobra.Command, args []string) error {
+		log.SetFormatter(&PlainFormatter{})
+		v, err := cmd.Flags().GetBool("verbose")
+		if err != nil {
+			return err
+		}
+
+		if v {
+			log.SetLevel(log.DebugLevel)
+		}
+
+		return nil
+	},
 }
 
 // ExecuteCLI adds all child commands to the root command and sets flags appropriately.
@@ -37,6 +56,8 @@ func init() {
 	rootCmd.PersistentFlags().StringVar(&cfgFile, "config", "", "config file (default is $HOME/.config/capeprivacy/cape.yaml)")
 	rootCmd.PersistentFlags().StringP("url", "u", "https://newdemo.capeprivacy.com", "Cape Cloud URL")
 	rootCmd.PersistentFlags().Bool("insecure", false, "!!! For development only !!! Disable TLS certificate verification.")
+	rootCmd.PersistentFlags().BoolP("verbose", "v", false, "verbose output")
+
 	if err := rootCmd.PersistentFlags().MarkHidden("insecure"); err != nil {
 		log.Error("flag not found")
 		cobra.CheckErr(err)

cmd/cape/cmd/run.go

@@ -6,9 +6,9 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"os"
 
 	"github.com/gorilla/websocket"
+	"github.com/pkg/errors"
 	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 
@@ -105,7 +105,7 @@ func run(cmd *cobra.Command, args []string) error {
 		return fmt.Errorf("error processing data: %w", err)
 	}
 
-	fmt.Fprintf(os.Stderr, "Success! Results from your function:\n")
+	log.Infof("Success! Results from your function:\n")
 	fmt.Println(string(results))
 	return nil
 }
@@ -139,19 +139,22 @@ func doRun(url string, functionID string, data []byte, insecure bool) ([]byte, e
 	}
 
 	req := RunRequest{Nonce: nonce, AuthToken: token}
+	log.Debug("\n> Sending Nonce and Auth Token")
 	err = c.WriteJSON(req)
 	if err != nil {
-		log.Println("error writing deploy request")
-		return nil, err
+		return nil, errors.Wrap(err, "error writing run request")
 	}
 
+	log.Debug("* Waiting for attestation document...")
+
 	var msg Message
 	err = c.ReadJSON(&msg)
 	if err != nil {
 		log.Println("error reading attestation doc")
 		return nil, err
 	}
 
+	log.Debug("< Auth Completed. Received Attestation Document")
 	doc, err := attest.Attest(msg.Message)
 	if err != nil {
 		log.Println("error attesting")
@@ -164,16 +167,20 @@ func doRun(url string, functionID string, data []byte, insecure bool) ([]byte, e
 		return nil, err
 	}
 
+	log.Debug("\n> Sending Encrypted Inputs")
 	err = writeData(c, encryptedData)
 	if err != nil {
 		return nil, err
 	}
 
+	log.Debug("* Waiting for function results...")
+
 	resData := &RunResponse{}
 	err = c.ReadJSON(&resData)
 	if err != nil {
 		return nil, err
 	}
+	log.Debugf("< Received Function Results.")
 
 	return resData.Message, nil
 }

cmd/cape/cmd/test.go

@@ -8,6 +8,8 @@ import (
 
 	"github.com/spf13/cobra"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/capeprivacy/cli/capetest"
 	czip "github.com/capeprivacy/cli/zip"
 )
@@ -90,6 +92,7 @@ func Test(cmd *cobra.Command, args []string) error {
 		return err
 	}
 
+	log.Info()
 	return nil
 }