X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/28e50cc9480fdad416404542511a172cdc7253c7..HEAD:/lib/crunchrun/logging_test.go diff --git a/lib/crunchrun/logging_test.go b/lib/crunchrun/logging_test.go index fab333b433..e747a2069e 100644 --- a/lib/crunchrun/logging_test.go +++ b/lib/crunchrun/logging_test.go @@ -5,31 +5,33 @@ package crunchrun import ( + "bytes" "fmt" + "io" "strings" "testing" "time" "git.arvados.org/arvados.git/sdk/go/arvados" - "git.arvados.org/arvados.git/sdk/go/arvadosclient" . "gopkg.in/check.v1" + check "gopkg.in/check.v1" ) -type LoggingTestSuite struct { - client *arvados.Client -} - -type TestTimestamper struct { - count int +// newTestTimestamper wraps an io.Writer, inserting a predictable +// RFC3339NanoFixed timestamp at the beginning of each line. +func newTestTimestamper(w io.Writer) *prefixer { + count := 0 + return &prefixer{ + writer: w, + prefixFunc: func() string { + count++ + return fmt.Sprintf("2015-12-29T15:51:45.%09dZ ", count) + }, + } } -func (this *TestTimestamper) Timestamp(t time.Time) string { - this.count += 1 - t, err := time.ParseInLocation(time.RFC3339Nano, fmt.Sprintf("2015-12-29T15:51:45.%09dZ", this.count), t.Location()) - if err != nil { - panic(err) - } - return RFC3339Timestamp(t) +type LoggingTestSuite struct { + client *arvados.Client } // Gocheck boilerplate @@ -45,26 +47,20 @@ func (s *LoggingTestSuite) TestWriteLogs(c *C) { api := &ArvTestClient{} kc := &KeepTestClient{} defer kc.Close() - cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-dz642-zzzzzzzzzzzzzzz") + c.Assert(err, IsNil) + f, err := cr.openLogFile("crunch-run") c.Assert(err, IsNil) - cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp + cr.CrunchLog = newLogWriter(newTestTimestamper(f)) cr.CrunchLog.Print("Hello world!") cr.CrunchLog.Print("Goodbye") - cr.CrunchLog.Close() - c.Check(api.Calls, Equals, 1) + c.Check(api.Calls, Equals, 0) - mt, err := cr.LogCollection.MarshalManifest(".") - c.Check(err, IsNil) - c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n") - - logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" + - "2015-12-29T15:51:45.000000002Z Goodbye\n" - - c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run") - c.Check(api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext) - c.Check(string(kc.Content), Equals, logtext) + logs := logFileContent(c, cr, "crunch-run.txt") + c.Check(logs, Matches, `....-..-..T..:..:..\..........Z Hello world!\n`+ + `....-..-..T..:..:..\..........Z Goodbye\n`) } func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) { @@ -74,61 +70,36 @@ func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) { api := &ArvTestClient{} kc := &KeepTestClient{} defer kc.Close() - cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-zzzzzzzzzzzzzzz") c.Assert(err, IsNil) - cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp - cr.CrunchLog.Immediate = nil - + f, err := cr.openLogFile("crunch-run") + c.Assert(err, IsNil) + cr.CrunchLog = newLogWriter(newTestTimestamper(f)) for i := 0; i < 2000000; i++ { cr.CrunchLog.Printf("Hello %d", i) } cr.CrunchLog.Print("Goodbye") - cr.CrunchLog.Close() - - c.Check(api.Calls > 0, Equals, true) - c.Check(api.Calls < 2000000, Equals, true) - - mt, err := cr.LogCollection.MarshalManifest(".") - c.Check(err, IsNil) - c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n") -} -func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) { - api := &ArvTestClient{} - kc := &KeepTestClient{} - defer kc.Close() - cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") - c.Assert(err, IsNil) - ts := &TestTimestamper{} - cr.CrunchLog.Timestamper = ts.Timestamp - w, err := cr.NewLogWriter("stdout") - c.Assert(err, IsNil) - stdout := NewThrottledLogger(w) - stdout.Timestamper = ts.Timestamp - - cr.CrunchLog.Print("Hello world!") - stdout.Print("Doing stuff") - cr.CrunchLog.Print("Goodbye") - stdout.Print("Blurb") - cr.CrunchLog.Close() - stdout.Close() - - logText := make(map[string]string) - for _, content := range api.Content { - log := content["log"].(arvadosclient.Dict) - logText[log["event_type"].(string)] += log["properties"].(map[string]string)["text"] - } - - c.Check(logText["crunch-run"], Equals, `2015-12-29T15:51:45.000000001Z Hello world! -2015-12-29T15:51:45.000000003Z Goodbye -`) - c.Check(logText["stdout"], Equals, `2015-12-29T15:51:45.000000002Z Doing stuff -2015-12-29T15:51:45.000000004Z Blurb + logs := logFileContent(c, cr, "crunch-run.txt") + c.Check(strings.Count(logs, "\n"), Equals, 2000001) + // Redact most of the logs except the start/end for the regexp + // match -- otherwise, when the regexp fails, gocheck spams + // the test logs with tens of megabytes of quoted strings. + c.Assert(len(logs) > 10000, Equals, true) + c.Check(logs[:500]+"\n...\n"+logs[len(logs)-500:], Matches, `(?ms)2015-12-29T15:51:45.000000001Z Hello 0 +2015-12-29T15:51:45.000000002Z Hello 1 +2015-12-29T15:51:45.000000003Z Hello 2 +2015-12-29T15:51:45.000000004Z Hello 3 +.* +2015-12-29T15:51:45.001999998Z Hello 1999997 +2015-12-29T15:51:45.001999999Z Hello 1999998 +2015-12-29T15:51:45.002000000Z Hello 1999999 +2015-12-29T15:51:45.002000001Z Goodbye `) mt, err := cr.LogCollection.MarshalManifest(".") c.Check(err, IsNil) - c.Check(mt, Equals, ". 48f9023dc683a850b1c9b482b14c4b97+163 0:83:crunch-run.txt 83:80:stdout.txt\n") + c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n") } func (s *LoggingTestSuite) TestLogUpdate(c *C) { @@ -146,14 +117,13 @@ func (s *LoggingTestSuite) TestLogUpdate(c *C) { api := &ArvTestClient{} kc := &KeepTestClient{} defer kc.Close() - cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-dz642-zzzzzzzzzzzzzzz") + c.Assert(err, IsNil) + f, err := cr.openLogFile("crunch-run") c.Assert(err, IsNil) - ts := &TestTimestamper{} - cr.CrunchLog.Timestamper = ts.Timestamp - w, err := cr.NewLogWriter("stdout") + cr.CrunchLog = newLogWriter(newTestTimestamper(f)) + stdout, err := cr.openLogFile("stdout") c.Assert(err, IsNil) - stdout := NewThrottledLogger(w) - stdout.Timestamper = ts.Timestamp c.Check(cr.logUUID, Equals, "") cr.CrunchLog.Printf("Hello %1000s", "space") @@ -162,60 +132,45 @@ func (s *LoggingTestSuite) TestLogUpdate(c *C) { } c.Check(cr.logUUID, Not(Equals), "") cr.CrunchLog.Print("Goodbye") - fmt.Fprint(stdout, "Goodbye\n") - cr.CrunchLog.Close() - stdout.Close() - w.Close() + fmt.Fprintln(stdout, "Goodbye") + + c.Check(logFileContent(c, cr, "crunch-run.txt"), Matches, `....-..-..T..:..:............Z Hello {995}space\n`+ + `....-..-..T..:..:............Z Goodbye\n`) + c.Check(logFileContent(c, cr, "stdout.txt"), Matches, `Goodbye\n`) mt, err := cr.LogCollection.MarshalManifest(".") c.Check(err, IsNil) - // Block packing depends on whether there's an update - // between the two Goodbyes -- either way the first - // block will be 4dc76. - c.Check(mt, Matches, `. 4dc76e0a212bfa30c39d76d8c16da0c0\+1038 (afc503bc1b9a828b4bb543cb629e936c\+78|90699dc22545cd74a0664303f70bc05a\+39 276b49339fd5203d15a93ff3de11bfb9\+39) 0:1077:crunch-run.txt 1077:39:stdout.txt\n`) + c.Check(mt, Matches, `. 4dc76e0a212bfa30c39d76d8c16da0c0\+1038 5be52044a8c51e7b62dd62be07872968\+47 0:1077:crunch-run.txt 1077:8:stdout.txt\n`) } } -func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) { - s.testWriteLogsWithRateLimit(c, "crunchLogThrottleBytes", 50, 65536, "Exceeded rate 50 bytes per 60 seconds") -} +type filterSuite struct{} -func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) { - s.testWriteLogsWithRateLimit(c, "crunchLogThrottleLines", 1, 1024, "Exceeded rate 1 lines per 60 seconds") -} +var _ = Suite(&filterSuite{}) -func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytesPerEvent(c *C) { - s.testWriteLogsWithRateLimit(c, "crunchLimitLogBytesPerJob", 50, 67108864, "Exceeded log limit 50 bytes (crunch_limit_log_bytes_per_job)") +func (*filterSuite) TestFilterKeepstoreErrorsOnly(c *check.C) { + var buf bytes.Buffer + f := filterKeepstoreErrorsOnly{WriteCloser: nopCloser{&buf}} + for _, s := range []string{ + "not j", + "son\n" + `{"msg":"foo"}` + "\n{}\n" + `{"msg":"request"}` + "\n" + `{"msg":1234}` + "\n\n", + "\n[\n", + `{"msg":"response","respStatusCode":404,"foo": "bar"}` + "\n", + `{"msg":"response","respStatusCode":206}` + "\n", + } { + f.Write([]byte(s)) + } + c.Check(buf.String(), check.Equals, `not json +{"msg":"foo"} +{} +{"msg":1234} +[ +{"msg":"response","respStatusCode":404,"foo": "bar"} +`) } -func (s *LoggingTestSuite) testWriteLogsWithRateLimit(c *C, throttleParam string, throttleValue int, throttleDefault int, expected string) { - discoveryMap[throttleParam] = float64(throttleValue) - defer func() { - discoveryMap[throttleParam] = float64(throttleDefault) - }() - - api := &ArvTestClient{} - kc := &KeepTestClient{} - defer kc.Close() - cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") - c.Assert(err, IsNil) - cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp - - cr.CrunchLog.Print("Hello world!") - cr.CrunchLog.Print("Goodbye") - cr.CrunchLog.Close() - - c.Check(api.Calls, Equals, 1) - - mt, err := cr.LogCollection.MarshalManifest(".") - c.Check(err, IsNil) - c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n") - - logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" + - "2015-12-29T15:51:45.000000002Z Goodbye\n" - - c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run") - stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"] - c.Check(true, Equals, strings.Contains(stderrLog, expected)) - c.Check(string(kc.Content), Equals, logtext) +type nopCloser struct { + io.Writer } + +func (nopCloser) Close() error { return nil }