services/crunch-run/logging_test.go

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