Add windows tests for query logger (#6653)

* Add windows tests
* Do not rely on time.Time in timer

Signed-off-by: Julien Pivotto <roidelapluie@inuits.eu>

.circleci/config.yml

@@ -56,8 +56,14 @@ jobs:
     working_directory: /go/src/github.com/prometheus/prometheus
     steps:
     - checkout
-    # TSDB is where the most risk is Windows wise, so only test there for now.
+    - run:
-    - run: go test ./tsdb/...
+        shell: bash
+        command: |
+          (cd web/ui && GOOS= GOARCH= go generate -mod=vendor)
+          go test -mod=vendor -test.v `go list ./...|grep -Exv "(github.com/prometheus/prometheus/discovery.*|github.com/prometheus/prometheus/config|github.com/prometheus/prometheus/web)"`
+        environment:
+          GOGC: "20"
+          GOOPTS: "-p 2 -mod=vendor"
   fuzzit_regression:
     executor: fuzzit
     working_directory: /go/src/github.com/prometheus/prometheus

cmd/prometheus/main_test.go

@@ -16,7 +16,7 @@ package main
 import (
 	"context"
 	"fmt"
-	"net/http"
+	"io/ioutil"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -51,54 +51,6 @@ func TestMain(m *testing.M) {
 	os.Exit(exitCode)
 }
 
-// As soon as prometheus starts responding to http request should be able to accept Interrupt signals for a graceful shutdown.
-func TestStartupInterrupt(t *testing.T) {
-	if testing.Short() {
-		t.Skip("skipping test in short mode.")
-	}
-
-	prom := exec.Command(promPath, "-test.main", "--config.file="+promConfig, "--storage.tsdb.path="+promData)
-	err := prom.Start()
-	if err != nil {
-		t.Errorf("execution error: %v", err)
-		return
-	}
-
-	done := make(chan error)
-	go func() {
-		done <- prom.Wait()
-	}()
-
-	var startedOk bool
-	var stoppedErr error
-
-Loop:
-	for x := 0; x < 10; x++ {
-		// error=nil means prometheus has started so can send the interrupt signal and wait for the grace shutdown.
-		if _, err := http.Get("http://localhost:9090/graph"); err == nil {
-			startedOk = true
-			prom.Process.Signal(os.Interrupt)
-			select {
-			case stoppedErr = <-done:
-				break Loop
-			case <-time.After(10 * time.Second):
-			}
-			break Loop
-		}
-		time.Sleep(500 * time.Millisecond)
-	}
-
-	if !startedOk {
-		t.Errorf("prometheus didn't start in the specified timeout")
-		return
-	}
-	if err := prom.Process.Kill(); err == nil {
-		t.Errorf("prometheus didn't shutdown gracefully after sending the Interrupt signal")
-	} else if stoppedErr != nil && stoppedErr.Error() != "signal: interrupt" { // TODO - find a better way to detect when the process didn't exit as expected!
-		t.Errorf("prometheus exited with an unexpected error:%v", stoppedErr)
-	}
-}
-
 func TestComputeExternalURL(t *testing.T) {
 	tests := []struct {
 		input string
@@ -246,7 +198,16 @@ func TestWALSegmentSizeBounds(t *testing.T) {
 
 	for size, expectedExitStatus := range map[string]int{"9MB": 1, "257MB": 1, "10": 2, "1GB": 1, "12MB": 0} {
 		prom := exec.Command(promPath, "-test.main", "--storage.tsdb.wal-segment-size="+size, "--config.file="+promConfig)
-		err := prom.Start()
+
+		// Log stderr in case of failure.
+		stderr, err := prom.StderrPipe()
+		testutil.Ok(t, err)
+		go func() {
+			slurp, _ := ioutil.ReadAll(stderr)
+			t.Log(string(slurp))
+		}()
+
+		err = prom.Start()
 		testutil.Ok(t, err)
 
 		if expectedExitStatus == 0 {
@@ -256,7 +217,7 @@ func TestWALSegmentSizeBounds(t *testing.T) {
 			case err := <-done:
 				t.Errorf("prometheus should be still running: %v", err)
 			case <-time.After(5 * time.Second):
-				prom.Process.Signal(os.Interrupt)
+				prom.Process.Kill()
 			}
 			continue
 		}

cmd/prometheus/main_unix_test.go

@@ -0,0 +1,74 @@
+// Copyright 2020 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+//
+// +build !windows
+
+package main
+
+import (
+	"net/http"
+	"os"
+	"os/exec"
+	"testing"
+	"time"
+)
+
+// As soon as prometheus starts responding to http request it should be able to
+// accept Interrupt signals for a graceful shutdown.
+func TestStartupInterrupt(t *testing.T) {
+	if testing.Short() {
+		t.Skip("skipping test in short mode.")
+	}
+
+	prom := exec.Command(promPath, "-test.main", "--config.file="+promConfig, "--storage.tsdb.path="+promData)
+	err := prom.Start()
+	if err != nil {
+		t.Errorf("execution error: %v", err)
+		return
+	}
+
+	done := make(chan error)
+	go func() {
+		done <- prom.Wait()
+	}()
+
+	var startedOk bool
+	var stoppedErr error
+
+Loop:
+	for x := 0; x < 10; x++ {
+		// error=nil means prometheus has started so we can send the interrupt
+		// signal and wait for the graceful shutdown.
+		if _, err := http.Get("http://localhost:9090/graph"); err == nil {
+			startedOk = true
+			prom.Process.Signal(os.Interrupt)
+			select {
+			case stoppedErr = <-done:
+				break Loop
+			case <-time.After(10 * time.Second):
+			}
+			break Loop
+		}
+		time.Sleep(500 * time.Millisecond)
+	}
+
+	if !startedOk {
+		t.Errorf("prometheus didn't start in the specified timeout")
+		return
+	}
+	if err := prom.Process.Kill(); err == nil {
+		t.Errorf("prometheus didn't shutdown gracefully after sending the Interrupt signal")
+	} else if stoppedErr != nil && stoppedErr.Error() != "signal: interrupt" { // TODO - find a better way to detect when the process didn't exit as expected!
+		t.Errorf("prometheus exited with an unexpected error:%v", stoppedErr)
+	}
+}

cmd/prometheus/query_log_test.go

@@ -24,6 +24,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"runtime"
 	"strconv"
 	"testing"
 	"time"
@@ -248,7 +249,7 @@ func (p *queryLogTest) run(t *testing.T) {
 	testutil.Ok(t, prom.Start())
 
 	defer func() {
-		prom.Process.Signal(os.Interrupt)
+		prom.Process.Kill()
 		prom.Wait()
 	}()
 	testutil.Ok(t, p.waitForPrometheus())
@@ -298,9 +299,15 @@ func (p *queryLogTest) run(t *testing.T) {
 	p.validateLastQuery(t, ql)
 	qc = len(ql)
 
+	// The last part of the test can not succeed on Windows because you can't
+	// rename files used by other processes.
+	if runtime.GOOS == "windows" {
+		return
+	}
 	// Move the file, Prometheus should still write to the old file.
 	newFile, err := ioutil.TempFile("", "newLoc")
 	testutil.Ok(t, err)
+	testutil.Ok(t, newFile.Close())
 	defer os.Remove(newFile.Name())
 	testutil.Ok(t, os.Rename(queryLogFile.Name(), newFile.Name()))
 	ql = readQueryLog(t, newFile.Name())

discovery/file/file_test.go

@@ -80,6 +80,7 @@ func (t *testRunner) copyFileTo(src string, name string) string {
 	_, err = io.Copy(newf, f)
 	testutil.Ok(t, err)
 	testutil.Ok(t, f.Close())
+	testutil.Ok(t, newf.Close())
 
 	dst := filepath.Join(t.dir, name)
 	err = os.Rename(newf.Name(), dst)

pkg/logging/file_test.go

@@ -14,10 +14,10 @@
 package logging
 
 import (
-	"errors"
 	"io/ioutil"
 	"os"
 	"regexp"
+	"strings"
 	"testing"
 
 	"github.com/prometheus/prometheus/util/testutil"
@@ -32,7 +32,8 @@ func TestJSONFileLogger_basic(t *testing.T) {
 	testutil.Ok(t, err)
 	testutil.Assert(t, l != nil, "logger can't be nil")
 
-	l.Log("test", "yes")
+	err = l.Log("test", "yes")
+	testutil.Ok(t, err)
 	r := make([]byte, 1024)
 	_, err = f.Read(r)
 	testutil.Ok(t, err)
@@ -44,5 +45,40 @@ func TestJSONFileLogger_basic(t *testing.T) {
 	testutil.Ok(t, err)
 
 	err = l.file.Close()
-	testutil.Assert(t, errors.Is(err, os.ErrClosed), "file was not closed")
+	testutil.NotOk(t, err)
+	testutil.Assert(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed")
+}
+
+func TestJSONFileLogger_parallel(t *testing.T) {
+	f, err := ioutil.TempFile("", "")
+	testutil.Ok(t, err)
+	defer f.Close()
+
+	l, err := NewJSONFileLogger(f.Name())
+	testutil.Ok(t, err)
+	testutil.Assert(t, l != nil, "logger can't be nil")
+
+	err = l.Log("test", "yes")
+	testutil.Ok(t, err)
+
+	l2, err := NewJSONFileLogger(f.Name())
+	testutil.Ok(t, err)
+	testutil.Assert(t, l != nil, "logger can't be nil")
+
+	err = l2.Log("test", "yes")
+	testutil.Ok(t, err)
+
+	err = l.Close()
+	testutil.Ok(t, err)
+
+	err = l.file.Close()
+	testutil.NotOk(t, err)
+	testutil.Assert(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed")
+
+	err = l2.Close()
+	testutil.Ok(t, err)
+
+	err = l2.file.Close()
+	testutil.NotOk(t, err)
+	testutil.Assert(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed")
 }

promql/engine_test.go

@@ -16,6 +16,7 @@ package promql
 import (
 	"context"
 	"errors"
+	"strings"
 	"testing"
 	"time"
 
@@ -106,7 +107,9 @@ func TestQueryTimeout(t *testing.T) {
 	testutil.NotOk(t, res.Err, "expected timeout error but got none")
 
 	var e ErrQueryTimeout
-	testutil.Assert(t, errors.As(res.Err, &e), "expected timeout error but got: %s", res.Err)
+	// TODO: when circleci-windows moves to go 1.13:
+	// testutil.Assert(t, errors.As(res.Err, &e), "expected timeout error but got: %s", res.Err)
+	testutil.Assert(t, strings.HasPrefix(res.Err.Error(), e.Error()), "expected timeout error but got: %s", res.Err)
 }
 
 const errQueryCanceled = ErrQueryCanceled("test statement execution")
@@ -496,7 +499,9 @@ func TestEngineShutdown(t *testing.T) {
 	testutil.NotOk(t, res2.Err, "expected error on querying with canceled context but got none")
 
 	var e ErrQueryCanceled
-	testutil.Assert(t, errors.As(res2.Err, &e), "expected cancellation error but got: %s", res2.Err)
+	// TODO: when circleci-windows moves to go 1.13:
+	// testutil.Assert(t, errors.As(res2.Err, &e), "expected cancellation error but got: %s", res2.Err)
+	testutil.Assert(t, strings.HasPrefix(res2.Err.Error(), e.Error()), "expected cancellation error but got: %s", res2.Err)
 }
 
 func TestEngineEvalStmtTimestamps(t *testing.T) {

util/stats/timer.go

@@ -24,7 +24,7 @@ import (
 // was running (the time between Start() and Stop()).
 type Timer struct {
 	name     fmt.Stringer
-	created  time.Time
+	created  int
 	start    time.Time
 	duration time.Duration
 }
@@ -72,7 +72,7 @@ func (t *TimerGroup) GetTimer(name fmt.Stringer) *Timer {
 	}
 	timer := &Timer{
 		name:    name,
-		created: time.Now(),
+		created: len(t.timers),
 	}
 	t.timers[name] = timer
 	return timer
@@ -95,7 +95,7 @@ func (t Timers) Swap(i, j int) {
 }
 
 func (s byCreationTimeSorter) Less(i, j int) bool {
-	return s.Timers[i].created.Before(s.Timers[j].created)
+	return s.Timers[i].created < s.Timers[j].created
 }
 
 // Return a string representation of a TimerGroup.

util/testutil/testing.go

@@ -57,7 +57,7 @@ func NotOk(tb TB, err error, a ...interface{}) {
 	if err == nil {
 		if len(a) != 0 {
 			format := a[0].(string)
-			tb.Fatalf("\033[31m"+format+": expected error, got none\033[39m", a...)
+			tb.Fatalf("\033[31m"+format+": expected error, got none\033[39m", a[1:]...)
 		}
 		tb.Fatalf("\033[31mexpected error, got none\033[39m")
 	}