cmd: Add log parser

.ci/run.sh

@@ -9,6 +9,39 @@
 
 set -e
 
+check_log_files()
+{
+	make log-parser
+
+	# XXX: Only the CC runtime uses structured logging,
+	# XXX: hence specify by name (rather than using $RUNTIME).
+	for component in \
+		kata-proxy \
+		kata-runtime-cc \
+		kata-shim
+	do
+		file="${component}.log"
+		args="--no-pager -q -o cat -a -t \"${component}\""
+
+		cmd="sudo journalctl ${args} > ${file}"
+		eval "$cmd"
+	done
+
+	logs=$(ls "$(pwd)"/*.log)
+	{ kata-log-parser --debug --check-only --error-if-no-records $logs; ret=$?; } || true
+
+	# Always remove logs since:
+	#
+	# - We don't want to waste disk-space.
+	# - The teardown script will save the full logs anyway.
+	# - the log parser tool shows full details of what went wrong.
+	rm -f $logs
+
+	[ $ret -eq 0 ] && true || false
+}
+
 export RUNTIME="kata-runtime"
 
 sudo -E PATH="$PATH" bash -c "make check"
+
+check_log_files

.gitignore

@@ -1 +1,2 @@
 ginkgo
+/cmd/log-parser/kata-log-parser

Makefile

@@ -24,6 +24,9 @@ else
 	./ginkgo -v -focus "${FOCUS}" ./integration/docker/ -- -runtime=${RUNTIME} -timeout=${TIMEOUT}
 endif
 
+log-parser:
+	make -C cmd/log-parser
+
 check: integration
 
-.PHONY: check checkcommits integration ginkgo
+.PHONY: check checkcommits integration ginkgo log-parser

cmd/log-parser/Gopkg.toml

@@ -0,0 +1,23 @@
+[[constraint]]
+  name = "github.com/BurntSushi/toml"
+  version = "0.3.0"
+
+[[constraint]]
+  name = "github.com/go-logfmt/logfmt"
+  version = "0.3.0"
+
+[[constraint]]
+  name = "github.com/urfave/cli"
+  version = "1.20.0"
+
+[[constraint]]
+  branch = "v2"
+  name = "gopkg.in/yaml.v2"
+
+[[constraint]]
+  name = "github.com/sirupsen/logrus"
+  version = "1.0.3"
+
+[prune]
+  go-tests = true
+  unused-packages = true

cmd/log-parser/Makefile

@@ -0,0 +1,31 @@
+#
+# Copyright (c) 2017-2018 Intel Corporation
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+
+TARGET = kata-log-parser
+SOURCES = $(shell find . 2>&1 | grep -E '.*\.go$$')
+
+VERSION := ${shell cat ./VERSION}
+COMMIT_NO := $(shell git rev-parse HEAD 2> /dev/null || true)
+COMMIT := $(if $(shell git status --porcelain --untracked-files=no),"${COMMIT_NO}-dirty","${COMMIT_NO}")
+
+BINDIR := $(GOPATH)/bin
+DESTTARGET := $(abspath $(BINDIR)/$(TARGET))
+
+default: install
+
+check:
+	go test -v .
+
+$(TARGET): $(SOURCES) check
+	go build -o "$(TARGET)" -ldflags "-X main.name=${TARGET} -X main.commit=${COMMIT} -X main.version=${VERSION}" .
+
+install: $(TARGET)
+	install -D $(TARGET) $(DESTTARGET)
+
+clean:
+	rm -f $(TARGET)
+
+.PHONY: check install clean

cmd/log-parser/README.md

@@ -0,0 +1,98 @@
+# `kata-log-parser`
+
+* [Logfile requirements](#logfile-requirements)
+* [Component logfiles](#component-logfiles)
+* [Usage](#usage)
+
+`kata-log-parser` is a tool that combines logfiles generated by the various
+system components, sorts them by timestamp, and re-displays the log entries. A
+time delta is added to show how much time has elapsed between each log entry.
+
+The tool also checks the validity of all log records, can re-format the logs,
+and output them in a different format.
+
+For more information on the `kata-log-parser` tool, use the help command:
+
+```
+$ kata-log-parser --help
+```
+
+## Logfile requirements
+
+The tool reads logfiles in the [logfmt](https://brandur.org/logfmt) structured
+logging format. For example, a logfile created by the golang
+[logrus](https://godoc.org/github.com/sirupsen/logrus) package.
+
+The tool requires that the following fields are defined for each log record:
+
+- Log level field (`level`): must be one of the logrus `LogLevel` values
+  in string format (e.g. `debug`, `info`, `error`).
+
+- Name field (`name`): a single word that specifies the name of the
+  application that generates the log record (e.g. `kata-runtime`).
+
+- Process ID field (`pid`): the numeric process identifier for the process
+  that generates the log record.
+
+- Source field (`source`): a single word that specifies the name of a unique
+  part of the system (e.g. `proxy`, `runtime`, `shim`).
+
+- Timestamp field (`time`): in [RFC3339](https://www.ietf.org/rfc/rfc3339.txt)
+  format and including a nanosecond value.
+
+Additional to the fields above, the tool also expects the following field:
+
+- Message field (`msg`): a textual message allowing log records to be
+  disambiguated.
+
+## Component logfiles
+
+The primary logfiles the tool reads are:
+
+- The [proxy](https://github.com/kata-containers/proxy) log.
+
+  This log also includes embedded log entries from the
+  [agent](https://github.com/katacontainers/agent). `kata-log-parser`
+  automatically unpacks and displays the entries. During this process, the
+  encapsulating proxy log messages are discarded.
+
+- The [runtime](https://github.com/kata-containers/runtime) log.
+
+  This log also includes
+  [virtcontainers](https://github.com/containers/virtcontainers) log entries.
+
+- The [shim](https://github.com/kata-containers/shim) log.
+
+## Usage
+
+To merge all logs:
+
+1. [Enable full debug](https://github.com/kata-containers/documentation/wiki/Developer-Guide#enable-full-debug).
+1. Clear the systemd journal (optional):
+   ```
+   $ sudo systemctl stop systemd-journald
+   $ sudo rm -f /var/log/journal/*/* /run/log/journal/*/*
+   $ sudo systemctl start systemd-journald   
+   ```
+1. Create a container.
+1. Collect the logs.
+    1. Save the proxy log, which includes agent log details:
+       ```
+       $ sudo journalctl -q -o cat -a -t kata-proxy > ./proxy.log
+       ```
+    1. Save the runtime log:
+       ```
+       $ sudo journalctl -q -o cat -a -t kata-runtime > ./runtime.log
+       ```
+    1. Save the shim log:
+       ```
+       $ sudo journalctl -q -o cat -a -t kata-shim > ./shim.log
+       ```
+1. Ensure the logs are readable:
+   ```
+   $ sudo chown $USER *.log
+   ```
+1. Run the script:
+   ```
+   $ kata-log-parser proxy.log runtime.sh shim.log
+   ```

cmd/log-parser/VERSION

@@ -0,0 +1 @@
+0.0.1

cmd/log-parser/agent.go

@@ -0,0 +1,86 @@
+//
+// Copyright (c) 2017-2018 Intel Corporation
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+
+package main
+
+import (
+	"fmt"
+	"strings"
+)
+
+const (
+	// "source=agent" logs are actually encoded within proxy logs so need
+	// to be unpacked.
+	agentSourceField = "agent"
+)
+
+// agentLogEntry returns true if the specified log entry actually contains
+// an encoded agent log entry.
+func agentLogEntry(le LogEntry) bool {
+	if le.Source != agentSourceField {
+		return false
+	}
+
+	msg := le.Msg
+	if msg == "" {
+		return false
+	}
+
+	if strings.HasPrefix(msg, "time=") {
+		return true
+	}
+
+	return false
+}
+
+// unpackAgentLogEntry unpacks the proxy log entry that encodes an agent
+// message and returns the agent log entry, discarding the proxy log entry
+// that held it.
+func unpackAgentLogEntry(le LogEntry) (agent LogEntry, err error) {
+	if le.Source != agentSourceField {
+		return LogEntry{}, fmt.Errorf("agent log entry has wrong source (expected %v, got %v): %+v",
+			agentSourceField, le.Source, le)
+	}
+
+	msg := le.Msg
+	if msg == "" {
+		return LogEntry{}, fmt.Errorf("no agent message data (entry %+v", le)
+	}
+
+	file := le.Filename
+	if file == "" {
+		return LogEntry{}, fmt.Errorf("filename blank (entry %+v)", le)
+	}
+
+	line := le.Line
+	if line == 0 {
+		return LogEntry{}, fmt.Errorf("invalid line number (entry %+v)", le)
+	}
+
+	reader := strings.NewReader(le.Msg)
+
+	entries, err := parseLogFmtData(reader, file)
+	if err != nil {
+		return LogEntry{}, fmt.Errorf("failed to parse agent log entry %+v: %v", le, err)
+	}
+
+	expectedRecords := 1
+
+	count := entries.Len()
+	if count != expectedRecords {
+		return LogEntry{}, fmt.Errorf("expected %d record, got %d", expectedRecords, count)
+	}
+
+	agent = entries.Entries[0]
+
+	// Supplement the agent entry with a few extra details
+	agent.Count = le.Count
+	agent.Source = agentSourceField
+	agent.Filename = file
+	agent.Line = line
+
+	return agent, nil
+}