diff --git a/cli/logs.go b/cli/logs.go index 8301c8bf1..63c589c55 100644 --- a/cli/logs.go +++ b/cli/logs.go @@ -1,11 +1,12 @@ package main import ( - "bytes" "context" - "fmt" + "io" + "os" "github.com/alibaba/pouch/apis/types" + "github.com/docker/docker/pkg/stdcopy" "github.com/spf13/cobra" ) @@ -25,6 +26,7 @@ type LogsCommand struct { follow bool since string tail string + until string timestamps bool } @@ -47,17 +49,17 @@ func (lc *LogsCommand) Init(c *Cli) { // addFlags adds flags for specific command. func (lc *LogsCommand) addFlags() { flagSet := lc.cmd.Flags() - flagSet.BoolVarP(&lc.details, "details", "", false, "Show extra provided to logs") flagSet.BoolVarP(&lc.follow, "follow", "f", false, "Follow log output") - flagSet.StringVarP(&lc.since, "since", "", "", "Show logs since timestamp") + flagSet.StringVarP(&lc.since, "since", "", "", "Show logs since timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)") + flagSet.StringVarP(&lc.until, "until", "", "", "Show logs before timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)") flagSet.StringVarP(&lc.tail, "tail", "", "all", "Number of lines to show from the end of the logs default \"all\"") flagSet.BoolVarP(&lc.timestamps, "timestamps", "t", false, "Show timestamps") + + // TODO(fuwei): support the detail functionality } // runLogs is the entry of LogsCommand command. func (lc *LogsCommand) runLogs(args []string) error { - // TODO - containerName := args[0] ctx := context.Background() @@ -67,25 +69,30 @@ func (lc *LogsCommand) runLogs(args []string) error { ShowStdout: true, ShowStderr: true, Since: lc.since, + Until: lc.until, Timestamps: lc.timestamps, Follow: lc.follow, Tail: lc.tail, - Details: lc.details, } - resp, err := apiClient.ContainerLogs(ctx, containerName, opts) + body, err := apiClient.ContainerLogs(ctx, containerName, opts) if err != nil { return err } - defer resp.Close() + defer body.Close() - buf := new(bytes.Buffer) - buf.ReadFrom(resp) - - fmt.Printf(buf.String()) + c, err := apiClient.ContainerGet(ctx, containerName) + if err != nil { + return err + } - return nil + if c.Config.Tty { + _, err = io.Copy(os.Stdout, body) + } else { + _, err = stdcopy.StdCopy(os.Stdout, os.Stderr, body) + } + return err } // logsExample shows examples in logs command, and is used in auto-generated cli docs. diff --git a/client/container_logs.go b/client/container_logs.go index dce110ebb..80153bf94 100644 --- a/client/container_logs.go +++ b/client/container_logs.go @@ -4,12 +4,16 @@ import ( "context" "io" "net/url" + "time" "github.com/alibaba/pouch/apis/types" + "github.com/alibaba/pouch/pkg/utils" ) // ContainerLogs return the logs generated by a container in an io.ReadCloser. func (client *APIClient) ContainerLogs(ctx context.Context, name string, options types.ContainerLogsOptions) (io.ReadCloser, error) { + now := time.Now() + query := url.Values{} if options.ShowStdout { query.Set("stdout", "1") @@ -20,21 +24,25 @@ func (client *APIClient) ContainerLogs(ctx context.Context, name string, options } if options.Since != "" { - // TODO + sinceTs, err := utils.GetUnixTimestamp(options.Since, now) + if err != nil { + return nil, err + } + query.Set("since", sinceTs) } if options.Until != "" { - // TODO + untilTs, err := utils.GetUnixTimestamp(options.Until, now) + if err != nil { + return nil, err + } + query.Set("until", untilTs) } if options.Timestamps { query.Set("timestamps", "1") } - if options.Details { - query.Set("details", "1") - } - if options.Follow { query.Set("follow", "1") } @@ -44,6 +52,5 @@ func (client *APIClient) ContainerLogs(ctx context.Context, name string, options if err != nil { return nil, err } - ensureCloseReader(resp) return resp.Body, nil } diff --git a/client/container_logs_test.go b/client/container_logs_test.go new file mode 100644 index 000000000..e91e00b4a --- /dev/null +++ b/client/container_logs_test.go @@ -0,0 +1,94 @@ +package client + +import ( + "bytes" + "context" + "fmt" + "io/ioutil" + "net/http" + "strings" + "testing" + + "github.com/alibaba/pouch/apis/types" +) + +func TestContainerLogsServerError(t *testing.T) { + client := &APIClient{ + HTTPCli: newMockClient(errorMockResponse(http.StatusInternalServerError, "Server error")), + } + + _, err := client.ContainerLogs(context.Background(), "nothing", types.ContainerLogsOptions{}) + if err == nil || !strings.Contains(err.Error(), "Server error") { + t.Fatalf("expected a Server Error, got %v", err) + } +} + +func TestContainerLogsOK(t *testing.T) { + expectedURL := "/containers/container_id/logs" + expectedSinceTS := "1531728000.000000000" // 2018-07-16T08:00Z + expectedUntilTS := "1531728300.000000000" // 2018-07-16T08:05Z + + opts := types.ContainerLogsOptions{ + Follow: true, + ShowStdout: true, + ShowStderr: false, + Timestamps: true, + + Since: "2018-07-16T08:00Z", + Until: "2018-07-16T08:05Z", + Tail: "10", + } + + httpClient := newMockClient(func(req *http.Request) (*http.Response, error) { + if !strings.HasPrefix(req.URL.Path, expectedURL) { + return nil, fmt.Errorf("expected URL %s, got %s", expectedURL, req.URL) + } + + if req.Method != http.MethodGet { + return nil, fmt.Errorf("expected HTTP Method = %s, got %s", http.MethodGet, req.Method) + } + + query := req.URL.Query() + if got := query.Get("follow"); got != "1" { + return nil, fmt.Errorf("expected follow mode (1), got %v", got) + } + + if got := query.Get("stdout"); got != "1" { + return nil, fmt.Errorf("expected stdout mode (1), got %v", got) + } + + if got := query.Get("stderr"); got != "" { + return nil, fmt.Errorf("expected without stderr mode, got %v", got) + } + + if got := query.Get("timestamps"); got != "1" { + return nil, fmt.Errorf("expected timestamps mode, got %v", got) + } + + if got := query.Get("tail"); got != "10" { + return nil, fmt.Errorf("expected tail = %v, got %v", opts.Tail, got) + } + + if got := query.Get("since"); got != expectedSinceTS { + return nil, fmt.Errorf("expected since = %v, got %v", expectedSinceTS, got) + } + + if got := query.Get("until"); got != expectedUntilTS { + return nil, fmt.Errorf("expected since = %v, got %v", expectedUntilTS, got) + } + + return &http.Response{ + StatusCode: http.StatusOK, + Body: ioutil.NopCloser(bytes.NewReader([]byte(""))), + }, nil + }) + + client := &APIClient{ + HTTPCli: httpClient, + } + + _, err := client.ContainerLogs(context.Background(), "container_id", opts) + if err != nil { + t.Fatal(err) + } +} diff --git a/daemon/logger/jsonfile/utils.go b/daemon/logger/jsonfile/utils.go index eb1df1ecc..6cac58ed6 100644 --- a/daemon/logger/jsonfile/utils.go +++ b/daemon/logger/jsonfile/utils.go @@ -193,15 +193,19 @@ func seekOffsetByTailLines(rs io.ReadSeeker, n int) (int64, error) { cnt = 0 left = int64(0) b []byte + + readN = int64(0) ) for { + readN = int64(blockSize) left = size + int64(block*blockSize) if left < 0 { + readN = int64(blockSize) + left left = 0 } - b = make([]byte, blockSize) + b = make([]byte, readN) if _, err := rs.Seek(left, os.SEEK_SET); err != nil { return 0, err } diff --git a/pkg/utils/utils.go b/pkg/utils/utils.go index a20f0c047..4ab029ae9 100644 --- a/pkg/utils/utils.go +++ b/pkg/utils/utils.go @@ -88,6 +88,92 @@ func FormatTimeInterval(input int64) (formattedTime string, err error) { return formattedTime, nil } +// GetUnixTimestamp will parse the value into time and get the nano-timestamp +// in string. +// +// NOTE: if the value is not relative time, GetUnixTimestamp will use RFC3339 +// format to parse the value. +func GetUnixTimestamp(value string, base time.Time) (string, error) { + // time.ParseDuration will handle the 5h, 7d relative time. + if d, err := time.ParseDuration(value); value != "0" && err == nil { + return strconv.FormatInt(base.Add(-d).Unix(), 10), nil + } + + var ( + // rfc3399 + layoutDate = "2006-01-02" + layoutDateWithH = "2006-01-02T15" + layoutDateWithHM = "2006-01-02T15:04" + layoutDateWithHMS = "2006-01-02T15:04:05" + layoutDateWithHMSNano = "2006-01-02T15:04:05.999999999" + + layout string + ) + + // if the value doesn't contain any z, Z, +, T, : and -, it maybe + // timestamp and we should return value. + if !strings.ContainsAny(value, "zZ+.:T-") { + return value, nil + } + + // if the value containns any z, Z or +, we should parse it with timezone + isLocal := !(strings.ContainsAny(value, "zZ+") || strings.Count(value, "-") == 3) + + if strings.Contains(value, ".") { + // if the value contains ., we should parse it with nano + if isLocal { + layout = layoutDateWithHMSNano + } else { + layout = layoutDateWithHMSNano + "Z07:00" + } + } else if strings.Contains(value, "T") { + // if the value contains T, we should parse it with h:m:s + numColons := strings.Count(value, ":") + + // NOTE: + // from https://tools.ietf.org/html/rfc3339 + // + // time-numoffset = ("+" / "-") time-hour [[":"] time-minute] + // + // if the value has zero with +/-, it may contains the extra + // colon like +08:00, which we should remove the extra colon. + if !isLocal && !strings.ContainsAny(value, "zZ") && numColons > 0 { + numColons-- + } + + switch numColons { + case 0: + layout = layoutDateWithH + case 1: + layout = layoutDateWithHM + default: + layout = layoutDateWithHMS + } + + if !isLocal { + layout += "Z07:00" + } + } else if isLocal { + layout = layoutDate + } else { + layout = layoutDate + "Z07:00" + } + + var t time.Time + var err error + + if isLocal { + t, err = time.ParseInLocation(layout, value, time.FixedZone(base.Zone())) + } else { + t, err = time.Parse(layout, value) + } + + if err != nil { + return "", err + } + return fmt.Sprintf("%d.%09d", t.Unix(), int64(t.Nanosecond())), nil +} + // ParseTimestamp returns seconds and nanoseconds. // // 1. If the value is empty, it will return default second, the second arg. diff --git a/pkg/utils/utils_test.go b/pkg/utils/utils_test.go index 43dc3acf3..b791c2cdc 100644 --- a/pkg/utils/utils_test.go +++ b/pkg/utils/utils_test.go @@ -398,6 +398,76 @@ func TestCheckPidExist(t *testing.T) { } } +func TestGetTimestamp(t *testing.T) { + now := time.Now().In(time.UTC) + + tCases := []struct { + val string + expected string + hasError bool + }{ + // relative time + {"1s", fmt.Sprintf("%d", now.Add(-1*time.Second).Unix()), false}, + {"1m", fmt.Sprintf("%d", now.Add(-1*time.Minute).Unix()), false}, + {"1.5h", fmt.Sprintf("%d", now.Add(-90*time.Minute).Unix()), false}, + {"1h30m", fmt.Sprintf("%d", now.Add(-90*time.Minute).Unix()), false}, + + // time + {"2018-07-16T08:00:00.999999999+08:00", "1531699200.999999999", false}, + {"2018-07-16T08:00:00.999999999+00:00", "1531728000.999999999", false}, + {"2018-07-16T08:00:00.999999999-00:00", "1531728000.999999999", false}, + {"2018-07-16T08:00:00.999999999Z", "1531728000.999999999", false}, + {"2018-07-16T08:00:00.999999999", "1531728000.999999999", false}, + + {"2018-07-16T08:00:00", "1531728000.000000000", false}, + {"2018-07-16T08:00:00Z", "1531728000.000000000", false}, + {"2018-07-16T08:00:00+00:00", "1531728000.000000000", false}, + {"2018-07-16T08:00:00-00:00", "1531728000.000000000", false}, + + {"2018-07-16T08:00", "1531728000.000000000", false}, + {"2018-07-16T08:00Z", "1531728000.000000000", false}, + {"2018-07-16T08:00+00:00", "1531728000.000000000", false}, + {"2018-07-16T08:00-00:00", "1531728000.000000000", false}, + + {"2018-07-16T08", "1531728000.000000000", false}, + {"2018-07-16T08Z", "1531728000.000000000", false}, + {"2018-07-16T08+01:00", "1531724400.000000000", false}, + {"2018-07-16T08-01:00", "1531731600.000000000", false}, + + {"2018-07-16", "1531699200.000000000", false}, + {"2018-07-16Z", "1531699200.000000000", false}, + {"2018-07-16+01:00", "1531695600.000000000", false}, + {"2018-07-16-01:00", "1531702800.000000000", false}, + + // timestamp + {"0", "0", false}, + {"12", "12", false}, + {"12a", "12a", false}, + + // invalid input + {"-12", "", true}, + {"2006-01-02T15:04:0Z", "", true}, + {"2006-01-02T15:04:0", "", true}, + {"2006-01-02T15:0Z", "", true}, + {"2006-01-02T15:0", "", true}, + } + + for _, tc := range tCases { + got, err := GetUnixTimestamp(tc.val, now) + if err != nil && !tc.hasError { + t.Fatalf("unexpected error %v", err) + } + + if err == nil && tc.hasError { + t.Fatal("expected error, but got nothing") + } + + if got != tc.expected { + t.Errorf("expected %v, but got %v", tc.expected, got) + } + } +} + func TestParseTimestamp(t *testing.T) { tCases := []struct { val string diff --git a/test/api_container_logs_test.go b/test/api_container_logs_test.go index e6d17a2be..30ca58ef2 100644 --- a/test/api_container_logs_test.go +++ b/test/api_container_logs_test.go @@ -118,8 +118,8 @@ func (suite *APIContainerLogsSuite) TestSinceAndUntil(c *check.C) { allLogs = suite.syncReadLog(c, name, map[string]string{ "stdout": "1", - "since": fmt.Sprintf("%d.%09d", sinceTime.Unix(), sinceTime.UnixNano()), - "until": fmt.Sprintf("%d.%09d", untilTime.Unix(), untilTime.UnixNano()), + "since": fmt.Sprintf("%d.%09d", sinceTime.Unix(), sinceTime.Nanosecond()), + "until": fmt.Sprintf("%d.%09d", untilTime.Unix(), untilTime.Nanosecond()), }) c.Assert(len(allLogs), check.Equals, 1) diff --git a/test/cli_logs_test.go b/test/cli_logs_test.go index 5ec441d34..5cf9e657b 100644 --- a/test/cli_logs_test.go +++ b/test/cli_logs_test.go @@ -1,9 +1,16 @@ package main import ( + "fmt" + "strings" + "time" + + "github.com/alibaba/pouch/pkg/utils" + "github.com/alibaba/pouch/test/command" "github.com/alibaba/pouch/test/environment" "github.com/go-check/check" + "github.com/gotestyourself/gotestyourself/icmd" ) // PouchLogsSuite is the test suite for logs CLI. @@ -17,12 +24,135 @@ func init() { func (suite *PouchLogsSuite) SetUpSuite(c *check.C) { SkipIfFalse(c, environment.IsLinux) - environment.PruneAllContainers(apiClient) - PullImage(c, busyboxImage) } -// TearDownTest does cleanup work in the end of each test. -func (suite *PouchLogsSuite) TeadDownTest(c *check.C) { - // TODO +// TestCreatedContainerLogIsEmpty tests logs for created container. +func (suite *PouchLogsSuite) TestCreatedContainerLogIsEmpty(c *check.C) { + cname := "TestCLILogs_EmptyLogInCreatedContainer" + + command.PouchRun("create", "--name", cname, busyboxImage).Assert(c, icmd.Success) + defer DelContainerForceMultyTime(c, cname) + + res := command.PouchRun("logs", cname) + res.Assert(c, icmd.Success) + c.Assert(res.Combined(), check.Equals, "") +} + +// TestSinceAndUntil tests the since and until. +func (suite *PouchLogsSuite) TestSinceAndUntil(c *check.C) { + cname := "TestCLILogs_Since_and_Until" + totalLine := 5 + + command.PouchRun( + "run", + "-t", + "--name", cname, busyboxImage, + "sh", "-c", fmt.Sprintf("for i in $(seq 1 %v); do echo hello$i; sleep 1; done;", totalLine), + ).Assert(c, icmd.Success) + defer DelContainerForceMultyTime(c, cname) + + allLogs := suite.syncLogs(c, cname, "--timestamps") + c.Assert(len(allLogs), check.Equals, totalLine) + + // get the since and until time + sinceTime, err := time.Parse(utils.TimeLayout, strings.Split(allLogs[2], " ")[0]) + c.Assert(err, check.IsNil) + + untilTime, err := time.Parse(utils.TimeLayout, strings.Split(allLogs[3], " ")[0]) + c.Assert(err, check.IsNil) + untilTime = untilTime.Add(-200 * time.Nanosecond) + + allLogs = suite.syncLogs(c, cname, + "--since", fmt.Sprintf("%d", sinceTime.UnixNano()), + "--until", fmt.Sprintf("%d", untilTime.UnixNano())) + c.Assert(len(allLogs), check.Equals, 1) +} + +// TestTimestamp tests the timestamps flag. +func (suite *PouchLogsSuite) TestTimestamp(c *check.C) { + cname := "TestCLILogs_timestamp" + + command.PouchRun( + "run", + "-t", + "--name", cname, + busyboxImage, + "echo", "hello", + ).Assert(c, icmd.Success) + defer DelContainerForceMultyTime(c, cname) + + allLogs := suite.syncLogs(c, cname, "--timestamps") + c.Assert(len(allLogs), check.Equals, 1) + + _, err := time.Parse(utils.TimeLayout, strings.Split(allLogs[0], " ")[0]) + c.Assert(err, check.IsNil) + c.Assert(strings.TrimSpace(strings.Split(allLogs[0], " ")[1]), check.Equals, "hello") +} + +// TestTailMode tests follow mode. +func (suite *PouchLogsSuite) TestTailLine(c *check.C) { + cname := "TestCLILogs_tail_line" + DelContainerForceMultyTime(c, cname) + totalLine := 100 + + command.PouchRun( + "run", + "-t", + "--name", cname, + busyboxImage, + "sh", "-c", fmt.Sprintf("for i in $(seq 1 %v); do echo hello-$i; done;", totalLine), + ).Assert(c, icmd.Success) + + for _, tc := range []struct { + input string + expected int + }{ + {"1000", totalLine}, + {"100", totalLine}, + {"67", 67}, + {"5", 5}, + {"0", totalLine}, + {"-1", totalLine}, + {"wronglinenumber", totalLine}, + } { + allLogs := suite.syncLogs(c, cname, "--tail", tc.input) + c.Assert(allLogs, check.HasLen, tc.expected) + } +} + +// TestFollowMode tests follow mode. +func (suite *PouchLogsSuite) TestFollowMode(c *check.C) { + cname := "TestCLILogs_follow_mode" + + command.PouchRun( + "run", + "-d", + "--name", cname, + busyboxImage, + "sh", "-c", "for i in $(seq 1 3); do sleep 2; echo hello; done;", + ).Assert(c, icmd.Success) + defer DelContainerForceMultyTime(c, cname) + + waitCh := make(chan error) + go func() { + waitCh <- command.PouchRun("logs", "-f", cname).Error + close(waitCh) + }() + + select { + case err := <-waitCh: + c.Assert(err, check.IsNil) + case <-time.After(15 * time.Second): + c.Fatal("pouch logs -f may hanged") + } +} + +func (suite *PouchLogsSuite) syncLogs(c *check.C, cname string, flags ...string) []string { + args := append([]string{"logs"}, flags...) + + res := command.PouchRun(append(args, cname)...) + res.Assert(c, icmd.Success) + + return strings.Split(strings.TrimSpace(string(res.Combined())), "\n") }