Merge lp:~chipaca/snappy/logs into lp:~snappy-dev/snappy/snappy-moved-to-github

[John Lenton]

add "logs" to the service command.

Logs!

[lp:~chipaca/snappy/logs]

647. By John Lenton on 2015-09-03

lint & etc

648. By John Lenton on 2015-09-03

found a problem with the format, fixed and added test

[Michael Vogt (mvo)]

Looks very nice, thanks!

review: Approve

=== modified file 'cmd/snappy/cmd_service.go'
--- cmd/snappy/cmd_service.go	2015-08-24 10:51:07 +0000
+++ cmd/snappy/cmd_service.go	2015-09-03 15:54:41 +0000
@@ -38,19 +38,23 @@
 	Restart svcRestart `command:"restart"`
 	Enable  svcEnable  `command:"enable"`
 	Disable svcDisable `command:"disable"`
+	Logs    svcLogs    `command:"logs"`
 }
+
 type svcBase struct {
 	Args struct {
 		Snap    string `positional-arg-name:"snap"`
 		Service string `positional-arg-name:"service"`
 	} `positional-args:"yes"`
 }
+
 type svcStatus struct{ svcBase }
 type svcStart struct{ svcBase }
 type svcStop struct{ svcBase }
 type svcRestart struct{ svcBase }
 type svcEnable struct{ svcBase }
 type svcDisable struct{ svcBase }
