Merge pull request #519 from AkihiroSuda/log-shim2

supervisor: print runtime's log on failure of ContainerCreate()

supervisor/service.go

@@ -58,6 +58,17 @@ type Service struct {
 	shims map[string]*shimClient
 }
 
+func (s *Service) propagateRuntimeLog(client *shimClient, entries int) {
+	logs, err := client.readRuntimeLogEntries(entries)
+	if err != nil {
+		log.G(s.ctx).WithError(err).WithField("container", client.id).
+			Warnf("failed to read shim log")
+		return
+	}
+	log.G(s.ctx).WithField("container", client.id).
+		Warnf("shim log (last %d entry): %v", entries, logs)
+}
+
 func (s *Service) CreateContainer(ctx context.Context, r *executionapi.CreateContainerRequest) (*executionapi.CreateContainerResponse, error) {
 	client, err := s.newShim(r.ID)
 	if err != nil {
@@ -65,6 +76,7 @@ func (s *Service) CreateContainer(ctx context.Context, r *executionapi.CreateCon
 	}
 	defer func() {
 		if err != nil {
+			s.propagateRuntimeLog(client, 1)
 			s.removeShim(r.ID)
 		}
 	}()

supervisor/shim.go

@@ -2,13 +2,16 @@ package supervisor
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"log"
 	"net"
 	"os"
 	"os/exec"
 	"path/filepath"
+	"strings"
 	"syscall"
 	"time"
 
@@ -103,6 +106,41 @@ func (s *shimClient) stop() {
 	os.RemoveAll(s.root)
 }
 
+func (s *shimClient) readRuntimeLogEntries(lastEntries int) ([]map[string]interface{}, error) {
+	f, err := os.Open(filepath.Join(s.root, "log.json"))
+	if err != nil {
+		return nil, err
+	}
+	defer f.Close()
+	return parseRuntimeLog(f, lastEntries)
+}
+
+// parseRuntimeLog parses log.json.
+// If lastEntries is greater than 0, only some last entries are returned.
+func parseRuntimeLog(r io.Reader, lastEntries int) ([]map[string]interface{}, error) {
+	b, err := ioutil.ReadAll(r)
+	if err != nil {
+		return nil, err
+	}
+	lines := strings.Split(string(b), "\n")
+	if lastEntries > 0 {
+		lines = lines[len(lines)-lastEntries-1 : len(lines)]
+	}
+	var entries []map[string]interface{}
+	for _, line := range lines {
+		line = strings.TrimSpace(line)
+		if line == "" {
+			continue
+		}
+		var entry map[string]interface{}
+		if err := json.Unmarshal([]byte(line), &entry); err != nil {
+			return nil, errors.Wrapf(err, "cannot unmarshal JSON string %q", line)
+		}
+		entries = append(entries, entry)
+	}
+	return entries, nil
+}
+
 func connectToShim(socket string) (shim.ShimClient, error) {
 	// reset the logger for grpc to log to dev/null so that it does not mess with our stdio
 	grpclog.SetLogger(log.New(ioutil.Discard, "", log.LstdFlags))

supervisor/shim_test.go

@@ -0,0 +1,47 @@
+package supervisor
+
+import (
+	"reflect"
+	"strings"
+	"testing"
+)
+
+func TestParseRuntimeLog(t *testing.T) {
+	s := `{"level": "error", "msg": "foo\n", "time": "2017-01-01T00:00:42Z"}
+{"level": "error", "msg": "bar\n", "time": "2017-01-01T00:00:43Z"}
+`
+	testCases := []struct {
+		entries  int
+		expected []map[string]interface{}
+	}{
+		{
+			entries: 0,
+			expected: []map[string]interface{}{
+				map[string]interface{}{"level": "error", "msg": "foo\n", "time": "2017-01-01T00:00:42Z"},
+				map[string]interface{}{"level": "error", "msg": "bar\n", "time": "2017-01-01T00:00:43Z"},
+			},
+		},
+		{
+			entries: 1,
+			expected: []map[string]interface{}{
+				map[string]interface{}{"level": "error", "msg": "bar\n", "time": "2017-01-01T00:00:43Z"}},
+		},
+		{
+			entries: 2,
+			expected: []map[string]interface{}{
+				map[string]interface{}{"level": "error", "msg": "foo\n", "time": "2017-01-01T00:00:42Z"},
+				map[string]interface{}{"level": "error", "msg": "bar\n", "time": "2017-01-01T00:00:43Z"},
+			},
+		},
+	}
+
+	for _, tc := range testCases {
+		got, err := parseRuntimeLog(strings.NewReader(s), tc.entries)
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !reflect.DeepEqual(tc.expected, got) {
+			t.Fatalf("expected %v, got %v", tc.expected, got)
+		}
+	}
+}