Merge lp:~jamesodhunt/snappy/log-commands-that-change-system-state into lp:~snappy-dev/snappy/snappy-moved-to-github

[James Hunt]

* Added logging calls for commands that modify the system state.
* partition/partition.go:
  - Added RootfsLabel() and OtherRootfsLabel() implementations to enable
    rich log messages.
* Upated tests for new functions.

This branch was rather awkward given the way we handle clicks and s-i parts differently. I've tried to keep the log calls as "high up" in the calling stack as possible, but on occasion you'll see that I had to dive down a little lower than desired to fit in with the current code structure.

Note too that there is a small amount of duplication in the logging output:

a) Installing and then removing a snap gives the following:

INFO:snappy:/home/james/go/src/launchpad.net/snappy/snappy/click.go:735:Installed webdm (version 0.1)
INFO:snappy:/home/james/go/src/launchpad.net/snappy/snappy/install.go:92:Installed com.ubuntu.snappy.webdm (version 0.1)
INFO:snappy:/home/james/go/src/launchpad.net/snappy/snappy/snapp.go:322:Removed webdm (version 0.1)

Which of the 2 "Installed" message do we want to keep?

b) s-i parts:

INFO:snappy:/home/james/go/src/launchpad.net/snappy/snappy/systemimage.go:202:Updated system-b partition to version 346
INFO:snappy:/home/james/go/src/launchpad.net/snappy/snappy/systemimage.go:142:Updated system to boot from system-b partition on next boot
INFO:snappy:/home/james/go/src/launchpad.net/snappy/cmd/snappy-go/cmd_update.go:66:Installed ubuntu-core (version 346)

I wonder if we could retain all the s-i messages since:

a) An installed message should be provided for all parts.
b) The other 2 Updated messages are useful as they provide details of the partition (essential IMHO).

[John Lenton (chipaca)]

I don't have answers to your questions (is an MP the right place to ask the questions? are you really asking, or is it your way of exploring future work?). But the branch looks good.

review: Approve

[Michael Vogt (mvo)]

Thanks for working on this!

I started reviewing this branch but I think this needs a quick sync with Sergio before I continue. By doing most of the logging in cmd/snappy webdm will have to duplicate that code.

It seems worthwhile to talk about moving the cmd/ bits into snappy/partition so that he automatically benefits.

I still have some inline comments, it seems like there is value in extracting some of the common pattern(s) into helpers.

review: Needs Information

[John Lenton (chipaca)]

So, talking with mvo and sergiusens, we need to change the approach entirely: we need to change cmd_* to be as simple as possible, and pass loggers (and the other bits) into the library for the library itself to do the logging on the passed in loggers.

review: Disapprove

Unmerged revisions

268. By James Hunt on 2015-03-27

* Sync with lp:snappy.

267. By James Hunt on 2015-03-27

* Added logging calls for commands that modify the system state.
* partition/partition.go:
  - Added RootfsLabel() and OtherRootfsLabel() implementations to enable
    rich log messages.
* Upated tests for new functions.

=== modified file 'cmd/snappy-go/cmd_booted.go'
--- cmd/snappy-go/cmd_booted.go	2015-03-26 13:02:07 +0000
+++ cmd/snappy-go/cmd_booted.go	2015-03-27 15:11:19 +0000
@@ -21,6 +21,8 @@
 	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/priv"
 	"launchpad.net/snappy/snappy"
+
+	"github.com/juju/loggo"
 )
 
 type cmdBooted struct {
@@ -46,5 +48,14 @@
 		return logger.LogError(err)
 	}
 
-	return logger.LogError(parts[0].(*snappy.SystemImagePart).MarkBootSuccessful())
+	si := parts[0].(*snappy.SystemImagePart)
+	if err = si.MarkBootSuccessful(); err != nil {
+		return logger.LogError(err)
+	}
+
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("Partition %s (version %s) booted successfully",
+		si.RootfsLabel(), si.Version())
+
+	return nil
 }

=== modified file 'cmd/snappy-go/cmd_hwassign.go'
--- cmd/snappy-go/cmd_hwassign.go	2015-03-26 09:12:58 +0000
+++ cmd/snappy-go/cmd_hwassign.go	2015-03-27 15:11:19 +0000
@@ -20,6 +20,8 @@
 import (
 	"fmt"
 
+	"github.com/juju/loggo"
+	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/priv"
 	"launchpad.net/snappy/snappy"
 )
@@ -59,6 +61,11 @@
 		return err
 	}
 
-	fmt.Printf("'%s' is now allowed to access '%s'\n", x.Positional.PackageName, x.Positional.DevicePath)
+	msg := fmt.Sprintf("'%s' is now allowed to access '%s'", x.Positional.PackageName, x.Positional.DevicePath)
+	fmt.Printf("%s\n", msg)
+
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("%s", msg)
+
 	return nil
 }

