services/crunch-run/logging_test.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.0
   4
   5 package main
   6
   7 import (
   8         "fmt"
   9         "strings"
  10         "testing"
  11         "time"
  12
  13         "git.curoverse.com/arvados.git/sdk/go/arvados"
  14         "git.curoverse.com/arvados.git/sdk/go/arvadosclient"
  15         . "gopkg.in/check.v1"
  16 )
  17
  18 type LoggingTestSuite struct {
  19         client *arvados.Client
  20 }
  21
  22 type TestTimestamper struct {
  23         count int
  24 }
  25
  26 func (this *TestTimestamper) Timestamp(t time.Time) string {
  27         this.count += 1
  28         t, err := time.ParseInLocation(time.RFC3339Nano, fmt.Sprintf("2015-12-29T15:51:45.%09dZ", this.count), t.Location())
  29         if err != nil {
  30                 panic(err)
  31         }
  32         return RFC3339Timestamp(t)
  33 }
  34
  35 // Gocheck boilerplate
  36 var _ = Suite(&LoggingTestSuite{})
  37
  38 func (s *LoggingTestSuite) SetUpTest(c *C) {
  39         s.client = arvados.NewClientFromEnv()
  40         crunchLogUpdatePeriod = time.Hour * 24 * 365
  41         crunchLogUpdateSize = 1 << 50
  42 }
  43
  44 func (s *LoggingTestSuite) TestWriteLogs(c *C) {
  45         api := &ArvTestClient{}
  46         kc := &KeepTestClient{}
  47         defer kc.Close()
  48         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  49         c.Assert(err, IsNil)
  50         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  51
  52         cr.CrunchLog.Print("Hello world!")
  53         cr.CrunchLog.Print("Goodbye")
  54         cr.CrunchLog.Close()
  55
  56         c.Check(api.Calls, Equals, 1)
  57
  58         mt, err := cr.LogCollection.MarshalManifest(".")
  59         c.Check(err, IsNil)
  60         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
  61
  62         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
  63                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
  64
  65         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
  66         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext)
  67         c.Check(string(kc.Content), Equals, logtext)
  68 }
  69
  70 func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) {
  71         if testing.Short() {
  72                 return
  73         }
  74         api := &ArvTestClient{}
  75         kc := &KeepTestClient{}
  76         defer kc.Close()
  77         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  78         c.Assert(err, IsNil)
  79         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  80         cr.CrunchLog.Immediate = nil
  81
  82         for i := 0; i < 2000000; i++ {
  83                 cr.CrunchLog.Printf("Hello %d", i)
  84         }
  85         cr.CrunchLog.Print("Goodbye")
  86         cr.CrunchLog.Close()
  87
  88         c.Check(api.Calls > 0, Equals, true)
  89         c.Check(api.Calls < 2000000, Equals, true)
  90
  91         mt, err := cr.LogCollection.MarshalManifest(".")
  92         c.Check(err, IsNil)
  93         c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n")
  94 }
  95
  96 func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) {
  97         api := &ArvTestClient{}
  98         kc := &KeepTestClient{}
  99         defer kc.Close()
 100         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
 101         c.Assert(err, IsNil)
 102         ts := &TestTimestamper{}
 103         cr.CrunchLog.Timestamper = ts.Timestamp
 104         w, err := cr.NewLogWriter("stdout")
 105         c.Assert(err, IsNil)
 106         stdout := NewThrottledLogger(w)
 107         stdout.Timestamper = ts.Timestamp
 108
 109         cr.CrunchLog.Print("Hello world!")
 110         stdout.Print("Doing stuff")
 111         cr.CrunchLog.Print("Goodbye")
 112         stdout.Print("Blurb")
 113         cr.CrunchLog.Close()
 114         stdout.Close()
 115
 116         logText := make(map[string]string)
 117         for _, content := range api.Content {
 118                 log := content["log"].(arvadosclient.Dict)
 119                 logText[log["event_type"].(string)] += log["properties"].(map[string]string)["text"]
 120         }
 121
 122         c.Check(logText["crunch-run"], Equals, `2015-12-29T15:51:45.000000001Z Hello world!
 123 2015-12-29T15:51:45.000000003Z Goodbye
 124 `)
 125         c.Check(logText["stdout"], Equals, `2015-12-29T15:51:45.000000002Z Doing stuff
 126 2015-12-29T15:51:45.000000004Z Blurb
 127 `)
 128
 129         mt, err := cr.LogCollection.MarshalManifest(".")
 130         c.Check(err, IsNil)
 131         c.Check(mt, Equals, ". 48f9023dc683a850b1c9b482b14c4b97+163 0:83:crunch-run.txt 83:80:stdout.txt\n")
 132 }
 133
 134 func (s *LoggingTestSuite) TestLogUpdate(c *C) {
 135         for _, trial := range []struct {
 136                 maxBytes    int64
 137                 maxDuration time.Duration
 138         }{
 139                 {1000, 10 * time.Second},
 140                 {1000000, time.Millisecond},
 141         } {
 142                 c.Logf("max %d bytes, %s", trial.maxBytes, trial.maxDuration)
 143                 crunchLogUpdateSize = trial.maxBytes
 144                 crunchLogUpdatePeriod = trial.maxDuration
 145
 146                 api := &ArvTestClient{}
 147                 kc := &KeepTestClient{}
 148                 defer kc.Close()
 149                 cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
 150                 c.Assert(err, IsNil)
 151                 ts := &TestTimestamper{}
 152                 cr.CrunchLog.Timestamper = ts.Timestamp
 153                 w, err := cr.NewLogWriter("stdout")
 154                 c.Assert(err, IsNil)
 155                 stdout := NewThrottledLogger(w)
 156                 stdout.Timestamper = ts.Timestamp
 157
 158                 c.Check(cr.logUUID, Equals, "")
 159                 cr.CrunchLog.Printf("Hello %1000s", "space")
 160                 for i, t := 0, time.NewTicker(time.Millisecond); i < 5000 && cr.logUUID == ""; i++ {
 161                         <-t.C
 162                 }
 163                 c.Check(cr.logUUID, Not(Equals), "")
 164                 cr.CrunchLog.Print("Goodbye")
 165                 fmt.Fprint(stdout, "Goodbye\n")
 166                 cr.CrunchLog.Close()
 167                 stdout.Close()
 168                 w.Close()
 169
 170                 mt, err := cr.LogCollection.MarshalManifest(".")
 171                 c.Check(err, IsNil)
 172                 // Block packing depends on whether there's an update
 173                 // between the two Goodbyes -- either way the first
 174                 // block will be 4dc76.
 175                 c.Check(mt, Matches, `. 4dc76e0a212bfa30c39d76d8c16da0c0\+1038 (afc503bc1b9a828b4bb543cb629e936c\+78|90699dc22545cd74a0664303f70bc05a\+39 276b49339fd5203d15a93ff3de11bfb9\+39) 0:1077:crunch-run.txt 1077:39:stdout.txt\n`)
 176         }
 177 }
 178
 179 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) {
 180         s.testWriteLogsWithRateLimit(c, "crunchLogThrottleBytes", 50, 65536, "Exceeded rate 50 bytes per 60 seconds")
 181 }
 182
 183 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) {
 184         s.testWriteLogsWithRateLimit(c, "crunchLogThrottleLines", 1, 1024, "Exceeded rate 1 lines per 60 seconds")
 185 }
 186
 187 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytesPerEvent(c *C) {
 188         s.testWriteLogsWithRateLimit(c, "crunchLimitLogBytesPerJob", 50, 67108864, "Exceeded log limit 50 bytes (crunch_limit_log_bytes_per_job)")
 189 }
 190
 191 func (s *LoggingTestSuite) testWriteLogsWithRateLimit(c *C, throttleParam string, throttleValue int, throttleDefault int, expected string) {
 192         discoveryMap[throttleParam] = float64(throttleValue)
 193         defer func() {
 194                 discoveryMap[throttleParam] = float64(throttleDefault)
 195         }()
 196
 197         api := &ArvTestClient{}
 198         kc := &KeepTestClient{}
 199         defer kc.Close()
 200         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
 201         c.Assert(err, IsNil)
 202         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
 203
 204         cr.CrunchLog.Print("Hello world!")
 205         cr.CrunchLog.Print("Goodbye")
 206         cr.CrunchLog.Close()
 207
 208         c.Check(api.Calls, Equals, 1)
 209
 210         mt, err := cr.LogCollection.MarshalManifest(".")
 211         c.Check(err, IsNil)
 212         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
 213
 214         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
 215                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
 216
 217         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
 218         stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]
 219         c.Check(true, Equals, strings.Contains(stderrLog, expected))
 220         c.Check(string(kc.Content), Equals, logtext)
 221 }