Merge pull request #490 from Crazykev/test-log

Print integration test log when case failed

Author: laijs

.gitignore

@@ -58,3 +58,4 @@ _testmain.go
 # ignore test_data
 test_data
 !test_data/Makefile
+integration-test/config.json

Makefile.am

@@ -22,5 +22,4 @@ build-runv:
 	go build -tags "static_build $(HYPER_BULD_TAGS)" -o runv .
 test-integration:
 	cd integration-test/test_data && make
-	cd integration-test && go test -check.v -test.timeout=120m ${TESTFLAGS} . ; ret=$$? ;\
-	sync; sleep 20; sync; find /var/log/hyper/ -type f -exec echo -e '\n\nLog of ' {} ':' \; -exec cat {} \; ; exit $$ret
+	cd integration-test && go test -check.v -test.timeout=120m ${TESTFLAGS} .

containerd/containerd.go

@@ -32,6 +32,9 @@ const (
 	defaultStateDir     = "/run/runv-containerd"
 	defaultListenType   = "unix"
 	defaultGRPCEndpoint = "/run/runv-containerd/containerd.sock"
+	// runv-containerd is a relativly short term program
+	// since we can't change the flush interval in glog, flush here manaully.
+	glogFlushInterval = 5 * time.Second
 )
 
 var ContainerdCommand = cli.Command{
@@ -152,6 +155,8 @@ func daemon(sv *supervisor.Supervisor, address string) error {
 	s := make(chan os.Signal, 2048)
 	signal.Notify(s, syscall.SIGTERM, syscall.SIGINT, syscall.SIGQUIT)
 
+	go glogFlushDaemon()
+
 	server, err := startServer(address, sv)
 	if err != nil {
 		return err
@@ -161,6 +166,7 @@ func daemon(sv *supervisor.Supervisor, address string) error {
 	glog.V(1).Infof("stopping containerd after receiving %s", sig)
 	time.Sleep(3 * time.Second) // TODO: fix it by proper way
 	server.Stop()
+	glog.Flush()
 	return nil
 }
 
@@ -200,3 +206,9 @@ func startServer(address string, sv *supervisor.Supervisor) (*grpc.Server, error
 	}()
 	return s, nil
 }
+
+func glogFlushDaemon() {
+	for range time.NewTicker(glogFlushInterval).C {
+		glog.Flush()
+	}
+}

integration-test/exec_test.go

@@ -15,6 +15,7 @@ import (
 )
 
 func (s *RunVSuite) TestExecHelloWorld(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "testExecHelloWorld"
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"sleep", "10"}
@@ -43,6 +44,7 @@ func (s *RunVSuite) TestExecHelloWorld(c *check.C) {
 }
 
 func (s *RunVSuite) TestExecWithTty(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "TestExecWithTty"
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"sleep", "10"}
@@ -91,6 +93,7 @@ func (s *RunVSuite) TestExecWithTty(c *check.C) {
 }
 
 func (s *RunVSuite) TestExecWithProcessJson(c *check.C) {
+	defer s.PrintLog(c)
 	process := specs.Process{
 		Terminal: false,
 		User:     specs.User{},

integration-test/init_test.go

@@ -3,26 +3,29 @@ package main
 import (
 	"bytes"
 	"encoding/json"
+	"fmt"
 	"io/ioutil"
 	"os"
 	"os/exec"
 	"path/filepath"
 	"runtime"
 	"testing"
+	"time"
 
 	"github.com/docker/docker/integration-cli/checker"
 	"github.com/go-check/check"
 	"github.com/opencontainers/runtime-spec/specs-go"
 )
 
 const (
-	testDataDir    = "test_data"
-	busyboxTarName = "busybox.tar"
-	configFileName = "config.json"
-	kernelName     = "kernel"
-	initrdName     = "hyper-initrd.img"
-	binaryName     = "runv"
-	rootfsName     = "rootfs"
+	testDataDir        = "test_data"
+	busyboxTarName     = "busybox.tar"
+	configFileName     = "config.json"
+	kernelName         = "kernel"
+	initrdName         = "hyper-initrd.img"
+	binaryName         = "runv"
+	rootfsName         = "rootfs"
+	logFileNamePattern = "runv*INFO*"
 )
 
 var (
@@ -63,6 +66,7 @@ type RunVSuite struct {
 	initrdPath string
 	bundlePath string
 	configPath string
+	logPath    string
 }
 
 var _ = check.Suite(&RunVSuite{})
@@ -110,12 +114,23 @@ func (s *RunVSuite) SetUpSuite(c *check.C) {
 
 func (s *RunVSuite) TearDownSuite(c *check.C) {}
 
-func (s *RunVSuite) SetUpTest(c *check.C) {}
+func (s *RunVSuite) SetUpTest(c *check.C) {
+	s.logPath = c.MkDir()
+}
 
 func (s *RunVSuite) TearDownTest(c *check.C) {
 	// FIXME: Use runv kill/delete to do reliable garbage collection
 	// after kill/delete functions are stable
-	exec.Command("pkill", "-9", "runv-namespaced").Run()
-	exec.Command("pkill", "-9", "qemu").Run()
-	exec.Command("pkill", "-9", "containerd-nslistener")
+	killAllRunvComponent(9)
+}
+
+func (s *RunVSuite) PrintLog(c *check.C) {
+	if c.Failed() {
+		// kill runv gently to enable garbage collection and flush log
+		killAllRunvComponent(15)
+		time.Sleep(3 * time.Second)
+		out, err := exec.Command("sh", "-c", fmt.Sprintf("find %s -type f -name '%s' -exec echo -e '\n\nLog of ' {} ':' \\; -exec cat {} \\;", s.logPath, logFileNamePattern)).CombinedOutput()
+		c.Assert(err, checker.IsNil)
+		c.Logf("Test case %s failed, retrieve runv log from directory %s:\n%s", c.TestName(), s.logPath, out)
+	}
 }

integration-test/kill_test.go

@@ -9,6 +9,7 @@ import (
 )
 
 func (s *RunVSuite) TestKillKILL(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "testKillKILL"
 	spec := defaultTestSpec
 	c.Assert(s.addSpec(&spec), checker.IsNil)

integration-test/list_test.go

@@ -21,6 +21,7 @@ type containerState struct {
 }
 
 func (s *RunVSuite) TestListSleep(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "testListSleep"
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"sleep", "10"}
@@ -48,6 +49,7 @@ func (s *RunVSuite) TestListSleep(c *check.C) {
 }
 
 func (s *RunVSuite) TestListSleepJson(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "testListSleepJson"
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"sleep", "10"}

integration-test/spec_test.go

@@ -13,6 +13,7 @@ import (
 )
 
 func (s *RunVSuite) TestSpecDefault(c *check.C) {
+	defer s.PrintLog(c)
 	expectedSpec := defaultTestSpec
 	expectedSpec.Process.Terminal = true
 	expectedSpec.Process.Args = []string{"sh"}

integration-test/start_test.go

@@ -16,6 +16,7 @@ import (
 )
 
 func (s *RunVSuite) TestStartHelloworld(c *check.C) {
+	defer s.PrintLog(c)
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"echo", "hello"}
 	c.Assert(s.addSpec(&spec), checker.IsNil)
@@ -26,6 +27,7 @@ func (s *RunVSuite) TestStartHelloworld(c *check.C) {
 }
 
 func (s *RunVSuite) TestStartPid(c *check.C) {
+	defer s.PrintLog(c)
 	c.Skip("enable this after fixing")
 	ctrName := "testStartPid"
 	spec := defaultTestSpec
@@ -80,6 +82,7 @@ func (s *RunVSuite) TestStartPid(c *check.C) {
 }
 
 func (s *RunVSuite) TestStartWithTty(c *check.C) {
+	defer s.PrintLog(c)
 	ctrName := "TestStartWithTty"
 	spec := defaultTestSpec
 	spec.Process.Terminal = true

integration-test/state_test.go

@@ -31,6 +31,7 @@ func (s *RunVSuite) TestStateSleep(c *check.C) {
 	//TODO: enable this after fixing!!!
 	//c.Skip("enable this after fixing")
 
+	defer s.PrintLog(c)
 	ctrName := "testStateSleep"
 	spec := defaultTestSpec
 	spec.Process.Args = []string{"sleep", "10"}