=== modified file 'cmd/snappy-go/cmd_hwunassign.go'
--- cmd/snappy-go/cmd_hwunassign.go	2015-03-26 09:12:58 +0000
+++ cmd/snappy-go/cmd_hwunassign.go	2015-03-27 15:11:19 +0000
@@ -20,6 +20,8 @@
 import (
 	"fmt"
 
+	"github.com/juju/loggo"
+	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/priv"
 	"launchpad.net/snappy/snappy"
 )
@@ -54,6 +56,11 @@
 		return err
 	}
 
-	fmt.Printf("'%s' is no longer allowed to access '%s'\n", x.Positional.PackageName, x.Positional.DevicePath)
+	msg := fmt.Sprintf("'%s' is no longer allowed to access '%s'", x.Positional.PackageName, x.Positional.DevicePath)
+	fmt.Printf("%s\n", msg)
+
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("%s", msg)
+
 	return nil
 }

=== modified file 'cmd/snappy-go/cmd_rollback.go'
--- cmd/snappy-go/cmd_rollback.go	2015-03-26 09:12:58 +0000
+++ cmd/snappy-go/cmd_rollback.go	2015-03-27 15:11:19 +0000
@@ -20,6 +20,8 @@
 import (
 	"fmt"
 
+	"github.com/juju/loggo"
+	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/priv"
 	"launchpad.net/snappy/snappy"
 )
@@ -61,7 +63,12 @@
 	if err != nil {
 		return err
 	}
-	fmt.Printf("Setting %s to version %s\n", pkg, nowVersion)
+
+	msg := fmt.Sprintf("Set %s to version %s", pkg, nowVersion)
+	fmt.Printf("%s\n", msg)
+
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("%s", msg)
 
 	return nil
 }

=== modified file 'cmd/snappy-go/cmd_update.go'
--- cmd/snappy-go/cmd_update.go	2015-03-26 13:02:07 +0000
+++ cmd/snappy-go/cmd_update.go	2015-03-27 15:11:19 +0000
@@ -21,6 +21,8 @@
 	"fmt"
 	"os"
 
+	"github.com/juju/loggo"
+	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/priv"
 	"launchpad.net/snappy/snappy"
 )
@@ -60,6 +62,8 @@
 		if err := part.Install(pbar, 0); err != nil {
 			return err
 		}
+		l := loggo.GetLogger(logger.LoggerName)
+		l.Infof("Installed %s (version %s)", part.Name(), part.Version())
 	}
 
 	if len(updates) > 0 {

=== modified file 'partition/partition.go'
--- partition/partition.go	2015-03-26 09:05:27 +0000
+++ partition/partition.go	2015-03-27 15:11:19 +0000
@@ -142,6 +142,12 @@
 
 	// run the function f with the otherRoot mounted
 	RunWithOther(rw MountOption, f func(otherRoot string) (err error)) (err error)
+
+	// Returns the label for the current partition
+	RootfsLabel() string
+
+	// Returns the label for the other partition
+	OtherRootfsLabel() string
 }
 
 // Partition is the type to interact with the partition
@@ -623,6 +629,16 @@
 	return nil
 }
 
+// RootfsLabel returns the partition label for the current rootfs.
+func (p *Partition) RootfsLabel() string {
+	return p.rootPartition().name
+}
+
+// OtherRootfsLabel returns the partition label for the other rootfs.
+func (p *Partition) OtherRootfsLabel() string {
+	return p.otherRootPartition().name
+}
+
 // Return pointer to blockDevice representing the "other" root
 // filesystem (which is not currently mounted)
 func (p *Partition) otherRootPartition() (result *blockDevice) {

=== modified file 'partition/partition_test.go'
--- partition/partition_test.go	2015-03-26 09:12:58 +0000
+++ partition/partition_test.go	2015-03-27 15:11:19 +0000
@@ -159,6 +159,9 @@
 	c.Assert(other.name, Equals, "system-b")
 	c.Assert(other.device, Equals, "/dev/sda4")
 	c.Assert(other.parentName, Equals, "/dev/sda")
+
+	c.Assert(p.RootfsLabel(), Equals, root.name)
+	c.Assert(p.OtherRootfsLabel(), Equals, other.name)
 }
 
 func (s *PartitionTestSuite) TestRunWithOtherDualParitionRO(c *C) {

=== modified file 'snappy/click.go'
--- snappy/click.go	2015-03-27 11:36:27 +0000
+++ snappy/click.go	2015-03-27 15:11:19 +0000
@@ -42,6 +42,7 @@
 	"launchpad.net/snappy/helpers"
 	"launchpad.net/snappy/logger"
 
+	"github.com/juju/loggo"
 	"github.com/mvo5/goconfigparser"
 )
 
@@ -734,6 +735,9 @@
 		return err
 	}
 
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("Installed %s (version %s)", manifest.Name, manifest.Version)
+
 	return nil
 }
 

