diff --git a/docs/logging.md b/docs/logging.md index 7e11fad04..b4d151e3a 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -42,32 +42,40 @@ 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. -Usage examples: +### Message format + +The format used to read logs is similar to [kmsg](https://www.kernel.org/doc/Documentation/ABI/testing/dev-kmsg): +``` +,; +``` +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 ``` / # logread -f -2017-04-15T15:37:37Z memlogd memlogd started -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: waiting for carrier -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: carrier acquired -2017-04-15T15:37:37Z 002-dhcpcd.stdout DUID 00:01:00:01:20:84:fa:c1:02:50:00:00:00:24 -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: IAID 00:00:00:24 -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: adding address fe80::84e3:ca52:2590:fe80 -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: soliciting an IPv6 router -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: soliciting a DHCP lease -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: offered 192.168.65.37 from 192.168.65.1 `vpnkit' -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: leased 192.168.65.37 for 7199 seconds -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: adding route to 192.168.65.0/24 -2017-04-15T15:37:37Z 002-dhcpcd.stdout eth0: adding default route via 192.168.65.1 -2017-04-15T15:37:37Z 002-dhcpcd.stdout exiting due to oneshot -2017-04-15T15:37:37Z 002-dhcpcd.stdout dhcpcd exited -2017-04-15T15:37:37Z rngd.stderr Unable to open file: /dev/tpm0 +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 +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 +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 -/ # logwrite echo testing123 -testing123 -/ # logread | tail -n1 -2017-04-15T15:37:45Z echo.stdout testing123 -/ # echo -en "GET / HTTP/1.0\n\n" | nc localhost 80 > /dev/null -/ # logread | grep nginx -2017-04-15T15:42:40Z nginx.stdout 127.0.0.1 - - [15/Apr/2017:15:42:40 +0000] "GET / HTTP/1.0" 200 612 "-" "-" "-" ``` Current issues and limitations: diff --git a/pkg/memlogd/cmd/memlogd/main.go b/pkg/memlogd/cmd/memlogd/main.go index e2c0d7584..ccccb4933 100644 --- a/pkg/memlogd/cmd/memlogd/main.go +++ b/pkg/memlogd/cmd/memlogd/main.go @@ -66,7 +66,7 @@ func logQueryHandler(l *connListener) { } func (msg *logEntry) String() string { - return fmt.Sprintf("%s %s %s", msg.time.Format(time.RFC3339), msg.source, msg.msg) + return fmt.Sprintf("%s,%s;%s", msg.time.Format(time.RFC3339), msg.source, msg.msg) } func ringBufferHandler(ringSize, chanSize int, logCh chan logEntry, queryMsgChan chan queryMessage) { @@ -220,6 +220,23 @@ func readLogFromFd(maxLineLen int, fd int, source string, logCh chan logEntry) { } } +func loggingRequestHandler(lineMaxLength int, logCh chan logEntry, fdMsgChan chan fdMessage) { + for true { + select { + case msg := <-fdMsgChan: // incoming fd + if strings.Contains(msg.name, ";") { + // The log message spec bans ";" in the log names + doLog(logCh, fmt.Sprintf("ERROR: cannot register log with name '%s' as it contains ;", msg.name)) + if err := syscall.Close(msg.fd); err != nil { + doLog(logCh, fmt.Sprintf("ERROR: failed to close fd: %s", err)) + } + continue + } + go readLogFromFd(lineMaxLength, msg.fd, msg.name, logCh) + } + } +} + func main() { var err error @@ -304,16 +321,14 @@ func main() { fdMsgChan := make(chan fdMessage) queryMsgChan := make(chan queryMessage) + // receive fds from the logging Unix domain socket and send on fdMsgChan go receiveFdHandler(connLogFd, logCh, fdMsgChan) + // receive fds from the querying Unix domain socket and send on queryMsgChan go receiveQueryHandler(connQuery, logCh, queryMsgChan) + // process both log messages and queries go ringBufferHandler(linesInBuffer, linesInBuffer, logCh, queryMsgChan) doLog(logCh, "memlogd started") - for true { - select { - case msg := <-fdMsgChan: // incoming fd - go readLogFromFd(lineMaxLength, msg.fd, msg.name, logCh) - } - } + loggingRequestHandler(lineMaxLength, logCh, fdMsgChan) } diff --git a/pkg/memlogd/cmd/memlogd/main_test.go b/pkg/memlogd/cmd/memlogd/main_test.go index bf5670ad3..b2d6c72dc 100644 --- a/pkg/memlogd/cmd/memlogd/main_test.go +++ b/pkg/memlogd/cmd/memlogd/main_test.go @@ -6,6 +6,7 @@ import ( "log" "net" "os" + "strings" "syscall" "testing" "time" @@ -44,7 +45,7 @@ func TestFinite(t *testing.T) { for i := 0; i < 2*linesInBuffer; i++ { logCh <- logEntry{time: time.Now(), source: "memlogd", msg: "hello TestFinite"} } - a, b := socketpair() + a, b := loopback() defer a.Close() defer b.Close() queryM := queryMessage{ @@ -85,7 +86,7 @@ func TestFinite2(t *testing.T) { logCh <- logEntry{time: time.Now(), source: "memlogd", msg: "hello TestFinite2"} } - a, b := socketpair() + a, b := loopback() defer a.Close() defer b.Close() queryM := queryMessage{ @@ -112,22 +113,86 @@ func TestFinite2(t *testing.T) { } } -func socketpair() (net.Conn, net.Conn) { +func TestGoodName(t *testing.T) { + // Test that the source names can't contain ";" + linesInBuffer := 10 + logCh := make(chan logEntry) + fdMsgChan := make(chan fdMessage) + queryMsgChan := make(chan queryMessage) + + go ringBufferHandler(linesInBuffer, linesInBuffer, logCh, queryMsgChan) + go loggingRequestHandler(80, logCh, fdMsgChan) + fds, err := syscall.Socketpair(syscall.AF_UNIX, syscall.SOCK_STREAM, 0) if err != nil { log.Fatal("Unable to create socketpair: ", err) } - f := os.NewFile(uintptr(fds[0]), "a") - a, err := net.FileConn(f) - if err != nil { - log.Fatal("Unable to create net.Conn from socketpair: ", err) + a := fdToConn(fds[0]) + b := fdToConn(fds[1]) + defer a.Close() + defer b.Close() + // defer close fds + + fdMsgChan <- fdMessage{ + name: "semi-colons are banned;", + fd: fds[0], } - _ = f.Close() - f = os.NewFile(uintptr(fds[1]), "b") - b, err := net.FileConn(f) - if err != nil { - log.Fatal("Unable to create net.Conn from socketpair: ", err) + // although the fd should be rejected my memlogd the Write should be buffered + // by the kernel and not block. + if _, err := b.Write([]byte("hello\n")); err != nil { + log.Fatalf("Failed to write log message: %s", err) + } + c, d := loopback() + defer c.Close() + defer d.Close() + // this log should not be in the ring because the connection was rejected. + queryM := queryMessage{ + conn: c, + mode: logDumpFollow, + } + queryMsgChan <- queryM + // The error log is generated asynchronously. It should be fast. On error time out + // after 5s. + d.SetDeadline(time.Now().Add(5 * time.Second)) + r := bufio.NewReader(d) + for { + line, err := r.ReadString('\n') + if err == io.EOF { + break + } + if err != nil { + log.Fatalf("Unexpected error reading from socket: %s", err) + } + if strings.Contains(line, "ERROR: cannot register log") { + return + } + } + t.Fatal("Failed to read error message when registering a log with a ;") +} + +// caller must close fd themselves: closing the net.Conn will not close fd. +func fdToConn(fd int) net.Conn { + f := os.NewFile(uintptr(fd), "") + c, err := net.FileConn(f) + if err != nil { + log.Fatal("Unable to create net.Conn from file descriptor: ", err) + } + return c +} + +func loopback() (net.Conn, net.Conn) { + fds, err := syscall.Socketpair(syscall.AF_UNIX, syscall.SOCK_STREAM, 0) + if err != nil { + log.Fatal("Unable to create socketpair: ", err) + } + a := fdToConn(fds[0]) + b := fdToConn(fds[1]) + // net.Conns are independent of the fds, so we must close the fds now. + if err := syscall.Close(fds[0]); err != nil { + log.Fatal("Unable to close socketpair fd: ", err) + } + if err := syscall.Close(fds[1]); err != nil { + log.Fatal("Unable to close socketpair fd: ", err) } - _ = f.Close() return a, b }