sql: running logic tests with stressrace produces race in time.Now()

[thoszhang]

When I run logic tests with stressrace, I sometimes get a failure due to a data race in time.Now(). This seems to be the exact same problem as #30027, which was thought to have been fixed as of Go 1.11 (I think), but I'm getting it with Go 1.12.

The most reliable way I've found to reproduce this is by supplying a TESTS regex that doesn't match any tests (e.g., TestLogic/not_a_real_test), in which case I get this failure every time:

lucy@gceworker-lucy:~/go/src/github.com/cockroachdb/cockroach$ go version
go version go1.12.7 linux/amd64
lucy@gceworker-lucy:~/go/src/github.com/cockroachdb/cockroach$ make stressrace TESTS='TestLogic/not_a_real_test' PKG=github.com/cockroachdb/cockroach/pkg/sql/logictest TESTTIMEOUT=5m STRESSFLAGS='-maxtime 20m -timeout 10m'
Running make with -j24
GOPATH set to /home/lucy/go
Cleaning old generated files.
GOFLAGS= go test -race -exec 'stress -maxtime 20m -timeout 10m' -tags ' gss make x86_64_linux_gnu' -ldflags '-X github.com/cockroachdb/cockroach/pkg/build.typ=development -extldflags "" -X "github.com/cockroachdb/cockroach/pkg/build.tag=v19.2.0-alpha.20190606-1687-gcfde7a92b5-dirty" -X "github.com/cockroachdb/cockroach/pkg/build.rev=cfde7a92b551ae02599df33a46c44c8ec266a3c6" -X "github.com/cockroachdb/cockroach/pkg/build.cgoTargetTriple=x86_64-linux-gnu"  ' -run "TestLogic/not_a_real_test" -timeout 0 github.com/cockroachdb/cockroach/pkg/sql/logictest  -v -args -test.timeout 5m

I190829 17:43:12.168269 1 rand.go:83  Random seed: -5711090402640773854
=== RUN   TestLogic
--- total: 0 tests, 0 failures
--- PASS: TestLogic (0.18s)
    test_log_scope.go:77: test logs captured to: /tmp/logTestLogic318149004
    test_log_scope.go:58: use -show-logs to present logs inline
testing: warning: no tests to run
PASS
==================
WARNING: DATA RACE
Read at 0x000007b297e8 by goroutine 9:
  time.Now()
      /usr/local/go/src/time/time.go:1094 +0xf5
  time.sendTime()
      /usr/local/go/src/time/sleep.go:138 +0x44

Previous write at 0x000007b297e8 by goroutine 42:
  [failed to restore the stack]

Goroutine 9 (running) created at:
  runtime.(*timersBucket).addtimerLocked()
      /usr/local/go/src/runtime/time.go:169 +0x10d
  github.com/cockroachdb/cockroach/pkg/util/log.flushDaemon()
      /usr/local/go/src/time/tick.go:58 +0x42

Goroutine 42 (finished) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:916 +0x65a
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1157 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:865 +0x163
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1155 +0x523
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1072 +0x2eb
  github.com/cockroachdb/cockroach/pkg/sql/logictest.TestMain()
      /home/lucy/go/src/github.com/cockroachdb/cockroach/pkg/sql/logictest/main_test.go:33 +0x15d
  main.main()
      _testmain.go:46 +0x222
==================


ERROR: exit status 66

1 runs completed, 1 failures, over 1s
context canceled
FAIL
FAIL	github.com/cockroachdb/cockroach/pkg/sql/logictest	1.155s
Makefile:962: recipe for target 'stressrace' failed
make: *** [stressrace] Error 1

This also happens sometimes if I run other actual tests, though - simply running all the logic tests usually causes this to happen.

[cucaroach]

I think this is caused by this line:

cockroach/pkg/sql/logictest/logic.go

Line 3185 in 65c30a3

time.Local = time.UTC

Deleting this line fixes the race but breaks some unit tests, in particular this one:

statement ok
SET TIME ZONE UTC

query T
SELECT '12:00:00':::TIMETZ;
----
0000-01-01 12:00:00 +0000 UTC

I get:

    logic.go:2273:

        testdata/logic_test/timetz-min:4: SELECT '12:00:00':::TIMETZ;
        expected:
            0000-01-01 12:00:00 +0000 UTC
        but found (query options: "") :
            0000-01-01 12:00:00 +0000 +0000

So it appears hacking the time.Local field hides the fact that the SET TIME ZONE statement isn't working. cc @otan I'll probably spend some more time on this next flex friday if someone else doesn't snipe it.

[otan]

this is most likely because we're using lib/pq to format time directly in logictest, and they have some default format strings that do not make sense

we'll likely want to change our timestamp printing to follow our CLI printing style to avoid this, e.g. #63541

[knz]

fyi #63541 is merged