Add action logs to model export

Gopkg.toml

@@ -62,7 +62,7 @@
   name = "github.com/juju/bundlechanges"
 
 [[constraint]]
-  revision = "303c0a2ac03fb315309324f8a1f7164b27c8193f"
+  revision = "ef199d6ad38cb2f3c5e32cf9006624e22ee66002"
   name = "github.com/juju/description"
 
 [[constraint]]

api/uniter/unit_test.go

@@ -160,8 +160,8 @@ func (s *unitSuite) TestLogActionMessage(c *gc.C) {
 	c.Assert(err, jc.ErrorIsNil)
 	messages := anAction.Messages()
 	c.Assert(messages, gc.HasLen, 1)
-	c.Assert(messages[0].Message, gc.Equals, "hello")
-	c.Assert(messages[0].Timestamp, gc.NotNil)
+	c.Assert(messages[0].Message(), gc.Equals, "hello")
+	c.Assert(messages[0].Timestamp(), gc.NotNil)
 }
 
 func (s *unitSuite) TestEnsureDead(c *gc.C) {

apiserver/common/action.go

@@ -249,8 +249,8 @@ func MakeActionResult(actionReceiverTag names.Tag, action state.Action) params.A
 	}
 	for _, m := range action.Messages() {
 		result.Log = append(result.Log, params.ActionMessage{
-			Timestamp: m.Timestamp,
-			Message:   m.Message,
+			Timestamp: m.Timestamp(),
+			Message:   m.Message(),
 		})
 	}
 

apiserver/facades/agent/uniter/uniter_test.go

