Implement podman logs with log-driver journald

Add a journald reader that translates the journald entry to a k8s-file formatted line, to be added as a log line

Note: --follow with journald hasn't been implemented. It's going to be a larger undertaking that can wait.

Signed-off-by: Peter Hunt <pehunt@redhat.com>

cmd/podman/shared/create.go

@@ -603,7 +603,7 @@ func ParseCreateOpts(ctx context.Context, c *GenericCLIResults, runtime *libpod.
 
 	memorySwappiness := c.Int64("memory-swappiness")
 
-	logDriver := "k8s-file"
+	logDriver := libpod.KubernetesLogging
 	if c.Changed("log-driver") {
 		logDriver = c.String("log-driver")
 	}

docs/podman-logs.1.md

@@ -23,6 +23,8 @@ Note: If you are following a container which is removed `podman container rm`
 or removed on exit `podman run --rm ...`, then there is a chance the the log
 file will be removed before `podman logs` reads the final content.
 
+Also note: **--follow** is not currently supported when the container's log driver is journald
+
 **--latest, -l**
 
 Instead of providing the container name or ID, use the last created container. If you use methods other than Podman

libpod/container_log.go

@@ -19,6 +19,16 @@ const (
 	// zeroes are not trimmed, taken from
 	// https://github.com/golang/go/issues/19635
 	logTimeFormat = "2006-01-02T15:04:05.000000000Z07:00"
+
+	// readLogTimeFormat is the format the log lines will be read in
+	readLogTimeFormat = time.RFC3339Nano
+
+	// partialLogType signifies a log line that exceeded the buffer
+	// length and needed to spill into a new line
+	partialLogType = "P"
+
+	// fullLogType signifies a log line is full
+	fullLogType = "F"
 )
 
 // LogOptions is the options you can use for logs
@@ -55,9 +65,16 @@ func (r *Runtime) Log(containers []*Container, options *LogOptions, logChannel c
 func (c *Container) ReadLog(options *LogOptions, logChannel chan *LogLine) error {
 	// TODO Skip sending logs until journald logs can be read
 	// TODO make this not a magic string
-	if c.LogDriver() == "journald" {
-		return ErrNotImplemented
+	if c.LogDriver() == JournaldLogging {
+		if options.Follow {
+			return errors.Errorf("The follow option with journald logging is not currently supported")
 		}
+		return c.readFromJournal(options, logChannel)
+	}
+	return c.readFromLogFile(options, logChannel)
+}
+
+func (c *Container) readFromLogFile(options *LogOptions, logChannel chan *LogLine) error {
 	t, tailLog, err := getLogFile(c.LogPath(), options)
 	if err != nil {
 		// If the log file does not exist, this is not fatal.
@@ -196,7 +213,7 @@ func newLogLine(line string) (*LogLine, error) {
 	if len(splitLine) < 4 {
 		return nil, errors.Errorf("'%s' is not a valid container log line", line)
 	}
-	logTime, err := time.Parse(time.RFC3339Nano, splitLine[0])
+	logTime, err := time.Parse(readLogTimeFormat, splitLine[0])
 	if err != nil {
 		return nil, errors.Wrapf(err, "unable to convert time %s from container log", splitLine[0])
 	}
@@ -211,7 +228,7 @@ func newLogLine(line string) (*LogLine, error) {
 
 // Partial returns a bool if the log line is a partial log type
 func (l *LogLine) Partial() bool {
-	if l.ParseLogType == "P" {
+	if l.ParseLogType == partialLogType {
 		return true
 	}
 	return false

libpod/container_log_linux.go

@@ -0,0 +1,114 @@
+//+build linux
+
+package libpod
+
+import (
+	"fmt"
+	"io"
+	"strings"
+	"time"
+
+	journal "github.com/coreos/go-systemd/sdjournal"
+	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
+)
+
+const (
+	// journaldLogOut is the journald priority signifying stdout
+	journaldLogOut = "6"
+
+	// journaldLogErr is the journald priority signifying stderr
+	journaldLogErr = "3"
+
+	// bufLen is the length of the buffer to read from a k8s-file
+	// formatted log line
+	// It consists of conmon.TSBUFLEN+2+conmon.STDIOBUFSIZE+'\0'
+	bufLen = 44 + 2 + 8192 + 1
+)
+
+func (c *Container) readFromJournal(options *LogOptions, logChannel chan *LogLine) error {
+	var config journal.JournalReaderConfig
+	config.NumFromTail = options.Tail
+	config.Formatter = journalFormatter
+	defaultTime := time.Time{}
+	if options.Since != defaultTime {
+		// coreos/go-systemd/sdjournal doesn't correctly handle requests for data in the future
+		// return nothing instead of fasely printing
+		if time.Now().Before(options.Since) {
+			return nil
+		}
+		config.Since = time.Since(options.Since)
+	}
+	config.Matches = append(config.Matches, journal.Match{
+		Field: "CONTAINER_ID_FULL",
+		Value: c.ID(),
+	})
+	options.WaitGroup.Add(1)
+
+	r, err := journal.NewJournalReader(config)
+	if err != nil {
+		return err
+	}
+	if r == nil {
+		return errors.Errorf("journal reader creation failed")
+	}
+	if options.Tail == 0 {
+		r.Rewind()
+	}
+
+	go func() {
+		bytes := make([]byte, bufLen)
+		// /me complains about no do-while in go
+		ec, err := r.Read(bytes)
+		for ec != 0 && err == nil {
+			// because we are reusing bytes, we need to make
+			// sure the old data doesn't get into the new line
+			bytestr := string(bytes[:ec])
+			logLine, err2 := newLogLine(bytestr)
+			if err2 != nil {
+				logrus.Error(err2)
+				continue
+			}
+			logChannel <- logLine
+			ec, err = r.Read(bytes)
+		}
+		if err != nil && err != io.EOF {
+			logrus.Error(err)
+		}
+		r.Close()
+		options.WaitGroup.Done()
+	}()
+	return nil
+}
+
+func journalFormatter(entry *journal.JournalEntry) (string, error) {
+	usec := entry.RealtimeTimestamp
+	timestamp := time.Unix(0, int64(usec)*int64(time.Microsecond))
+	output := timestamp.Format(readLogTimeFormat) + " "
+	priority, ok := entry.Fields["PRIORITY"]
+	if !ok {
+		return "", errors.Errorf("no PRIORITY field present in journal entry")
+	}
+	if priority == journaldLogOut {
+		output += "stdout "
+	} else if priority == journaldLogErr {
+		output += "stderr "
+	} else {
+		return "", errors.Errorf("unexpected PRIORITY field in journal entry")
+	}
+
+	// if CONTAINER_PARTIAL_MESSAGE is defined, the log type is "P"
+	if _, ok := entry.Fields["CONTAINER_PARTIAL_MESSAGE"]; ok {
+		output += fmt.Sprintf("%s ", partialLogType)
+	} else {
+		output += fmt.Sprintf("%s ", fullLogType)
+	}
+
+	// Finally, append the message
+	msg, ok := entry.Fields["MESSAGE"]
+	if !ok {
+		return "", fmt.Errorf("no MESSAGE field present in journal entry")
+	}
+	output += strings.TrimSpace(msg)
+	return output, nil
+}

libpod/container_log_unsupported.go

@@ -0,0 +1,7 @@
+//+build !linux
+
+package libpod
+
+func (c *Container) readFromJournal(options *LogOptions, logChannel chan *LogLine) error {
+	return ErrOSNotSupported
+}

libpod/oci.go

@@ -42,6 +42,12 @@ const (
 	// NsRunDir is the default directory in which running network namespaces
 	// are stored
 	NsRunDir = "/var/run/netns"
+
+	// JournaldLogging is the string conmon expects to specify journald logging
+	JournaldLogging = "journald"
+
+	// KubernetesLogging is the string conmon expects when specifying to use the kubernetes logging format
+	KubernetesLogging = "k8s-file"
 )
 
 // OCIRuntime represents an OCI-compatible runtime that libpod can call into

libpod/oci_linux.go

@@ -237,7 +237,7 @@ func (r *OCIRuntime) createOCIContainer(ctr *Container, cgroupParent string, res
 		args = append(args, "--log-size-max", fmt.Sprintf("%v", r.logSizeMax))
 	}
 
-	logDriver := "k8s-file"
+	logDriver := KubernetesLogging
 	if ctr.LogDriver() != "" {
 		logDriver = ctr.LogDriver()
 	}

test/e2e/logs_test.go

@@ -140,4 +140,82 @@ var _ = Describe("Podman logs", func() {
 		results.WaitWithDefaultTimeout()
 		Expect(results.ExitCode()).To(BeZero())
 	})
+
+	It("podman journald logs for container", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(3))
+	})
+
+	It("podman journald logs tail two lines", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", "--tail", "2", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(2))
+	})
+
+	It("podman journald logs tail 99 lines", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", "--tail", "99", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(3))
+	})
+
+	It("podman journald logs tail 2 lines with timestamps", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", "--tail", "2", "-t", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(2))
+	})
+
+	It("podman journald logs latest with since time", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", "--since", "2017-08-07T10:10:09.056611202-04:00", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(3))
+	})
+
+	It("podman journald logs latest with since duration", func() {
+		Skip("need to verify images have correct packages for journald")
+		logc := podmanTest.Podman([]string{"run", "--log-driver", "journald", "-dt", ALPINE, "sh", "-c", "echo podman; echo podman; echo podman"})
+		logc.WaitWithDefaultTimeout()
+		Expect(logc.ExitCode()).To(Equal(0))
+		cid := logc.OutputToString()
+
+		results := podmanTest.Podman([]string{"logs", "--since", "10m", cid})
+		results.WaitWithDefaultTimeout()
+		Expect(results.ExitCode()).To(Equal(0))
+		Expect(len(results.OutputToStringArray())).To(Equal(3))
+	})
 })