Repository: go
Issue: cmd/go,testing,doc: better information about debugging test cache failures
Labels: help wanted,NeedsInvestigation

I'm trying to figure out why Go is not caching a test I wrote. First, after about 10-15 minutes of searching (including through old issues here) I could not find the flag to enable the debug output that shows you how Go builds its cache. Finally, I found it `(GODEBUG=gocache{hash,test}=1)`

I am trying to read through the output of `gocachehash=1` but it's still not easy to figure out what is going wrong. The obvious first thing to do is to run the tests twice and then diff the output and see what's different. However, the output (about 10,000 lines) from two gocachehash runs prints out in different order each time so the diff is very large. 

Next I tried sorting each output file and printing it. This yields a pretty manageable diff.

```
1c1
< --- PASS: TestZipServed (0.08s)
---
> --- PASS: TestZipServed (0.07s)
5d4
< HASH /Users/kevin/Library/Caches/go-build/07/076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e-d: 076863ca534c50cc9e8a07b4a34b9ace144717479540c5554dae6736e55cb97e
13a13
> HASH /Users/kevin/Library/Caches/go-build/2d/2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b-d: 2d26f8ed83dc6de73bc9496e28d0e378ec6945d8641b2016bae22f9c0ddb929b
18d17
< HASH /Users/kevin/Library/Caches/go-build/37/376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8-d: 376397066f40ef1fac96c02af9c4a0699a0e5aa019bc41dafa3d93954e7fe7c8
41a41
> HASH /Users/kevin/Library/Caches/go-build/af/af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c-d: af711140c05b585b7bf422b3d109876cfa289b0551b3933d9c8b25ac5166b24c
44d43
< HASH /Users/kevin/Library/Caches/go-build/bb/bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd-d: bbffa5c817822dfef6bfc0da140b7a660f2c606658e504c66219c9b99d544bfd
46a46
> HASH /Users/kevin/Library/Caches/go-build/cc/cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91-d: cc58b0a1ebc54513f2062ad23b50ae86906345c8c01f85423ac1a3f401e71b91
50a51
> HASH /Users/kevin/Library/Caches/go-build/d7/d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d-d: d7f61ad9a5bd0b6f79299046b000f58a46489414bfd56724d1359d150532fd6d
52a54
> HASH /Users/kevin/Library/Caches/go-build/db/dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a-d: dbf620d8019f251ec68ba6d82177b3d3f8db4e5c08f0d7021e6db57f1326075a
1366c1368
< HASH /var/folders/s1/909yt58s4wj8h_7v7frr8rkm0000gn/T/go-build401879888/b001/_testmain.go: 20eb5f28897c44000e3a30317c33d3c9a8c3c2a3e6e76c1efeaaca21a18e5e62
---
> HASH /var/folders/s1/909yt58s4wj8h_7v7frr8rkm0000gn/T/go-build828546655/b001/_testmain.go: 20eb5f28897c44000e3a30317c33d3c9a8c3c2a3e6e76c1efeaaca21a18e5e62
7518c7520
< HASH[open]: "stat 1476 1a4 2019-11-01 04:46:46.985735425 +0000 UTC false\n"
---
> HASH[open]: "stat 1476 1a4 2019-11-01 04:46:55.122015265 +0000 UTC false\n"
10467c10469
< ok  	github.com/example/project/src/package	1.113s
---
> ok  	github.com/example/project/src/package	1.111s
```

I repeated the same exercise with a test that printed out `(cached)` to compare. The cached test diff also had `HASH ... /T/go-build` lines so I assume those are a red herring. That essentially leaves this diff:

```
< HASH[open]: "stat 1476 1a4 2019-11-01 04:46:46.985735425 +0000 UTC false\n"
---
> HASH[open]: "stat 1476 1a4 2019-11-01 04:46:55.122015265 +0000 UTC false\n"
```

However I am confused by this one as well because the content hash of the opened file is identical, so I'm not sure why Go is refusing to use the test cache.

Am I correct that these "stat" lines are the reason Go is not caching the result of this test? If so, what is the problem that is leading Go to not cache the results?

Can we build a tool to automate the process of debugging test hashes? E.g. run a test twice, capture the output, sort it, print the lines that differ.