diff --git a/docs/logging.md b/docs/logging.md index b4d151e3a..8ae60a777 100644 --- 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 `` is an RFC3339-formatted timestamp, `` is the name of the log (e.g. `docker-ce.out`) and `` is the output. The `` 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 diff --git a/examples/logging.yml b/examples/logging.yml index b33ed357f..792e0b948 100644 --- 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 diff --git a/pkg/logwrite/Dockerfile b/pkg/logwrite/Dockerfile new file mode 100644 index 000000000..1ab7a6103 --- /dev/null +++ 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"] diff --git a/pkg/logwrite/build.yml b/pkg/logwrite/build.yml new file mode 100644 index 000000000..9aecb26f4 --- /dev/null +++ b/pkg/logwrite/build.yml @@ -0,0 +1,5 @@ +image: logwrite +config: + binds: + - /var/run:/var/run + - /var/log:/var/log diff --git a/pkg/logwrite/logwrite.go b/pkg/logwrite/logwrite.go new file mode 100644 index 000000000..c4f1aa399 --- /dev/null +++ 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: +// ,; +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. + 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) + } + } +} diff --git a/test/cases/040_packages/030_logwrite/check.sh b/test/cases/040_packages/030_logwrite/check.sh new file mode 100755 index 000000000..ac44a4385 --- /dev/null +++ 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 diff --git a/test/cases/040_packages/030_logwrite/test.sh b/test/cases/040_packages/030_logwrite/test.sh new file mode 100644 index 000000000..25ebe133c --- /dev/null +++ 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 diff --git a/test/cases/040_packages/030_logwrite/test.yml b/test/cases/040_packages/030_logwrite/test.yml new file mode 100644 index 000000000..f0102be83 --- /dev/null +++ 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