Merge pull request #935 from weaveworks/debug-logging

Add debug logging

README.md

@@ -238,6 +238,12 @@ Then, run the local build via
 
 Scope has a collection of built in debugging tools to aid Scope delevopers.
 
+- To get debug information in the logs launch Scope with `--debug`:
+```
+scope launch --debug
+docker logs weavescope
+```
+
 - To have the Scope App or Scope Probe dump their goroutine stacks, run:
 ```
 kill -QUIT $(pgrep -f scope-(app|probe))

app/api_topology.go

@@ -77,7 +77,7 @@ func handleWebsocket(
 ) {
 	conn, err := upgrader.Upgrade(w, r, nil)
 	if err != nil {
-		// log.Println("Upgrade:", err)
+		// log.Info("Upgrade:", err)
 		return
 	}
 	defer conn.Close()

app/controls.go

@@ -1,12 +1,12 @@
 package app
 
 import (
-	"log"
 	"math/rand"
 	"net/http"
 	"net/rpc"
 	"sync"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/gorilla/mux"
 
 	"github.com/weaveworks/scope/common/xfer"
@@ -73,7 +73,7 @@ func (cr *controlRouter) handleControl(w http.ResponseWriter, r *http.Request) {
 	)
 	handler, ok := cr.get(probeID)
 	if !ok {
-		log.Printf("Probe %s is not connected right now...", probeID)
+		log.Errorf("Probe %s is not connected right now...", probeID)
 		http.NotFound(w, r)
 		return
 	}
@@ -101,7 +101,7 @@ func (cr *controlRouter) handleProbeWS(w http.ResponseWriter, r *http.Request) {
 
 	conn, err := upgrader.Upgrade(w, r, nil)
 	if err != nil {
-		log.Printf("Error upgrading to websocket: %v", err)
+		log.Errorf("Error upgrading to websocket: %v", err)
 		return
 	}
 	defer conn.Close()

app/pipes.go

@@ -2,11 +2,11 @@ package app
 
 import (
 	"io"
-	"log"
 	"net/http"
 	"sync"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/gorilla/mux"
 
 	"github.com/weaveworks/scope/common/mtime"
@@ -99,7 +99,7 @@ func (pr *PipeRouter) timeout() {
 
 		if (pipe.ui.refCount == 0 && now.Sub(pipe.ui.lastUsedTime) >= pipeTimeout) ||
 			(pipe.probe.refCount == 0 && now.Sub(pipe.probe.lastUsedTime) >= pipeTimeout) {
-			log.Printf("Timing out pipe %s", id)
+			log.Infof("Timing out pipe %s", id)
 			pipe.Close()
 			pipe.tombstoneTime = now
 		}
@@ -122,7 +122,7 @@ func (pr *PipeRouter) getOrCreate(id string) (*pipe, bool) {
 	defer pr.Unlock()
 	p, ok := pr.pipes[id]
 	if !ok {
-		log.Printf("Creating pipe id %s", id)
+		log.Infof("Creating pipe id %s", id)
 		p = &pipe{
 			ui:    end{lastUsedTime: mtime.Now()},
 			probe: end{lastUsedTime: mtime.Now()},
@@ -178,7 +178,7 @@ func (pr *PipeRouter) handleWs(endSelector func(*pipe) (*end, io.ReadWriter)) fu
 
 		conn, err := upgrader.Upgrade(w, r, nil)
 		if err != nil {
-			log.Printf("Error upgrading to websocket: %v", err)
+			log.Errorf("Error upgrading to websocket: %v", err)
 			return
 		}
 		defer conn.Close()
@@ -191,7 +191,7 @@ func (pr *PipeRouter) delete(w http.ResponseWriter, r *http.Request) {
 	pipeID := mux.Vars(r)["pipeID"]
 	pipe, ok := pr.getOrCreate(pipeID)
 	if ok && pr.retain(pipeID, pipe, &pipe.ui) {
-		log.Printf("Closing pipe %s", pipeID)
+		log.Infof("Closing pipe %s", pipeID)
 		pipe.Close()
 		pipe.tombstoneTime = mtime.Now()
 		pr.release(pipeID, pipe, &pipe.ui)

app/server_helpers.go

@@ -2,15 +2,16 @@ package app
 
 import (
 	"encoding/json"
-	"log"
 	"net/http"
+
+	log "github.com/Sirupsen/logrus"
 )
 
 func respondWith(w http.ResponseWriter, code int, response interface{}) {
 	w.Header().Set("Content-Type", "application/json")
 	w.Header().Add("Cache-Control", "no-cache")
 	w.WriteHeader(code)
 	if err := json.NewEncoder(w).Encode(response); err != nil {
-		log.Print(err)
+		log.Error(err)
 	}
 }

common/sanitize/sanitize.go

@@ -2,10 +2,11 @@ package sanitize
 
 import (
 	"fmt"
-	"log"
 	"net"
 	"net/url"
 	"strings"
+
+	log "github.com/Sirupsen/logrus"
 )
 
 // URL returns a function that sanitizes a URL string. It lets underspecified
@@ -23,7 +24,7 @@ func URL(defaultScheme string, defaultPort int, defaultPath string) func(string)
 		}
 		u, err := url.Parse(s)
 		if err != nil {
-			log.Printf("%q: %v", s, err)
+			log.Errorf("%q: %v", s, err)
 			return s // oh well
 		}
 		if _, port, err := net.SplitHostPort(u.Host); err != nil && defaultPort > 0 {

docker/entrypoint.sh

@@ -88,6 +88,16 @@ while true; do
             fi
             APP_ARGS="$APP_ARGS -$ARG_NAME=$ARG_VALUE"
             ;;
+	--debug)
+            APP_ARGS="$APP_ARGS -log.level=debug"
+	    PROBE_ARGS="$PROBE_ARGS -log.level=debug"
+            ;;
+        --no-app)
+            touch /etc/service/app/down
+            ;;
+        --no-probe)
+            touch /etc/service/probe/down
+            ;;
         --probe.*)
             if echo "$1" | grep "=" 1>/dev/null; then
                 ARG_NAME=$(echo "$1" | sed 's/\-\-probe\.\([^=]*\)=\(.*\)/\1/')
@@ -112,12 +122,6 @@ while true; do
             TOKEN_PROVIDED=true
             touch /etc/service/app/down
             ;;
-        --no-app)
-            touch /etc/service/app/down
-            ;;
-        --no-probe)
-            touch /etc/service/probe/down
-            ;;
         *)
             break
             ;;

probe/appclient/app_client.go

@@ -4,12 +4,12 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"net/rpc"
 	"sync"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/gorilla/websocket"
 
 	"github.com/weaveworks/scope/common/sanitize"
@@ -170,7 +170,7 @@ func (c *appClient) doWithBackoff(msg string, f func() (bool, error)) {
 			continue
 		}
 
-		log.Printf("Error doing %s for %s, backing off %s: %v", msg, c.target, backoff, err)
+		log.Errorf("Error doing %s for %s, backing off %s: %v", msg, c.target, backoff, err)
 		select {
 		case <-time.After(backoff):
 		case <-c.quit:
@@ -192,7 +192,7 @@ func (c *appClient) controlConnection() (bool, error) {
 		return false, err
 	}
 	defer func() {
-		log.Printf("Closing control connection to %s", c.target)
+		log.Infof("Closing control connection to %s", c.target)
 		conn.Close()
 	}()
 
@@ -214,8 +214,8 @@ func (c *appClient) controlConnection() (bool, error) {
 
 func (c *appClient) ControlConnection() {
 	go func() {
-		log.Printf("Control connection to %s starting", c.target)
-		defer log.Printf("Control connection to %s exiting", c.target)
+		log.Infof("Control connection to %s starting", c.target)
+		defer log.Infof("Control connection to %s exiting", c.target)
 		c.doWithBackoff("controls", c.controlConnection)
 	}()
 }
@@ -242,8 +242,8 @@ func (c *appClient) publish(r io.Reader) error {
 
 func (c *appClient) startPublishing() {
 	go func() {
-		log.Printf("Publish loop for %s starting", c.target)
-		defer log.Printf("Publish loop for %s exiting", c.target)
+		log.Infof("Publish loop for %s starting", c.target)
+		defer log.Infof("Publish loop for %s exiting", c.target)
 		c.doWithBackoff("publish", func() (bool, error) {
 			r := <-c.readers
 			if r == nil {
@@ -291,8 +291,8 @@ func (c *appClient) pipeConnection(id string, pipe xfer.Pipe) (bool, error) {
 
 func (c *appClient) PipeConnection(id string, pipe xfer.Pipe) {
 	go func() {
-		log.Printf("Pipe %s connection to %s starting", id, c.target)
-		defer log.Printf("Pipe %s connection to %s exiting", id, c.target)
+		log.Infof("Pipe %s connection to %s starting", id, c.target)
+		defer log.Infof("Pipe %s connection to %s exiting", id, c.target)
 		c.doWithBackoff(id, func() (bool, error) {
 			return c.pipeConnection(id, pipe)
 		})

probe/appclient/multi_client.go

@@ -6,10 +6,11 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"strings"
 	"sync"
 
+	log "github.com/Sirupsen/logrus"
+
 	"github.com/weaveworks/scope/common/xfer"
 	"github.com/weaveworks/scope/report"
 )
@@ -75,13 +76,13 @@ func (c *multiClient) Set(hostname string, endpoints []string) {
 
 			client, err := c.clientFactory(hostname, endpoint)
 			if err != nil {
-				log.Printf("Error creating new app client: %v", err)
+				log.Errorf("Error creating new app client: %v", err)
 				return
 			}
 
 			details, err := client.Details()
 			if err != nil {
-				log.Printf("Error fetching app details: %v", err)
+				log.Errorf("Error fetching app details: %v", err)
 			}
 
 			clients <- clientTuple{details, client}

probe/appclient/resolver.go

@@ -1,12 +1,13 @@
 package appclient
 
 import (
-	"log"
 	"net"
 	"strconv"
 	"strings"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
+
 	"github.com/weaveworks/scope/common/xfer"
 )
 
@@ -74,7 +75,7 @@ func prepare(strs []string) []target {
 			var err error
 			host, port, err = net.SplitHostPort(s)
 			if err != nil {
-				log.Printf("invalid address %s: %v", s, err)
+				log.Errorf("invalid address %s: %v", s, err)
 				continue
 			}
 		} else {

probe/docker/container.go

@@ -5,7 +5,6 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"net/http/httputil"
@@ -15,6 +14,7 @@ import (
 	"sync"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	docker "github.com/fsouza/go-dockerclient"
 
 	"github.com/weaveworks/scope/common/mtime"
@@ -162,30 +162,30 @@ func (c *container) StartGatheringStats() error {
 	}
 
 	go func() {
-		log.Printf("docker container: collecting stats for %s", c.container.ID)
+		log.Infof("docker container: collecting stats for %s", c.container.ID)
 		req, err := http.NewRequest("GET", fmt.Sprintf("/containers/%s/stats", c.container.ID), nil)
 		if err != nil {
-			log.Printf("docker container: %v", err)
+			log.Errorf("docker container: %v", err)
 			return
 		}
 		req.Header.Set("User-Agent", "weavescope")
 
 		url, err := url.Parse(endpoint)
 		if err != nil {
-			log.Printf("docker container: %v", err)
+			log.Errorf("docker container: %v", err)
 			return
 		}
 
 		dial, err := DialStub(url.Scheme, url.Path)
 		if err != nil {
-			log.Printf("docker container: %v", err)
+			log.Errorf("docker container: %v", err)
 			return
 		}
 
 		conn := NewClientConnStub(dial, nil)
 		resp, err := conn.Do(req)
 		if err != nil {
-			log.Printf("docker container: %v", err)
+			log.Errorf("docker container: %v", err)
 			return
 		}
 		defer resp.Body.Close()
@@ -198,21 +198,21 @@ func (c *container) StartGatheringStats() error {
 			c.Lock()
 			defer c.Unlock()
 
-			log.Printf("docker container: stopped collecting stats for %s", c.container.ID)
+			log.Infof("docker container: stopped collecting stats for %s", c.container.ID)
 			c.statsConn = nil
 		}()
 
 		var stats docker.Stats
 		decoder := json.NewDecoder(resp.Body)
 		for err := decoder.Decode(&stats); err != io.EOF; err = decoder.Decode(&stats) {
 			if err != nil {
-				log.Printf("docker container: error reading event, did container stop? %v", err)
+				log.Errorf("docker container: error reading event, did container stop? %v", err)
 				return
 			}
 
 			c.Lock()
 			if c.numPending >= len(c.pendingStats) {
-				log.Printf("docker container: dropping stats.")
+				log.Warnf("docker container: dropping stats.")
 			} else {
 				c.latestStats = stats
 				c.pendingStats[c.numPending] = stats

probe/docker/container_test.go

@@ -5,12 +5,12 @@ import (
 	"encoding/json"
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"testing"
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	client "github.com/fsouza/go-dockerclient"
 
 	"github.com/weaveworks/scope/common/mtime"