cmd/log-parser: Add containerID to standard log entry

Extract the container ID from the structured logs and add it to the
standard `LogEntry` type. This will allow (most of) the log entries to
be associated with individual containers, which will make debugging and
analysis easier.

Fixes #453.

Signed-off-by: James O. D. Hunt <james.o.hunt@intel.com>

cmd/log-parser/agent_test.go

@@ -165,3 +165,41 @@ func TestUnpackAgentLogEntry(t *testing.T) {
 		}
 	}
 }
+
+func TestUnpackAgentLogEntryWithContainerID(t *testing.T) {
+	assert := assert.New(t)
+
+	now := time.Now().UTC()
+	nano := now.Format(time.RFC3339Nano)
+
+	source := "agent"
+
+	containerID := "51f062b90853e22c0817392395bc0c43cd6a0bb9e456b1bd0e28433f805475d6"
+	execID := "51f062b90853e22c0817392395bc0c43cd6a0bb9e456b1bd0e28433f805475d6"
+
+	// agent log fields added when agent debug is enabled
+	msg := fmt.Sprintf(`"new request"`)
+
+	grpcTrace := fmt.Sprintf(`container_id:"%s" exec_id:"%s"`, containerID, execID)
+	grpcRequest := "/grpc.AgentService/CreateContainer"
+
+	agentMsg := fmt.Sprintf("time=%q source=%s level=%s pid=%d name=%s msg=%q request=%q req=%q",
+		nano, source, testLevel, testPid, testName, msg, grpcRequest, grpcTrace)
+
+	le := LogEntry{
+		Count:    123,
+		Source:   "agent",
+		Filename: "/foo/bar.txt",
+		Line:     101,
+		Msg:      agentMsg,
+	}
+
+	agent, err := unpackAgentLogEntry(le)
+	assert.NoError(err)
+
+	// Ensure the newly unpacked LogEntry is valid
+	err = agent.Check()
+	assert.NoError(err)
+
+	assert.Equal(containerID, agent.Container)
+}

cmd/log-parser/logentry.go

@@ -37,7 +37,7 @@ type MapSS map[string]string
 
 // Version of LogEntry contents (in semver.org format).
 // XXX: Update whenever LogEntry changes!
-const logEntryFormatVersion = "0.0.1"
+const logEntryFormatVersion = "0.0.2"
 
 // LogEntry is the main type used by the tool. It encapsulates a number of
 // fields that all system components are expected to set, but also includes
@@ -73,6 +73,19 @@ type LogEntry struct {
 	Source string
 	Name   string
 
+	// Container ID. This is set for most, but not all log records.
+	//
+	// Excluded log records include:
+	//
+	// - runtime log entries where the specified CLI command does not
+	//   operate on a container (or a single container).
+	//
+	// - proxy log entries which contain kernel boot output from the
+	//   guest.
+	//
+	// - early startup agent log entries.
+	Container string
+
 	// Used to store additional (non-standard) fields
 	Data MapSS
 }
@@ -131,6 +144,9 @@ func (le LogEntry) Check() error {
 		return fmt.Errorf("missing component name: %+v", le)
 	}
 
+	// Note: le.Container cannot be checked since it is not present in all
+	// entries.
+
 	m := map[string]string{
 		"Level":  le.Level,
 		"Source": le.Source,

cmd/log-parser/parse.go

@@ -51,6 +51,8 @@ const (
 		`\d{1,9}` +
 		// timezone
 		timezonePattern
+
+	agentContainerIDPattern = `container_id:"([^"]*)"`
 )
 
 type kvPair struct {
@@ -60,10 +62,14 @@ type kvPair struct {
 
 type kvPairs []kvPair
 
-var dateFormatRE *regexp.Regexp
+var (
+	dateFormatRE       *regexp.Regexp
+	agentContainerIDRE *regexp.Regexp
+)
 
 func init() {
 	dateFormatRE = regexp.MustCompile(dateFormatPattern)
+	agentContainerIDRE = regexp.MustCompile(agentContainerIDPattern)
 }
 
 // parseLogFmtData reads logfmt records using the provided reader and returns
@@ -88,6 +94,30 @@ func parseLogFmtData(reader io.Reader, file string) (LogEntries, error) {
 			key := string(d.Key())
 			value := string(d.Value())
 
+			// If agent debug is enabled, every gRPC request ("req")
+			// is logged. Since most such requests contain the
+			// container ID as a `container_id` field, extract and
+			// save it when present.
+			//
+			// See: https://github.com/kata-containers/agent/blob/master/protocols/grpc/agent.proto
+			//
+			// Note that we save the container ID in addition to
+			// the original value.
+			if key == "req" {
+				matches := agentContainerIDRE.FindSubmatch([]byte(value))
+				if matches != nil {
+					containerID := string(matches[1])
+
+					pair := kvPair{
+						key:   "container",
+						value: containerID,
+					}
+
+					// save key/value pair
+					keyvals = append(keyvals, pair)
+				}
+			}
+
 			pair := kvPair{
 				key:   key,
 				value: value,
@@ -214,6 +244,9 @@ func handleLogEntry(l *LogEntry, key, value string) (err error) {
 	}
 
 	switch key {
+	case "container":
+		l.Container = value
+
 	case "level":
 		l.Level = value