@@ -1151,8 +1151,8 @@ func (s *uniterSuite) TestLogActionMessage(c *gc.C) {
 	c.Assert(err, jc.ErrorIsNil)
 	messages := anAction.Messages()
 	c.Assert(messages, gc.HasLen, 1)
-	c.Assert(messages[0].Message, gc.Equals, "hello")
-	c.Assert(messages[0].Timestamp, gc.NotNil)
+	c.Assert(messages[0].Message(), gc.Equals, "hello")
+	c.Assert(messages[0].Timestamp(), gc.NotNil)
 }
 
 func (s *uniterSuite) TestWatchActionNotifications(c *gc.C) {

apiserver/facades/client/action/action_test.go

@@ -19,6 +19,7 @@ import (
 	"github.com/juju/juju/apiserver/facades/client/action"
 	"github.com/juju/juju/apiserver/params"
 	apiservertesting "github.com/juju/juju/apiserver/testing"
+	"github.com/juju/juju/core/actions"
 	jujutesting "github.com/juju/juju/juju/testing"
 	"github.com/juju/juju/state"
 	statetesting "github.com/juju/juju/state/testing"
@@ -816,7 +817,11 @@ func (s *actionSuite) TestWatchActionProgress(c *gc.C) {
 	a, err := s.Model.Action("1")
 	c.Assert(err, jc.ErrorIsNil)
 	logged := a.Messages()
-	expected, err := json.Marshal(logged[0])
+	c.Assert(logged, gc.HasLen, 1)
+	expected, err := json.Marshal(actions.ActionMessage{
+		Message:   logged[0].Message(),
+		Timestamp: logged[0].Timestamp(),
+	})
 	c.Assert(err, jc.ErrorIsNil)
 
 	wc.AssertChange(string(expected))

state/action.go

@@ -112,8 +112,18 @@ type actionDoc struct {
 
 // ActionMessage represents a progress message logged by an action.
 type ActionMessage struct {
-	Message   string    `bson:"message"`
-	Timestamp time.Time `bson:"timestamp"`
+	MessageValue   string    `bson:"message"`
+	TimestampValue time.Time `bson:"timestamp"`
+}
+
+// Timestamp returns the message timestamp.
+func (m ActionMessage) Timestamp() time.Time {
+	return m.TimestampValue
+}
+
+// Message returns the message string.
+func (m ActionMessage) Message() string {
+	return m.MessageValue
 }
 
 // action represents an instruction to do some "action" and is expected
@@ -268,15 +278,21 @@ func (a *action) Messages() []ActionMessage {
 	result := make([]ActionMessage, len(a.doc.Logs))
 	for i, m := range a.doc.Logs {
 		result[i] = ActionMessage{
-			Message:   m.Message,
-			Timestamp: m.Timestamp.UTC(),
+			MessageValue:   m.MessageValue,
+			TimestampValue: m.TimestampValue.UTC(),
 		}
 	}
 	return result
 }
 
 // Log adds message to the action's progress message array.
 func (a *action) Log(message string) error {
+	// Just to ensure we do not allow bad actions to fill up disk.
+	// 1000 messages should be enough for anyone.
+	if len(a.doc.Logs) > 1000 {
+		logger.Warningf("exceeded 1000 log messages, action may be stuck")
+		return nil
+	}
 	m, err := a.st.Model()
 	if err != nil {
 		return errors.Trace(err)
@@ -298,7 +314,7 @@ func (a *action) Log(message string) error {
 				Id:     a.doc.DocId,
 				Assert: bson.D{{"status", ActionRunning}},
 				Update: bson.D{{"$push", bson.D{
-					{"messages", ActionMessage{Message: message, Timestamp: a.st.nowToTheSecond().UTC()}},
+					{"messages", ActionMessage{MessageValue: message, TimestampValue: a.st.nowToTheSecond().UTC()}},
 				}}},
 			}}
 		return ops, nil

state/action_test.go

@@ -15,6 +15,7 @@ import (
 	gc "gopkg.in/check.v1"
 	"gopkg.in/juju/names.v3"
 
+	"github.com/juju/juju/core/actions"
 	"github.com/juju/juju/state"
 	statetesting "github.com/juju/juju/state/testing"
 	"github.com/juju/juju/testing"
@@ -296,8 +297,8 @@ func (s *ActionSuite) TestActionMessages(c *gc.C) {
 		obtained := a.Messages()
 		c.Assert(obtained, gc.HasLen, i+1)
 		for j, am := range obtained {
-			c.Assert(am.Timestamp, gc.Equals, clock.Now().UTC())
-			c.Assert(am.Message, gc.Equals, messages[j])
+			c.Assert(am.Timestamp(), gc.Equals, clock.Now().UTC())
+			c.Assert(am.Message(), gc.Equals, messages[j])
 		}
 	}
 
@@ -938,17 +939,17 @@ func (s *ActionSuite) TestWatchActionLogs(c *gc.C) {
 		return time.Unix(0, startNow.UnixNano()).Add(offset).UTC()
 	}
 
-	checkExpected := func(wc statetesting.StringsWatcherC, expected []state.ActionMessage) {
+	checkExpected := func(wc statetesting.StringsWatcherC, expected []actions.ActionMessage) {
 		var ch []string
 		s.State.StartSync()
 		select {
 		case ch = <-wc.Watcher.Changes():
 		case <-time.After(testing.LongWait):
 			c.Fatalf("watcher did not send change")
 		}
-		var msg []state.ActionMessage
+		var msg []actions.ActionMessage
 		for i, chStr := range ch {
-			var gotMessage state.ActionMessage
+			var gotMessage actions.ActionMessage
 			err := json.Unmarshal([]byte(chStr), &gotMessage)
 			c.Assert(err, jc.ErrorIsNil)
 			// We can't control the actual time so check for
@@ -965,7 +966,7 @@ func (s *ActionSuite) TestWatchActionLogs(c *gc.C) {
 	defer statetesting.AssertStop(c, w)
 	wc := statetesting.NewStringsWatcherC(c, s.State, w)
 	// make sure the previously pending actions are sent on the watcher
-	expected := []state.ActionMessage{{
+	expected := []actions.ActionMessage{{
 		Timestamp: startNow,
 		Message:   "first",
 	}}
@@ -978,7 +979,7 @@ func (s *ActionSuite) TestWatchActionLogs(c *gc.C) {
 	err = fa1.Log("yet another")
 	c.Assert(err, jc.ErrorIsNil)
 
-	expected = []state.ActionMessage{{
+	expected = []actions.ActionMessage{{
 		Timestamp: startNow,
 		Message:   "another",
 	}, {
@@ -991,7 +992,7 @@ func (s *ActionSuite) TestWatchActionLogs(c *gc.C) {
 	// tracking of already reported messages works.
 	err = fa1.Log("and yet another")
 	c.Assert(err, jc.ErrorIsNil)
-	expected = []state.ActionMessage{{
+	expected = []actions.ActionMessage{{
 		Timestamp: makeTimestamp(0 * time.Second),
 		Message:   "and yet another",
 	}}
@@ -1002,7 +1003,7 @@ func (s *ActionSuite) TestWatchActionLogs(c *gc.C) {
 	defer statetesting.AssertStop(c, w)
 	wc2 := statetesting.NewStringsWatcherC(c, s.State, w2)
 	// make sure the previously pending actions are sent on the watcher
-	expected = []state.ActionMessage{{
+	expected = []actions.ActionMessage{{
 		Timestamp: startNow,
 		Message:   "first",
 	}, {

state/migration_export.go

@@ -1411,7 +1411,7 @@ func (e *exporter) actions() error {
 	e.logger.Debugf("read %d actions", len(actions))
 	for _, action := range actions {
 		results, message := action.Results()
-		e.model.AddAction(description.ActionArgs{
+		arg := description.ActionArgs{
 			Receiver:   action.Receiver(),
 			Name:       action.Name(),
 			Parameters: action.Parameters(),
@@ -1422,7 +1422,13 @@ func (e *exporter) actions() error {
 			Results:    results,
 			Message:    message,
 			Id:         action.Id(),
-		})
+		}
+		messages := action.Messages()
+		arg.Messages = make([]description.ActionMessage, len(messages))
+		for i, m := range messages {
+			arg.Messages[i] = m
+		}
+		e.model.AddAction(arg)
 	}
 	return nil
 }

state/migration_export_test.go

@@ -1365,7 +1365,11 @@ func (s *MigrationExportSuite) TestActions(c *gc.C) {
 	m, err := s.State.Model()
 	c.Assert(err, jc.ErrorIsNil)
 
-	_, err = m.EnqueueAction(machine.MachineTag(), "foo", nil)
+	a, err := m.EnqueueAction(machine.MachineTag(), "foo", nil)
+	c.Assert(err, jc.ErrorIsNil)
+	a, err = a.Begin()
+	c.Assert(err, jc.ErrorIsNil)
+	err = a.Log("hello")
 	c.Assert(err, jc.ErrorIsNil)
 
 	model, err := s.State.Export()
@@ -1375,8 +1379,12 @@ func (s *MigrationExportSuite) TestActions(c *gc.C) {
 	action := actions[0]
 	c.Check(action.Receiver(), gc.Equals, machine.Id())
 	c.Check(action.Name(), gc.Equals, "foo")
-	c.Check(action.Status(), gc.Equals, "pending")
+	c.Check(action.Status(), gc.Equals, "running")
 	c.Check(action.Message(), gc.Equals, "")
+	logs := action.Logs()
+	c.Assert(logs, gc.HasLen, 1)
+	c.Assert(logs[0].Message(), gc.Equals, "hello")
+	c.Assert(logs[0].Timestamp().IsZero(), jc.IsFalse)
 }
 
 func (s *MigrationExportSuite) TestActionsSkipped(c *gc.C) {

state/watcher.go

@@ -25,6 +25,7 @@ import (
 	"gopkg.in/mgo.v2/bson"
 	"gopkg.in/tomb.v2"
 
+	"github.com/juju/juju/core/actions"
 	"github.com/juju/juju/core/instance"
 	"github.com/juju/juju/core/lxdprofile"
 	corenetwork "github.com/juju/juju/core/network"
@@ -2486,8 +2487,10 @@ func (w *actionLogsWatcher) messages() ([]string, error) {
 	}
 	var changes []string
 	for _, m := range doc.Messages {
-		m.Timestamp = m.Timestamp.UTC()
-		mjson, err := json.Marshal(m)
+		mjson, err := json.Marshal(actions.ActionMessage{
+			Message:   m.MessageValue,
+			Timestamp: m.TimestampValue.UTC(),
+		})
 		if err != nil {
 			return nil, errors.Trace(err)
 		}

worker/uniter/runner/context/context_test.go

@@ -388,7 +388,7 @@ func (s *InterfaceSuite) TestLogActionMessage(c *gc.C) {
 	c.Assert(err, jc.ErrorIsNil)
 	messages := a.Messages()
 	c.Assert(messages, gc.HasLen, 1)
-	c.Assert(messages[0].Message, gc.Equals, "hello world")
+	c.Assert(messages[0].Message(), gc.Equals, "hello world")
 }
 
 func (s *InterfaceSuite) TestRequestRebootAfterHook(c *gc.C) {