govc: add '-trace' flag

This flag piggy backs the '-debug' flag, writing formatted SOAP and REST traffic to stderr.

Fixes vmware#1124

govc/README.md

@@ -152,10 +152,18 @@ To configure the debug output you can use two environment variables.
 * `GOVC_DEBUG_PATH`: defaults to ~/.govmomi/debug
 * `GOVC_DEBUG_PATH_RUN`: defaults to timestamp of the run
 
-#### stdout debug
-If you prefer debug output to be sent to stdout and seen while the command is running you can override the file behavior
+The [../scripts/debug-format.sh] script can be used to format the debug output similar to the `-trace` flag.
+
+#### stderr debug
+If you prefer debug output to be sent to stderr and seen while the command is running you can override the file behavior
 by setting the debug path to a dash: `export GOVC_DEBUG_PATH=-`
 
+#### trace flag
+
+The `-trace` flag enables stderr debug, along with formatting the HTTP request and response bodies.
+XML bodies are formatted using `xmlstarlet` or `xmlformat` if installed and JSON bodies using `jq` if installed.
+Formatting can be disabled via `export GOVC_DEBUG_FORMAT=false`.
+
 ### Environment variables
 
 If you're using environment variables to set `GOVC_URL`, verify the values are set as expected:

govc/flags/debug.go

@@ -20,18 +20,43 @@ import (
 	"context"
 	"flag"
 	"fmt"
+	"io"
 	"os"
+	"os/exec"
 	"path/filepath"
 	"strings"
+	"sync"
 	"time"
 
 	"github.com/vmware/govmomi/vim25/debug"
+	"github.com/vmware/govmomi/vim25/soap"
 )
 
+type cmdFormat struct {
+	path string
+	err  error
+	args []string
+}
+
+func (c *cmdFormat) lookPath(file string, args ...string) {
+	c.args = args
+	c.path, c.err = exec.LookPath(file)
+}
+
+func (c *cmdFormat) cmd() (*exec.Cmd, error) {
+	if c.err != nil {
+		return nil, c.err
+	}
+	return exec.Command(c.path, c.args...), nil
+}
+
 type DebugFlag struct {
 	common
 
 	enable bool
+	trace  bool
+	xml    cmdFormat
+	json   cmdFormat
 }
 
 var debugFlagKey = flagKey("debug")
@@ -57,17 +82,100 @@ func (flag *DebugFlag) Register(ctx context.Context, f *flag.FlagSet) {
 
 		usage := fmt.Sprintf("Store debug logs [%s]", env)
 		f.BoolVar(&flag.enable, "debug", enable, usage)
+		f.BoolVar(&flag.trace, "trace", false, "Write SOAP/REST traffic to stderr")
 	})
 }
 
