Merge pull request #33 from buildboxhq/refactor-logging

Refactor logging

agent.go

@@ -3,7 +3,7 @@ package main
 import (
   "os"
   "fmt"
-  "log"
+  "github.com/Sirupsen/logrus"
   "github.com/codegangsta/cli"
   "github.com/buildboxhq/buildbox-agent/buildbox"
 )
@@ -124,6 +124,11 @@ func main() {
 }
 
 func setupAgentFromCli(c *cli.Context, command string) *buildbox.Agent {
+  // Init debugging
+  if c.Bool("debug") {
+    buildbox.LoggerInitDebug()
+  }
+
   agentAccessToken := c.String("access-token")
 
   // Should we look to the environment for the agent access token?
@@ -151,24 +156,20 @@ func setupAgentFromCli(c *cli.Context, command string) *buildbox.Agent {
 
   // Set the agent options
   var agent buildbox.Agent;
-  agent.Debug = c.Bool("debug")
   agent.BootstrapScript = bootstrapScript
 
   // Client specific options
   agent.Client.AgentAccessToken = agentAccessToken
   agent.Client.URL = c.String("url")
-  agent.Client.Debug = agent.Debug
-
-  // Tell the user that debug mode has been enabled
-  if agent.Debug {
-    log.Printf("Debug mode enabled")
-  }
 
   // Setup the agent
   agent.Setup()
 
   // A nice welcome message
-  log.Printf("Started buildbox-agent `%s` (version %s)\n", agent.Name, buildbox.Version)
+  buildbox.Logger.WithFields(logrus.Fields{
+    "pid": os.Getpid(),
+    "version": buildbox.Version,
+  }).Infof("Started buildbox-agent `%s`", agent.Name)
 
   return &agent
 }

artifact.go

@@ -3,7 +3,6 @@ package main
 import (
   "os"
   "fmt"
-  "log"
   "github.com/codegangsta/cli"
   "github.com/buildboxhq/buildbox-agent/buildbox"
 )
@@ -75,6 +74,11 @@ func main() {
         cli.BoolFlag{"debug", "Enable debug mode"},
       },
       Action: func(c *cli.Context) {
+        // Init debugging
+        if c.Bool("debug") {
+          buildbox.LoggerInitDebug()
+        }
+
         agentAccessToken := c.String("agent-access-token")
 
         // Should we look to the environment for the agent access token?
@@ -114,41 +118,34 @@ func main() {
 
         // Set the agent options
         var agent buildbox.Agent;
-        agent.Debug = c.Bool("debug")
 
         // Client specific options
         agent.Client.AgentAccessToken = agentAccessToken
         agent.Client.URL = c.String("url")
-        agent.Client.Debug = agent.Debug
-
-        // Tell the user that debug mode has been enabled
-        if agent.Debug {
-          log.Printf("Debug mode enabled")
-        }
 
         // Setup the agent
         agent.Setup()
 
         // Find the actual job now
         job, err := agent.Client.JobFind(jobId)
         if err != nil {
-          log.Fatalf("Could not find job: %s", jobId)
+          buildbox.Logger.Fatalf("Could not find job: %s", jobId)
         }
 
         // Create artifact structs for all the files we need to upload
         artifacts, err := buildbox.CollectArtifacts(job, paths)
         if err != nil {
-          log.Fatalf("Failed to collect artifacts: %s", err)
+          buildbox.Logger.Fatalf("Failed to collect artifacts: %s", err)
         }
 
         if len(artifacts) == 0 {
-          log.Printf("No files matched paths: %s", paths)
+          buildbox.Logger.Infof("No files matched paths: %s", paths)
         } else {
-          log.Printf("Uploading %d files that match \"%s\"", len(artifacts), paths)
+          buildbox.Logger.Infof("Found %d files that match \"%s\"", len(artifacts), paths)
 
           err := buildbox.UploadArtifacts(agent.Client, job, artifacts, destination)
           if err != nil {
-            log.Fatalf("Failed to upload artifacts: %s", err)
+            buildbox.Logger.Fatalf("Failed to upload artifacts: %s", err)
           }
         }
       },

buildbox/agent.go

@@ -1,7 +1,6 @@
 package buildbox
 
 import (
-  "log"
   "fmt"
   "time"
   "strings"
@@ -22,9 +21,6 @@ type Agent struct {
   // The hostname of the agent
   Hostname string `json:"hostname,omitempty"`
 
-  // Whether to run the agent in Debug mode
-  Debug bool
-
   // The boostrap script to run
   BootstrapScript string
 
@@ -51,7 +47,7 @@ func (a *Agent) Setup() {
   // Figure out the hostname of the current machine
   hostname, err := exec.Command("hostname").Output()
   if err != nil {
-    log.Fatal(err)
+    Logger.Fatal(err)
   }
 
   // Set the hostname
@@ -61,7 +57,7 @@ func (a *Agent) Setup() {
   // current agent struct with data.
   err = a.Client.AgentUpdate(a)
   if err != nil {
-    log.Fatal(err)
+    Logger.Fatal(err)
   }
 }
 
@@ -82,11 +78,11 @@ func (a *Agent) MonitorSignals() {
     // This will block until a signal is sent
     sig := <-signals
 
-    log.Printf("Received signal `%s`", sig.String())
+    Logger.Debugf("Received signal `%s`", sig.String())
 
     // Only monitor certain signals
     if sig != syscall.SIGINT && sig != syscall.SIGUSR2 {
-      log.Printf("Ignoring signal `%s`", sig.String())
+      Logger.Debugf("Ignoring signal `%s`", sig.String())
 
       // Start monitoring signals again
       a.MonitorSignals()
@@ -96,7 +92,7 @@ func (a *Agent) MonitorSignals() {
 
     // If the agent isn't running a job, exit right away
     if a.Job == nil {
-      log.Printf("No jobs running. Exiting...")
+      Logger.Info("No jobs running. Exiting...")
       os.Exit(1)
     }
 
@@ -112,7 +108,7 @@ func (a *Agent) MonitorSignals() {
       // Die time.
       os.Exit(1)
     } else {
-      log.Print("Exiting... Waiting for job to finish before stopping. Send signal again to exit immediately.")
+      Logger.Info("Exiting... Waiting for job to finish before stopping. Send signal again to exit immediately.")
 
       a.stopping = true
     }
@@ -133,7 +129,7 @@ func (a *Agent) Start() {
     for {
       job, err := a.Client.JobNext()
       if err != nil {
-        log.Printf("Failed to get job (%s)", err)
+        Logger.Errorf("Failed to get job (%s)", err)
         break
       }
 
@@ -162,11 +158,11 @@ func (a *Agent) Run(id string) {
   job, err := a.Client.JobFindAndAssign(id)
 
   if err != nil {
-    log.Fatal(err)
+    Logger.Fatal(err)
   }
 
   if job.State != "scheduled" {
-    log.Fatalf("The agent can only run scheduled jobs. Current state is `%s`", job.State)
+    Logger.Fatalf("The agent can only run scheduled jobs. Current state is `%s`", job.State)
   }
 
   // Run the paticular job

buildbox/artifact.go

@@ -4,7 +4,6 @@ import (
   "fmt"
   "os"
   "strings"
-  "log"
   "errors"
   "path/filepath"
   "mime"
@@ -97,6 +96,8 @@ func CollectArtifacts(job *Job, artifactPaths string) (artifacts []*Artifact, er
     glob = strings.TrimSpace(glob)
 
     if glob != "" {
+      Logger.Debugf("Globbing %s for %s", workingDirectory, glob)
+
       files, err := Glob(workingDirectory, glob)
       if err != nil {
         return nil, err
@@ -181,6 +182,8 @@ func UploadArtifacts(client Client, job *Job, artifacts []*Artifact, destination
   var routines []chan string
   var concurrency int = 10
 
+  Logger.Debugf("Spinning up %d concurrent threads for uploads", concurrency)
+
   count := 0
   for _, artifact := range createdArtifacts {
     // Create a channel and apend it to the routines array. Once we've hit our
@@ -192,7 +195,8 @@ func UploadArtifacts(client Client, job *Job, artifacts []*Artifact, destination
     routines = append(routines, wait)
 
     if count >= concurrency {
-      // fmt.Printf("Maxiumum concurrent threads running. Waiting.\n")
+      Logger.Debug("Maxiumum concurrent threads running. Waiting.")
+
       // Wait for all the routines to finish, then reset
       waitForRoutines(routines)
       count = 0
@@ -208,22 +212,22 @@ func UploadArtifacts(client Client, job *Job, artifacts []*Artifact, destination
 
 func uploadRoutine(quit chan string, client Client, job *Job, artifact Artifact, uploader Uploader) {
   // Show a nice message that we're starting to upload the file
-  log.Printf("Uploading %s\n", artifact.Path)
+  Logger.Infof("Uploading %s (%d bytes)", artifact.Path, artifact.FileSize)
 
   // Upload the artifact and then set the state depending on whether or not
   // it passed.
   err := uploader.Upload(&artifact)
   if err != nil {
     artifact.State = "error"
-    log.Printf("Error uploading artifact %s (%s)", artifact.Path, err)
+    Logger.Errorf("Error uploading artifact %s (%s)", artifact.Path, err)
   } else {
     artifact.State = "finished"
   }
 
   // Update the state of the artifact on Buildbox
   _, err = client.ArtifactUpdate(job, artifact)
   if err != nil {
-    log.Printf("Error marking artifact %s as uploaded (%s)", artifact.Path, err)
+    Logger.Errorf("Error marking artifact %s as uploaded (%s)", artifact.Path, err)
   }
 
   // We can notify the channel that this routine has finished now

buildbox/client.go

@@ -2,15 +2,12 @@ package buildbox
 
 import (
   "net/http"
-  "net/http/httputil"
   _ "crypto/sha512" // import sha512 to make sha512 ssl certs work
   "encoding/json"
   "runtime"
   "strings"
   "io"
   "errors"
-  "log"
-  "os"
   "bytes"
 )
 
@@ -27,9 +24,6 @@ type Client struct {
   // The access token of the agent being used to make API requests
   AgentAccessToken string
 
-  // Debug mode can be used to dump the full request and response to stdout.
-  Debug bool
-
   // UserAgent to be provided in API requests. Set to DefaultUserAgent if not
   // specified.
   UserAgent string
@@ -112,9 +106,7 @@ func (c *Client) NewRequest(method string, path string, body interface{}) (*http
 // Submits an HTTP request, checks its response, and deserializes
 // the response into v.
 func (c *Client) DoReq(req *http.Request, v interface{}) error {
-  if c.Debug {
-    log.Printf("%s %s\n", req.Method, req.URL)
-  }
+  Logger.Debugf("%s %s", req.Method, req.URL)
 
   res, err := http.DefaultClient.Do(req)
   if err != nil {
@@ -125,16 +117,6 @@ func (c *Client) DoReq(req *http.Request, v interface{}) error {
   // this function
   defer res.Body.Close()
 
-  if c.Debug {
-    dump, err := httputil.DumpResponse(res, true)
-    if err != nil {
-      log.Println(err)
-    } else {
-      os.Stderr.Write(dump)
-      os.Stderr.Write([]byte{'\n'})
-    }
-  }
-
   // Check the response of the response
   if err = checkResp(res); err != nil {
     return err