+type svcLogs struct{ svcBase }
 
 func init() {
 	_, err := parser.AddCommand("service",
@@ -71,6 +75,7 @@
 	doRestart
 	doEnable
 	doDisable
+	doLogs
 )
 
 func (s *svcBase) doExecute(cmd int) ([]string, error) {
@@ -82,6 +87,8 @@
 	switch cmd {
 	case doStatus:
 		return actor.Status()
+	case doLogs:
+		return actor.Loglines()
 	case doStart:
 		return nil, actor.Start()
 	case doStop:
@@ -127,6 +134,21 @@
 	return err
 }
 
+func (s *svcLogs) Execute([]string) error {
+	return withMutex(func() error {
+		logs, err := s.doExecute(doLogs)
+		if err != nil {
+			return err
+		}
+
+		for i := range logs {
+			fmt.Println(logs[i])
+		}
+
+		return nil
+	})
+}
+
 func (s *svcStart) Execute(args []string) error {
 	return withMutex(func() error {
 		_, err := s.doExecute(doStart)

=== modified file 'po/snappy.pot'
--- po/snappy.pot	2015-08-24 10:51:07 +0000
+++ po/snappy.pot	2015-09-03 15:54:41 +0000
@@ -7,7 +7,7 @@
 msgid   ""
 msgstr  "Project-Id-Version: snappy\n"
         "Report-Msgid-Bugs-To: [e-mail]\n"
-        "POT-Creation-Date: 2015-08-24 11:49+0100\n"
+        "POT-Creation-Date: 2015-09-03 13:19+0100\n"
         "PO-Revision-Date: YEAR-MO-DA HO:MI+ZONE\n"
         "Last-Translator: FULL NAME <EMAIL@ADDRESS>\n"
         "Language-Team: LANGUAGE <[e-mail]>\n"
@@ -346,6 +346,10 @@
 msgid   "unable to enable %s's service %s: %v"
 msgstr  ""
 
+#, c-format
+msgid   "unable to get logs: %v"
+msgstr  ""
+
 #. TRANSLATORS: the first %s is the package name, the second is the service name; the %v is the error
 #, c-format
 msgid   "unable to start %s's service %s: %v"

=== modified file 'snappy/service.go'
--- snappy/service.go	2015-08-24 10:51:07 +0000
+++ snappy/service.go	2015-09-03 15:54:41 +0000
@@ -178,3 +178,36 @@
 
 	return nil
 }
+
+// Logs for all found services.
+func (actor *ServiceActor) Logs() ([]systemd.Log, error) {
+	var svcnames []string
+
+	for _, svc := range actor.svcs {
+		svcname := filepath.Base(generateServiceFileName(svc.m, *svc.svc))
+		svcnames = append(svcnames, svcname)
+	}
+
+	logs, err := actor.sysd.Logs(svcnames)
+	if err != nil {
+		return nil, fmt.Errorf(i18n.G("unable to get logs: %v"), err)
+	}
+
+	return logs, nil
+}
+
+// Loglines serializes the logs for all found services
+func (actor *ServiceActor) Loglines() ([]string, error) {
+	var lines []string
+
+	logs, err := actor.Logs()
+	if err != nil {
+		return nil, err
+	}
+
+	for i := range logs {
+		lines = append(lines, logs[i].String())
+	}
+
+	return lines, nil
+}

=== modified file 'snappy/service_test.go'
--- snappy/service_test.go	2015-08-24 10:51:07 +0000
+++ snappy/service_test.go	2015-09-03 15:54:41 +0000
@@ -35,6 +35,10 @@
 	argses [][]string
 	outs   [][]byte
 	errors []error
+	j      int
+	jsvcs  [][]string
+	jouts  [][]byte
+	jerrs  []error
 	pb     progress.Meter
 }
 
@@ -52,17 +56,38 @@
 	s.i++
 	return out, err
 }
+func (s *ServiceActorSuite) myJctl(svcs []string) (out []byte, err error) {
+	s.jsvcs = append(s.jsvcs, svcs)
+
+	if s.j < len(s.jouts) {
+		out = s.jouts[s.j]
+	}
+	if s.j < len(s.jerrs) {
+		err = s.jerrs[s.j]
+	}
+	s.j++
+
+	return out, err
+}
 
 func (s *ServiceActorSuite) SetUpTest(c *C) {
+	// force UTC timezone, for reproducible timestamps
+	os.Setenv("TZ", "")
+
 	SetRootDir(c.MkDir())
 	// TODO: this mkdir hack is so enable doesn't fail; remove when enable is the same as the rest
 	c.Assert(os.MkdirAll(filepath.Join(globalRootDir, "/etc/systemd/system/multi-user.target.wants"), 0755), IsNil)
 	systemd.SystemctlCmd = s.myRun
+	systemd.JournalctlCmd = s.myJctl
 	makeInstalledMockSnap(globalRootDir, "")
 	s.i = 0
 	s.argses = nil
 	s.errors = nil
 	s.outs = nil
+	s.j = 0
+	s.jsvcs = nil
+	s.jouts = nil
+	s.jerrs = nil
 	s.pb = &MockProgressMeter{}
 }
 
@@ -115,6 +140,11 @@
 		nil,                // status
 		&systemd.Timeout{}, // flag
 	}
+	s.jerrs = nil
+	s.jouts = [][]byte{
+		[]byte(`{"foo": "bar", "baz": 42}`),                    // for the Logs call
+		[]byte(`{"__REALTIME_TIMESTAMP":"42","MESSAGE":"hi"}`), // for the Loglines call
+	}
 
 	c.Check(actor.Stop(), IsNil)
 	c.Check(actor.Start(), IsNil)
@@ -125,6 +155,12 @@
 	c.Check(err, IsNil)
 	c.Assert(status, HasLen, 1)
 	c.Check(status[0], Equals, "hello-app\tsvc1\tenabled; loaded; active (running)")
+	logs, err := actor.Logs()
+	c.Check(err, IsNil)
+	c.Check(logs, DeepEquals, []systemd.Log{{"foo": "bar", "baz": 42.}})
+	lines, err := actor.Loglines()
+	c.Check(err, IsNil)
+	c.Check(lines, DeepEquals, []string{"1970-01-01T00:00:00.000042Z - hi"})
 }
 
 func (s *ServiceActorSuite) TestFindServicesReportsErrors(c *C) {
@@ -135,12 +171,6 @@
 
 	anError := errors.New("error")
 
-	s.outs = [][]byte{
-		nil,
-		nil,
-		nil,
-		nil,
-	}
 	s.errors = []error{
 		anError, // stop
 		anError, // start
@@ -149,6 +179,7 @@
 		anError, // disable
 		anError, // status
 	}
+	s.jerrs = []error{anError, anError}
 
 	c.Check(actor.Stop(), NotNil)
 	c.Check(actor.Start(), NotNil)
@@ -157,4 +188,8 @@
 	c.Check(actor.Disable(), NotNil)
 	_, err = actor.Status()
 	c.Check(err, NotNil)
+	_, err = actor.Logs()
+	c.Check(err, NotNil)
+	_, err = actor.Loglines()
+	c.Check(err, NotNil)
 }

