8019: add tests and address issues identified

diff --git a/services/crunch-run/logging.go b/services/crunch-run/logging.go
index a66525e7bf8274cbd4023e008a54f8bc29b54286..00cc06a04c8149d0356c40ced7c1a8f4e299c650 100644 (file)
--- a/services/crunch-run/logging.go
+++ b/services/crunch-run/logging.go
@@ -214,10 +214,10 @@ func (arvlog *ArvLogWriter) Write(p []byte) (n int, err error) {
                // It has been more than throttle_period seconds since the last
                // checkpoint; so reset the throttle
                if arvlog.logThrottleBytesSkipped > 0 {
-                       arvlog.stderrBufToFlush.WriteString(fmt.Sprintf("%s Skipped %d bytes of log\n", RFC3339Timestamp(time.Now()), arvlog.logThrottleBytesSkipped))
+                       arvlog.stderrBufToFlush.WriteString(fmt.Sprintf("%s Skipped %d bytes of log\n", RFC3339Timestamp(time.Now().UTC()), arvlog.logThrottleBytesSkipped))
                }
 
-               arvlog.logThrottleResetTime = time.Now().Add(time.Duration(int(crunchLogThrottlePeriod.(float64))))
+               arvlog.logThrottleResetTime = time.Now().Add(time.Second * time.Duration(int(crunchLogThrottlePeriod.(float64))))
                arvlog.logThrottleBytesSoFar = 0
                arvlog.logThrottleLinesSoFar = 0
                arvlog.logThrottleBytesSkipped = 0
@@ -314,20 +314,24 @@ func (arvlog *ArvLogWriter) rateLimit(line []byte) (bool, []byte, error) {
                }
 
                if arvlog.bytesLogged > int64(crunchLimitLogBytesPerJob.(float64)) {
-                       message = fmt.Sprintf("%s Exceeded log limit %d bytes (crunch_limit_log_bytes_per_job). Log will be truncated.", RFC3339Timestamp(time.Now()), int(crunchLimitLogBytesPerJob.(float64)))
+                       message = fmt.Sprintf("%s Exceeded log limit %d bytes (crunch_limit_log_bytes_per_job). Log will be truncated.", RFC3339Timestamp(time.Now().UTC()), int(crunchLimitLogBytesPerJob.(float64)))
                        arvlog.logThrottleResetTime = time.Now().Add(time.Duration(365 * 24 * time.Hour))
                        arvlog.logThrottleIsOpen = false
+
                } else if arvlog.logThrottleBytesSoFar > int64(crunchLogThrottleBytes.(float64)) {
                        remainingTime := arvlog.logThrottleResetTime.Sub(time.Now())
-                       message = fmt.Sprintf("%s Exceeded rate %d bytes per %d seconds (crunch_log_throttle_bytes). Logging will be silenced for the next %d seconds.", RFC3339Timestamp(time.Now()), crunchLogThrottleBytes, int(crunchLogThrottlePeriod.(float64)), remainingTime)
+                       message = fmt.Sprintf("%s Exceeded rate %d bytes per %d seconds (crunch_log_throttle_bytes). Logging will be silenced for the next %d seconds.", RFC3339Timestamp(time.Now().UTC()), int(crunchLogThrottleBytes.(float64)), int(crunchLogThrottlePeriod.(float64)), remainingTime/time.Second)
                        arvlog.logThrottleIsOpen = false
+
                } else if arvlog.logThrottleLinesSoFar > int64(crunchLogThrottleLines.(float64)) {
                        remainingTime := arvlog.logThrottleResetTime.Sub(time.Now())
-                       message = fmt.Sprintf("%s Exceeded rate %d lines per %d seconds (crunch_log_throttle_lines), logging will be silenced for the next %d seconds.", RFC3339Timestamp(time.Now()), crunchLogThrottleLines, int(crunchLogThrottlePeriod.(float64)), remainingTime)
+                       message = fmt.Sprintf("%s Exceeded rate %d lines per %d seconds (crunch_log_throttle_lines), logging will be silenced for the next %d seconds.", RFC3339Timestamp(time.Now().UTC()), int(crunchLogThrottleLines.(float64)), int(crunchLogThrottlePeriod.(float64)), remainingTime/time.Second)
                        arvlog.logThrottleIsOpen = false
+
                } else if partialLine && arvlog.logThrottleFirstPartialLine {
                        arvlog.logThrottleFirstPartialLine = false
-                       message = fmt.Sprintf("%s Rate-limiting partial segments of long lines to one every %d seconds.", RFC3339Timestamp(time.Now()), crunchLogPartialLineThrottlePeriod)
+                       message = fmt.Sprintf("%s Rate-limiting partial segments of long lines to one every %d seconds.", RFC3339Timestamp(time.Now().UTC()), int(crunchLogPartialLineThrottlePeriod.(float64)))
+
                }
        }
 
