From db83055a6278c0edd1597118377556e0e2b31d0e Mon Sep 17 00:00:00 2001 From: Matt Fellows Date: Sun, 5 Jun 2016 14:25:01 +1000 Subject: [PATCH] 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 | 13 ++++++++ command/daemon.go | 5 ++- command/pact_mock_service_cmd.go | 3 ++ command/root.go | 22 +++++++++++++- command/root_test.go | 52 +++++++++++++++++++++++++++++--- command/version_test.go | 7 +---- daemon/daemon.go | 10 ++++-- daemon/pact_mock_service.go | 4 +-- daemon/service.go | 17 ++++++++--- dsl/client.go | 8 ++++- dsl/mock_service.go | 6 +++- dsl/pact.go | 42 ++++++++++++++++++++++---- dsl/pact_test.go | 48 +++++++++++++++++++++++++++++ 13 files changed, 206 insertions(+), 31 deletions(-) diff --git a/README.md b/README.md index 0658fc1c0..b1c74af35 100644 --- a/README.md +++ b/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) diff --git a/command/daemon.go b/command/daemon.go index 24344967f..08a5d119f 100644 --- a/command/daemon.go +++ b/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) } diff --git a/command/pact_mock_service_cmd.go b/command/pact_mock_service_cmd.go index c161c5e0e..ec103e7c7 100644 --- a/command/pact_mock_service_cmd.go +++ b/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) diff --git a/command/root.go b/command/root.go index 1054b50b5..f4148fcef 100644 --- a/command/root.go +++ b/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) + } +} diff --git a/command/root_test.go b/command/root_test.go index 65e8fed49..78ff2a311 100644 --- a/command/root_test.go +++ b/command/root_test.go @@ -1,16 +1,15 @@ 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) @@ -18,3 +17,46 @@ func Test_RootCommand(t *testing.T) { 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)) +} diff --git a/command/version_test.go b/command/version_test.go index f07c3ae2b..79aac2c90 100644 --- a/command/version_test.go +++ b/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) diff --git a/daemon/daemon.go b/daemon/daemon.go index e33c7b12f..a69ef8a24 100644 --- a/daemon/daemon.go +++ b/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,7 +97,7 @@ 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() } @@ -104,12 +105,14 @@ func (d *Daemon) StartDaemon(port int) { // 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 diff --git a/daemon/pact_mock_service.go b/daemon/pact_mock_service.go index b7d073af0..fc9598985 100644 --- a/daemon/pact_mock_service.go +++ b/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() diff --git a/daemon/service.go b/daemon/service.go index f64be1fc7..216114bc1 100644 --- a/daemon/service.go +++ b/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) } diff --git a/dsl/client.go b/dsl/client.go index a53a1f30b..61ee3c8a7 100644 --- a/dsl/client.go +++ b/dsl/client.go @@ -24,6 +24,7 @@ type PactClient struct { } func getHTTPClient(port int) (*rpc.Client, error) { + log.Println("[DEBUG] creating an HTTP client") err := waitForPort(port) if err != nil { return nil, err @@ -34,12 +35,13 @@ func getHTTPClient(port int) (*rpc.Client, error) { // Use this to wait for a daemon to be running prior // to running tests. func waitForPort(port int) error { + log.Println("[DEBUG] waiting for port", port, "to become available") timeout := time.After(timeoutDuration) for { select { case <-timeout: - log.Printf("Expected server to start < %s", timeoutDuration) + log.Printf("[ERROR] Expected server to start < %s", timeoutDuration) return fmt.Errorf("Expected server to start < %s", timeoutDuration) case <-time.After(50 * time.Millisecond): _, err := net.Dial("tcp", fmt.Sprintf(":%d", port)) @@ -52,6 +54,7 @@ func waitForPort(port int) error { // StartServer starts a remote Pact Mock Server. func (p *PactClient) StartServer() *daemon.PactMockServer { + log.Println("[DEBUG] client: starting a server") var res daemon.PactMockServer client, err := getHTTPClient(p.Port) if err == nil { @@ -70,6 +73,7 @@ func (p *PactClient) StartServer() *daemon.PactMockServer { // ListServers starts a remote Pact Mock Server. func (p *PactClient) ListServers() *daemon.PactListResponse { + log.Println("[DEBUG] client: listing servers") var res daemon.PactListResponse client, err := getHTTPClient(p.Port) if err == nil { @@ -83,6 +87,7 @@ func (p *PactClient) ListServers() *daemon.PactListResponse { // StopServer stops a remote Pact Mock Server. func (p *PactClient) StopServer(server *daemon.PactMockServer) *daemon.PactMockServer { + log.Println("[DEBUG] client: stop server") var res daemon.PactMockServer client, err := getHTTPClient(p.Port) if err == nil { @@ -96,6 +101,7 @@ func (p *PactClient) StopServer(server *daemon.PactMockServer) *daemon.PactMockS // StopDaemon remotely shuts down the Pact Daemon. func (p *PactClient) StopDaemon() error { + log.Println("[DEBUG] client: stop daemon") var req, res string client, err := getHTTPClient(p.Port) if err == nil { diff --git a/dsl/mock_service.go b/dsl/mock_service.go index 886db4037..3f81f8cbd 100644 --- a/dsl/mock_service.go +++ b/dsl/mock_service.go @@ -51,7 +51,7 @@ func (m *PactMockService) call(method string, url string, object interface{}) er responseBody, err := ioutil.ReadAll(res.Body) res.Body.Close() - log.Printf("Response Body: %s\n", responseBody) + log.Printf("[DEBUG] mock service response Body: %s\n", responseBody) if res.StatusCode < 200 || res.StatusCode >= 300 { return errors.New(string(responseBody)) } @@ -60,24 +60,28 @@ func (m *PactMockService) call(method string, url string, object interface{}) er // DeleteInteractions removes any previous Mock Service Interactions. func (m *PactMockService) DeleteInteractions() error { + log.Println("[DEBUG] mock service delete interactions") url := fmt.Sprintf("%s/interactions", m.BaseURL) return m.call("DELETE", url, nil) } // AddInteraction adds a new Pact Mock Service interaction. func (m *PactMockService) AddInteraction(interaction *Interaction) error { + log.Println("[DEBUG] mock service add interaction") url := fmt.Sprintf("%s/interactions", m.BaseURL) return m.call("POST", url, interaction) } // Verify confirms that all interactions were called. func (m *PactMockService) Verify() error { + log.Println("[DEBUG] mock service verify") url := fmt.Sprintf("%s/interactions/verification", m.BaseURL) return m.call("GET", url, nil) } // WritePact writes the pact file to disk. func (m *PactMockService) WritePact() error { + log.Println("[DEBUG] mock service write pact") if m.Consumer == "" || m.Provider == "" { return errors.New("Consumer and Provider name need to be provided") } diff --git a/dsl/pact.go b/dsl/pact.go index 305a21531..6ca6cd976 100644 --- a/dsl/pact.go +++ b/dsl/pact.go @@ -2,7 +2,10 @@ package dsl import ( "fmt" + "log" + "os" + "github.com/hashicorp/logutils" "github.com/pact-foundation/pact-go/daemon" ) @@ -25,14 +28,19 @@ type Pact struct { // Interactions contains all of the Mock Service Interactions to be setup. Interactions []*Interaction + + // Log levels + LogLevel string + + // Used to detect if logging has been configured + logFilter *logutils.LevelFilter } // AddInteraction creates a new Pact interaction, initialising all // required things. Will automatically start a Mock Service if none running. func (p *Pact) AddInteraction() *Interaction { - if p.Server == nil { - p.Setup() - } + p.Setup() + log.Printf("[DEBUG] pact add interaction") i := &Interaction{} p.Interactions = append(p.Interactions, i) return i @@ -42,16 +50,37 @@ func (p *Pact) AddInteraction() *Interaction { // suite begins. AddInteraction() will automatically call this if no Mock Server // has been started. func (p *Pact) Setup() *Pact { - client := &PactClient{Port: p.Port} - p.pactClient = client - p.Server = client.StartServer() + p.setupLogging() + log.Printf("[DEBUG] pact setup") + if p.Server == nil { + client := &PactClient{Port: p.Port} + p.pactClient = client + p.Server = client.StartServer() + } return p } +// Configure logging +func (p *Pact) setupLogging() { + if p.logFilter == nil { + if p.LogLevel == "" { + p.LogLevel = "INFO" + } + p.logFilter = &logutils.LevelFilter{ + Levels: []logutils.LogLevel{"DEBUG", "WARN", "ERROR"}, + MinLevel: logutils.LogLevel(p.LogLevel), + Writer: os.Stderr, + } + log.SetOutput(p.logFilter) + } + log.Printf("[DEBUG] pact setup logging") +} + // Teardown stops the Pact Mock Server. This usually is called on completion // of each test suite. func (p *Pact) Teardown() *Pact { + log.Printf("[DEBUG] teardown") p.Server = p.pactClient.StopServer(p.Server) return p @@ -60,6 +89,7 @@ func (p *Pact) Teardown() *Pact { // Verify runs the current test case against a Mock Service. // Will cleanup interactions between tests within a suite. func (p *Pact) Verify(integrationTest func() error) error { + log.Printf("[DEBUG] pact verify") mockServer := &PactMockService{ BaseURL: fmt.Sprintf("http://localhost:%d", p.Server.Port), Consumer: p.Consumer, diff --git a/dsl/pact_test.go b/dsl/pact_test.go index bb2aac13c..d7523f34c 100644 --- a/dsl/pact_test.go +++ b/dsl/pact_test.go @@ -2,7 +2,10 @@ package dsl import ( "fmt" + "io/ioutil" + "log" "net/http" + "os" "strconv" "strings" "testing" @@ -20,6 +23,50 @@ func getPort(url string) int { return i } +func TestPact_setupLogging(t *testing.T) { + res := captureOutput(func() { + (&Pact{LogLevel: "DEBUG"}).setupLogging() + 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() { + (&Pact{LogLevel: "INFO"}).setupLogging() + log.Print("[DEBUG] this should not display") + }) + + if res != "" { + t.Fatalf("Expected log message to be empty but got '%s'", res) + } + + res = captureOutput(func() { + (&Pact{LogLevel: "NONE"}).setupLogging() + log.Print("[ERROR] this should not display") + }) + + if res != "" { + t.Fatalf("Expected log message to be empty but got '%s'", res) + } +} + +// Capture output from a log write +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)) +} + func TestPact_Verify(t *testing.T) { ms := setupMockServer(true, t) defer ms.Close() @@ -136,6 +183,7 @@ func TestPact_Integration(t *testing.T) { Port: 6666, Consumer: "My Consumer", Provider: "My Provider", + LogLevel: "DEBUG", } defer pact.Teardown()