=== modified file 'snappy/install.go'
--- snappy/install.go	2015-03-26 13:02:07 +0000
+++ snappy/install.go	2015-03-27 15:11:19 +0000
@@ -22,6 +22,7 @@
 	"os"
 	"strings"
 
+	"github.com/juju/loggo"
 	"launchpad.net/snappy/logger"
 )
 
@@ -81,7 +82,14 @@
 		// act only on parts that are downloadable
 		if !part.IsInstalled() {
 			pbar := NewTextProgress(part.Name())
-			return logger.LogError(part.Install(pbar, flags))
+			err = part.Install(pbar, flags)
+
+			if err != nil {
+				return logger.LogError(err)
+			}
+
+			l := loggo.GetLogger(logger.LoggerName)
+			l.Infof("Installed %s (version %s)", part.Name(), part.Version())
 		}
 	}
 

=== modified file 'snappy/snapp.go'
--- snappy/snapp.go	2015-03-26 13:02:07 +0000
+++ snappy/snapp.go	2015-03-27 15:11:19 +0000
@@ -33,7 +33,9 @@
 	"time"
 
 	"launchpad.net/snappy/helpers"
+	"launchpad.net/snappy/logger"
 
+	"github.com/juju/loggo"
 	"gopkg.in/yaml.v2"
 )
 
@@ -313,7 +315,13 @@
 		return ErrPackageNotRemovable
 	}
 
-	return removeClick(s.basedir)
+	if err = removeClick(s.basedir); err != nil {
+		return logger.LogError(err)
+	}
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("Removed %s (version %s)", s.m.Name, s.m.Version)
+
+	return nil
 }
 
 // Config is used to to configure the snap

=== modified file 'snappy/systemimage.go'
--- snappy/systemimage.go	2015-03-26 13:02:07 +0000
+++ snappy/systemimage.go	2015-03-27 15:11:19 +0000
@@ -27,7 +27,9 @@
 	"strings"
 	"time"
 
+	"github.com/juju/loggo"
 	"launchpad.net/snappy/coreconfig"
+	"launchpad.net/snappy/logger"
 	"launchpad.net/snappy/partition"
 
 	"github.com/mvo5/goconfigparser"
@@ -127,6 +129,21 @@
 	return s.lastUpdate
 }
 
+// toggleNextBootAndLog toggles the rootfs that will be used for the
+// next boot and logs details of the change.
+func (s *SystemImagePart) toggleNextBootAndLog() (err error) {
+	err = s.partition.ToggleNextBoot()
+	if err != nil {
+		return err
+	}
+
+	l := loggo.GetLogger(logger.LoggerName)
+	l.Infof("Updated system to boot from %s partition on next boot",
+		s.partition.OtherRootfsLabel())
+
+	return nil
+}
+
 // SetActive sets the snap active
 func (s *SystemImagePart) SetActive() (err error) {
 	isNextBootOther := s.partition.IsNextBootOther()
@@ -139,7 +156,7 @@
 		return nil
 	}
 
-	return s.partition.ToggleNextBoot()
+	return s.toggleNextBootAndLog()
 }
 
 // Install installs the snap
@@ -175,10 +192,16 @@
 
 	// Check that the final system state is as expected.
 	if err = s.verifyUpgradeWasApplied(); err != nil {
-		return err
+		return logger.LogError(err)
 	}
 
-	return s.partition.ToggleNextBoot()
+	l := loggo.GetLogger(logger.LoggerName)
+
+	l.Infof("Updated %s partition to version %s",
+		s.partition.OtherRootfsLabel(),
+		s.version)
+
+	return s.toggleNextBootAndLog()
 }
 
 // Ensure the expected version update was applied to the expected partition.
@@ -244,6 +267,11 @@
 	return s.partition.MarkBootSuccessful()
 }
 
+// RootfsLabel returns the label for the current root filesystem
+func (s *SystemImagePart) RootfsLabel() string {
+	return s.partition.RootfsLabel()
+}
+
 // Channel returns the system-image-server channel used
 func (s *SystemImagePart) Channel() string {
 	return s.channelName

=== modified file 'snappy/systemimage_test.go'
--- snappy/systemimage_test.go	2015-03-26 09:12:58 +0000
+++ snappy/systemimage_test.go	2015-03-27 15:11:19 +0000
@@ -167,6 +167,14 @@
 	return f("/other")
 }
 
+func (p *MockPartition) RootfsLabel() string {
+	return ""
+}
+
+func (p *MockPartition) OtherRootfsLabel() string {
+	return ""
+}
+
 func (s *SITestSuite) TestSystemImagePartInstallUpdatesPartition(c *C) {
 	// add a update
 	mockSystemImageIndexJSON = fmt.Sprintf(mockSystemImageIndexJSONTemplate, "2")