13 files changed, 466 insertions, 15 deletions

diff --git a/cmd/snappy-go/cmd_booted.go b/cmd/snappy-go/cmd_booted.go
index 04639bb640..17117d1740 100644
--- a/cmd/snappy-go/cmd_booted.go
+++ b/cmd/snappy-go/cmd_booted.go
@@ -1,6 +1,9 @@
 package main
 
-import "launchpad.net/snappy/snappy"
+import (
+	"launchpad.net/snappy/logger"
+	"launchpad.net/snappy/snappy"
+)
 
 type cmdBooted struct {
 }
@@ -20,8 +23,8 @@ func (x *cmdBooted) Execute(args []string) (err error) {
 
	parts, err := snappy.InstalledSnapsByType(snappy.SnapTypeCore)
	if err != nil {
-	return err
+	return logger.LogError(err)
	}
 
-	return parts[0].(*snappy.SystemImagePart).MarkBootSuccessful()
+	return logger.LogError(parts[0].(*snappy.SystemImagePart).MarkBootSuccessful())
 }
diff --git a/cmd/snappy-go/cmd_config.go b/cmd/snappy-go/cmd_config.go
index 4606f3147a..1ecffd1db1 100644
--- a/cmd/snappy-go/cmd_config.go
+++ b/cmd/snappy-go/cmd_config.go
@@ -6,6 +6,7 @@ import (
	"io/ioutil"
	"os"
 
+	"launchpad.net/snappy/logger"
	"launchpad.net/snappy/snappy"
 )
 
@@ -29,7 +30,7 @@ func init() {
	if _, err := parser.AddCommand("config", shortConfigHelp, longConfigHelp, &cmdConfigData); err != nil {
	// panic here as something must be terribly wrong if there is an
	// error here
-	panic(err)
+	logger.LogAndPanic(err)
	}
 }
 
diff --git a/cmd/snappy-go/cmd_info.go b/cmd/snappy-go/cmd_info.go
index a04c067bd9..ff43890d38 100644
--- a/cmd/snappy-go/cmd_info.go
+++ b/cmd/snappy-go/cmd_info.go
@@ -5,6 +5,7 @@ import (
	"strings"
 
	"launchpad.net/snappy/helpers"
+	"launchpad.net/snappy/logger"
	"launchpad.net/snappy/snappy"
 )
 
@@ -30,7 +31,7 @@ func init() {
	if _, err := parser.AddCommand("info", shortInfoHelp, longInfoHelp, &cmdInfoData); err != nil {
	// panic here as something must be terribly wrong if there is an
	// error here
-	panic(err)
+	logger.LogAndPanic(err)
	}
 }
 
diff --git a/cmd/snappy-go/cmd_list.go b/cmd/snappy-go/cmd_list.go
index f8e32c3890..e2bb6e74b3 100644
--- a/cmd/snappy-go/cmd_list.go
+++ b/cmd/snappy-go/cmd_list.go
@@ -7,6 +7,7 @@ import (
	"text/tabwriter"
	"time"
 
+	"launchpad.net/snappy/logger"
	"launchpad.net/snappy/snappy"
 )
 
