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/arvadosclient"
  14         . "gopkg.in/check.v1"
  15 )
  16
  17 type LoggingTestSuite struct{}
  18
  19 type TestTimestamper struct {
  20         count int
  21 }
  22
  23 func (this *TestTimestamper) Timestamp(t time.Time) string {
  24         this.count += 1
  25         t, err := time.ParseInLocation(time.RFC3339Nano, fmt.Sprintf("2015-12-29T15:51:45.%09dZ", this.count), t.Location())
  26         if err != nil {
  27                 panic(err)
  28         }
  29         return RFC3339Timestamp(t)
  30 }
  31
  32 // Gocheck boilerplate
  33 var _ = Suite(&LoggingTestSuite{})
  34
  35 func (s *LoggingTestSuite) TestWriteLogs(c *C) {
  36         api := &ArvTestClient{}
  37         kc := &KeepTestClient{}
  38         defer kc.Close()
  39         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  40         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  41
  42         cr.CrunchLog.Print("Hello world!")
  43         cr.CrunchLog.Print("Goodbye")
  44         cr.CrunchLog.Close()
  45
  46         c.Check(api.Calls, Equals, 1)
  47
  48         mt, err := cr.LogCollection.ManifestText()
  49         c.Check(err, IsNil)
  50         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
  51
  52         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
  53                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
  54
  55         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
  56         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext)
  57         c.Check(string(kc.Content), Equals, logtext)
  58 }
  59
  60 func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) {
  61         if testing.Short() {
  62                 return
  63         }
  64         api := &ArvTestClient{}
  65         kc := &KeepTestClient{}
  66         defer kc.Close()
  67         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  68         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  69         cr.CrunchLog.Immediate = nil
  70
  71         for i := 0; i < 2000000; i++ {
  72                 cr.CrunchLog.Printf("Hello %d", i)
  73         }
  74         cr.CrunchLog.Print("Goodbye")
  75         cr.CrunchLog.Close()
  76
  77         c.Check(api.Calls > 1, Equals, true)
  78         c.Check(api.Calls < 2000000, Equals, true)
  79
  80         mt, err := cr.LogCollection.ManifestText()
  81         c.Check(err, IsNil)
  82         c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n")
  83 }
  84
  85 func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) {
  86         api := &ArvTestClient{}
  87         kc := &KeepTestClient{}
  88         defer kc.Close()
  89         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  90         ts := &TestTimestamper{}
  91         cr.CrunchLog.Timestamper = ts.Timestamp
  92         stdout := NewThrottledLogger(cr.NewLogWriter("stdout"))
  93         stdout.Timestamper = ts.Timestamp
  94
  95         cr.CrunchLog.Print("Hello world!")
  96         stdout.Print("Doing stuff")
  97         cr.CrunchLog.Print("Goodbye")
  98         stdout.Print("Blurb")
  99         cr.CrunchLog.Close()
 100         stdout.Close()
 101
 102         logText := make(map[string]string)
 103         for _, content := range api.Content {
 104                 log := content["log"].(arvadosclient.Dict)
 105                 logText[log["event_type"].(string)] += log["properties"].(map[string]string)["text"]
 106         }
 107
 108         c.Check(logText["crunch-run"], Equals, `2015-12-29T15:51:45.000000001Z Hello world!
 109 2015-12-29T15:51:45.000000003Z Goodbye
 110 `)
 111         c.Check(logText["stdout"], Equals, `2015-12-29T15:51:45.000000002Z Doing stuff
 112 2015-12-29T15:51:45.000000004Z Blurb
 113 `)
 114
 115         mt, err := cr.LogCollection.ManifestText()
 116         c.Check(err, IsNil)
 117         c.Check(mt, Equals, ""+
 118                 ". 408672f5b5325f7d20edfbf899faee42+83 0:83:crunch-run.txt\n"+
 119                 ". c556a293010069fa79a6790a931531d5+80 0:80:stdout.txt\n")
 120 }
 121
 122 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) {
 123         testWriteLogsWithRateLimit(c, "crunchLogThrottleBytes", 50, 65536, "Exceeded rate 50 bytes per 60 seconds")
 124 }
 125
 126 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) {
 127         testWriteLogsWithRateLimit(c, "crunchLogThrottleLines", 1, 1024, "Exceeded rate 1 lines per 60 seconds")
 128 }
 129
 130 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytesPerEvent(c *C) {
 131         testWriteLogsWithRateLimit(c, "crunchLimitLogBytesPerJob", 50, 67108864, "Exceeded log limit 50 bytes (crunch_limit_log_bytes_per_job)")
 132 }
 133
 134 func testWriteLogsWithRateLimit(c *C, throttleParam string, throttleValue int, throttleDefault int, expected string) {
 135         discoveryMap[throttleParam] = float64(throttleValue)
 136         defer func() {
 137                 discoveryMap[throttleParam] = float64(throttleDefault)
 138         }()
 139
 140         api := &ArvTestClient{}
 141         kc := &KeepTestClient{}
 142         defer kc.Close()
 143         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
 144         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
 145
 146         cr.CrunchLog.Print("Hello world!")
 147         cr.CrunchLog.Print("Goodbye")
 148         cr.CrunchLog.Close()
 149
 150         c.Check(api.Calls, Equals, 1)
 151
 152         mt, err := cr.LogCollection.ManifestText()
 153         c.Check(err, IsNil)
 154         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
 155
 156         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
 157                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
 158
 159         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
 160         stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]
 161         c.Check(true, Equals, strings.Contains(stderrLog, expected))
 162         c.Check(string(kc.Content), Equals, logtext)
 163 }