=== modified file 'systemd/systemd.go'
--- systemd/systemd.go	2015-08-24 10:51:07 +0000
+++ systemd/systemd.go	2015-09-03 15:54:41 +0000
@@ -21,11 +21,14 @@
 
 import (
 	"bytes"
+	"encoding/json"
 	"fmt"
+	"io"
 	"os"
 	"os/exec"
 	"path/filepath"
 	"regexp"
+	"strconv"
 	"strings"
 	"text/template"
 	"time"
@@ -58,6 +61,26 @@
 // systemctl. It's exported so it can be overridden by testing.
 var SystemctlCmd = run
 
+// jctl calls journalctl to get the JSON logs of the given services, wrapping the error if any.
+func jctl(svcs []string) ([]byte, error) {
+	cmd := []string{"journalctl", "-o", "json"}
+
+	for i := range svcs {
+		cmd = append(cmd, "-u", svcs[i])
+	}
+
+	bs, err := exec.Command(cmd[0], cmd[1:]...).Output() // journalctl can be messy with its stderr
+	if err != nil {
+		exitCode, _ := helpers.ExitCode(err)
+		return nil, &Error{cmd: cmd, exitCode: exitCode, msg: bs}
+	}
+
+	return bs, nil
+}
+
+// JournalctlCmd is called from Logs to run journalctl; exported for testing.
+var JournalctlCmd = jctl
+
 // Systemd exposes a minimal interface to manage systemd via the systemctl command.
 type Systemd interface {
 	DaemonReload() error
@@ -69,8 +92,12 @@
 	Restart(service string, timeout time.Duration) error
 	GenServiceFile(desc *ServiceDescription) string
 	Status(service string) (string, error)
+	Logs(services []string) ([]Log, error)
 }
 
+// A Log is a single entry in the systemd journal
+type Log map[string]interface{}
+
 // ServiceDescription describes a snappy systemd service
 type ServiceDescription struct {
 	AppName     string
@@ -142,6 +169,38 @@
 	return err
 }
 
+// Logs for the given service
+func (*systemd) Logs(serviceNames []string) ([]Log, error) {
+	bs, err := JournalctlCmd(serviceNames)
+	if err != nil {
+		return nil, err
+	}
+
+	const noEntries = "-- No entries --\n"
+	if len(bs) == len(noEntries) && string(bs) == noEntries {
+		return nil, nil
+	}
+
+	var logs []Log
+	dec := json.NewDecoder(bytes.NewReader(bs))
+	for {
+		var log Log
+
+		err = dec.Decode(&log)
+		if err != nil {
+			break
+		}
+
+		logs = append(logs, log)
+	}
+
+	if err != io.EOF {
+		return nil, err
+	}
+
+	return logs, nil
+}
+
 var statusregex = regexp.MustCompile(`(?m)^(?:(.*?)=(.*))?$`)
 
 func (s *systemd) Status(serviceName string) (string, error) {
@@ -313,3 +372,33 @@
 	_, isTimeout := err.(*Timeout)
 	return isTimeout
 }
+
+const myFmt = "2006-01-02T15:04:05.000000Z07:00"
+
+func (l Log) String() string {
+	t := "-(no timestamp!)-"
+	if ius, ok := l["__REALTIME_TIMESTAMP"]; ok {
+		// according to systemd.journal-fields(7) it's microseconds as a decimal string
+		sus, ok := ius.(string)
+		if ok {
+			if us, err := strconv.ParseInt(sus, 10, 64); err == nil {
+				t = time.Unix(us/1000000, 1000*(us%1000000)).Format(myFmt)
+			} else {
+				t = fmt.Sprintf("-(timestamp not a decimal number: %#v)-", sus)
+			}
+		} else {
+			t = fmt.Sprintf("-(timestamp not a string: %#v)-", ius)
+		}
+	}
+
+	sid, ok := l["SYSLOG_IDENTIFIER"].(string)
+	if !ok {
+		sid = "-"
+	}
+	msg, ok := l["MESSAGE"].(string)
+	if !ok {
+		msg = "-"
+	}
+
+	return fmt.Sprintf("%s %s %s", t, sid, msg)
+}

=== modified file 'systemd/systemd_test.go'
--- systemd/systemd_test.go	2015-08-24 10:51:07 +0000
+++ systemd/systemd_test.go	2015-09-03 15:54:41 +0000
@@ -48,22 +48,39 @@
 	argses [][]string
 	errors []error
 	outs   [][]byte
-	rep    *testreporter
+
+	j     int
+	jsvcs [][]string
+	jouts [][]byte
+	jerrs []error
+
+	rep *testreporter
 }
 
 var _ = Suite(&SystemdTestSuite{})
 
 func (s *SystemdTestSuite) SetUpTest(c *C) {
+	// force UTC timezone, for reproducible timestamps
+	os.Setenv("TZ", "")
+
 	SystemctlCmd = s.myRun
 	s.i = 0
 	s.argses = nil
 	s.errors = nil
 	s.outs = nil
+
+	JournalctlCmd = s.myJctl
+	s.j = 0
+	s.jsvcs = nil
+	s.jouts = nil
+	s.jerrs = nil
+
 	s.rep = new(testreporter)
 }
 
 func (s *SystemdTestSuite) TearDownTest(c *C) {
 	SystemctlCmd = run
+	JournalctlCmd = jctl
 }
 
 func (s *SystemdTestSuite) myRun(args ...string) (out []byte, err error) {
@@ -78,6 +95,20 @@
 	return out, err
 }
 