@@ -31,7 +32,7 @@ func init() {
	if err != nil {
	// panic here as something must be terribly wrong if there is an
	// error here
-	panic(err)
+	logger.LogAndPanic(err)
	}
 
	cmd.Aliases = append(cmd.Aliases, "li")
diff --git a/cmd/snappy-go/main.go b/cmd/snappy-go/main.go
index c6e2a01d0b..6abf54126e 100644
--- a/cmd/snappy-go/main.go
+++ b/cmd/snappy-go/main.go
@@ -2,9 +2,12 @@ package main
 
 import (
	"errors"
+	"fmt"
	"os"
	"syscall"
 
+	"launchpad.net/snappy/logger"
+
	"github.com/jessevdk/go-flags"
 )
 
@@ -20,9 +23,9 @@ var optionsData options
 var parser = flags.NewParser(&optionsData, flags.Default)
 
 func init() {
-	if os.Getenv("SNAPPY_DEBUG") != "" {
-	// FIXME: need a global logger!
-	//setupLogger()
+	err := logger.ActivateLogger()
+	if err != nil {
+	fmt.Fprintf(os.Stderr, "WARNING: failed to activate logging: %s\n", err)
	}
 }
 
diff --git a/dependencies.tsv b/dependencies.tsv
index a5be8cb61c..3f9683e167 100644
--- a/dependencies.tsv
+++ b/dependencies.tsv
@@ -1,6 +1,7 @@
 code.google.com/p/go.crypto	hg	69e2a90ed92d03812364aeb947b7068dc42e561e	235
 github.com/cheggaaa/pb	git	e8c7cc515bfde3e267957a3b110080ceed51354e	2014-12-02T07:01:21Z
 github.com/jessevdk/go-flags	git	15347ef417a300349807983f15af9e65cd2e1b3a	2015-01-25T08:53:51Z
+github.com/juju/loggo	git	4c7cbce140ca070eeb59a28f4bf9507e511711f9	2015-02-26T05:51:10Z
 github.com/mvo5/goconfigparser	git	26426272dda20cc76aa1fa44286dc743d2972fe8	2015-02-12T09:37:50Z
 gopkg.in/yaml.v2	git	49c95bdc21843256fb6c4e0d370a05f24a0bf213	2015-02-24T22:57:58Z
 launchpad.net/gocheck	bzr	gustavo@niemeyer.net-20140225173054-xu9zlkf9kxhvow02	87
diff --git a/logger/logger.go b/logger/logger.go
new file mode 100644
index 0000000000..6e238fb93c
--- /dev/null
+++ b/logger/logger.go
@@ -0,0 +1,165 @@
+package logger
+
+import (
+	"fmt"
+	"log/syslog"
+	"runtime/debug"
+	"strings"
+	"time"
+
+	"github.com/juju/loggo"
+)
+
+// Name used in the prefix for all logged messages
+const LoggerName = "snappy"
+
+// LogWriterInterface allows the tests to replace the syslog
+// implementation.
+type LogWriterInterface interface {
+	// syslog.Writer
+	Debug(m string) error
+	Info(m string) error
+	Warning(m string) error
+	Err(m string) error
+	Crit(m string) error
+}
+
+// LogWriter object that handles writing log entries
+type LogWriter struct {
+	systemLog LogWriterInterface
+}
+
+// Write sends the log details specified by the params to the logging
+// back-end (in this case syslog).
+func (l *LogWriter) Write(level loggo.Level, name string, filename string, line int, timestamp time.Time, message string) {
+	var f func(string) error
+
+	record := l.Format(level, name, filename, line, timestamp, message)
+
+	// map log level to syslog priority
+	switch level {
+	case loggo.DEBUG:
+	f = l.systemLog.Debug
+
+	case loggo.INFO:
+	f = l.systemLog.Info
+
+	case loggo.WARNING:
+	f = l.systemLog.Warning
+
+	case loggo.ERROR:
+	f = l.systemLog.Err
+
+	case loggo.CRITICAL:
+	f = l.systemLog.Crit
+	}
+
+	// write the log record.
+	//
+	// Note that with loggo, the actual logging functions never
+	// return errors, so although these syslog functions may fail,
+	// there's not much we can do about it.
+	f(record)
+
+	if level >= loggo.ERROR {
+	l.logStacktrace(level, name, filename, line, timestamp, f)
+	}
+}
+
+func (l *LogWriter) logStacktrace(level loggo.Level, name string, filename string, line int, timestamp time.Time, f func(string) error) {
+	stack := debug.Stack()
+
+	str := "Stack trace:"
+	record := l.Format(level, name, filename, line, timestamp, str)
+	f(record)
+
+	for _, entry := range strings.Split(string(stack), "\n") {
+	if entry == "" {
+	continue
+	}
+
+	formatted := fmt.Sprintf(" %s", strings.Replace(entry, "\t", " ", -1))
+	record := l.Format(level, name, filename, line, timestamp, formatted)
+	f(record)
+	}
+}
+
+// Format handles how each log entry should appear.
+// Note that the timestamp field is not used as syslog adds that for us.
+func (l *LogWriter) Format(level loggo.Level, module, filename string, line int, timestamp time.Time, message string) string {
+	return fmt.Sprintf("%s:%s:%s:%d:%s", level, module, filename, line, message)
+}
+
+// A variable to make testing easier
+var getSyslog = func(priority syslog.Priority, tag string) (w LogWriterInterface, err error) {
+	return syslog.New(syslog.LOG_NOTICE|syslog.LOG_LOCAL0, LoggerName)
+}
+
+// newLogWriter creates a new LogWriter.
+func newLogWriter() (l *LogWriter, err error) {
+
+	l = new(LogWriter)
+
+	// Note that the log level here is just the default - Write()
+	// will alter it as needed.
+	l.systemLog, err = getSyslog(syslog.LOG_NOTICE|syslog.LOG_LOCAL0, LoggerName)
+	if err != nil {
+	return nil, err
+	}
+
+	return l, nil
+}
+
+// ActivateLogger handles creating, configuring and enabling a new syslog logger.
+func ActivateLogger() (err error) {
+	// Remove any existing loggers of the type we care about.
+	//
+	// No check on the success of these operations is performed since the
+	// loggo API does not allow the existing loggers to be iterated so we
+	// cannot know if there is already a syslog writer registered (for
+	// example if newLogWriter() gets called multiple times).
+	_, _, _ = loggo.RemoveWriter("default")
+	_, _, _ = loggo.RemoveWriter("syslog")
+
+	writer, err := newLogWriter()
+	if err != nil {
+	return err
+	}
+
+	// activate our syslog logger
+	err = loggo.RegisterWriter("syslog", writer, loggo.TRACE)
+	if err != nil {
+	return err
+	}
+
+	logger := loggo.GetLogger(LoggerName)
+
+	// ensure that all log messages are output
+	logger.SetLogLevel(loggo.TRACE)
+
+	return nil
+}
+
+// LogAndPanic logs the specified error, including a backtrace, then calls
+// panic().
+func LogAndPanic(err error) {
+	if err == nil {
+	return
+	}
+
+	logger := loggo.GetLogger(LoggerName)
+	logger.Criticalf(err.Error())
+	panic(err)
+}
+
+// LogError logs the specified error (if set), then returns it to be dealt with by
+// higher-level parts of the system.
+func LogError(err error) error {
+	if err == nil {
+	return nil
+	}
+
+	logger := loggo.GetLogger(LoggerName)
+	logger.Errorf(err.Error())
+	return err
+}
diff --git a/logger/logger_test.go b/logger/logger_test.go
new file mode 100644
index 0000000000..85eef9edd3
--- /dev/null
+++ b/logger/logger_test.go
@@ -0,0 +1,269 @@
+package logger
+
+import (
+	"bytes"
+	"errors"
+	"fmt"
+	"log/syslog"
+	"os"
+	"regexp"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/juju/loggo"
+	. "launchpad.net/gocheck"
+)
+
+func Test(t *testing.T) { TestingT(t) }
+
+type LoggerTestSuite struct {
+}
+
+var _ = Suite(&LoggerTestSuite{})
+
+type MockLogWriter struct {
+	buf bytes.Buffer
+}
+
+var mockWriter *MockLogWriter
+
+func mockGetSyslog(priority syslog.Priority, tag string) (w LogWriterInterface, err error) {
+	mockWriter = &MockLogWriter{}
+	return mockWriter, nil
+}
+
+func readLines() (lines []string) {
+	lines = strings.Split(string(mockWriter.buf.Bytes()), "\n")
+
+	// remove the last line if empty due to split.
+	length := len(lines)
+	last := lines[length-1]
+	if last == "" {
+	lines = lines[:length-1]
+	}
+	return lines
+}
+
+func (ts *LoggerTestSuite) SetUpTest(c *C) {
+	getSyslog = mockGetSyslog
+}
+
+func (w *MockLogWriter) write(m string) error {
+	_, err := w.buf.Write([]byte(m))
+	return err
+}
+
+func (w *MockLogWriter) Write(bytes []byte) (n int, err error) {
+	return w.buf.Write(bytes)
+}
+
+func (w *MockLogWriter) Debug(m string) error {
+	_, err := w.buf.Write([]byte(fmt.Sprintf("DEBUG: %s\n", m)))
+	return err
+}
+
+func (w *MockLogWriter) Info(m string) error {
+	_, err := w.buf.Write([]byte(fmt.Sprintf("INFO: %s\n", m)))
+	return err
+}
+
+func (w *MockLogWriter) Warning(m string) error {
+	_, err := w.buf.Write([]byte(fmt.Sprintf("WARNING: %s\n", m)))
+	return err
+}
+
+func (w *MockLogWriter) Err(m string) error {
+	_, err := w.buf.Write([]byte(fmt.Sprintf("ERROR: %s\n", m)))
+	return err
+}
+
+func (w *MockLogWriter) Crit(m string) error {
+	_, err := w.buf.Write([]byte(fmt.Sprintf("CRITICAL: %s\n", m)))
+	return err
+}
+
+// Search for value in array and return true if found
+func sliceContainsString(array []string, value string) bool {
+	str := string(strings.Join(array, ""))
+
+	return strings.Contains(str, value)
+}
+
+// Return true if array contains the patter regex.
+func sliceContainsRegex(array []string, regex string) bool {
+	str := string(strings.Join(array, ""))
+
+	pattern := regexp.MustCompile(regex)
+
+	matches := pattern.FindAllStringSubmatch(str, -1)
+
+	return matches != nil
+}
+
+func fileSize(path string) int64 {
+	st, err := os.Stat(path)
+
+	if err != nil {
+	return -1
+	}
+
+	return st.Size()
+}
+
+func (ts *LoggerTestSuite) TestNewLogWriter(c *C) {
+	w, err := newLogWriter()
+	c.Assert(err, IsNil)
+	c.Assert(w, Not(IsNil))
+	c.Assert(w.systemLog, Not(IsNil))
+}
+
+func (ts *LoggerTestSuite) TestWrite(c *C) {
+	w, err := newLogWriter()
+	c.Assert(err, IsNil)
+	c.Assert(w, Not(IsNil))
+	c.Assert(w.systemLog, Not(IsNil))
+
+	t := time.Now()
+	strTime := fmt.Sprintf("%s", t)
+
+	w.Write(loggo.DEBUG, "module", "filename", 1234, t, "a message")
+	lines := readLines()
+	c.Assert(len(lines), Equals, 1)
+
+	c.Assert(sliceContainsString(lines, "module"), Equals, true)
+	c.Assert(sliceContainsString(lines, "filename"), Equals, true)
+	c.Assert(sliceContainsString(lines, "1234"), Equals, true)
+
+	// We discard the timestamp as syslog adds that itself
+	c.Assert(sliceContainsString(lines, strTime), Equals, false)
+
+	c.Assert(sliceContainsString(lines, "a message"), Equals, true)
+}
+
+func (ts *LoggerTestSuite) TestFormat(c *C) {
+	w, err := newLogWriter()
+	c.Assert(err, IsNil)
+	c.Assert(w, Not(IsNil))
+	c.Assert(w.systemLog, Not(IsNil))
+
+	out := w.Format(loggo.ERROR, "module", "filename", 1234, time.Now(), "a message")
+
+	expected := fmt.Sprintf("%s:%s:%s:%d:%s", "ERROR", "module", "filename", 1234, "a message")
+
+	c.Assert(out, Equals, expected)
+}
+
+func (ts *LoggerTestSuite) TestLogStackTrace(c *C) {
+	var output []string
+
+	w, err := newLogWriter()
+	c.Assert(err, IsNil)
+	c.Assert(w, Not(IsNil))
+
+	f := func(s string) error {
+	output = append(output, s)
+	return nil
+	}
+
+	t := time.Now()
+	strTime := fmt.Sprintf("%s", t)
+
+	w.logStacktrace(loggo.DEBUG, "name", "filename", 9876, t, f)
+
+	c.Assert(sliceContainsString(output, "Stack trace"), Equals, true)
+	c.Assert(sliceContainsString(output, "name"), Equals, true)
+	c.Assert(sliceContainsString(output, "filename"), Equals, true)
+	c.Assert(sliceContainsString(output, "9876"), Equals, true)
+
+	// We discard the timestamp as syslog adds that itself
+	c.Assert(sliceContainsString(output, strTime), Equals, false)
+}
+
+func (ts *LoggerTestSuite) checkLogLevel(c *C, level, msg string) {
+	err := ActivateLogger()
+	c.Assert(err, IsNil)
+
+	expectBacktrace := (level == "ERROR" || level == "CRITICAL")
+
+	logger := loggo.GetLogger("snappy")
+	c.Assert(logger, Not(IsNil))
+
+	switch level {
+	case "DEBUG":
+	c.Assert(logger.IsDebugEnabled(), Equals, true)
+	logger.Debugf(msg)
+
+	case "INFO":
+	c.Assert(logger.IsInfoEnabled(), Equals, true)
+	logger.Infof(msg)
+
+	case "ERROR":
+	c.Assert(logger.IsErrorEnabled(), Equals, true)
+	logger.Errorf(msg)
+
+	case "CRITICAL":
+	// loggo doesn't provide a IsCriticalEnabled()
+	c.Assert(logger.IsErrorEnabled(), Equals, true)
+	logger.Criticalf(msg)
+	}
+
+	lines := readLines()
+
+	if expectBacktrace {
+	c.Assert(len(lines) > 1, Equals, true)
+	} else {
+	c.Assert(len(lines), Equals, 1)
+	}
+
+	needle := fmt.Sprintf("%s.*%s", level, msg)
+	c.Assert(sliceContainsRegex(lines, needle), Equals, true)
+
+	c.Assert(sliceContainsString(lines, "Stack trace"), Equals, expectBacktrace)
+}
+
+func (ts *LoggerTestSuite) TestLogLevels(c *C) {
+	msg := "an error message"
+	levels := []string{"DEBUG", "INFO", "ERROR", "CRITICAL"}
+
+	for _, level := range levels {
+	ts.checkLogLevel(c, level, msg)
+	}
+}
+
+func (ts *LoggerTestSuite) TestLogError(c *C) {
+	level := "ERROR"
+	msg := "I am an error"
+
+	err := ActivateLogger()
+	c.Assert(err, IsNil)
+
+	result := LogError(nil)
+	c.Assert(result, IsNil)
+
+	err = errors.New(msg)
+	c.Assert(err, Not(IsNil))
+
+	// We expect to get back exactly what was passsed...
+	result = LogError(err)
+	c.Assert(result, DeepEquals, err)
+
+	// ... but also to have the error logged
+	ts.checkLogLevel(c, level, msg)
+}
+
+func (ts *LoggerTestSuite) TestLogAndPanic(c *C) {
+	level := "CRITICAL"
+	msg := "I am a fatal error"
+
+	err := ActivateLogger()
+	c.Assert(err, IsNil)
+
+	err = errors.New(msg)
+
+	// expect a panic...
+	c.Assert(func() { LogAndPanic(err) }, Panics, err)
+
+	// ... and a log entry
+	ts.checkLogLevel(c, level, msg)
+}
diff --git a/snappy/click.go b/snappy/click.go
index f7852562f3..8c00da501b 100644
--- a/snappy/click.go
+++ b/snappy/click.go
@@ -23,6 +23,7 @@ import (
	"text/template"
 
	"launchpad.net/snappy/helpers"
+	"launchpad.net/snappy/logger"
 
	"github.com/mvo5/goconfigparser"
 )
@@ -410,7 +411,7 @@ WantedBy=multi-user.target
	}
	if err := t.Execute(&templateOut, wrapperData); err != nil {
	// this can never happen, except we forget a variable
-	panic(err)
+	logger.LogAndPanic(err)
	}
 
	return templateOut.String()
diff --git a/snappy/install.go b/snappy/install.go
index e0cee9595e..f21262ed37 100644
--- a/snappy/install.go
+++ b/snappy/install.go
@@ -5,6 +5,8 @@ import (
	"io/ioutil"
	"os"
	"strings"
+
+	"launchpad.net/snappy/logger"
 )
 
 var cloudMetaDataFile = "/var/lib/cloud/seed/nocloud-net/meta-data"
@@ -47,7 +49,7 @@ func Install(args []string) (err error) {
	flags |= AllowUnauthenticated
	}
	if err := installClick(name, flags); err != nil {
-	return err
+	return logger.LogError(err)
	}
	didSomething = true
	continue
@@ -62,7 +64,7 @@ func Install(args []string) (err error) {
	fmt.Printf("Installing %s\n", part.Name())
	err = part.Install(pbar)
	if err != nil {
-	return err
+	return logger.LogError(err)
	}
	didSomething = true
	}
diff --git a/snappy/remove.go b/snappy/remove.go
index 15b4e7bd71..75ac6625c8 100644
--- a/snappy/remove.go
+++ b/snappy/remove.go
@@ -2,6 +2,8 @@ package snappy
 
 import (
	"strings"
+
+	"launchpad.net/snappy/logger"
 )
 
 // Remove a part by a partSpec string, this can be "name" or "name=version"
@@ -25,5 +27,5 @@ func Remove(partSpec string) error {
	return ErrPackageNotFound
	}
 
-	return part.Uninstall()
+	return logger.LogError(part.Uninstall())
 }
diff --git a/snappy/set.go b/snappy/set.go
index 6bca3d758f..9e3a924691 100644
--- a/snappy/set.go
+++ b/snappy/set.go
@@ -3,6 +3,8 @@ package snappy
 import (
	"fmt"
	"strings"
+
+	"launchpad.net/snappy/logger"
 )
 
 func setActive(pkg, ver string) (err error) {
@@ -43,7 +45,7 @@ func SetProperty(pkgname string, args ...string) (err error) {
	}
	err := f(pkgname, s[1])
	if err != nil {
-	return err
+	return logger.LogError(err)
	}
	}
 
diff --git a/snappy/systemimage.go b/snappy/systemimage.go
index 7d49e9e12c..021c6f7a6c 100644
--- a/snappy/systemimage.go
+++ b/snappy/systemimage.go
@@ -16,7 +16,7 @@ import (
	"time"
 
	"launchpad.net/snappy/coreconfig"
-	partition "launchpad.net/snappy/partition"
+	"launchpad.net/snappy/partition"
 
	"github.com/mvo5/goconfigparser"
 )