X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/be191fe42348d23708f0c4de8ace619644b18b2d..cbf93e8d897448dbd52369afe89fef2392140ff1:/services/crunch-run/logging_test.go diff --git a/services/crunch-run/logging_test.go b/services/crunch-run/logging_test.go index 79214fca7d..78f984db5b 100644 --- a/services/crunch-run/logging_test.go +++ b/services/crunch-run/logging_test.go @@ -1,13 +1,23 @@ +// Copyright (C) The Arvados Authors. All rights reserved. +// +// SPDX-License-Identifier: AGPL-3.0 + package main import ( "fmt" + "strings" + "testing" + "time" + + "git.curoverse.com/arvados.git/sdk/go/arvados" "git.curoverse.com/arvados.git/sdk/go/arvadosclient" . "gopkg.in/check.v1" - "time" ) -type LoggingTestSuite struct{} +type LoggingTestSuite struct { + client *arvados.Client +} type TestTimestamper struct { count int @@ -15,16 +25,28 @@ type TestTimestamper struct { func (this *TestTimestamper) Timestamp(t time.Time) string { this.count += 1 - return fmt.Sprintf("2015-12-29T15:51:45.%09dZ", this.count) + 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) } // Gocheck boilerplate var _ = Suite(&LoggingTestSuite{}) +func (s *LoggingTestSuite) SetUpTest(c *C) { + s.client = arvados.NewClientFromEnv() + crunchLogUpdatePeriod = time.Hour * 24 * 365 + crunchLogUpdateSize = 1 << 50 +} + func (s *LoggingTestSuite) TestWriteLogs(c *C) { api := &ArvTestClient{} kc := &KeepTestClient{} - cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + 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!") @@ -33,7 +55,7 @@ func (s *LoggingTestSuite) TestWriteLogs(c *C) { c.Check(api.Calls, Equals, 1) - mt, err := cr.LogCollection.ManifestText() + mt, err := cr.LogCollection.MarshalManifest(".") c.Check(err, IsNil) c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n") @@ -46,22 +68,27 @@ func (s *LoggingTestSuite) TestWriteLogs(c *C) { } func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) { + if testing.Short() { + return + } api := &ArvTestClient{} kc := &KeepTestClient{} - cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + defer kc.Close() + cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + c.Assert(err, IsNil) cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp cr.CrunchLog.Immediate = nil - for i := 0; i < 2000000; i += 1 { + for i := 0; i < 2000000; i++ { cr.CrunchLog.Printf("Hello %d", i) } cr.CrunchLog.Print("Goodbye") cr.CrunchLog.Close() - c.Check(api.Calls > 1, Equals, true) + c.Check(api.Calls > 0, Equals, true) c.Check(api.Calls < 2000000, Equals, true) - mt, err := cr.LogCollection.ManifestText() + mt, err := cr.LogCollection.MarshalManifest(".") c.Check(err, IsNil) c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n") } @@ -69,32 +96,126 @@ func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) { func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) { api := &ArvTestClient{} kc := &KeepTestClient{} - cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + defer kc.Close() + cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz") + c.Assert(err, IsNil) ts := &TestTimestamper{} cr.CrunchLog.Timestamper = ts.Timestamp - stdout := NewThrottledLogger(cr.NewLogWriter("stdout")) + 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 +`) + + 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") +} + +func (s *LoggingTestSuite) TestLogUpdate(c *C) { + for _, trial := range []struct { + maxBytes int64 + maxDuration time.Duration + }{ + {1000, 10 * time.Second}, + {1000000, time.Millisecond}, + } { + c.Logf("max %d bytes, %s", trial.maxBytes, trial.maxDuration) + crunchLogUpdateSize = trial.maxBytes + crunchLogUpdatePeriod = trial.maxDuration + + 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 + + c.Check(cr.logUUID, Equals, "") + cr.CrunchLog.Printf("Hello %1000s", "space") + for i, t := 0, time.NewTicker(time.Millisecond); i < 5000 && cr.logUUID == ""; i++ { + <-t.C + } + c.Check(cr.logUUID, Not(Equals), "") + cr.CrunchLog.Print("Goodbye") + fmt.Fprint(stdout, "Goodbye\n") + cr.CrunchLog.Close() + stdout.Close() + w.Close() + + 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`) + } +} + +func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) { + s.testWriteLogsWithRateLimit(c, "crunchLogThrottleBytes", 50, 65536, "Exceeded rate 50 bytes per 60 seconds") +} +func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) { + s.testWriteLogsWithRateLimit(c, "crunchLogThrottleLines", 1, 1024, "Exceeded rate 1 lines per 60 seconds") +} + +func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytesPerEvent(c *C) { + s.testWriteLogsWithRateLimit(c, "crunchLimitLogBytesPerJob", 50, 67108864, "Exceeded log limit 50 bytes (crunch_limit_log_bytes_per_job)") +} + +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() - logtext1 := "2015-12-29T15:51:45.000000001Z Hello world!\n" + - "2015-12-29T15:51:45.000000003Z 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, logtext1) - stdout.Close() - logtext2 := "2015-12-29T15:51:45.000000002Z Doing stuff\n" + - "2015-12-29T15:51:45.000000004Z Blurb\n" - c.Check(api.Content[1]["log"].(arvadosclient.Dict)["event_type"], Equals, "stdout") - c.Check(api.Content[1]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext2) + c.Check(api.Calls, Equals, 1) - mt, err := cr.LogCollection.ManifestText() + mt, err := cr.LogCollection.MarshalManifest(".") c.Check(err, IsNil) - c.Check(mt, Equals, ""+ - ". 408672f5b5325f7d20edfbf899faee42+83 0:83:crunch-run.txt\n"+ - ". c556a293010069fa79a6790a931531d5+80 0:80:stdout.txt\n") + 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) }