feat(logging): standardise log and output messages

Add leveled logging across most key components. Add common flags (--verbose --logLevel( to CLI and
arguments to the Pact DSL to control log level.

README.md

@@ -167,6 +167,19 @@ escape backslashes.
 
 Read more about [flexible matching](https://github.com/realestate-com-au/pact/wiki/Regular-expressions-and-type-matching-with-Pact).
 
+### Output Logging
+
+Pact Go uses a simple log utility ([logutils](https://github.com/hashicorp/logutils))
+to filter log messages. The CLI already contains flags to manage this,
+should you want to control log level in your tests, you can set it like so:
+
+```
+pact := &Pact{
+  ...
+	LogLevel: "DEBUG", // One of DEBUG, INFO, ERROR, NONE
+}
+```
+
 ## Contact
 
 * Twitter: [@pact_up](https://twitter.com/pact_up)

command/daemon.go

@@ -5,18 +5,21 @@ import (
 	"github.com/spf13/cobra"
 )
 
+var port int
 var daemonCmd = &cobra.Command{
 	Use:   "daemon",
 	Short: "Creates a daemon for the Pact DSLs to communicate with",
 	Long:  `Creates a daemon for the Pact DSLs to communicate with`,
 	Run: func(cmd *cobra.Command, args []string) {
+		setLogLevel(verbose, logLevel)
+
 		svc := &daemon.PactMockService{}
 		svc.Setup()
-		port := 6666
 		daemon.NewDaemon(svc).StartDaemon(port)
 	},
 }
 
 func init() {
+	daemonCmd.LocalFlags().IntVarP(&port, "port", "p", 6666, "Local daemon port")
 	RootCmd.AddCommand(daemonCmd)
 }

command/pact_mock_service_cmd.go

@@ -1,6 +1,7 @@
 package command
 
 import (
+	"log"
 	"os"
 	"os/signal"
 
@@ -13,6 +14,8 @@ var mockServiceCmd = &cobra.Command{
 	Short: "Runs the Pact Mock Server",
 	Long:  `Runs the Pact Mock Server on a randomly available port`,
 	Run: func(cmd *cobra.Command, args []string) {
+		log.Println("[DEBUG] starting pact mock server")
+		setLogLevel(verbose, logLevel)
 		c := make(chan os.Signal, 1)
 		signal.Notify(c, os.Interrupt, os.Kill)
 

command/root.go

@@ -2,13 +2,18 @@ package command
 
 import (
 	"fmt"
+	"io/ioutil"
+	"log"
 	"os"
 
+	"github.com/hashicorp/logutils"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 )
 
 var cfgFile string
+var verbose bool
+var logLevel string
 
 // RootCmd represents the base command when called without any subcommands
 var RootCmd = &cobra.Command{
@@ -37,8 +42,10 @@ func init() {
 	// Here you will define your flags and configuration settings.
 	// Cobra supports Persistent Flags, which, if defined here,
 	// will be global for your application.
-
 	RootCmd.PersistentFlags().StringVar(&cfgFile, "config", "", "config file (default is $HOME/.pact-go.yaml)")
+	RootCmd.PersistentFlags().BoolVarP(&verbose, "verbose", "v", true, "verbose output")
+	RootCmd.PersistentFlags().StringVarP(&logLevel, "logLevel", "l", "INFO", "Set the logging level (DEBUG, INFO, ERROR)")
+
 	// Cobra also supports local flags, which will only run
 	// when this action is called directly.
 	RootCmd.Flags().BoolP("toggle", "t", false, "Help message for toggle")
@@ -59,3 +66,16 @@ func initConfig() {
 		fmt.Println("Using config file:", viper.ConfigFileUsed())
 	}
 }
+
+func setLogLevel(verbose bool, level string) {
+	filter := &logutils.LevelFilter{
+		Levels:   []logutils.LogLevel{"DEBUG", "INFO", "ERROR"},
+		MinLevel: logutils.LogLevel(level),
+		Writer:   os.Stderr,
+	}
+	log.SetOutput(filter)
+
+	if !verbose {
+		log.SetOutput(ioutil.Discard)
+	}
+}

command/root_test.go

@@ -1,20 +1,62 @@
 package command
 
 import (
+	"io/ioutil"
+	"log"
 	"os"
+	"strings"
 	"testing"
 )
 
-func init() {
-	// Set CLI flags to simulate real
-	os.Args = []string{"version"}
-}
-
 func Test_RootCommand(t *testing.T) {
+	os.Args = []string{"version"}
 	err := RootCmd.Execute()
 	if err != nil {
 		t.Fatalf("Error: %v", err)
 	}
 
 	Execute()
 }
+
+func Test_LogLevel(t *testing.T) {
+	res := captureOutput(func() {
+		setLogLevel(true, "DEBUG")
+		log.Println("[DEBUG] this should display")
+	})
+
+	if !strings.Contains(res, "[DEBUG] this should display") {
+		t.Fatalf("Expected log message to contain '[DEBUG] this should display' but got '%s'", res)
+	}
+
+	res = captureOutput(func() {
+		setLogLevel(true, "INFO")
+		log.Print("[DEBUG] this should not display")
+	})
+
+	if res != "" {
+		t.Fatalf("Expected log message to be empty but got '%s'", res)
+	}
+
+	res = captureOutput(func() {
+		setLogLevel(false, "INFO")
+		log.Print("[DEBUG] this should not display")
+	})
+
+	if res != "" {
+		t.Fatalf("Expected log message to be empty but got '%s'", res)
+	}
+}
+
+func captureOutput(action func()) string {
+	rescueStderr := os.Stderr
+	r, w, _ := os.Pipe()
+	os.Stderr = w
+
+	action()
+
+	w.Close()
+	out, _ := ioutil.ReadAll(r)
+	os.Stderr = rescueStderr
+
+	return strings.TrimSpace(string(out))
+}

command/version_test.go

@@ -5,13 +5,8 @@ import (
 	"testing"
 )
 
-func init() {
-	// Set CLI flags to simulate real
-	// os.Args = append(os.Args, "version")
-	os.Args = []string{"version"}
-}
-
 func Test_VersionCommand(t *testing.T) {
+	os.Args = []string{"version"}
 	err := versionCmd.Execute()
 	if err != nil {
 		t.Fatalf("Error: %v", err)

daemon/daemon.go

@@ -4,6 +4,7 @@ package daemon
 
 import (
 	"fmt"
+	"log"
 	"net"
 	"net/http"
 	"net/rpc"
@@ -70,7 +71,7 @@ func NewDaemon(pactMockServiceManager Service) *Daemon {
 
 // StartDaemon starts the daemon RPC server.
 func (d *Daemon) StartDaemon(port int) {
-	fmt.Println("Starting daemon on port", port)
+	log.Println("[INFO] daemon - starting daemon on port", port)
 
 	serv := rpc.NewServer()
 	serv.Register(d)
@@ -96,20 +97,22 @@ func (d *Daemon) StartDaemon(port int) {
 	// Wait for sigterm
 	signal.Notify(d.signalChan, os.Interrupt, os.Kill)
 	s := <-d.signalChan
-	fmt.Println("Got signal:", s, ". Shutting down all services")
+	log.Println("[INFO] daemon - received signal:", s, ", shutting down all services")
 
 	d.Shutdown()
 }
 
 // StopDaemon allows clients to programmatically shuts down the running Daemon
 // via RPC.
 func (d *Daemon) StopDaemon(request string, reply *string) error {
+	log.Println("[DEBUG] daemon - stop daemon")
 	d.signalChan <- os.Interrupt
 	return nil
 }
 
 // Shutdown ensures all services are cleanly destroyed.
 func (d *Daemon) Shutdown() {
+	log.Println("[DEBUG] daemon - shutdown")
 	for _, s := range d.pactMockSvcManager.List() {
 		if s != nil {
 			d.pactMockSvcManager.Stop(s.Process.Pid)
@@ -120,6 +123,7 @@ func (d *Daemon) Shutdown() {
 // StartServer starts a mock server and returns a pointer to aPactMockServer
 // struct.
 func (d *Daemon) StartServer(request *PactMockServer, reply *PactMockServer) error {
+	log.Println("[DEBUG] daemon - starting mock server")
 	server := &PactMockServer{}
 	port, svc := d.pactMockSvcManager.NewService(request.Args)
 	server.Port = port
@@ -132,6 +136,7 @@ func (d *Daemon) StartServer(request *PactMockServer, reply *PactMockServer) err
 
 // ListServers returns a slice of all running PactMockServers.
 func (d *Daemon) ListServers(request PactMockServer, reply *PactListResponse) error {
+	log.Println("[DEBUG] daemon - listing mock servers")
 	var servers []*PactMockServer
 
 	for port, s := range d.pactMockSvcManager.List() {
@@ -150,6 +155,7 @@ func (d *Daemon) ListServers(request PactMockServer, reply *PactListResponse) er
 
 // StopServer stops the given mock server.
 func (d *Daemon) StopServer(request *PactMockServer, reply *PactMockServer) error {
+	log.Println("[DEBUG] daemon - stopping mock server")
 	success, err := d.pactMockSvcManager.Stop(request.Pid)
 	if success == true {
 		request.Status = 0

daemon/pact_mock_service.go

@@ -21,15 +21,13 @@ func (m *PactMockService) NewService(args []string) (int, Service) {
 	dir, _ := os.Getwd()
 	logDir := fmt.Sprintf(filepath.Join(dir, "logs"))
 	dir = fmt.Sprintf(filepath.Join(dir, "pacts"))
-	log.Println("Starting mock service on port:", port)
+	log.Println("[DEBUG] starting mock service on port:", port)
 
 	m.Args = []string{
 		fmt.Sprintf("--port %d", port),
 		fmt.Sprintf("--pact-specification-version %d", version),
 		fmt.Sprintf("--pact-dir %s", dir),
 		fmt.Sprintf("--log %s/pact.log", logDir),
-		fmt.Sprintf("--cors"),
-		// fmt.Sprintf("--ssl"),
 	}
 	m.Args = append(m.Args, args...)
 	m.Command = getCommandPath()

daemon/service.go

@@ -3,6 +3,7 @@ package daemon
 import (
 	"bufio"
 	"fmt"
+	"log"
 	"os"
 	"os/exec"
 )
@@ -29,6 +30,7 @@ type ServiceManager struct {
 
 // Setup the Management services.
 func (s *ServiceManager) Setup() {
+	log.Println("[DEBUG] setting up a service manager")
 	s.commandCreatedChan = make(chan *exec.Cmd)
 	s.commandCompleteChan = make(chan *exec.Cmd)
 	s.processes = make(map[int]*exec.Cmd)
@@ -40,6 +42,7 @@ func (s *ServiceManager) Setup() {
 
 // addServiceMonitor watches a channel to add services into operation.
 func (s *ServiceManager) addServiceMonitor() {
+	log.Println("[DEBUG] starting service creation monitor")
 	for {
 		select {
 		case p := <-s.commandCreatedChan:
@@ -52,6 +55,7 @@ func (s *ServiceManager) addServiceMonitor() {
 
 // removeServiceMonitor watches a channel to remove services from operation.
 func (s *ServiceManager) removeServiceMonitor() {
+	log.Println("[DEBUG] starting service removal monitor")
 	var p *exec.Cmd
 	for {
 		select {
@@ -66,6 +70,7 @@ func (s *ServiceManager) removeServiceMonitor() {
 
 // Stop a Service and returns the exit status.
 func (s *ServiceManager) Stop(pid int) (bool, error) {
+	log.Println("[DEBUG] stopping service with pid", pid)
 	cmd := s.processes[pid]
 
 	// Remove service from registry
@@ -84,43 +89,45 @@ func (s *ServiceManager) Stop(pid int) (bool, error) {
 
 // List all Service PIDs.
 func (s *ServiceManager) List() map[int]*exec.Cmd {
+	log.Println("[DEBUG] listing services")
 	return s.processes
 }
 
 // Start a Service and log its output.
 func (s *ServiceManager) Start() *exec.Cmd {
+	log.Println("[DEBUG] starting service")
 	cmd := exec.Command(s.Command, s.Args...)
 	cmd.Env = s.Env
 
 	cmdReader, err := cmd.StdoutPipe()
 	if err != nil {
-		fmt.Fprintln(os.Stderr, "Error creating StdoutPipe for Cmd", err)
+		log.Printf("[ERROR] unable to create output pipe for cmd: %s\n", err.Error())
 		os.Exit(1)
 	}
 
 	cmdReaderErr, err := cmd.StderrPipe()
 	if err != nil {
-		fmt.Fprintln(os.Stderr, "Error creating StdoutPipe for Cmd", err)
+		log.Printf("[ERROR] unable to create error pipe for cmd: %s\n", err.Error())
 		os.Exit(1)
 	}
 
 	scanner := bufio.NewScanner(cmdReader)
 	go func() {
 		for scanner.Scan() {
-			fmt.Printf("error: | %s\n", scanner.Text())
+			log.Printf("[ERROR] %s\n", scanner.Text())
 		}
 	}()
 
 	scanner2 := bufio.NewScanner(cmdReaderErr)
 	go func() {
 		for scanner2.Scan() {
-			fmt.Printf("mock-service:  %s\n", scanner2.Text())
+			log.Printf("[INFO] service: %s\n", scanner2.Text())
 		}
 	}()
 
 	err = cmd.Start()
 	if err != nil {
-		fmt.Fprintln(os.Stderr, "Error starting Cmd", err)
+		log.Println("[ERROR] service", err.Error())
 		os.Exit(1)
 	}