+type cmdFormatCloser struct {
+	rc  io.Closer
+	in  io.Closer
+	cmd *exec.Cmd
+	wg  *sync.WaitGroup
+}
+
+func (c *cmdFormatCloser) Close() error {
+	_ = c.rc.Close()
+	_ = c.in.Close()
+	c.wg.Wait()
+	return c.cmd.Wait()
+}
+
+func (flag *DebugFlag) newFormatReader(rc io.ReadCloser, w io.Writer, ext string) (io.ReadCloser, error) {
+	var err error
+	var cmd *exec.Cmd
+
+	switch ext {
+	case "json":
+		cmd, err = flag.json.cmd()
+		if err != nil {
+			return nil, err
+		}
+	case "xml":
+		cmd, err = flag.xml.cmd()
+		if err != nil {
+			return nil, err
+		}
+	default:
+		return nil, fmt.Errorf("unsupported type %s", ext)
+	}
+
+	cmd.Stderr = os.Stderr
+
+	stdin, err := cmd.StdinPipe()
+	if err != nil {
+		return nil, err
+	}
+
+	stdout, err := cmd.StdoutPipe()
+	if err != nil {
+		return nil, err
+	}
+
+	err = cmd.Start()
+	if err != nil {
+		return nil, err
+	}
+
+	var wg sync.WaitGroup
+	wg.Add(1)
+	go func() {
+		_, _ = io.Copy(w, stdout)
+		wg.Done()
+	}()
+
+	return debug.ReadCloser{
+		Reader: io.TeeReader(rc, stdin),
+		Closer: &cmdFormatCloser{rc, stdin, cmd, &wg},
+	}, nil
+}
+
+func (flag *DebugFlag) debugTrace(rc io.ReadCloser, w io.Writer, ext string) io.ReadCloser {
+	rc, err := flag.newFormatReader(rc, w, ext)
+	if err != nil {
+		return debug.NewTeeReader(rc, w)
+	}
+	return rc
+}
+
 func (flag *DebugFlag) Process(ctx context.Context) error {
+	// Base path for storing debug logs.
+	r := os.Getenv("GOVC_DEBUG_PATH")
+
+	if flag.trace {
+		r = "-"
+		flag.enable = true
+		if os.Getenv("GOVC_DEBUG_FORMAT") != "false" {
+			flag.xml.lookPath("xmlstarlet", "fo")
+			flag.json.lookPath("jq", ".")
+			soap.Trace = flag.debugTrace
+		}
+	}
+
 	if !flag.enable {
 		return nil
 	}
 
 	return flag.ProcessOnce(func() error {
-		// Base path for storing debug logs.
-		r := os.Getenv("GOVC_DEBUG_PATH")
 		switch r {
 		case "-":
 			debug.SetProvider(&debug.LogProvider{})

govc/test/cli.bats

@@ -36,6 +36,12 @@ load test_helper
 
   version=$(govc about -json -c -vim-version 6.8.2 | jq -r .Client.Version)
   assert_equal 6.8.2 "$version" # client specified version
+
+  run govc about -trace
+  assert_success
+
+  run env GOVC_DEBUG_FORMAT=false govc about -trace
+  assert_success
 }
 
 @test "about.cert" {

govc/usage.sh

@@ -7,6 +7,7 @@ done
 common_opts=$(cat <<EOF
   -cert=                    Certificate [GOVC_CERTIFICATE]
   -debug=false              Store debug logs [GOVC_DEBUG]
+  -trace=false              Write SOAP/REST traffic to stderr
   -dump=false               Enable output dump
   -json=false               Enable JSON output
   -xml=false                Enable XML output

scripts/debug-format.sh

@@ -0,0 +1,37 @@
+#!/bin/bash -e
+
+# format the most recent debug run
+cd ${GOVC_DEBUG_PATH-"$HOME/.govmomi/debug"}
+cd $(ls -t | head -1)
+
+header() {
+  printf "<!-- %s %s/%s\n%s\n-->\n" "$1" "$PWD" "$2" "$(tr -d '\r' < "$3")"
+}
+
+jqformat() {
+  jq .
+}
+
+xmlformat() {
+  xmlstarlet fo
+}
+
+for file in *.req.*; do
+  ext=${file##*.}
+  if [ "$ext" = "headers" ] ; then
+    continue
+  fi
+
+  base=$(basename "$file" ".req.$ext")
+  header Request "$file" "${base}.req.headers"
+  format=xmlformat
+  if [ "$ext" = "json" ] ; then
+    format=jqformat
+  fi
+  $format < "$file"
+  file="${base}.res.$ext"
+  if [ -e "$file" ] ; then
+    header Response "$file" "${base}.res.headers"
+    $format < "$file"
+  fi
+done

vim25/debug/debug.go

@@ -29,6 +29,20 @@ type Provider interface {
 	Flush()
 }
 
+// ReadCloser is a struct that satisfies the io.ReadCloser interface
+type ReadCloser struct {
+	io.Reader
+	io.Closer
+}
+
+// NewTeeReader wraps io.TeeReader and patches through the Close() function.
+func NewTeeReader(rc io.ReadCloser, w io.Writer) io.ReadCloser {
+	return ReadCloser{
+		Reader: io.TeeReader(rc, w),
+		Closer: rc,
+	}
+}
+
 var currentProvider Provider = nil
 var scrubPassword = regexp.MustCompile(`<password>(.*)</password>`)
 
@@ -55,8 +69,5 @@ func Flush() {
 }
 
 func Scrub(in []byte) []byte {
-	out := string(in)
-	out = scrubPassword.ReplaceAllString(out, `<password>********</password>`)
-
-	return []byte(out)
+	return scrubPassword.ReplaceAll(in, []byte(`<password>********</password>`))
 }

vim25/debug/log.go

@@ -17,8 +17,9 @@ limitations under the License.
 package debug
 
 import (
+	"fmt"
 	"io"
-	"log"
+	"os"
 )
 
 type LogWriterCloser struct {
@@ -29,7 +30,7 @@ func NewLogWriterCloser() *LogWriterCloser {
 }
 
 func (lwc *LogWriterCloser) Write(p []byte) (n int, err error) {
-	log.Print(string(Scrub(p)))
+	fmt.Fprint(os.Stderr, string(Scrub(p)))
 	return len(p), nil
 }
 
@@ -41,7 +42,6 @@ type LogProvider struct {
 }
 
 func (s *LogProvider) NewFile(p string) io.WriteCloser {
-	log.Print(p)
 	return NewLogWriterCloser()
 }
 

vim25/soap/client.go

@@ -528,8 +528,6 @@ func (c *Client) Do(ctx context.Context, req *http.Request, f func(*http.Respons
 		return err
 	}
 
-	defer res.Body.Close()
-
 	if d.enabled() {
 		d.debugResponse(res, ext)
 	}
@@ -538,6 +536,8 @@ func (c *Client) Do(ctx context.Context, req *http.Request, f func(*http.Respons
 		c.setInsecureCookies(res)
 	}
 
+	defer res.Body.Close()
+
 	return f(res)
 }
 

vim25/soap/debug.go

@@ -27,18 +27,13 @@ import (
 	"github.com/vmware/govmomi/vim25/debug"
 )
 
-// teeReader wraps io.TeeReader and patches through the Close() function.
-type teeReader struct {
-	io.Reader
-	io.Closer
-}
-
-func newTeeReader(rc io.ReadCloser, w io.Writer) io.ReadCloser {
-	return teeReader{
-		Reader: io.TeeReader(rc, w),
-		Closer: rc,
+var (
+	// Trace reads an http request or response from rc and writes to w.
+	// The content type (kind) should be one of "xml" or "json".
+	Trace = func(rc io.ReadCloser, w io.Writer, kind string) io.ReadCloser {
+		return debug.NewTeeReader(rc, w)
 	}
-}
+)
 
 // debugRoundTrip contains state and logic needed to debug a single round trip.
 type debugRoundTrip struct {
@@ -92,7 +87,7 @@ func (d *debugRoundTrip) debugRequest(req *http.Request) string {
 	ext := d.ext(req.Header)
 	// Capture body
 	wc = d.newFile("req." + ext)
-	req.Body = newTeeReader(req.Body, wc)
+	req.Body = Trace(req.Body, wc, ext)
 
 	// Delay closing until marked done
 	d.cs = append(d.cs, wc)
@@ -113,7 +108,7 @@ func (d *debugRoundTrip) debugResponse(res *http.Response, ext string) {
 
 	// Capture body
 	wc = d.newFile("res." + ext)
-	res.Body = newTeeReader(res.Body, wc)
+	res.Body = Trace(res.Body, wc, ext)
 
 	// Delay closing until marked done
 	d.cs = append(d.cs, wc)