+func (s *SystemdTestSuite) myJctl(svcs []string) (out []byte, err error) {
+	s.jsvcs = append(s.jsvcs, svcs)
+
+	if s.j < len(s.jouts) {
+		out = s.jouts[s.j]
+	}
+	if s.j < len(s.jerrs) {
+		err = s.jerrs[s.j]
+	}
+	s.j++
+
+	return out, err
+}
+
 func (s *SystemdTestSuite) errorRun(args ...string) (out []byte, err error) {
 	return nil, &Error{cmd: args, exitCode: 1, msg: []byte("error on error")}
 }
@@ -312,3 +343,55 @@
 	c.Check(IsTimeout(os.ErrInvalid), Equals, false)
 	c.Check(IsTimeout(&Timeout{}), Equals, true)
 }
+
+func (s *SystemdTestSuite) TestLogErrJctl(c *C) {
+	s.jerrs = []error{&Timeout{}}
+
+	logs, err := New("", s.rep).Logs([]string{"foo"})
+	c.Check(err, NotNil)
+	c.Check(logs, IsNil)
+	c.Check(s.jsvcs, DeepEquals, [][]string{{"foo"}})
+	c.Check(s.j, Equals, 1)
+}
+
+func (s *SystemdTestSuite) TestLogErrJSON(c *C) {
+	s.jouts = [][]byte{[]byte("this is not valid json.")}
+
+	logs, err := New("", s.rep).Logs([]string{"foo"})
+	c.Check(err, NotNil)
+	c.Check(logs, IsNil)
+	c.Check(s.jsvcs, DeepEquals, [][]string{{"foo"}})
+	c.Check(s.j, Equals, 1)
+}
+
+func (s *SystemdTestSuite) TestLogs(c *C) {
+	s.jouts = [][]byte{[]byte(`{"a": 1}
+{"a": 2}
+`)}
+
+	logs, err := New("", s.rep).Logs([]string{"foo"})
+	c.Check(err, IsNil)
+	c.Check(logs, DeepEquals, []Log{{"a": 1.}, {"a": 2.}})
+	c.Check(s.jsvcs, DeepEquals, [][]string{{"foo"}})
+	c.Check(s.j, Equals, 1)
+}
+
+func (s *SystemdTestSuite) TestLogString(c *C) {
+	c.Check(Log{}.String(), Equals, "-(no timestamp!)- - -")
+	c.Check(Log{
+		"__REALTIME_TIMESTAMP": 42,
+	}.String(), Equals, "-(timestamp not a string: 42)- - -")
+	c.Check(Log{
+		"__REALTIME_TIMESTAMP": "what",
+	}.String(), Equals, "-(timestamp not a decimal number: \"what\")- - -")
+	c.Check(Log{
+		"__REALTIME_TIMESTAMP": "0",
+		"MESSAGE":              "hi",
+	}.String(), Equals, "1970-01-01T00:00:00.000000Z - hi")
+	c.Check(Log{
+		"__REALTIME_TIMESTAMP": "42",
+		"MESSAGE":              "hi",
+		"SYSLOG_IDENTIFIER":    "me",
+	}.String(), Equals, "1970-01-01T00:00:00.000042Z me hi")
+
+}