Remove paris traceroute and add latency metric (#103)

* remove paris options

* add latency histogram

* add comment about cache lifetime

* add comment about log spaced bins

Author: gfr10598

caller.go

@@ -1,4 +1,4 @@
-// traceroute-caller is a wrapper around the `paris-traceroute` and
+// traceroute-caller is a wrapper around the
 // `scamper` commands and can be invoked in two different poll and
 // listen modes:
 //
@@ -45,14 +45,12 @@ var (
 	scattachBin       = flag.String("scamper.sc_attach", "sc_attach", "The path to the sc_attach binary.")
 	scwarts2jsonBin   = flag.String("scamper.sc_warts2json", "sc_warts2json", "The path to the sc_warts2json binary.")
 	scamperCtrlSocket = flag.String("scamper.unixsocket", "/tmp/scamperctrl", "The name of the UNIX-domain socket that the scamper daemon should listen on")
-	scamperTimeout    = flag.Duration("scamper.timeout", 300*time.Second, "how long to wait to complete a scamper trace.")
-	parisBin          = flag.String("paris.bin", "paris-traceroute", "The path to the paris-traceroute binary.")
-	parisTimeout      = flag.Duration("paris.timeout", 60*time.Second, "how long to wait to complete a paris-traceroute trace.")
+	scamperTimeout    = flag.Duration("scamper.timeout", 900*time.Second, "how long to wait to complete a scamper trace.")
 	outputPath        = flag.String("outputPath", "/var/spool/scamper", "path of output")
 	waitTime          = flag.Duration("waitTime", 5*time.Second, "how long to wait between subsequent listings of open connections")
 	poll              = flag.Bool("poll", true, "Whether the polling method should be used to see new connections.")
 	tracerType        = flagx.Enum{
-		Options: []string{"paris-traceroute", "scamper", "scamper-daemon", "scamper-daemon-with-paris-backup", "scamper-daemon-with-scamper-backup"},
+		Options: []string{"scamper", "scamper-daemon", "scamper-daemon-with-scamper-backup"},
 		Value:   "scamper",
 	}
 
@@ -62,7 +60,7 @@ var (
 )
 
 func init() {
-	flag.Var(&tracerType, "tracetool", "Choose whether paris-traceroute or scamper should be used.")
+	flag.Var(&tracerType, "tracetool", "Choose whether scamper or scamper-daemon should be used.")
 }
 
 func main() {
@@ -89,18 +87,11 @@ func main() {
 		Warts2JSONBinary: *scwarts2jsonBin,
 		ControlSocket:    *scamperCtrlSocket,
 	}
-	parisTracer := &tracer.Paris{
-		Binary:     *parisBin,
-		OutputPath: *outputPath,
-		Timeout:    *parisTimeout,
-	}
 
 	var cache *ipcache.RecentIPCache
 
 	// Set up the cache three different ways, depending on the trace method requested.
 	switch tracerType.Value {
-	case "paris-traceroute":
-		cache = ipcache.New(ctx, parisTracer, *ipcache.IPCacheTimeout, *ipcache.IPCacheUpdatePeriod)
 	case "scamper":
 		cache = ipcache.New(ctx, scamper, *ipcache.IPCacheTimeout, *ipcache.IPCacheUpdatePeriod)
 	case "scamper-daemon":
@@ -122,15 +113,6 @@ func main() {
 			cache.UpdateTracer(scamper)
 			wg.Done()
 		}()
-	case "scamper-daemon-with-paris-backup":
-		cache = ipcache.New(ctx, scamperDaemon, *ipcache.IPCacheTimeout, *ipcache.IPCacheUpdatePeriod)
-		wg.Add(1)
-		go func() {
-			scamperDaemon.MustStart(ctx)
-			// When the scamper daemon dies, switch to paris-traceroute.
-			cache.UpdateTracer(parisTracer)
-			wg.Done()
-		}()
 	}
 
 	if *poll {

caller_test.go

@@ -73,7 +73,7 @@ func TestMainWithConnectionListener(t *testing.T) {
 	*eventsocket.Filename = dir + "/events.sock"
 	*outputPath = dir
 	*poll = false
-	tracerType.Value = "paris-traceroute"
+	tracerType.Value = "scamper"
 
 	ctx, cancel = context.WithCancel(context.Background())
 	go srv.Serve(ctx)
@@ -108,32 +108,8 @@ func TestMainWithBackupScamper(t *testing.T) {
 	main()
 }
 
-func TestMainWithBackupPT(t *testing.T) {
-	dir, err := ioutil.TempDir("", "TestMainWithBackupPT")
-	rtx.Must(err, "Could not create temp dir")
-	defer os.RemoveAll(dir)
-	srv := eventsocket.New(dir + "/events.sock")
-	rtx.Must(srv.Listen(), "Could not start the empty server")
-
-	*prometheusx.ListenAddress = ":0"
-	*eventsocket.Filename = dir + "/events.sock"
-	*outputPath = dir
-	*poll = false
-	*scamperCtrlSocket = dir + "/scamper.sock"
-	*scamperBin = "false"
-	tracerType.Value = "scamper-daemon-with-paris-backup"
-
-	ctx, cancel = context.WithCancel(context.Background())
-	go srv.Serve(ctx)
-	go func() {
-		time.Sleep(1 * time.Second)
-		cancel()
-	}()
-	main()
-}
-
 func TestMainWithBadArgs(t *testing.T) {
-	tracerType.Value = "paris-traceroute"
+	tracerType.Value = "scamper"
 	*eventsocket.Filename = ""
 	*outputPath = "/tmp/"
 	*poll = false

ipcache/ipcache.go

@@ -12,6 +12,8 @@ import (
 
 var (
 	// IPCacheTimeout sets a lower bound on the amount of time between subsequent traceroutes to a single IP address.
+	// Since traces typically take 5 to 10 minutes, this cache timeout should probably be adjusted to something
+	// more like 15 minutes, or perhaps even an hour.
 	IPCacheTimeout = flag.Duration("IPCacheTimeout", 120*time.Second, "Timeout duration in seconds for IPCache")
 
 	// IPCacheUpdatePeriod determines how long to wait between cache-scrubbing attempts.
@@ -91,8 +93,7 @@ func (rc *RecentIPCache) GetCacheLength() int {
 	return len(rc.cache)
 }
 
-// UpdateTracer switches the Tracer being used. This allows us to dynamically
-// switch between scamper and paris-traceroute.
+// UpdateTracer switches the Tracer being used.
 func (rc *RecentIPCache) UpdateTracer(t Tracer) {
 	rc.mu.Lock()
 	defer rc.mu.Unlock()
@@ -117,6 +118,10 @@ func New(ctx context.Context, trace Tracer, ipCacheTimeout, ipCacheUpdatePeriod
 			m.mu.Lock()
 			for k, v := range m.cache {
 				if now.Sub(v.timeStamp) > ipCacheTimeout {
+					// Note that if there is a trace in progress, the events
+					// waiting for it to complete will still get the result
+					// and save it.  But this allows a new trace to be started
+					// on the same IP address.
 					delete(m.cache, k)
 				}
 			}

tracer/paris.go

@@ -91,21 +91,31 @@ func (s *Scamper) trace(conn connection.Connection, t time.Time) (string, error)
 	log.Println("Starting a trace to be put in", filename)
 	buff := bytes.Buffer{}
 
-	_, err = buff.WriteString(GetMetaline(conn, false, ""))
-	// XXX Should not use panic recovery.  Convert these to errors.
+	// WriteString never errors, but may panic on OOM
+	_, _ = buff.WriteString(GetMetaline(conn, false, ""))
+	// TODO Should not use panic recovery.  Convert these to errors.
 	rtx.PanicOnError(err, "Could not write to buffer")
 
 	cmd := pipe.Line(
 		pipe.Exec(s.Binary, "-I", "tracelb -P icmp-echo -q 3 -O ptr "+conn.RemoteIP, "-o-", "-O", "json"),
 		pipe.Write(&buff),
 	)
+	start := time.Now()
 	err = pipe.RunTimeout(cmd, s.ScamperTimeout)
+	latency := time.Since(start).Seconds()
+	if err != nil {
+		traceTimeHistogram.WithLabelValues("error").Observe(latency)
+	} else {
+		traceTimeHistogram.WithLabelValues("success").Observe(latency)
+	}
+
 	tracesPerformed.WithLabelValues("scamper").Inc()
 	if err != nil && err.Error() == pipe.ErrTimeout.Error() {
 		log.Println("Trace timed out: ", cmd)
 		return "", err
 	}
 
+	// TODO - should we really panic here?
 	rtx.PanicOnError(err, "Command %v failed", cmd)
 	rtx.PanicOnError(ioutil.WriteFile(filename, buff.Bytes(), 0666), "Could not save output to file")
 	return buff.String(), nil
@@ -213,10 +223,18 @@ func (d *ScamperDaemon) trace(conn connection.Connection, t time.Time) (string,
 		pipe.Exec(d.Warts2JSONBinary),
 		pipe.Write(&buff),
 	)
+	start := time.Now()
 	err = pipe.RunTimeout(cmd, d.ScamperTimeout)
+	latency := time.Since(start).Seconds()
 	tracesPerformed.WithLabelValues("scamper-daemon").Inc()
+	if err != nil {
+		traceTimeHistogram.WithLabelValues("error").Observe(latency)
+	} else {
+		traceTimeHistogram.WithLabelValues("success").Observe(latency)
+	}
+
 	if err != nil && err.Error() == pipe.ErrTimeout.Error() {
-		log.Println("TimeOut for Trace: ", cmd)
+		log.Println("Trace timed out: ", cmd)
 		return "", err
 	}