@@ -339,7 +343,7 @@ func (arvlog *ArvLogWriter) rateLimit(line []byte) (bool, []byte, error) {
        if message != "" {
                // Yes, write to logs, but use our "rate exceeded" message
                // instead of the log message that exceeded the limit.
-               message += " A complete log is still being written to Keep, and will be available when the job finishes.\n"
+               message += " A complete log is still being written to Keep, and will be available when the job finishes."
                return true, []byte(message), nil
        } else if partialLine {
                return false, line, nil

diff --git a/services/crunch-run/logging_test.go b/services/crunch-run/logging_test.go
index 91af16dc4970386b4c8f8301387b0b32943e5df7..2ea9a3136774b058846ff63f0fbdee653237e21c 100644 (file)
--- a/services/crunch-run/logging_test.go
+++ b/services/crunch-run/logging_test.go
@@ -4,6 +4,7 @@ import (
        "fmt"
        "git.curoverse.com/arvados.git/sdk/go/arvadosclient"
        . "gopkg.in/check.v1"
+       "strings"
        "testing"
        "time"
 )
@@ -110,7 +111,12 @@ func (s *LoggingTestSuite) TestWriteMultipleLogs(c *C) {
                ". c556a293010069fa79a6790a931531d5+80 0:80:stdout.txt\n")
 }
 
-func (s *LoggingTestSuite) TestWriteLogsWithRateLimit(c *C) {
+func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleBytes(c *C) {
+       discoveryMap["crunchLogThrottleBytes"] = float64(50)
+       defer func() {
+               discoveryMap["crunchLogThrottleBytes"] = float64(65536)
+       }()
+
        api := &ArvTestClient{}
        kc := &KeepTestClient{}
        cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
@@ -130,6 +136,37 @@ func (s *LoggingTestSuite) TestWriteLogsWithRateLimit(c *C) {
                "2015-12-29T15:51:45.000000002Z Goodbye\n"
 
        c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
-       c.Check(api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"], Equals, logtext)
+       stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]
+       c.Check(true, Equals, strings.Contains(stderrLog, "Exceeded rate 50 bytes per 60 seconds"))
+       c.Check(string(kc.Content), Equals, logtext)
+}
+
+func (s *LoggingTestSuite) TestWriteLogsWithRateLimitThrottleLines(c *C) {
+       discoveryMap["crunchLogThrottleLines"] = float64(1)
+       defer func() {
+               discoveryMap["crunchLogThrottleLines"] = float64(1024)
+       }()
+
+       api := &ArvTestClient{}
+       kc := &KeepTestClient{}
+       cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzzzzzzzzzzzz")
+       cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
+
+       cr.CrunchLog.Print("Hello world!")
+       cr.CrunchLog.Print("Goodbye")
+       cr.CrunchLog.Close()
+
+       c.Check(api.Calls, Equals, 1)
+
+       mt, err := cr.LogCollection.ManifestText()
+       c.Check(err, IsNil)
+       c.Check(mt, Equals, ". 74561df9ae65ee9f35d5661d42454264+83 0:83:crunch-run.txt\n")
+
+       logtext := "2015-12-29T15:51:45.000000001Z Hello world!\n" +
+               "2015-12-29T15:51:45.000000002Z Goodbye\n"
+
+       c.Check(api.Content[0]["log"].(arvadosclient.Dict)["event_type"], Equals, "crunch-run")
+       stderrLog := api.Content[0]["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]
+       c.Check(true, Equals, strings.Contains(stderrLog, "Exceeded rate 1 lines per 60 seconds"))
        c.Check(string(kc.Content), Equals, logtext)
 }