Add a start time parameter to debug-log endpoint

Christian Muirhead · Christian Muirhead · commit 9155be145a78 · 2016-11-30T14:46:31.000+13:00
This is needed to make the migration log transfer process step
restartable without too many duplicated log records.

Add the start time parameter to the client, but not to the debug-log
command at the moment. I'll add a bug to add it there.
diff --git a/api/client_test.go b/api/client_test.go
@@ -13,6 +13,7 @@ import (
 	"net/url"
 	"path"
 	"strings"
+	"time"
 
 	"github.com/juju/errors"
 	"github.com/juju/httprequest"
@@ -445,6 +446,7 @@ func (s *clientSuite) TestWatchDebugLogParamsEncoded(c *gc.C) {
 		Level:         loggo.ERROR,
 		Replay:        true,
 		NoTail:        true,
+		StartTime:     time.Date(2016, 11, 30, 11, 48, 0, 100, time.UTC),
 	}
 
 	client := s.APIState.Client()
@@ -463,6 +465,7 @@ func (s *clientSuite) TestWatchDebugLogParamsEncoded(c *gc.C) {
 		"level":         {"ERROR"},
 		"replay":        {"true"},
 		"noTail":        {"true"},
+		"startTime":     {"2016-11-30T11:48:00.0000001Z"},
 	})
 }
 
