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 }
  41
  42 func (s *LoggingTestSuite) TestWriteLogs(c *C) {
  43         api := &ArvTestClient{}
  44         kc := &KeepTestClient{}
  45         defer kc.Close()
  46         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  47         c.Assert(err, IsNil)
  48         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  49
  50         cr.CrunchLog.Print("Hello world!")
  51         cr.CrunchLog.Print("Goodbye")
  52         cr.CrunchLog.Close()
  53
  54         c.Check(api.Calls, Equals, 1)
  55
  56         mt, err := cr.LogCollection.MarshalManifest(".")
  57         c.Check(err, IsNil)
  58         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
  59
  60         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
  61                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
  62
  63         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
  64         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext)
  65         c.Check(string(kc.Content), Equals, logtext)
  66 }
  67
  68 func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) {
  69         if testing.Short() {
  70                 return
  71         }
  72         api := &ArvTestClient{}
  73         kc := &KeepTestClient{}
  74         defer kc.Close()
  75         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  76         c.Assert(err, IsNil)
  77         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
  78         cr.CrunchLog.Immediate = nil
  79
  80         for i := 0; i < 2000000; i++ {
  81                 cr.CrunchLog.Printf("Hello %d", i)
  82         }
  83         cr.CrunchLog.Print("Goodbye")
  84         cr.CrunchLog.Close()
  85
  86         c.Check(api.Calls > 1, Equals, true)
  87         c.Check(api.Calls < 2000000, Equals, true)
  88
  89         mt, err := cr.LogCollection.MarshalManifest(".")
  90         c.Check(err, IsNil)
  91         c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n")
  92 }
  93
  94 func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) {
  95         api := &ArvTestClient{}
  96         kc := &KeepTestClient{}
  97         defer kc.Close()
  98         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
  99         c.Assert(err, IsNil)
 100         ts := &TestTimestamper{}
 101         cr.CrunchLog.Timestamper = ts.Timestamp
 102         w, err := cr.NewLogWriter("stdout")
 103         c.Assert(err, IsNil)
 104         stdout := NewThrottledLogger(w)
 105         stdout.Timestamper = ts.Timestamp
 106
 107         cr.CrunchLog.Print("Hello world!")
 108         stdout.Print("Doing stuff")
 109         cr.CrunchLog.Print("Goodbye")
 110         stdout.Print("Blurb")
 111         cr.CrunchLog.Close()
 112         stdout.Close()
 113
 114         logText := make(map[string]string)
 115         for _, content := range api.Content {
 116                 log := content["log"].(arvadosclient.Dict)
 117                 logText[log["event_type"].(string)] += log["properties"].(map[string]string)["text"]
 118         }
 119
 120         c.Check(logText["crunch-run"], Equals, `2015-12-29T15:51:45.000000001Z Hello world!
 121 2015-12-29T15:51:45.000000003Z Goodbye
 122 `)
 123         c.Check(logText["stdout"], Equals, `2015-12-29T15:51:45.000000002Z Doing stuff
 124 2015-12-29T15:51:45.000000004Z Blurb
 125 `)
 126
 127         mt, err := cr.LogCollection.MarshalManifest(".")
 128         c.Check(err, IsNil)
 129         c.Check(mt, Equals, ". 48f9023dc683a850b1c9b482b14c4b97+163 0:83:crunch-run.txt 83:80:stdout.txt\n")
 130 }
 131
 132 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) {
 133         s.testWriteLogsWithRateLimit(c, "crunchLogThrottleBytes", 50, 65536, "Exceeded rate 50 bytes per 60 seconds")
 134 }
 135
 136 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) {
 137         s.testWriteLogsWithRateLimit(c, "crunchLogThrottleLines", 1, 1024, "Exceeded rate 1 lines per 60 seconds")
 138 }
 139
 140 func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytesPerEvent(c *C) {
 141         s.testWriteLogsWithRateLimit(c, "crunchLimitLogBytesPerJob", 50, 67108864, "Exceeded log limit 50 bytes (crunch_limit_log_bytes_per_job)")
 142 }
 143
 144 func (s *LoggingTestSuite) testWriteLogsWithRateLimit(c *C, throttleParam string, throttleValue int, throttleDefault int, expected string) {
 145         discoveryMap[throttleParam] = float64(throttleValue)
 146         defer func() {
 147                 discoveryMap[throttleParam] = float64(throttleDefault)
 148         }()
 149
 150         api := &ArvTestClient{}
 151         kc := &KeepTestClient{}
 152         defer kc.Close()
 153         cr, err := NewContainerRunner(s.client, api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
 154         c.Assert(err, IsNil)
 155         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
 156
 157         cr.CrunchLog.Print("Hello world!")
 158         cr.CrunchLog.Print("Goodbye")
 159         cr.CrunchLog.Close()
 160
 161         c.Check(api.Calls, Equals, 1)
 162
 163         mt, err := cr.LogCollection.MarshalManifest(".")
 164         c.Check(err, IsNil)
 165         c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
 166
 167         logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
 168                 "2015-12-29T15:51:45.000000002Z Goodbye\n"
 169
 170         c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
 171         stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]
 172         c.Check(true, Equals, strings.Contains(stderrLog, expected))
 173         c.Check(string(kc.Content), Equals, logtext)
 174 }