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