diff --git a/api/common/logs.go b/api/common/logs.go
@@ -50,6 +50,9 @@ type DebugLogParams struct {
 	// NoTail tells the server to only return the logs it has now, and not
 	// to wait for new logs to arrive.
 	NoTail bool
+	// StartTime should be a time in the past - only records with a
+	// log time on or after StartTime will be returned.
+	StartTime time.Time
 }
 
 func (args DebugLogParams) URLQuery() url.Values {
@@ -74,6 +77,9 @@ func (args DebugLogParams) URLQuery() url.Values {
 	if args.Level != loggo.UNSPECIFIED {
 		attrs.Set("level", fmt.Sprint(args.Level))
 	}
+	if !args.StartTime.IsZero() {
+		attrs.Set("startTime", args.StartTime.Format(time.RFC3339Nano))
+	}
 	return attrs
 }
 
diff --git a/apiserver/debuglog.go b/apiserver/debuglog.go
@@ -9,6 +9,7 @@ import (
 	"net/url"
 	"strconv"
 	"syscall"
+	"time"
 
 	"github.com/juju/errors"
 	"github.com/juju/loggo"
@@ -144,6 +145,7 @@ func (s *debugLogSocketImpl) sendLogRecord(record *params.LogMessage) error {
 
 // debugLogParams contains the parsed debuglog API request parameters.
 type debugLogParams struct {
+	startTime     time.Time
 	maxLines      uint
 	fromTheStart  bool
 	noTail        bool
@@ -200,6 +202,17 @@ func readDebugLogParams(queryMap url.Values) (*debugLogParams, error) {
 		params.filterLevel = level
 	}
 
+	if value := queryMap.Get("startTime"); value != "" {
+		startTime, err := time.Parse(time.RFC3339Nano, value)
+		if err != nil {
+			return nil, errors.Errorf("start time %q is not a valid time in RFC3339 format", value)
+		}
+		if startTime.After(time.Now()) {
+			return nil, errors.Errorf("start time %q is in the future", value)
+		}
+		params.startTime = startTime
+	}
+
 	params.includeEntity = queryMap["includeEntity"]
 	params.excludeEntity = queryMap["excludeEntity"]
 	params.includeModule = queryMap["includeModule"]
diff --git a/apiserver/debuglog_db.go b/apiserver/debuglog_db.go
@@ -58,6 +58,7 @@ func makeLogTailerParams(reqParams *debugLogParams) *state.LogTailerParams {
 	params := &state.LogTailerParams{
 		MinLevel:      reqParams.filterLevel,
 		NoTail:        reqParams.noTail,
+		StartTime:     reqParams.startTime,
 		InitialLines:  int(reqParams.backlog),
 		IncludeEntity: reqParams.includeEntity,
 		ExcludeEntity: reqParams.excludeEntity,
diff --git a/apiserver/debuglog_db_internal_test.go b/apiserver/debuglog_db_internal_test.go
@@ -30,10 +30,12 @@ func (s *debugLogDBIntSuite) SetUpTest(c *gc.C) {
 }
 
 func (s *debugLogDBIntSuite) TestParamConversion(c *gc.C) {
+	t1 := time.Date(2016, 11, 30, 10, 51, 0, 0, time.UTC)
 	reqParams := &debugLogParams{
 		fromTheStart:  false,
 		noTail:        true,
 		backlog:       11,
+		startTime:     t1,
 		filterLevel:   loggo.INFO,
 		includeEntity: []string{"foo"},
 		includeModule: []string{"bar"},
@@ -47,7 +49,7 @@ func (s *debugLogDBIntSuite) TestParamConversion(c *gc.C) {
 
 		// Start time will be used once the client is extended to send
 		// time range arguments.
-		c.Assert(params.StartTime.IsZero(), jc.IsTrue)
+		c.Assert(params.StartTime, gc.Equals, t1)
 		c.Assert(params.NoTail, jc.IsTrue)
 		c.Assert(params.MinLevel, gc.Equals, loggo.INFO)
 		c.Assert(params.InitialLines, gc.Equals, 11)
diff --git a/featuretests/dblog_test.go b/featuretests/dblog_test.go
@@ -210,3 +210,49 @@ func (s *debugLogDbSuite) TestLogsAPI(c *gc.C) {
 		Message:   "beep beep",
 	})
 }
+
+func (s *debugLogDbSuite) TestLogsUsesStartTime(c *gc.C) {
+	dbLogger := state.NewEntityDbLogger(s.State, names.NewMachineTag("99"), version.Current)
+	defer dbLogger.Close()
+
+	t1 := time.Date(2015, 6, 23, 13, 8, 49, 100, time.UTC)
+	// Check that start time has subsecond resolution.
+	t2 := time.Date(2015, 6, 23, 13, 8, 51, 50, time.UTC)
+	t3 := t1.Add(2 * time.Second)
+	t4 := t1.Add(4 * time.Second)
+	dbLogger.Log(t1, "juju.foo", "code.go:42", loggo.INFO, "spinto band")
+	dbLogger.Log(t2, "juju.quux", "ok.go:101", loggo.INFO, "king gizzard and the lizard wizard")
+	dbLogger.Log(t3, "juju.bar", "go.go:99", loggo.ERROR, "born ruffians")
+	dbLogger.Log(t4, "juju.baz", "go.go.go:23", loggo.WARNING, "cold war kids")
+
+	client := s.APIState.Client()
+	logMessages, err := client.WatchDebugLog(api.DebugLogParams{
+		StartTime: t3,
+	})
+	c.Assert(err, jc.ErrorIsNil)
+
+	assertMessage := func(expected api.LogMessage) {
+		select {
+		case actual := <-logMessages:
+			c.Assert(actual, jc.DeepEquals, expected)
+		case <-time.After(coretesting.LongWait):
+			c.Fatal("timed out waiting for log line")
+		}
+	}
+	assertMessage(api.LogMessage{
+		Entity:    "machine-99",
+		Timestamp: t3,
+		Severity:  "ERROR",
+		Module:    "juju.bar",
+		Location:  "go.go:99",
+		Message:   "born ruffians",
+	})
+	assertMessage(api.LogMessage{
+		Entity:    "machine-99",
+		Timestamp: t4,
+		Severity:  "WARNING",
+		Module:    "juju.baz",
+		Location:  "go.go.go:23",
+		Message:   "cold war kids",
+	})
+}

Original file line number	Diff line number	Diff line change
`@@ -50,6 +50,9 @@ type DebugLogParams struct {`
`50`	`50`	`// NoTail tells the server to only return the logs it has now, and not`
`51`	`51`	`// to wait for new logs to arrive.`
`52`	`52`	`NoTail bool`
	`53`	`+ // StartTime should be a time in the past - only records with a`
	`54`	`+ // log time on or after StartTime will be returned.`
	`55`	`+ StartTime time.Time`
`53`	`56`	`}`
`54`	`57`
`55`	`58`	`func (args DebugLogParams) URLQuery() url.Values {`
`@@ -74,6 +77,9 @@ func (args DebugLogParams) URLQuery() url.Values {`
`74`	`77`	`if args.Level != loggo.UNSPECIFIED {`
`75`	`78`	`attrs.Set("level", fmt.Sprint(args.Level))`
`76`	`79`	`}`
	`80`	`+ if !args.StartTime.IsZero() {`
	`81`	`+ attrs.Set("startTime", args.StartTime.Format(time.RFC3339Nano))`
	`82`	`+ }`
`77`	`83`	`return attrs`
`78`	`84`	`}`
`79`	`85`