lib/crunchrun/logging_test.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.0
   4
   5 package crunchrun
   6
   7 import (
   8         "bytes"
   9         "fmt"
  10         "io"
  11         "strings"
  12         "testing"
  13         "time"
  14
  15         "git.arvados.org/arvados.git/sdk/go/arvados"
  16         . "gopkg.in/check.v1"
  17         check "gopkg.in/check.v1"
  18 )
  19
  20 // newTestTimestamper wraps an io.Writer, inserting a predictable
  21 // RFC3339NanoFixed timestamp at the beginning of each line.
  22 func newTestTimestamper(w io.Writer) *prefixer {
  23         count := 0
  24         return &prefixer{
  25                 writer: w,
  26                 prefixFunc: func() string {
  27                         count++
  28                         return fmt.Sprintf("2015-12-29T15:51:45.%09dZ ", count)
  29                 },
  30         }
  31 }
  32
  33 type LoggingTestSuite struct {
  34         client *arvados.Client
  35 }
  36
  37 // Gocheck boilerplate
  38 var _ = Suite(&LoggingTestSuite{})
  39
  40 func (s *LoggingTestSuite) SetUpTest(c *C) {
  41         s.client = arvados.NewClientFromEnv()
  42         crunchLogUpdatePeriod = time.Hour * 24 * 365
  43         crunchLogUpdateSize = 1 << 50
  44 }
  45
  46 func (s *LoggingTestSuite) TestWriteLogs(c *C) {
  47         api := &ArvTestClient{}
  48         kc := &KeepTestClient{}
  49         defer kc.Close()
  50         cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-dz642-zzzzzzzzzzzzzzz")
  51         c.Assert(err, IsNil)
  52         f, err := cr.openLogFile("crunch-run")
  53         c.Assert(err, IsNil)
  54         cr.CrunchLog = newLogWriter(newTestTimestamper(f))
  55
  56         cr.CrunchLog.Print("Hello world!")
  57         cr.CrunchLog.Print("Goodbye")
  58
  59         c.Check(api.Calls, Equals, 0)
  60
  61         logs := logFileContent(c, cr, "crunch-run.txt")
  62         c.Check(logs, Matches, `....-..-..T..:..:..\..........Z Hello world!\n`+
  63                 `....-..-..T..:..:..\..........Z Goodbye\n`)
  64 }
  65
  66 func (s *LoggingTestSuite) TestWriteLogsLarge(c *C) {
  67         if testing.Short() {
  68                 return
  69         }
  70         api := &ArvTestClient{}
  71         kc := &KeepTestClient{}
  72         defer kc.Close()
  73         cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-zzzzzzzzzzzzzzz")
  74         c.Assert(err, IsNil)
  75         f, err := cr.openLogFile("crunch-run")
  76         c.Assert(err, IsNil)
  77         cr.CrunchLog = newLogWriter(newTestTimestamper(f))
  78         for i := 0; i < 2000000; i++ {
  79                 cr.CrunchLog.Printf("Hello %d", i)
  80         }
  81         cr.CrunchLog.Print("Goodbye")
  82
  83         logs := logFileContent(c, cr, "crunch-run.txt")
  84         c.Check(strings.Count(logs, "\n"), Equals, 2000001)
  85         // Redact most of the logs except the start/end for the regexp
  86         // match -- otherwise, when the regexp fails, gocheck spams
  87         // the test logs with tens of megabytes of quoted strings.
  88         c.Assert(len(logs) > 10000, Equals, true)
  89         c.Check(logs[:500]+"\n...\n"+logs[len(logs)-500:], Matches, `(?ms)2015-12-29T15:51:45.000000001Z Hello 0
  90 2015-12-29T15:51:45.000000002Z Hello 1
  91 2015-12-29T15:51:45.000000003Z Hello 2
  92 2015-12-29T15:51:45.000000004Z Hello 3
  93 .*
  94 2015-12-29T15:51:45.001999998Z Hello 1999997
  95 2015-12-29T15:51:45.001999999Z Hello 1999998
  96 2015-12-29T15:51:45.002000000Z Hello 1999999
  97 2015-12-29T15:51:45.002000001Z Goodbye
  98 `)
  99
 100         mt, err := cr.LogCollection.MarshalManifest(".")
 101         c.Check(err, IsNil)
 102         c.Check(mt, Equals, ". 9c2c05d1fae6aaa8af85113ba725716d+67108864 80b821383a07266c2a66a4566835e26e+21780065 0:88888929:crunch-run.txt\n")
 103 }
 104
 105 func (s *LoggingTestSuite) TestLogUpdate(c *C) {
 106         for _, trial := range []struct {
 107                 maxBytes    int64
 108                 maxDuration time.Duration
 109         }{
 110                 {1000, 10 * time.Second},
 111                 {1000000, time.Millisecond},
 112         } {
 113                 c.Logf("max %d bytes, %s", trial.maxBytes, trial.maxDuration)
 114                 crunchLogUpdateSize = trial.maxBytes
 115                 crunchLogUpdatePeriod = trial.maxDuration
 116
 117                 api := &ArvTestClient{}
 118                 kc := &KeepTestClient{}
 119                 defer kc.Close()
 120                 cr, err := NewContainerRunner(s.client, api, kc, "zzzzz-dz642-zzzzzzzzzzzzzzz")
 121                 c.Assert(err, IsNil)
 122                 f, err := cr.openLogFile("crunch-run")
 123                 c.Assert(err, IsNil)
 124                 cr.CrunchLog = newLogWriter(newTestTimestamper(f))
 125                 stdout, err := cr.openLogFile("stdout")
 126                 c.Assert(err, IsNil)
 127
 128                 c.Check(cr.logUUID, Equals, "")
 129                 cr.CrunchLog.Printf("Hello %1000s", "space")
 130                 for i, t := 0, time.NewTicker(time.Millisecond); i < 5000 && cr.logUUID == ""; i++ {
 131                         <-t.C
 132                 }
 133                 c.Check(cr.logUUID, Not(Equals), "")
 134                 cr.CrunchLog.Print("Goodbye")
 135                 fmt.Fprintln(stdout, "Goodbye")
 136
 137                 c.Check(logFileContent(c, cr, "crunch-run.txt"), Matches, `....-..-..T..:..:............Z Hello  {995}space\n`+
 138                         `....-..-..T..:..:............Z Goodbye\n`)
 139                 c.Check(logFileContent(c, cr, "stdout.txt"), Matches, `Goodbye\n`)
 140
 141                 mt, err := cr.LogCollection.MarshalManifest(".")
 142                 c.Check(err, IsNil)
 143                 c.Check(mt, Matches, `. 4dc76e0a212bfa30c39d76d8c16da0c0\+1038 5be52044a8c51e7b62dd62be07872968\+47 0:1077:crunch-run.txt 1077:8:stdout.txt\n`)
 144         }
 145 }
 146
 147 type filterSuite struct{}
 148
 149 var _ = Suite(&filterSuite{})
 150
 151 func (*filterSuite) TestFilterKeepstoreErrorsOnly(c *check.C) {
 152         var buf bytes.Buffer
 153         f := filterKeepstoreErrorsOnly{WriteCloser: nopCloser{&buf}}
 154         for _, s := range []string{
 155                 "not j",
 156                 "son\n" + `{"msg":"foo"}` + "\n{}\n" + `{"msg":"request"}` + "\n" + `{"msg":1234}` + "\n\n",
 157                 "\n[\n",
 158                 `{"msg":"response","respStatusCode":404,"foo": "bar"}` + "\n",
 159                 `{"msg":"response","respStatusCode":206}` + "\n",
 160         } {
 161                 f.Write([]byte(s))
 162         }
 163         c.Check(buf.String(), check.Equals, `not json
 164 {"msg":"foo"}
 165 {}
 166 {"msg":1234}
 167 [
 168 {"msg":"response","respStatusCode":404,"foo": "bar"}
 169 `)
 170 }
 171
 172 type nopCloser struct {
 173         io.Writer
 174 }
 175
 176 func (nopCloser) Close() error { return nil }