Add pkg/logwrite which writes and rotates log files

This process connects to memlogd and streams logs to individual files, one per log. It keeps track of how many bytes have been written to each file and rotates when the file size exceeds a defined threshold. By default the maximum size of each file before rotation is 1MiB and we keep up to 10 files per log. Signed-off-by: David Scott <dave.scott@docker.com>
2025-07-21 18:11:35 +00:00 · 2018-07-02 15:41:37 +01:00 · 2018-07-02 15:41:37 +01:00 · 565f787bb3
commit 565f787bb3
parent 4b4d56913d
8 changed files with 323 additions and 24 deletions
--- a/docs/logging.md
+++ b/docs/logging.md
@ -39,8 +39,8 @@ The circular buffer has a fixed size (overridden by the command-line argument

 To store the logs somewhere more permanent, for example a disk or a remote
 network service, a service should be added to the yaml which connects to
-`memlogd` and streams the logs. The example program `logread` in the `memlogd`
-package demonstrates how to do this.
+`memlogd` and streams the logs. The `logwrite` service described below shows
+how to do this.

 ### Message format

@ -52,33 +52,35 @@ where `<timestamp>` is an RFC3339-formatted timestamp, `<log>` is the name of
 the log (e.g. `docker-ce.out`) and `<body>` is the output. The `<log>` must
 not contain the character `;`.

-### Usage examples
+## logwrite: writing logs to disk
+
+The service `pkg/logwrite` connects to `memlogd` and streams the logs to files
+in `/var/log`. The logs are automatically rotated; by default each file has
+a maximum size of 1 MiB and up to 10 files are kept per log. The arguments
+`-max-log-files` and `-max-log-size` can be used to override these defaults.
+
+Here is an example log file:
 ```
-/ # logread -f
-2018-07-05T13:22:32Z,memlogd;memlogd started
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: waiting for carrier
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.err;eth0: could not detect a useable init
- system
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: carrier acquired
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;DUID 00:01:00:01:22:d0:d8:18:02:50:00:00:00:02
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: IAID 00:00:00:02
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: adding address fe80::d33a:3936:
-2ee4:5c8c
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: soliciting an IPv6 router
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: soliciting a DHCP lease
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: offered 192.168.65.4 from 192.1
-68.65.1 `vpnkit'
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: leased 192.168.65.4 for 7200 se
+# cat /var/log/onboot.001-dhcpcd.out 
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: waiting for carrier
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: carrier acquired
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out DUID 00:01:00:01:22:d4:93:05:02:50:00
+:00:00:06
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: IAID 00:00:00:06
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: adding address fe80::f346:56a6:590d:5ea4
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: soliciting an IPv6 router
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: soliciting a DHCP lease
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: offered 192.168.65.8 from 192.168.65.1 `vpnkit'
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: leased 192.168.65.8 for 7200 se
 conds
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: adding route to 192.168.65.0/24
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;eth0: adding default route via 192.16
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: adding route to 192.168.65.0/24
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out eth0: adding default route via 192.16
 8.65.1
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;exiting due to oneshot
-2018-07-05T13:22:32Z,onboot.001-dhcpcd.out;dhcpcd exited
-^C
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out exiting due to oneshot
+2018-07-08T09:16:53Z onboot.001-dhcpcd.out dhcpcd exited
 ```

-Current issues and limitations:
+## Current issues and limitations:

 - No docker logger plugin support yet - it could be nice to add support to
  memlogd, so the docker container logs would also be gathered in one place
--- a/examples/logging.yml
+++ b/examples/logging.yml
@ -24,6 +24,8 @@ services:
  - name: write-to-the-logs
    image: alpine
    command: ["/bin/sh", "-c", "while /bin/true; do echo hello $(date); sleep 1; done" ]
+  - name: write-and-rotate-logs
+    image: linuxkit/logwrite:7859c102a963828fd9c5aa3837db9600483220c7
 trust:
  org:
    - linuxkit
--- a/pkg/logwrite/Dockerfile
+++ b/pkg/logwrite/Dockerfile
@ -0,0 +1,14 @@
+FROM linuxkit/alpine:6264e5b39af8eb1da7ffa4c05a7ccc597da01197 AS build
+
+RUN apk add --no-cache go musl-dev
+ENV GOPATH=/go PATH=$PATH:/go/bin
+
+COPY logwrite.go /go/src/logwrite/
+RUN go-compile.sh /go/src/logwrite
+
+FROM scratch
+ENTRYPOINT []
+CMD []
+WORKDIR /
+COPY --from=build /go/bin/logwrite usr/bin/logwrite
+CMD ["/usr/bin/logwrite"]
--- a/pkg/logwrite/build.yml
+++ b/pkg/logwrite/build.yml
@ -0,0 +1,5 @@
+image: logwrite
+config:
+  binds:
+    - /var/run:/var/run
+    - /var/log:/var/log
--- a/pkg/logwrite/logwrite.go
+++ b/pkg/logwrite/logwrite.go
@ -0,0 +1,203 @@
+package main
+
+// Write logs to files and perform rotation.
+
+import (
+	"bufio"
+	"errors"
+	"flag"
+	"fmt"
+	"io"
+	"log"
+	"net"
+	"os"
+	"path/filepath"
+	"strings"
+	"time"
+)
+
+// These must be kept in sync with memlogd:
+const (
+	logDump byte = iota
+	logFollow
+	logDumpFollow
+)
+
+const mb = 1024 * 1024
+
+// LogMessage is a message received from memlogd.
+type LogMessage struct {
+	Time    time.Time // time message was received by memlogd
+	Name    string    // name of the service that wrote the message
+	Message string    // body of the message
+}
+
+func (m *LogMessage) String() string {
+	return m.Time.Format(time.RFC3339) + " " + m.Name + " " + m.Message
+}
+
+// ParseLogMessage reconstructs a LogMessage from a line of text which looks like:
+// <timestamp>,<origin>;<body>
+func ParseLogMessage(line string) (*LogMessage, error) {
+	bits := strings.SplitN(line, ";", 2)
+	if len(bits) != 2 {
+		return nil, errors.New("Failed to parse log message: " + line)
+	}
+	bits2 := strings.Split(bits[0], ",")
+	if len(bits2) < 2 {
+		// There could be more parameters in future
+		return nil, errors.New("Failed to parse log message: " + line)
+	}
+	Time, err := time.Parse(time.RFC3339, bits2[0])
+	if err != nil {
+		return nil, err
+	}
+	return &LogMessage{
+		Time:    Time,
+		Name:    bits2[1],
+		Message: bits[1],
+	}, nil
+}
+
+// LogFile is where we write LogMessages to
+type LogFile struct {
+	File         *os.File // active file handle
+	Name         string   // filename of log file
+	Dir          string   // log file directory
+	BytesWritten int      // total number of bytes written so far
+}
+
+// NewLogFile creates a new LogFile.
+func NewLogFile(dir, name string) (*LogFile, error) {
+	// If the log exists already we want to append to it.
+	f, err := os.OpenFile(filepath.Join(dir, name), os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0644)
+	if err != nil {
+		return nil, err
+	}
+	fi, err := f.Stat()
+	if err != nil {
+		return nil, err
+	}
+	return &LogFile{
+		File:         f,
+		Name:         name,
+		Dir:          dir,
+		BytesWritten: int(fi.Size()),
+	}, nil
+}
+
+// Write appends a message to the log file
+func (l *LogFile) Write(m *LogMessage) error {
+	s := m.String()
+	_, err := io.WriteString(l.File, s)
+	if err == nil {
+		l.BytesWritten += len(s)
+	}
+	return err
+}
+
+// Close a log file
+func (l *LogFile) Close() error {
+	return l.File.Close()
+}
+
+// Rotate closes the current log file, rotates the files and creates an empty log file.
+func (l *LogFile) Rotate(maxLogFiles int) error {
+	if err := l.File.Close(); err != nil {
+		return err
+	}
+	path := filepath.Join(l.Dir, l.Name)
+	for i := maxLogFiles - 1; i >= 0; i-- {
+		newerFile := fmt.Sprintf("%s.%d", path, i-1)
+		// special case: if index is 0 we omit the suffix i.e. we expect
+		// foo foo.1 foo.2 up to foo.<maxLogFiles-1>
+		if i == 0 {
+			newerFile = path
+		}
+		olderFile := fmt.Sprintf("%s.%d", path, i)
+		// overwrite the olderFile with the newerFile
+		err := os.Rename(newerFile, olderFile)
+		if os.IsNotExist(err) {
+			// the newerFile does not exist
+			continue
+		}
+		if err != nil {
+			return err
+		}
+	}
+	f, err := os.Create(path)
+	if err != nil {
+		return err
+	}
+	l.File = f
+	l.BytesWritten = 0
+	return nil
+}
+
+func main() {
+	socketPath := flag.String("socket", "/var/run/memlogdq.sock", "memlogd log query socket")
+	logDir := flag.String("log-dir", "/var/log", "Directory containing log files")
+	maxLogFiles := flag.Int("max-log-files", 10, "Maximum number of rotated log files before deletion")
+	maxLogSize := flag.Int("max-log-size", mb, "Maximum size of a log file before rotation")
+	flag.Parse()
+
+	addr := net.UnixAddr{
+		Name: *socketPath,
+		Net:  "unix",
+	}
+	conn, err := net.DialUnix("unix", nil, &addr)
+	if err != nil {
+		log.Fatal(err)
+	}
+	defer conn.Close()
+
+	n, err := conn.Write([]byte{logDumpFollow})
+	if err != nil || n < 1 {
+		log.Fatalf("Failed to write request to memlogd socket: %v", err)
+	}
+
+	// map of service name to active log file
+	logs := make(map[string]*LogFile)
+
+	r := bufio.NewReader(conn)
+	for {
+		line, err := r.ReadString('\n')
+		if err == io.EOF {
+			return
+		}
+		if err != nil {
+			log.Fatalf("Failed to read from memlogd: %v", err)
+		}
+		msg, err := ParseLogMessage(line)
+		if err != nil {
+			log.Println(err)
+			continue
+		}
+		if strings.HasPrefix(msg.Name, "logwrite") {
+			// don't log our own output in a loop
+			continue
+		}
+
+		var logF *LogFile
+		var ok bool
+		if logF, ok = logs[msg.Name]; !ok {
+			logF, err = NewLogFile(*logDir, msg.Name)
+			if err != nil {
+				log.Printf("Failed to create log file %s: %v", msg.Name, err)
+				continue
+			}
+			logs[msg.Name] = logF
+		}
+		if err = logF.Write(msg); err != nil {
+			log.Printf("Failed to write to log file %s: %v", msg.Name, err)
+			if err := logF.Close(); err != nil {
+				log.Printf("Failed to close log file %s: %v", msg.Name, err)
+			}
+			delete(logs, msg.Name)
+			continue
+		}
+		if logF.BytesWritten > *maxLogSize {
+			logF.Rotate(*maxLogFiles)
+		}
+	}
+}
--- a/test/cases/040_packages/030_logwrite/check.sh
+++ b/test/cases/040_packages/030_logwrite/check.sh
@ -0,0 +1,14 @@
+#!/bin/sh
+
+for i in $(seq 1 20); do
+	if [ -e /var/log/fill-the-logs.out.0 ]; then
+		printf "logwrite test suite PASSED\n" > /dev/console
+		/sbin/poweroff -f
+	fi
+	sleep 1
+done
+
+printf "logwrite test suite FAILED\n" > /dev/console
+echo "contents of /var/log:" > /dev/console
+ls -l /var/log > /dev/console
+/sbin/poweroff -f
--- a/test/cases/040_packages/030_logwrite/test.sh
+++ b/test/cases/040_packages/030_logwrite/test.sh
@ -0,0 +1,24 @@
+#!/bin/sh
+# SUMMARY: Check that the logwrite package works
+# LABELS:
+# REPEAT:
+
+set -e
+
+# Source libraries. Uncomment if needed/defined
+#. "${RT_LIB}"
+. "${RT_PROJECT_ROOT}/_lib/lib.sh"
+NAME=logwrite
+
+clean_up() {
+	rm -rf ${NAME}-*
+}
+trap clean_up EXIT
+
+# Test code goes here
+linuxkit build -disable-content-trust -format kernel+initrd -name "${NAME}" test.yml
+RESULT="$(linuxkit run ${NAME})"
+echo "${RESULT}"
+echo "${RESULT}" | grep -q "suite PASSED"
+
+exit 0
--- a/test/cases/040_packages/030_logwrite/test.yml
+++ b/test/cases/040_packages/030_logwrite/test.yml
@ -0,0 +1,35 @@
+kernel:
+  image: linuxkit/kernel:4.14.53
+  cmdline: "console=ttyS0 console=ttyAMA0"
+init:
+  - linuxkit/init:6cc1442112980c889230b6449df09d5b48de6854
+  - linuxkit/runc:v0.4
+  - linuxkit/containerd:f2bc1bda1ab18146967fa1a149800aaf14bee81b
+  - linuxkit/ca-certificates:v0.4
+  - linuxkit/memlogd:883f0d46e7d3ae2d787e8acb496da115a4707cbc
+services:
+# A service which generates logs of log messages
+  - name: fill-the-logs
+    image: alpine
+    command: ["/bin/sh", "-c", "while /bin/true; do echo hello $(date); done" ]
+  - name: write-and-rotate-logs
+    image: linuxkit/logwrite:7859c102a963828fd9c5aa3837db9600483220c7
+    command: ["/usr/bin/logwrite", "-max-log-size", "1024"]
+  - name: check-the-logs
+    image: alpine:3.8
+    binds:
+      - /check.sh:/check.sh
+      - /dev/console:/dev/console
+      - /var/log:/var/log
+    command: ["sh", "./check.sh"]
+    pid: host
+    capabilities:
+      - CAP_SYS_BOOT
+files:
+  - path: check.sh
+    source: ./check.sh
+trust:
+  org:
+    - linuxkit
+  image:
+    - alpine:3.8