Merge pull request #11263 from nalind/journal-read

libpod/Container.readFromJournal(): don't skip the first entry

go.mod

@@ -12,7 +12,7 @@ require (
 	github.com/containernetworking/cni v0.8.1
 	github.com/containernetworking/plugins v0.9.1
 	github.com/containers/buildah v1.22.3
-	github.com/containers/common v0.42.1
+	github.com/containers/common v0.43.2
 	github.com/containers/conmon v2.0.20+incompatible
 	github.com/containers/image/v5 v5.15.2
 	github.com/containers/ocicrypt v1.1.2

go.sum

@@ -240,11 +240,13 @@ github.com/containernetworking/plugins v0.9.1 h1:FD1tADPls2EEi3flPc2OegIY1M9pUa9
 github.com/containernetworking/plugins v0.9.1/go.mod h1:xP/idU2ldlzN6m4p5LmGiwRDjeJr6FLK6vuiUwoH7P8=
 github.com/containers/buildah v1.22.3 h1:RomxwUa24jMcqzXQetpw4wGMfNlNZLhc9qwyoWHblwc=
 github.com/containers/buildah v1.22.3/go.mod h1:JVXRyx5Rkp5w5jwvaXe45kuHtyoxpERMjXrR45+3Wfg=
-github.com/containers/common v0.42.1 h1:ADOZrVAS8ZY5hBAvr/GoRoPv5Z7TBkxWgxQEXQjlqac=
 github.com/containers/common v0.42.1/go.mod h1:AaF3ipZfgezsctDuhzLkq4Vl+LkEy7J74ikh2HSXDsg=
+github.com/containers/common v0.43.2 h1:oSP5d5sDrq7OkoqLPVrLpi1LZOAwpTwOZXgPDHfmD0E=
+github.com/containers/common v0.43.2/go.mod h1:BAoVyRYlxKZKAYpHcFMdrXlIZyzbJp9NwKTgadTd/Dg=
 github.com/containers/conmon v2.0.20+incompatible h1:YbCVSFSCqFjjVwHTPINGdMX1F6JXHGTUje2ZYobNrkg=
 github.com/containers/conmon v2.0.20+incompatible/go.mod h1:hgwZ2mtuDrppv78a/cOBNiCm6O0UMWGx1mu7P00nu5I=
 github.com/containers/image/v5 v5.14.0/go.mod h1:SxiBKOcKuT+4yTjD0AskjO+UwFvNcVOJ9qlAw1HNSPU=
+github.com/containers/image/v5 v5.15.0/go.mod h1:gzdBcooi6AFdiqfzirUqv90hUyHyI0MMdaqKzACKr2s=
 github.com/containers/image/v5 v5.15.2 h1:DKicmVr0h1HGkzs9muoErX+fVbV9sV9W5TyMy5perLE=
 github.com/containers/image/v5 v5.15.2/go.mod h1:8jejVSzTDfyPwr/HXp9rri34n/vbdavYk6IzTiB3TBw=
 github.com/containers/libtrust v0.0.0-20190913040956-14b96171aa3b h1:Q8ePgVfHDplZ7U33NwHZkrVELsZP5fYj9pM5WBZB2GE=
@@ -258,7 +260,9 @@ github.com/containers/psgo v1.5.2 h1:3aoozst/GIwsrr/5jnFy3FrJay98uujPCu9lTuSZ/Cw
 github.com/containers/psgo v1.5.2/go.mod h1:2ubh0SsreMZjSXW1Hif58JrEcFudQyIy9EzPUWfawVU=
 github.com/containers/storage v1.23.5/go.mod h1:ha26Q6ngehFNhf3AWoXldvAvwI4jFe3ETQAf/CeZPyM=
 github.com/containers/storage v1.32.6/go.mod h1:mdB+b89p+jU8zpzLTVXA0gWMmIo0WrkfGMh1R8O2IQw=
+github.com/containers/storage v1.33.0/go.mod h1:FUZPF4nJijX8ixdhByZJXf02cvbyLi6dyDwXdIe8QVY=
 github.com/containers/storage v1.33.1/go.mod h1:FUZPF4nJijX8ixdhByZJXf02cvbyLi6dyDwXdIe8QVY=
+github.com/containers/storage v1.34.0/go.mod h1:t6I+hTgPU0/tVxQ75vw406wDi/TXwYBqZp4QZV9N7b8=
 github.com/containers/storage v1.34.1 h1:PsBGMH7hwuQ3MOr7qTgPznFrE8ebfIbwQbg2gKvg0lE=
 github.com/containers/storage v1.34.1/go.mod h1:FY2TcbfgCLMU4lYoKnlZeZXeH353TOTbpDEA+sAcqAY=
 github.com/coreos/bbolt v1.3.2/go.mod h1:iRUV2dpdMOn7Bo10OQBFzIJO9kkE559Wcmn+qkEiiKk=
@@ -582,6 +586,7 @@ github.com/klauspost/compress v1.11.0/go.mod h1:aoV0uJVorq1K+umq18yTdKaF57EivdYs
 github.com/klauspost/compress v1.11.3/go.mod h1:aoV0uJVorq1K+umq18yTdKaF57EivdYsUV+/s2qKfXs=
 github.com/klauspost/compress v1.11.13/go.mod h1:aoV0uJVorq1K+umq18yTdKaF57EivdYsUV+/s2qKfXs=
 github.com/klauspost/compress v1.13.1/go.mod h1:8dP1Hq4DHOhN9w426knH3Rhby4rFm6D8eO+e+Dq5Gzg=
+github.com/klauspost/compress v1.13.3/go.mod h1:8dP1Hq4DHOhN9w426knH3Rhby4rFm6D8eO+e+Dq5Gzg=
 github.com/klauspost/compress v1.13.4 h1:0zhec2I8zGnjWcKyLl6i3gPqKANCCn5e9xmviEEeX6s=
 github.com/klauspost/compress v1.13.4/go.mod h1:8dP1Hq4DHOhN9w426knH3Rhby4rFm6D8eO+e+Dq5Gzg=
 github.com/klauspost/pgzip v1.2.5 h1:qnWYvvKqedOF2ulHpMG72XQol4ILEJ8k2wwRl/Km8oE=
@@ -713,6 +718,7 @@ github.com/onsi/gomega v1.10.1/go.mod h1:iN09h71vgCQne3DLsj+A5owkum+a2tYe+TOCB1y
 github.com/onsi/gomega v1.10.3/go.mod h1:V9xEwhxec5O8UDM77eCW8vLymOMltsqPVYWrpDsH8xc=
 github.com/onsi/gomega v1.10.5/go.mod h1:gza4q3jKQJijlu05nKWRCW/GavJumGt8aNRxWg7mt48=
 github.com/onsi/gomega v1.14.0/go.mod h1:cIuvLEne0aoVhAgh/O6ac0Op8WWw9H6eYCriF+tEHG0=
+github.com/onsi/gomega v1.15.0/go.mod h1:cIuvLEne0aoVhAgh/O6ac0Op8WWw9H6eYCriF+tEHG0=
 github.com/onsi/gomega v1.16.0 h1:6gjqkI8iiRHMvdccRJM8rVKjCWk6ZIm6FTm3ddIe4/c=
 github.com/onsi/gomega v1.16.0/go.mod h1:HnhC7FXeEQY45zxNK3PPoIUhzk/80Xly9PcubAlGdZY=
 github.com/opencontainers/go-digest v0.0.0-20170106003457-a6d0ee40d420/go.mod h1:cMLVZDEM3+U2I4VmLI6N8jQYUd2OVphdqWwCJHrFt2s=
@@ -751,6 +757,7 @@ github.com/opencontainers/selinux v1.5.1/go.mod h1:yTcKuYAh6R95iDpefGLQaPaRwJFwy
 github.com/opencontainers/selinux v1.6.0/go.mod h1:VVGKuOLlE7v4PJyT6h7mNWvq1rzqiriPsEqVhc+svHE=
 github.com/opencontainers/selinux v1.8.0/go.mod h1:RScLhm78qiWa2gbVCcGkC7tCGdgk3ogry1nUQF8Evvo=
 github.com/opencontainers/selinux v1.8.2/go.mod h1:MUIHuUEvKB1wtJjQdOyYRgOnLD2xAPP8dBsCoU0KuF8=
+github.com/opencontainers/selinux v1.8.3/go.mod h1:HTvjPFoGMbpQsG886e3lQwnsRWtE4TC1OF3OUvG9FAo=
 github.com/opencontainers/selinux v1.8.4 h1:krlgQ6/j9CkCXT5oW0yVXdQFOME3NjKuuAZXuR6O7P4=
 github.com/opencontainers/selinux v1.8.4/go.mod h1:HTvjPFoGMbpQsG886e3lQwnsRWtE4TC1OF3OUvG9FAo=
 github.com/openshift/imagebuilder v1.2.2-0.20210415181909-87f3e48c2656 h1:WaxyNFpmIDu4i6so9r6LVFIbSaXqsj8oitMitt86ae4=

libpod/container_log_linux.go

@@ -12,6 +12,7 @@ import (
 	"github.com/containers/podman/v3/libpod/define"
 	"github.com/containers/podman/v3/libpod/events"
 	"github.com/containers/podman/v3/libpod/logs"
+	"github.com/coreos/go-systemd/v22/journal"
 	"github.com/coreos/go-systemd/v22/sdjournal"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
@@ -29,6 +30,19 @@ func init() {
 	logDrivers = append(logDrivers, define.JournaldLogging)
 }
 
+// initializeJournal will write an empty string to the journal
+// when a journal is created. This solves a problem when people
+// attempt to read logs from a container that has never had stdout/stderr
+func (c *Container) initializeJournal(ctx context.Context) error {
+	m := make(map[string]string)
+	m["SYSLOG_IDENTIFIER"] = "podman"
+	m["PODMAN_ID"] = c.ID()
+	m["CONTAINER_ID_FULL"] = c.ID()
+	history := events.History
+	m["PODMAN_EVENT"] = history.String()
+	return journal.Send("", journal.PriInfo, m)
+}
+
 func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOptions, logChannel chan *logs.LogLine) error {
 	journal, err := sdjournal.NewJournal()
 	if err != nil {
@@ -63,12 +77,12 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 	}
 	// API requires Next() immediately after SeekHead().
 	if _, err := journal.Next(); err != nil {
-		return errors.Wrap(err, "initial journal cursor")
+		return errors.Wrap(err, "next journal")
 	}
 
 	// API requires a next|prev before getting a cursor.
 	if _, err := journal.Previous(); err != nil {
-		return errors.Wrap(err, "initial journal cursor")
+		return errors.Wrap(err, "previous journal")
 	}
 
 	// Note that the initial cursor may not yet be ready, so we'll do an
@@ -77,10 +91,10 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 	var cursorError error
 	for i := 1; i <= 3; i++ {
 		cursor, cursorError = journal.GetCursor()
-		if err != nil {
+		if cursorError != nil {
+			time.Sleep(time.Duration(i*100) * time.Millisecond)
 			continue
 		}
-		time.Sleep(time.Duration(i*100) * time.Millisecond)
 		break
 	}
 	if cursorError != nil {
@@ -104,6 +118,7 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 
 		tailQueue := []*logs.LogLine{} // needed for options.Tail
 		doTail := options.Tail > 0
+		lastReadCursor := ""
 		for {
 			select {
 			case <-ctx.Done():
@@ -113,18 +128,25 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 				// Fallthrough
 			}
 
-			if _, err := journal.Next(); err != nil {
-				logrus.Errorf("Failed to move journal cursor to next entry: %v", err)
-				return
+			if lastReadCursor != "" {
+				// Advance to next entry if we read this one.
+				if _, err := journal.Next(); err != nil {
+					logrus.Errorf("Failed to move journal cursor to next entry: %v", err)
+					return
+				}
 			}
-			latestCursor, err := journal.GetCursor()
+
+			// Fetch the location of this entry, presumably either
+			// the one that follows the last one we read, or that
+			// same last one, if there is no next entry (yet).
+			cursor, err = journal.GetCursor()
 			if err != nil {
 				logrus.Errorf("Failed to get journal cursor: %v", err)
 				return
 			}
 
-			// Hit the end of the journal.
-			if cursor == latestCursor {
+			// Hit the end of the journal (so far?).
+			if cursor == lastReadCursor {
 				if doTail {
 					// Flush *once* we hit the end of the journal.
 					startIndex := int64(len(tailQueue)-1) - options.Tail
@@ -145,8 +167,9 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 				journal.Wait(sdjournal.IndefiniteWait)
 				continue
 			}
-			cursor = latestCursor
+			lastReadCursor = cursor
 
+			// Read the journal entry.
 			entry, err := journal.GetEntry()
 			if err != nil {
 				logrus.Errorf("Failed to get journal entry: %v", err)

libpod/container_log_unsupported.go

@@ -13,3 +13,7 @@ import (
 func (c *Container) readFromJournal(_ context.Context, _ *logs.LogOptions, _ chan *logs.LogLine) error {
 	return errors.Wrapf(define.ErrOSNotSupported, "Journald logging only enabled with systemd on linux")
 }
+
+func (c *Container) initializeJournal(ctx context.Context) error {
+	return errors.Wrapf(define.ErrOSNotSupported, "Journald logging only enabled with systemd on linux")
+}

libpod/logs/log.go

@@ -251,11 +251,19 @@ func (l *LogLine) Write(stdout io.Writer, stderr io.Writer, logOpts *LogOptions)
 	switch l.Device {
 	case "stdout":
 		if stdout != nil {
-			fmt.Fprintln(stdout, l.String(logOpts))
+			if l.Partial() {
+				fmt.Fprint(stdout, l.String(logOpts))
+			} else {
+				fmt.Fprintln(stdout, l.String(logOpts))
+			}
 		}
 	case "stderr":
 		if stderr != nil {
-			fmt.Fprintln(stderr, l.String(logOpts))
+			if l.Partial() {
+				fmt.Fprint(stderr, l.String(logOpts))
+			} else {
+				fmt.Fprintln(stderr, l.String(logOpts))
+			}
 		}
 	default:
 		// Warn the user if the device type does not match. Most likely the file is corrupted.

libpod/oci_conmon_linux.go

@@ -625,9 +625,11 @@ func (r *ConmonOCIRuntime) HTTPAttach(ctr *Container, req *http.Request, w http.
 				if err != nil {
 					break
 				}
-				_, err = httpBuf.Write([]byte("\n"))
-				if err != nil {
-					break
+				if !logLine.Partial() {
+					_, err = httpBuf.Write([]byte("\n"))
+					if err != nil {
+						break
+					}
 				}
 				err = httpBuf.Flush()
 				if err != nil {

libpod/runtime_ctr.go

@@ -462,8 +462,15 @@ func (r *Runtime) setupContainer(ctx context.Context, ctr *Container) (_ *Contai
 		ctrNamedVolumes = append(ctrNamedVolumes, newVol)
 	}
 
-	if ctr.config.LogPath == "" && ctr.config.LogDriver != define.JournaldLogging && ctr.config.LogDriver != define.NoLogging {
-		ctr.config.LogPath = filepath.Join(ctr.config.StaticDir, "ctr.log")
+	switch ctr.config.LogDriver {
+	case define.NoLogging:
+		break
+	case define.JournaldLogging:
+		ctr.initializeJournal(ctx)
+	default:
+		if ctr.config.LogPath == "" {
+			ctr.config.LogPath = filepath.Join(ctr.config.StaticDir, "ctr.log")
+		}
 	}
 
 	if !MountExists(ctr.config.Spec.Mounts, "/dev/shm") && ctr.config.ShmDir == "" {

pkg/api/handlers/compat/containers_logs.go

@@ -152,9 +152,7 @@ func LogsFromContainer(w http.ResponseWriter, r *http.Request) {
 		}
 
 		frame.WriteString(line.Msg)
-		// Log lines in the compat layer require adding EOL
-		// https://github.com/containers/podman/issues/8058
-		if !utils.IsLibpodRequest(r) {
+		if !line.Partial() {
 			frame.WriteString("\n")
 		}
 

pkg/domain/infra/tunnel/containers.go

@@ -404,11 +404,11 @@ func (ic *ContainerEngine) ContainerLogs(_ context.Context, nameOrIDs []string,
 			return err
 		case line := <-stdoutCh:
 			if opts.StdoutWriter != nil {
-				_, _ = io.WriteString(opts.StdoutWriter, line+"\n")
+				_, _ = io.WriteString(opts.StdoutWriter, line)
 			}
 		case line := <-stderrCh:
 			if opts.StderrWriter != nil {
-				_, _ = io.WriteString(opts.StderrWriter, line+"\n")
+				_, _ = io.WriteString(opts.StderrWriter, line)
 			}
 		}
 	}

test/system/130-kill.bats

@@ -33,7 +33,7 @@ load helpers
     exec 5<$fifo
 
     # First container emits READY when ready; wait for it.
-    read -t 10 -u 5 ready
+    read -t 60 -u 5 ready
     is "$ready" "READY" "first log message from container"
 
     # Helper function: send the given signal, verify that it's received.
@@ -42,7 +42,7 @@ load helpers
         local signum=${2:-$1}       # e.g. if signal=HUP, we expect to see '1'
 
         run_podman kill -s $signal $cid
-        read -t 10 -u 5 actual || die "Timed out: no ACK for kill -s $signal"
+        read -t 60 -u 5 actual || die "Timed out: no ACK for kill -s $signal"
         is "$actual" "got: $signum" "Signal $signal handled by container"
     }
 

test/system/330-corrupt-images.bats

@@ -13,7 +13,8 @@ if [ -z "${PODMAN_CORRUPT_TEST_WORKDIR}" ]; then
     export PODMAN_CORRUPT_TEST_WORKDIR=$(mktemp -d --tmpdir=${BATS_TMPDIR:-${TMPDIR:-/tmp}} podman_corrupt_test.XXXXXX)
 fi
 
-PODMAN_CORRUPT_TEST_IMAGE_FQIN=quay.io/libpod/alpine@sha256:634a8f35b5f16dcf4aaa0822adc0b1964bb786fca12f6831de8ddc45e5986a00
+PODMAN_CORRUPT_TEST_IMAGE_CANONICAL_FQIN=quay.io/libpod/alpine@sha256:634a8f35b5f16dcf4aaa0822adc0b1964bb786fca12f6831de8ddc45e5986a00
+PODMAN_CORRUPT_TEST_IMAGE_TAGGED_FQIN=${PODMAN_CORRUPT_TEST_IMAGE_CANONICAL_FQIN%%@sha256:*}:test
 PODMAN_CORRUPT_TEST_IMAGE_ID=961769676411f082461f9ef46626dd7a2d1e2b2a38e6a44364bcbecf51e66dd4
 
 # All tests in this file (and ONLY in this file) run with a custom rootdir
@@ -59,7 +60,7 @@ function _corrupt_image_test() {
         run_podman load -i ${PODMAN_CORRUPT_TEST_WORKDIR}/img.tar
         # "podman load" restores it without a tag, which (a) causes rmi-by-name
         # to fail, and (b) causes "podman images" to exit 0 instead of 125
-        run_podman tag ${PODMAN_CORRUPT_TEST_IMAGE_ID} ${PODMAN_CORRUPT_TEST_IMAGE_FQIN}
+        run_podman tag ${PODMAN_CORRUPT_TEST_IMAGE_ID} ${PODMAN_CORRUPT_TEST_IMAGE_TAGGED_FQIN}
 
         # shortcut variable name
         local id=${PODMAN_CORRUPT_TEST_IMAGE_ID}
@@ -91,9 +92,9 @@ function _corrupt_image_test() {
 
 @test "podman corrupt images - initialize" {
     # Pull once, save cached copy.
-    run_podman pull $PODMAN_CORRUPT_TEST_IMAGE_FQIN
+    run_podman pull $PODMAN_CORRUPT_TEST_IMAGE_CANONICAL_FQIN
     run_podman save -o ${PODMAN_CORRUPT_TEST_WORKDIR}/img.tar \
-               $PODMAN_CORRUPT_TEST_IMAGE_FQIN
+               $PODMAN_CORRUPT_TEST_IMAGE_CANONICAL_FQIN
 }
 
 # END   first "test" does a one-time pull of our desired image
@@ -104,8 +105,8 @@ function _corrupt_image_test() {
     _corrupt_image_test "rmi -f ${PODMAN_CORRUPT_TEST_IMAGE_ID}"
 }
 
-@test "podman corrupt images - rmi -f <image-name>" {
-    _corrupt_image_test "rmi -f ${PODMAN_CORRUPT_TEST_IMAGE_FQIN}"
+@test "podman corrupt images - rmi -f <image-tagged-name>" {
+    _corrupt_image_test "rmi -f ${PODMAN_CORRUPT_TEST_IMAGE_TAGGED_FQIN}"
 }
 
 @test "podman corrupt images - rmi -f -a" {