whatcanGOwrong

This commit is contained in:
2024-09-19 21:38:24 -04:00
commit d0ae4d841d
17908 changed files with 4096831 additions and 0 deletions
@@ -0,0 +1,45 @@
The upload process converts count files into reports, and
uploads reports. There will be only one report, named YYYY-MM-DD.json,
for a given day.
First phase. Look at the localdir (os.UserConfigdir()/go/telemetry/local)
and find all .count and .json files. Find the count files that are no
longer active by looking at their metadata.
Second phase. Group the inactive count files by their expiry date, and
for each date generate the local report and the upload report. (The upload
report only contains the counters in the upload configuration.) The upload
report is saved in the local directory with a name like YYYY-MM-DD.json, if
there is no file already existing with that name.
If the local report is different, it is saved in the local directory
with a name like local.YYYY-MM-DD.json. The new upload report is
added to the list of .json files from the first phase. At this point
the count files are no longer needed and can be deleted.
Third phase. Look at the .json files in the list from the first phase.
If the name starts with local, skip it. If there is a file with the
identical name in the upload directory, remove the one in the local directory.
Otherwise try to upload the one in the local directory,
If the upload succeeds, move the file to the uploaded directory.
There are various error conditions.
1. Several processes could look at localdir and see work to do.
1A. They could see different sets of expired count files for some day.
This could happen if another process is removing count files. In this
case there is already a YYYY-MM-DD.json file either in localdir
or updatedir, so the process seeing fewer count files will not generate
a report.
1B. They could see the same count files, and no report in either directory.
They will both generate (in memory) reports and check to see if there
is a YYYY-MM-DD.json file in either directory. They could both then
write two files with the same name, but different X values, but
otherwise the same contents. The X values are very close to the front
of the file. Assuming reasonable file system semantics one version of
the file will be written. To minimize this, just before writing reports
the code checks again to see if they exist.
1C. Once there is an existing well-formed file YYYY-MM-DD.json in localdir
eventually the upload will succeed, and the file will be moved to updatedir.
It is possible that other processes will not see the file in updatedir and
upload it again and also move it to uploaddir. This is harmless as all
the uploaded files are identical.
@@ -0,0 +1,85 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"fmt"
"os"
"sync"
"time"
"golang.org/x/telemetry/internal/counter"
"golang.org/x/telemetry/internal/telemetry"
)
// time and date handling
var distantPast = 21 * 24 * time.Hour
// reports that are too old (21 days) are not uploaded
func (u *uploader) tooOld(date string, uploadStartTime time.Time) bool {
t, err := time.Parse(telemetry.DateOnly, date)
if err != nil {
u.logger.Printf("tooOld: %v", err)
return false
}
age := uploadStartTime.Sub(t)
return age > distantPast
}
// counterDateSpan parses the counter file named fname and returns the (begin,
// end) span recorded in its metadata, or an error if this data could not be
// extracted.
func (u *uploader) counterDateSpan(fname string) (begin, end time.Time, _ error) {
parsed, err := u.parseCountFile(fname)
if err != nil {
return time.Time{}, time.Time{}, err
}
timeBegin, ok := parsed.Meta["TimeBegin"]
if !ok {
return time.Time{}, time.Time{}, fmt.Errorf("missing counter metadata for TimeBegin")
}
begin, err = time.Parse(time.RFC3339, timeBegin)
if err != nil {
return time.Time{}, time.Time{}, fmt.Errorf("failed to parse TimeBegin: %v", err)
}
timeEnd, ok := parsed.Meta["TimeEnd"]
if !ok {
return time.Time{}, time.Time{}, fmt.Errorf("missing counter metadata for TimeEnd")
}
end, err = time.Parse(time.RFC3339, timeEnd)
if err != nil {
return time.Time{}, time.Time{}, fmt.Errorf("failed to parse TimeEnd: %v", err)
}
return begin, end, nil
}
// avoid parsing count files multiple times
type parsedCache struct {
mu sync.Mutex
m map[string]*counter.File
}
func (u *uploader) parseCountFile(fname string) (*counter.File, error) {
u.cache.mu.Lock()
defer u.cache.mu.Unlock()
if u.cache.m == nil {
u.cache.m = make(map[string]*counter.File)
}
if f, ok := u.cache.m[fname]; ok {
return f, nil
}
buf, err := os.ReadFile(fname)
if err != nil {
return nil, fmt.Errorf("parse ReadFile: %v for %s", err, fname)
}
f, err := counter.Parse(fname, buf)
if err != nil {
return nil, fmt.Errorf("parse Parse: %v for %s", err, fname)
}
u.cache.m[fname] = f
return f, nil
}
@@ -0,0 +1,425 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"bytes"
"fmt"
"io"
"log"
"net/http"
"net/http/httptest"
"os"
"path/filepath"
"runtime"
"strings"
"sync"
"testing"
"time"
"golang.org/x/telemetry/counter"
"golang.org/x/telemetry/internal/configtest"
"golang.org/x/telemetry/internal/regtest"
"golang.org/x/telemetry/internal/telemetry"
"golang.org/x/telemetry/internal/testenv"
)
// CreateTestUploadServer creates a test server that records the uploaded data.
// The server is closed as part of cleaning up t.
func CreateTestUploadServer(t *testing.T) (*httptest.Server, func() [][]byte) {
s := &uploadQueue{}
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
buf, err := io.ReadAll(r.Body)
if err != nil {
t.Errorf("invalid request received: %v", err)
http.Error(w, "read failed", http.StatusBadRequest)
return
}
s.Append(buf)
}))
t.Cleanup(srv.Close)
return srv, s.Get
}
type uploadQueue struct {
mu sync.Mutex
data [][]byte
}
func (s *uploadQueue) Append(data []byte) {
s.mu.Lock()
defer s.mu.Unlock()
s.data = append(s.data, data)
}
func (s *uploadQueue) Get() [][]byte {
s.mu.Lock()
defer s.mu.Unlock()
return s.data
}
func CreateTestUploadConfig(t *testing.T, counterNames, stackCounterNames []string) *telemetry.UploadConfig {
goVersion, progPath, progVersion := regtest.ProgramInfo(t)
GOOS, GOARCH := runtime.GOOS, runtime.GOARCH
programConfig := &telemetry.ProgramConfig{
Name: progPath,
Versions: []string{progVersion},
}
for _, c := range counterNames {
programConfig.Counters = append(programConfig.Counters, telemetry.CounterConfig{Name: c, Rate: 1})
}
for _, c := range stackCounterNames {
programConfig.Stacks = append(programConfig.Stacks, telemetry.CounterConfig{Name: c, Rate: 1, Depth: 16})
}
return &telemetry.UploadConfig{
GOOS: []string{GOOS},
GOARCH: []string{GOARCH},
SampleRate: 1.0,
GoVersion: []string{goVersion},
Programs: []*telemetry.ProgramConfig{programConfig},
}
}
func TestDates(t *testing.T) {
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewProgram(t, "prog", func() int {
counter.Inc("testing")
counter.NewStack("aStack", 4).Inc()
return 0
})
// Run a fake program that produces a counter file in the telemetryDir.
// readCountFileInfo will give us a template counter file content
// based on the counter file.
telemetryDir := t.TempDir()
if out, err := regtest.RunProg(t, telemetryDir, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cs := readCountFileInfo(t, filepath.Join(telemetryDir, "local"))
uc := CreateTestUploadConfig(t, nil, []string{"aStack"})
env := configtest.LocalProxyEnv(t, uc, "v1.2.3")
const today = "2020-01-24"
const yesterday = "2020-01-23"
telemetryEnableTime, _ := time.Parse(dateFormat, "2019-12-01") // back-date the telemetry acceptance
tests := []Test{ // each date must be different to subvert the parse cache
{ // test that existing counters and ready files are not uploaded if they span data before telemetry was enabled
name: "beforefirstupload",
today: "2019-12-04",
date: "2019-12-03",
begins: "2019-12-01",
ends: "2019-12-03",
readys: []string{"2019-12-01", "2019-12-02"},
// We get one local report: the newly created report.
// It is not ready as it begins on the same day that telemetry was
// enabled, and we err on the side of assuming it holds data from before
// the user turned on uploading.
wantLocal: 1,
// The report for 2019-12-01 is still ready, because it was not uploaded.
// This could happen in practice if the user disabled and then reenabled
// telmetry.
wantReady: 1,
// The report for 2019-12-02 was uploaded.
wantUploadeds: 1,
},
{ // test that existing counters and ready files are uploaded they only contain data after telemetry was enabled
name: "oktoupload",
today: "2019-12-10",
date: "2019-12-09",
begins: "2019-12-02",
ends: "2019-12-09",
readys: []string{"2019-12-07"},
wantLocal: 1,
wantUploadeds: 2, // Both new report and existing report are uploaded.
},
{ // test that an old countfile is removed and no reports generated
name: "oldcountfile",
today: today,
date: "2020-01-01",
begins: "2020-01-01",
ends: olderThan(t, today, distantPast, "oldcountfile"),
// one local; readys, uploads are empty, and there should be nothing left
wantLocal: 1,
},
{ // test that a count file expiring today is left alone
name: "todayscountfile",
today: today,
date: "2020-01-02",
begins: "2020-01-08",
ends: today,
wantCounts: 1,
},
{ // test that a count file expiring yesterday generates reports
name: "yesterdaycountfile",
today: today,
date: "2020-01-03",
begins: "2020-01-16",
ends: yesterday,
wantLocal: 1,
wantUploadeds: 1,
},
{ // count file already has local report, remove count file
name: "alreadydonelocal",
today: today,
date: "2020-01-04",
begins: "2020-01-16",
ends: yesterday,
locals: []string{yesterday},
wantCounts: 0,
wantLocal: 1,
},
{ // count file already has upload report, remove count file
name: "alreadydoneuploaded",
today: today,
date: "2020-01-05",
begins: "2020-01-16",
ends: "2020-01-23",
uploads: []string{"2020-01-23"},
wantCounts: 0, // count file has been used, remove it
wantLocal: 0, // no local report generated
wantUploadeds: 1, // the existing uploaded report
},
{ // for some reason there's a ready file in the future, don't upload it
name: "futurereadyfile",
today: "2020-01-24",
date: "2020-01-06",
begins: "2020-01-16",
ends: "2020-01-24", // count file not expired
readys: []string{"2020-01-25"},
wantCounts: 1, // active count file
wantReady: 1, // existing premature ready file
},
}
for _, tx := range tests {
t.Run(tx.name, func(t *testing.T) {
telemetryDir := t.TempDir()
srv, uploaded := CreateTestUploadServer(t)
dbg := filepath.Join(telemetryDir, "debug")
if err := os.MkdirAll(dbg, 0777); err != nil {
t.Fatal(err)
}
uploader, err := newUploader(RunConfig{
TelemetryDir: telemetryDir,
UploadURL: srv.URL,
Env: env,
})
if err != nil {
t.Fatal(err)
}
defer uploader.Close()
if err := uploader.dir.SetModeAsOf("on", telemetryEnableTime); err != nil {
t.Fatal(err)
}
uploader.startTime = mustParseDate(tx.today)
wantUploadCount := doTest(t, uploader, &tx, cs)
if got := len(uploaded()); wantUploadCount != got {
t.Errorf("server got %d upload requests, want %d", got, wantUploadCount)
}
})
}
}
func mustParseDate(d string) time.Time {
x, err := time.Parse(telemetry.DateOnly, d)
if err != nil {
log.Fatalf("couldn't parse time %s", d)
}
return x
}
// return a day more than 'old' before 'today'
func olderThan(t *testing.T, today string, old time.Duration, nm string) string {
x, err := time.Parse(telemetry.DateOnly, today)
if err != nil {
t.Errorf("%q not a day in test %s (%v)", today, nm, err)
return today // so test should fail
}
ans := x.Add(-old - 24*time.Hour)
msg := ans.Format(telemetry.DateOnly)
return msg
}
// Test is a single test.
//
// All dates are in YYYY-MM-DD format.
type Test struct {
name string // the test name; only used for descriptive output
today string // the date of the fake upload
// count file
date string // the date in of the upload file name; must be unique among tests
begins, ends string // the begin and end date stored in the counter metadata
// Dates of load reports in the local dir.
locals []string
// Dates of upload reports in the local dir.
readys []string
// Dates of reports already uploaded.
uploads []string
// number of expected results
wantCounts int
wantReady int
wantLocal int
wantUploadeds int
}
// Information from the counter file so its contents can be
// modified for tests
type countFileInfo struct {
beginOffset, endOffset int // where the dates are in the file
buf []byte // counter file contents
namePrefix string // the part of its name before the date
originalName string // its original name
}
// return useful information from the counter file to be used
// in creating tests. also compute and return the UploadConfig
// Note that there must be exactly one counter file in localDir.
func readCountFileInfo(t *testing.T, localDir string) *countFileInfo {
fis, err := os.ReadDir(localDir)
if err != nil {
t.Fatal(err)
}
var countFileName string
var countFileBuf []byte
for _, f := range fis {
if strings.HasSuffix(f.Name(), ".count") {
countFileName = filepath.Join(localDir, f.Name())
buf, err := os.ReadFile(countFileName)
if err != nil {
t.Fatal(err)
}
countFileBuf = buf
break
}
}
if len(countFileBuf) == 0 {
t.Fatalf("no contents read for %s", countFileName)
}
var cfilename string = countFileName
cfilename = filepath.Base(cfilename)
flds := strings.Split(cfilename, "-")
if len(flds) != 7 {
t.Fatalf("got %d fields, expected 7 (%q)", len(flds), cfilename)
}
pr := strings.Join(flds[:4], "-") + "-"
ans := countFileInfo{
buf: countFileBuf,
namePrefix: pr,
originalName: countFileName,
}
idx := bytes.Index(countFileBuf, []byte("TimeEnd: "))
if idx < 0 {
t.Fatalf("couldn't find TimeEnd in count file %q", countFileBuf[:100])
}
ans.endOffset = idx + len("TimeEnd: ")
idx = bytes.Index(countFileBuf, []byte("TimeBegin: "))
if idx < 0 {
t.Fatalf("couldn't find TimeBegin in countfile %q", countFileBuf[:100])
}
ans.beginOffset = idx + len("TimeBegin: ")
return &ans
}
func doTest(t *testing.T, u *uploader, test *Test, known *countFileInfo) int {
// set up directory contents
contents := bytes.Join([][]byte{
known.buf[:known.beginOffset],
[]byte(test.begins),
known.buf[known.beginOffset+len("YYYY-MM-DD") : known.endOffset],
[]byte(test.ends),
known.buf[known.endOffset+len("YYYY-MM-DD"):],
}, nil)
filename := known.namePrefix + test.date + ".v1.count"
if err := os.MkdirAll(u.dir.LocalDir(), 0777); err != nil {
t.Fatal(err)
}
if err := os.WriteFile(filepath.Join(u.dir.LocalDir(), filename), contents, 0666); err != nil {
t.Fatalf("writing count file for %s (%s): %v", test.name, filename, err)
}
for _, x := range test.locals {
nm := fmt.Sprintf("local.%s.json", x)
if err := os.WriteFile(filepath.Join(u.dir.LocalDir(), nm), []byte{}, 0666); err != nil {
t.Fatalf("%v writing local file %s", err, nm)
}
}
for _, x := range test.readys {
nm := fmt.Sprintf("%s.json", x)
if err := os.WriteFile(filepath.Join(u.dir.LocalDir(), nm), []byte{}, 0666); err != nil {
t.Fatalf("%v writing ready file %s", err, nm)
}
}
if len(test.uploads) > 0 {
os.MkdirAll(u.dir.UploadDir(), 0777)
}
for _, x := range test.uploads {
nm := fmt.Sprintf("%s.json", x)
if err := os.WriteFile(filepath.Join(u.dir.UploadDir(), nm), []byte{}, 0666); err != nil {
t.Fatalf("%v writing upload %s", err, nm)
}
}
// run
u.Run()
// check results
var cfiles, rfiles, lfiles, ufiles int
fis, err := os.ReadDir(u.dir.LocalDir())
if err != nil {
t.Errorf("%v reading localdir %s", err, u.dir.LocalDir())
return 0
}
for _, f := range fis {
switch {
case strings.HasSuffix(f.Name(), ".v1.count"):
cfiles++
case f.Name() == "weekends": // ok
case strings.HasPrefix(f.Name(), "local."):
lfiles++
case strings.HasSuffix(f.Name(), ".json"):
rfiles++
default:
t.Errorf("for %s, unexpected local file %s", test.name, f.Name())
}
}
var logcnt int
logs, err := os.ReadDir(u.dir.DebugDir())
if err == nil {
logcnt = len(logs)
}
if logcnt != 1 {
t.Errorf("expected 1 log file, got %d", logcnt)
}
fis, err = os.ReadDir(u.dir.UploadDir())
if err != nil {
t.Errorf("%v reading uploaddir %s", err, u.dir.UploadDir())
return 0
}
ufiles = len(fis) // assume there's nothing but .json reports
if test.wantCounts != cfiles {
t.Errorf("%s: got %d countfiles, wanted %d", test.name, cfiles, test.wantCounts)
}
if test.wantReady != rfiles {
t.Errorf("%s: got %d ready files, wanted %d", test.name, rfiles, test.wantReady)
}
if test.wantLocal != lfiles {
t.Errorf("%s: got %d localfiles, wanted %d", test.name, lfiles, test.wantLocal)
}
if test.wantUploadeds != ufiles {
t.Errorf("%s: got %d uploaded files, wanted %d", test.name, ufiles, test.wantUploadeds)
}
return ufiles - len(test.uploads)
}
@@ -0,0 +1,102 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"os"
"path/filepath"
"strings"
)
// files to handle
type work struct {
// absolute file names
countfiles []string // count files to process
readyfiles []string // old reports to upload
// relative names
uploaded map[string]bool // reports that have been uploaded
}
// find all the files that look like counter files or reports
// that need to be uploaded. (There may be unexpected leftover files
// and uploading is supposed to be idempotent.)
func (u *uploader) findWork() work {
localdir, uploaddir := u.dir.LocalDir(), u.dir.UploadDir()
var ans work
fis, err := os.ReadDir(localdir)
if err != nil {
u.logger.Printf("Could not find work: failed to read local dir %s: %v", localdir, err)
return ans
}
mode, asof := u.dir.Mode()
u.logger.Printf("Finding work: mode %s asof %s", mode, asof)
// count files end in .v1.count
// reports end in .json. If they are not to be uploaded they
// start with local.
for _, fi := range fis {
if strings.HasSuffix(fi.Name(), ".v1.count") {
fname := filepath.Join(localdir, fi.Name())
_, expiry, err := u.counterDateSpan(fname)
switch {
case err != nil:
u.logger.Printf("Error reading expiry for count file %s: %v", fi.Name(), err)
case expiry.After(u.startTime):
u.logger.Printf("Skipping count file %s: still active", fi.Name())
default:
u.logger.Printf("Collecting count file %s", fi.Name())
ans.countfiles = append(ans.countfiles, fname)
}
} else if strings.HasPrefix(fi.Name(), "local.") {
// skip
} else if strings.HasSuffix(fi.Name(), ".json") && mode == "on" {
// Collect reports that are ready for upload.
reportDate := u.uploadReportDate(fi.Name())
if !asof.IsZero() && !reportDate.IsZero() {
// If both the mode asof date and the report date are present, do the
// right thing...
//
// (see https://github.com/golang/go/issues/63142#issuecomment-1734025130)
if asof.Before(reportDate) {
// Note: since this report was created after telemetry was enabled,
// we can only assume that the process that created it checked that
// the counter data contained therein was all from after the asof
// date.
//
// TODO(rfindley): store the begin date in reports, so that we can
// verify this assumption.
u.logger.Printf("Uploadable: %s", fi.Name())
ans.readyfiles = append(ans.readyfiles, filepath.Join(localdir, fi.Name()))
}
} else {
// ...otherwise fall back on the old behavior of uploading all
// unuploaded files.
//
// TODO(rfindley): invert this logic following more testing. We
// should only upload if we know both the asof date and the report
// date, and they are acceptable.
u.logger.Printf("Uploadable (missing date): %s", fi.Name())
ans.readyfiles = append(ans.readyfiles, filepath.Join(localdir, fi.Name()))
}
}
}
fis, err = os.ReadDir(uploaddir)
if err != nil {
os.MkdirAll(uploaddir, 0777)
return ans
}
// There should be only one of these per day; maybe sometime
// we'll want to clean the directory.
ans.uploaded = make(map[string]bool)
for _, fi := range fis {
if strings.HasSuffix(fi.Name(), ".json") {
u.logger.Printf("Already uploaded: %s", fi.Name())
ans.uploaded[fi.Name()] = true
}
}
return ans
}
@@ -0,0 +1,56 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"net/http"
"reflect"
"strings"
"testing"
)
// make sure we can talk to the test server
// In practice this test runs last, so is somewhat superfluous,
// but it also checks that uploads and reads from the channel are matched
func TestSimpleServer(t *testing.T) {
srv, uploaded := CreateTestUploadServer(t)
url := srv.URL
resp, err := http.Post(url, "text/plain", strings.NewReader("hello"))
if err != nil {
t.Fatal(err)
}
if resp.StatusCode != http.StatusOK {
t.Errorf("%#v", resp.StatusCode)
}
got := uploaded()
want := [][]byte{[]byte("hello")}
if !reflect.DeepEqual(got, want) {
t.Errorf("got %s, want %s", got, want)
}
}
// make sure computeRandom() gets enough small values
// in case SamplingRate is as small as .001
func TestRandom(t *testing.T) {
// This test, being statistical, is intrinsically flaky
// It has failed once in its first 3 months at 4.5,
// so change the criterion to 7 sigma.
const N = 102400 // 35msec on an M1 mac
cnt := 0
for i := 0; i < N; i++ {
if computeRandom() < 1.0/1024 {
cnt++
}
}
// cnt has a binomial distribution. The normal
// approximation has mu=N*p=100, sigma=sqrt(N*p*(1-p))=10
// We reject if cnt is off by 45, which happens about 1/300,000
// if the computeRandom() is truly uniform. That is, the
// test will be flaky about 3 times in a million.
if cnt < 30 || cnt > 170 {
t.Errorf("cnt %d more than 7 sigma(10) from mean(100)", cnt)
}
}
@@ -0,0 +1,344 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"crypto/rand"
"encoding/binary"
"encoding/json"
"fmt"
"math"
"os"
"path/filepath"
"strings"
"time"
"golang.org/x/telemetry/internal/config"
"golang.org/x/telemetry/internal/counter"
"golang.org/x/telemetry/internal/telemetry"
)
// reports generates reports from inactive count files
func (u *uploader) reports(todo *work) ([]string, error) {
if mode, _ := u.dir.Mode(); mode == "off" {
return nil, nil // no reports
}
thisInstant := u.startTime
today := thisInstant.Format(telemetry.DateOnly)
lastWeek := latestReport(todo.uploaded)
if lastWeek >= today { //should never happen
lastWeek = ""
}
u.logger.Printf("Last week: %s, today: %s", lastWeek, today)
countFiles := make(map[string][]string) // expiry date string->filenames
earliest := make(map[string]time.Time) // earliest begin time for any counter
for _, f := range todo.countfiles {
begin, end, err := u.counterDateSpan(f)
if err != nil {
// This shouldn't happen: we should have already skipped count files that
// don't contain valid start or end times.
u.logger.Printf("BUG: failed to parse expiry for collected count file: %v", err)
continue
}
if end.Before(thisInstant) {
expiry := end.Format(dateFormat)
countFiles[expiry] = append(countFiles[expiry], f)
if earliest[expiry].IsZero() || earliest[expiry].After(begin) {
earliest[expiry] = begin
}
}
}
for expiry, files := range countFiles {
if notNeeded(expiry, *todo) {
u.logger.Printf("Files for %s not needed, deleting %v", expiry, files)
// The report already exists.
// There's another check in createReport.
u.deleteFiles(files)
continue
}
fname, err := u.createReport(earliest[expiry], expiry, files, lastWeek)
if err != nil {
u.logger.Printf("Failed to create report for %s: %v", expiry, err)
continue
}
if fname != "" {
u.logger.Printf("Ready to upload: %s", filepath.Base(fname))
todo.readyfiles = append(todo.readyfiles, fname)
}
}
return todo.readyfiles, nil
}
// latestReport returns the YYYY-MM-DD of the last report uploaded
// or the empty string if there are no reports.
func latestReport(uploaded map[string]bool) string {
var latest string
for name := range uploaded {
if strings.HasSuffix(name, ".json") {
if name > latest {
latest = name
}
}
}
if latest == "" {
return ""
}
// strip off the .json
return latest[:len(latest)-len(".json")]
}
// notNeeded returns true if the report for date has already been created
func notNeeded(date string, todo work) bool {
if todo.uploaded != nil && todo.uploaded[date+".json"] {
return true
}
// maybe the report is already in todo.readyfiles
for _, f := range todo.readyfiles {
if strings.Contains(f, date) {
return true
}
}
return false
}
func (u *uploader) deleteFiles(files []string) {
for _, f := range files {
if err := os.Remove(f); err != nil {
// this could be a race condition.
// conversely, on Windows, err may be nil and
// the file not deleted if anyone has it open.
u.logger.Printf("%v failed to remove %s", err, f)
}
}
}
// createReport creates local and upload report files by
// combining all the count files for the expiryDate, and
// returns the upload report file's path.
// It may delete the count files once local and upload report
// files are successfully created.
func (u *uploader) createReport(start time.Time, expiryDate string, countFiles []string, lastWeek string) (string, error) {
uploadOK := true
mode, asof := u.dir.Mode()
if mode != "on" {
u.logger.Printf("No upload config or mode %q is not 'on'", mode)
uploadOK = false // no config, nothing to upload
}
if u.tooOld(expiryDate, u.startTime) {
u.logger.Printf("Expiry date %s is too old", expiryDate)
uploadOK = false
}
// If the mode is recorded with an asof date, don't upload if the report
// includes any data on or before the asof date.
if !asof.IsZero() && !asof.Before(start) {
u.logger.Printf("As-of date %s is not before start %s", asof, start)
uploadOK = false
}
// TODO(rfindley): check that all the x.Meta are consistent for GOOS, GOARCH, etc.
report := &telemetry.Report{
Config: u.configVersion,
X: computeRandom(), // json encodes all the bits
Week: expiryDate,
LastWeek: lastWeek,
}
if report.X > u.config.SampleRate && u.config.SampleRate > 0 {
u.logger.Printf("X: %f > SampleRate:%f, not uploadable", report.X, u.config.SampleRate)
uploadOK = false
}
var succeeded bool
for _, f := range countFiles {
fok := false
x, err := u.parseCountFile(f)
if err != nil {
u.logger.Printf("Unparseable count file %s: %v", filepath.Base(f), err)
continue
}
prog := findProgReport(x.Meta, report)
for k, v := range x.Count {
if counter.IsStackCounter(k) {
// stack
prog.Stacks[k] += int64(v)
} else {
// counter
prog.Counters[k] += int64(v)
}
succeeded = true
fok = true
}
if !fok {
u.logger.Printf("no counters found in %s", f)
}
}
if !succeeded {
return "", fmt.Errorf("none of the %d count files for %s contained counters", len(countFiles), expiryDate)
}
// 1. generate the local report
localContents, err := json.MarshalIndent(report, "", " ")
if err != nil {
return "", fmt.Errorf("failed to marshal report for %s: %v", expiryDate, err)
}
// check that the report can be read back
// TODO(pjw): remove for production?
var report2 telemetry.Report
if err := json.Unmarshal(localContents, &report2); err != nil {
return "", fmt.Errorf("failed to unmarshal local report for %s: %v", expiryDate, err)
}
var uploadContents []byte
if uploadOK {
// 2. create the uploadable version
cfg := config.NewConfig(u.config)
upload := &telemetry.Report{
Week: report.Week,
LastWeek: report.LastWeek,
X: report.X,
Config: report.Config,
}
for _, p := range report.Programs {
// does the uploadConfig want this program?
// if so, copy over the Stacks and Counters
// that the uploadConfig mentions.
if !cfg.HasGoVersion(p.GoVersion) || !cfg.HasProgram(p.Program) || !cfg.HasVersion(p.Program, p.Version) {
continue
}
x := &telemetry.ProgramReport{
Program: p.Program,
Version: p.Version,
GOOS: p.GOOS,
GOARCH: p.GOARCH,
GoVersion: p.GoVersion,
Counters: make(map[string]int64),
Stacks: make(map[string]int64),
}
upload.Programs = append(upload.Programs, x)
for k, v := range p.Counters {
if cfg.HasCounter(p.Program, k) && report.X <= cfg.Rate(p.Program, k) {
x.Counters[k] = v
}
}
// and the same for Stacks
// this can be made more efficient, when it matters
for k, v := range p.Stacks {
before, _, _ := strings.Cut(k, "\n")
if cfg.HasStack(p.Program, before) && report.X <= cfg.Rate(p.Program, before) {
x.Stacks[k] = v
}
}
}
uploadContents, err = json.MarshalIndent(upload, "", " ")
if err != nil {
return "", fmt.Errorf("failed to marshal upload report for %s: %v", expiryDate, err)
}
}
localFileName := filepath.Join(u.dir.LocalDir(), "local."+expiryDate+".json")
uploadFileName := filepath.Join(u.dir.LocalDir(), expiryDate+".json")
/* Prepare to write files */
// if either file exists, someone has been here ahead of us
// (there is still a race, but this check shortens the open window)
if _, err := os.Stat(localFileName); err == nil {
u.deleteFiles(countFiles)
return "", fmt.Errorf("local report %s already exists", localFileName)
}
if _, err := os.Stat(uploadFileName); err == nil {
u.deleteFiles(countFiles)
return "", fmt.Errorf("report %s already exists", uploadFileName)
}
// write the uploadable file
var errUpload, errLocal error
if uploadOK {
_, errUpload = exclusiveWrite(uploadFileName, uploadContents)
}
// write the local file
_, errLocal = exclusiveWrite(localFileName, localContents)
/* Wrote the files */
// even though these errors won't occur, what should happen
// if errUpload == nil and it is ok to upload, and errLocal != nil?
if errLocal != nil {
return "", fmt.Errorf("failed to write local file %s (%v)", localFileName, errLocal)
}
if errUpload != nil {
return "", fmt.Errorf("failed to write upload file %s (%v)", uploadFileName, errUpload)
}
u.logger.Printf("Created %s, deleting %d count files", filepath.Base(uploadFileName), len(countFiles))
u.deleteFiles(countFiles)
if uploadOK {
return uploadFileName, nil
}
return "", nil
}
// exclusiveWrite attempts to create filename exclusively, and if successful,
// writes content to the resulting file handle.
//
// It returns a boolean indicating whether the exclusive handle was acquired,
// and an error indicating whether the operation succeeded.
// If the file already exists, exclusiveWrite returns (false, nil).
func exclusiveWrite(filename string, content []byte) (_ bool, rerr error) {
f, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0644)
if err != nil {
if os.IsExist(err) {
return false, nil
}
return false, err
}
defer func() {
if err := f.Close(); err != nil && rerr == nil {
rerr = err
}
}()
if _, err := f.Write(content); err != nil {
return false, err
}
return true, nil
}
// return an existing ProgremReport, or create anew
func findProgReport(meta map[string]string, report *telemetry.Report) *telemetry.ProgramReport {
for _, prog := range report.Programs {
if prog.Program == meta["Program"] && prog.Version == meta["Version"] &&
prog.GoVersion == meta["GoVersion"] && prog.GOOS == meta["GOOS"] &&
prog.GOARCH == meta["GOARCH"] {
return prog
}
}
prog := telemetry.ProgramReport{
Program: meta["Program"],
Version: meta["Version"],
GoVersion: meta["GoVersion"],
GOOS: meta["GOOS"],
GOARCH: meta["GOARCH"],
Counters: make(map[string]int64),
Stacks: make(map[string]int64),
}
report.Programs = append(report.Programs, &prog)
return &prog
}
// computeRandom returns a cryptographic random float64 in the range [0, 1],
// with 52 bits of precision.
func computeRandom() float64 {
for {
b := make([]byte, 8)
_, err := rand.Read(b)
if err != nil {
panic(fmt.Sprintf("rand.Read failed: %v", err))
}
// and turn it into a float64
x := math.Float64frombits(binary.LittleEndian.Uint64(b))
if math.IsNaN(x) || math.IsInf(x, 0) {
continue
}
x = math.Abs(x)
if x < 0x1p-1000 { // avoid underflow patterns
continue
}
frac, _ := math.Frexp(x) // 52 bits of randomness
return frac*2 - 1
}
}
@@ -0,0 +1,226 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"fmt"
"io"
"log"
"os"
"path"
"path/filepath"
"runtime/debug"
"strings"
"time"
"golang.org/x/telemetry/internal/configstore"
"golang.org/x/telemetry/internal/telemetry"
)
// RunConfig configures non-default behavior of a call to Run.
//
// All fields are optional, for testing or observability.
type RunConfig struct {
TelemetryDir string // if set, overrides the telemetry data directory
UploadURL string // if set, overrides the telemetry upload endpoint
LogWriter io.Writer // if set, used for detailed logging of the upload process
Env []string // if set, appended to the config download environment
StartTime time.Time // if set, overrides the upload start time
}
// Run generates and uploads reports, as allowed by the mode file.
func Run(config RunConfig) error {
defer func() {
if err := recover(); err != nil {
log.Printf("upload recover: %v", err)
}
}()
uploader, err := newUploader(config)
if err != nil {
return err
}
defer uploader.Close()
return uploader.Run()
}
// uploader encapsulates a single upload operation, carrying parameters and
// shared state.
type uploader struct {
// config is used to select counters to upload.
config *telemetry.UploadConfig //
configVersion string // version of the config
dir telemetry.Dir // the telemetry dir to process
uploadServerURL string
startTime time.Time
cache parsedCache
logFile *os.File
logger *log.Logger
}
// newUploader creates a new uploader to use for running the upload for the
// given config.
//
// Uploaders should only be used for one call to [uploader.Run].
func newUploader(rcfg RunConfig) (*uploader, error) {
// Determine the upload directory.
var dir telemetry.Dir
if rcfg.TelemetryDir != "" {
dir = telemetry.NewDir(rcfg.TelemetryDir)
} else {
dir = telemetry.Default
}
// Determine the upload URL.
uploadURL := rcfg.UploadURL
if uploadURL == "" {
uploadURL = "https://telemetry.go.dev/upload"
}
// Determine the upload logger.
//
// This depends on the provided rcfg.LogWriter and the presence of
// dir.DebugDir, as follows:
// 1. If LogWriter is present, log to it.
// 2. If DebugDir is present, log to a file within it.
// 3. If both LogWriter and DebugDir are present, log to a multi writer.
// 4. If neither LogWriter nor DebugDir are present, log to a noop logger.
var logWriters []io.Writer
logFile, err := debugLogFile(dir.DebugDir())
if err != nil {
logFile = nil
}
if logFile != nil {
logWriters = append(logWriters, logFile)
}
if rcfg.LogWriter != nil {
logWriters = append(logWriters, rcfg.LogWriter)
}
var logWriter io.Writer
switch len(logWriters) {
case 0:
logWriter = io.Discard
case 1:
logWriter = logWriters[0]
default:
logWriter = io.MultiWriter(logWriters...)
}
logger := log.New(logWriter, "", log.Ltime|log.Lmicroseconds|log.Lshortfile)
// Fetch the upload config, if it is not provided.
var (
config *telemetry.UploadConfig
configVersion string
)
if mode, _ := dir.Mode(); mode == "on" {
// golang/go#68946: only download the upload config if it will be used.
//
// TODO(rfindley): This is a narrow change aimed at minimally fixing the
// associated bug. In the future, we should read the mode only once during
// the upload process.
config, configVersion, err = configstore.Download("latest", rcfg.Env)
if err != nil {
return nil, err
}
} else {
config = &telemetry.UploadConfig{}
configVersion = "v0.0.0-0"
}
// Set the start time, if it is not provided.
startTime := time.Now().UTC()
if !rcfg.StartTime.IsZero() {
startTime = rcfg.StartTime
}
return &uploader{
config: config,
configVersion: configVersion,
dir: dir,
uploadServerURL: uploadURL,
startTime: startTime,
logFile: logFile,
logger: logger,
}, nil
}
// Close cleans up any resources associated with the uploader.
func (u *uploader) Close() error {
if u.logFile == nil {
return nil
}
return u.logFile.Close()
}
// Run generates and uploads reports
func (u *uploader) Run() error {
if telemetry.DisabledOnPlatform {
return nil
}
todo := u.findWork()
ready, err := u.reports(&todo)
if err != nil {
u.logger.Printf("Error building reports: %v", err)
return fmt.Errorf("reports failed: %v", err)
}
u.logger.Printf("Uploading %d reports", len(ready))
for _, f := range ready {
u.uploadReport(f)
}
return nil
}
// debugLogFile arranges to write a log file in the given debug directory, if
// it exists.
func debugLogFile(debugDir string) (*os.File, error) {
fd, err := os.Stat(debugDir)
if os.IsNotExist(err) {
return nil, nil
}
if err != nil {
return nil, err
}
if !fd.IsDir() {
return nil, fmt.Errorf("debug path %q is not a directory", debugDir)
}
info, ok := debug.ReadBuildInfo()
if !ok {
return nil, fmt.Errorf("no build info")
}
year, month, day := time.Now().UTC().Date()
goVers := info.GoVersion
// E.g., goVers:"go1.22-20240109-RC01 cl/597041403 +dcbe772469 X:loopvar"
words := strings.Fields(goVers)
goVers = words[0]
progPkgPath := info.Path
if progPkgPath == "" {
progPkgPath = strings.TrimSuffix(filepath.Base(os.Args[0]), ".exe")
}
prog := path.Base(progPkgPath)
progVers := info.Main.Version
if progVers == "(devel)" { // avoid special characters in created file names
progVers = "devel"
}
logBase := strings.ReplaceAll(
fmt.Sprintf("%s-%s-%s-%4d%02d%02d-%d.log", prog, progVers, goVers, year, month, day, os.Getpid()),
" ", "")
fname := filepath.Join(debugDir, logBase)
if _, err := os.Stat(fname); err == nil {
// This process previously called upload.Run
return nil, nil
}
f, err := os.OpenFile(fname, os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0666)
if err != nil {
if os.IsExist(err) {
return nil, nil // this process previously called upload.Run
}
return nil, err
}
return f, nil
}
@@ -0,0 +1,631 @@
// Copyright 2024 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload_test
import (
"bytes"
"encoding/json"
"fmt"
"net/http"
"net/http/httptest"
"os"
"path/filepath"
"regexp"
"runtime"
"strings"
"sync"
"testing"
"time"
"golang.org/x/telemetry/counter"
"golang.org/x/telemetry/internal/configstore"
"golang.org/x/telemetry/internal/configtest"
"golang.org/x/telemetry/internal/regtest"
"golang.org/x/telemetry/internal/telemetry"
"golang.org/x/telemetry/internal/testenv"
"golang.org/x/telemetry/internal/upload"
)
// runConfig sets up an upload environment for the provided test, with a
// fake proxy allowing the given counters, and a fake upload server.
//
// The returned RunConfig is ready to pass to Run to upload the given
// directory. The second return is a function to fetch all uploaded reports.
//
// For convenience, runConfig also sets the mode in telemetryDir to "on",
// back-dated to a time in the past. Callers that want to run the upload with a
// different mode can reset as necessary.
//
// All associated resources are cleaned up with t.Clean.
func runConfig(t *testing.T, telemetryDir string, counters, stackCounters []string) (upload.RunConfig, func() [][]byte) {
t.Helper()
if err := telemetry.NewDir(telemetryDir).SetModeAsOf("on", time.Now().Add(-365*24*time.Hour)); err != nil {
t.Fatal(err)
}
srv, uploaded := upload.CreateTestUploadServer(t)
uc := upload.CreateTestUploadConfig(t, counters, stackCounters)
env := configtest.LocalProxyEnv(t, uc, "v1.2.3")
return upload.RunConfig{
TelemetryDir: telemetryDir,
UploadURL: srv.URL,
LogWriter: testWriter{"", t},
Env: env,
}, uploaded
}
// testWriter is an io.Writer wrapping t.Log.
type testWriter struct {
prefix string
t *testing.T
}
func (w testWriter) Write(p []byte) (n int, err error) {
w.t.Log(w.prefix + strings.TrimSuffix(string(p), "\n")) // trim newlines added by logging
return len(p), nil
}
func TestRun_Basic(t *testing.T) {
// Check the correctness of a single upload to the local server.
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewProgram(t, "prog", func() int {
counter.Inc("knownCounter")
counter.Inc("unknownCounter")
counter.NewStack("aStack", 4).Inc()
return 0
})
// produce a counter file (timestamped with "today")
telemetryDir := t.TempDir()
if out, err := regtest.RunProgAsOf(t, telemetryDir, time.Now().Add(-8*24*time.Hour), prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
// Running the program should produce a counter file.
checkTelemetryFiles(t, telemetryDir, telemetryFiles{counterFiles: 1})
// Aside: writing the "debug" file here reproduces a scenario observed in the
// past where the "debug" directory could not be read.
// (there is no issue to reference for additional context, unfortunately)
logName := filepath.Join(telemetryDir, "debug")
err := os.WriteFile(logName, nil, 0666) // must be done before calling Run
if err != nil {
t.Fatal(err)
}
// Run the upload.
cfg, getUploads := runConfig(t, telemetryDir, []string{"knownCounter", "aStack"}, nil)
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
// The upload process should have deleted the counter file, and produced both
// a local and uploaded report.
checkTelemetryFiles(t, telemetryDir, telemetryFiles{localReports: 1, uploadedReports: 1})
// Check that the uploaded report matches our expectations exactly.
uploads := getUploads()
if len(uploads) != 1 {
t.Fatalf("got %d uploads, want 1", len(uploads))
}
var got telemetry.Report
if err := json.Unmarshal(uploads[0], &got); err != nil {
t.Fatal(err)
}
if got.Week == "" {
t.Errorf("Uploaded report missing Week field:\n%s", uploads[0])
}
if len(got.Programs) != 1 {
t.Fatalf("got %d uploaded programs, want 1", len(got.Programs))
}
gotProgram := got.Programs[0]
want := telemetry.Report{
Week: got.Week, // volatile
X: got.X, // volatile
Programs: []*telemetry.ProgramReport{{
Program: "upload.test",
Version: "",
GoVersion: gotProgram.GoVersion, // easiest to read this from the report
GOOS: runtime.GOOS,
GOARCH: runtime.GOARCH,
Counters: map[string]int64{
"knownCounter": 1,
},
Stacks: map[string]int64{},
}},
Config: "v1.2.3",
}
gotFormatted, err := json.MarshalIndent(got, "", "\t")
if err != nil {
t.Fatal(err)
}
wantFormatted, err := json.MarshalIndent(want, "", "\t")
if err != nil {
t.Fatal(err)
}
if got, want := string(gotFormatted), string(wantFormatted); got != want {
t.Errorf("Mismatching uploaded report:\ngot:\n%s\nwant:\n%s", got, want)
}
}
type telemetryFiles struct {
counterFiles int
localReports int
unuploadedReports int
uploadedReports int
// Other files like mode or weekends are intentionally omitted, because they
// are less interesting internal details.
}
// checkTelemetryFiles checks that the state of telemetryDir matches the
// desired telemetryFiles.
func checkTelemetryFiles(t *testing.T, telemetryDir string, want telemetryFiles) {
t.Helper()
dir := telemetry.NewDir(telemetryDir)
countFiles := func(dir, pattern string) int {
count := 0
fis, err := os.ReadDir(dir)
if err != nil {
return 0 // missing directory
}
re, err := regexp.Compile(pattern)
if err != nil {
t.Fatal(err)
}
for _, fi := range fis {
if re.MatchString(fi.Name()) {
count++
}
}
return count
}
got := telemetryFiles{
counterFiles: countFiles(dir.LocalDir(), `\.v1\.count`),
localReports: countFiles(dir.LocalDir(), `^local\..*\.json$`),
unuploadedReports: countFiles(dir.LocalDir(), `^[0-9].*\.json$`),
uploadedReports: countFiles(dir.UploadDir(), `^[0-9].*\.json$`),
}
if got != want {
t.Errorf("got telemetry files %+v, want %+v", got, want)
}
}
func TestRun_Retries(t *testing.T) {
// Check that the Run handles upload server status codes appropriately,
// and that retries behave as expected.
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewIncProgram(t, "prog", "counter")
tests := []struct {
initialStatus int
initialFiles telemetryFiles
filesAfterRetry telemetryFiles
}{
{
http.StatusOK,
telemetryFiles{localReports: 1, uploadedReports: 1},
telemetryFiles{localReports: 1, uploadedReports: 1},
},
{
http.StatusBadRequest,
telemetryFiles{localReports: 1},
telemetryFiles{localReports: 1},
},
{
http.StatusInternalServerError,
telemetryFiles{localReports: 1, unuploadedReports: 1},
telemetryFiles{localReports: 1, uploadedReports: 1},
},
}
for _, test := range tests {
t.Run(fmt.Sprint(test.initialStatus), func(t *testing.T) {
telemetryDir := t.TempDir()
if out, err := regtest.RunProgAsOf(t, telemetryDir, time.Now().Add(-8*24*time.Hour), prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
// Start an upload server that returns the given status code.
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
w.WriteHeader(test.initialStatus)
}))
t.Cleanup(srv.Close)
// Enable uploads.
dir := telemetry.NewDir(telemetryDir)
if err := dir.SetModeAsOf("on", time.Now().Add(-365*24*time.Hour)); err != nil {
t.Fatal(err)
}
// Write the proxy.
uc := upload.CreateTestUploadConfig(t, []string{"counter"}, nil)
env := configtest.LocalProxyEnv(t, uc, "v1.2.3")
// Run the upload.
badCfg := upload.RunConfig{
TelemetryDir: telemetryDir,
UploadURL: srv.URL,
Env: env,
}
if err := upload.Run(badCfg); err != nil {
t.Fatal(err)
}
// Check that the upload left the telemetry directory in the desired state.
checkTelemetryFiles(t, telemetryDir, test.initialFiles)
// Now re-run the upload with a succeeding upload server.
goodCfg, _ := runConfig(t, telemetryDir, []string{"counter"}, nil)
if err := upload.Run(goodCfg); err != nil {
t.Fatal(err)
}
// Check files after retrying.
checkTelemetryFiles(t, telemetryDir, test.filesAfterRetry)
})
}
}
func TestRun_MultipleUploads(t *testing.T) {
// This test checks that [upload.Run] produces multiple reports when counters
// span more than a week.
testenv.SkipIfUnsupportedPlatform(t)
// This program is run at two different dates.
prog := regtest.NewIncProgram(t, "prog", "counter1")
// Create two counter files to upload, at least a week apart.
telemetryDir := t.TempDir()
asof1 := time.Now().Add(-15 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof1, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
asof2 := time.Now().Add(-8 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof2, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"counter1", "counter2"}, nil)
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
uploads := getUploads()
if got, want := len(uploads), 2; got != want {
t.Fatalf("got %d uploads, want %d", got, want)
}
for _, upload := range uploads {
report := string(upload)
if !strings.Contains(report, "counter1") {
t.Errorf("Didn't get an upload for counter1. Report:\n%s", report)
}
}
}
func TestRun_EmptyUpload(t *testing.T) {
// This test verifies that an empty counter file does not cause uploads of
// another week's reports to fail.
testenv.SkipIfUnsupportedPlatform(t)
// prog1 runs in week 1, and increments no counter.
prog1 := regtest.NewIncProgram(t, "prog1")
// prog2 runs in week 2.
prog2 := regtest.NewIncProgram(t, "prog2", "week2")
telemetryDir := t.TempDir()
// Create two counter files to upload, at least a week apart.
// Week 1 has no counters, which in the past caused the both uploads to fail.
asof1 := time.Now().Add(-15 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof1, prog1); err != nil {
t.Fatalf("failed to run program: %s", out)
}
asof2 := time.Now().Add(-8 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof2, prog2); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"week1", "week2"}, nil)
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
// Check that we got one upload, for week 2.
uploads := getUploads()
if got, want := len(uploads), 1; got != want {
t.Fatalf("got %d uploads, want %d", got, want)
}
for _, upload := range uploads {
report := string(upload)
if !strings.Contains(report, "week2") {
t.Errorf("Didn't get an upload for week2. Report:\n%s", report)
}
}
}
func TestRun_MissingDate(t *testing.T) {
// This test verifies that a counter file with corrupt metadata does not
// prevent the uploader from uploading another week's reports.
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewIncProgram(t, "prog", "counter")
telemetryDir := t.TempDir()
// Create two counter files to upload, a week apart.
asof1 := time.Now().Add(-15 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof1, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
// Corrupt the week 1 counter file.
{
localDir := telemetry.NewDir(telemetryDir).LocalDir()
fis, err := os.ReadDir(localDir)
if err != nil {
t.Fatal(err)
}
var countFiles []string
for _, fi := range fis {
if strings.HasSuffix(fi.Name(), ".v1.count") {
countFiles = append(countFiles, filepath.Join(localDir, fi.Name()))
}
}
if len(countFiles) != 1 {
t.Fatalf("after first RunProgAsOf, found %d count files, want 1", len(countFiles))
}
countFile := countFiles[0]
data, err := os.ReadFile(countFile)
if err != nil {
t.Fatal(err)
}
// Importantly, the byte replacement here has the same length.
// If not, the entire file (and not just metadata) would be corrupt, due to
// the header length mismatch.
corrupted := bytes.Replace(data, []byte(`TimeBegin:`), []byte(`TimxBegin:`), 1)
if err := os.WriteFile(countFile, corrupted, 0666); err != nil {
t.Fatal(err)
}
}
asof2 := time.Now().Add(-8 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof2, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"counter"}, nil)
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
// Check that we got one upload, for week 2.
uploads := getUploads()
if got, want := len(uploads), 1; got != want {
t.Fatalf("got %d uploads, want %d", got, want)
}
report := string(uploads[0])
if !strings.Contains(report, "counter") {
t.Errorf("Didn't get an upload for counter. Report:\n%s", report)
}
}
func TestRun_ModeHandling(t *testing.T) {
// This test verifies that the uploader honors the telemetry mode, as well as
// its asof date.
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewIncProgram(t, "prog1", "counter")
tests := []struct {
mode string
wantConfigDownloads int64
wantUploads int
}{
{"off", 0, 0},
{"local", 0, 0},
{"on", 1, 1}, // only the second week is uploadable
}
for _, test := range tests {
t.Run(test.mode, func(t *testing.T) {
telemetryDir := t.TempDir()
// Create two counter files to upload, at least a week apart.
now := time.Now()
asof1 := now.Add(-15 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof1, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
asof2 := now.Add(-8 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof2, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"counter"}, nil)
// Enable telemetry as of 10 days ago. This should prevent the first week
// from being uploaded, but not the second.
if err := telemetry.NewDir(telemetryDir).SetModeAsOf(test.mode, now.Add(-10*24*time.Hour)); err != nil {
t.Fatal(err)
}
downloadsBefore := configstore.Downloads()
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
if got := configstore.Downloads() - downloadsBefore; got != test.wantConfigDownloads {
t.Errorf("configstore.Download called: %v, want %v", got, test.wantConfigDownloads)
}
uploads := getUploads()
if gotUploads := len(uploads); gotUploads != test.wantUploads {
t.Fatalf("got %d uploads, want %d", gotUploads, test.wantUploads)
}
})
}
}
func TestRun_DebugLog(t *testing.T) {
// This test verifies that the uploader honors the telemetry mode, as well as
// its asof date.
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewIncProgram(t, "prog1", "counter")
tests := []struct {
name string
setup func(t *testing.T) (telemetryDir string, err error)
wantDebugLogs int
wantUploads int
}{
{
name: "valid",
setup: func(t *testing.T) (string, error) {
userConfigDir := "user config" // test use of space in the name
if runtime.GOOS == "windows" {
userConfigDir = "userconfig" // windows doesn't allow space in dir name
}
telemetryDir := filepath.Join(t.TempDir(), userConfigDir)
return telemetryDir, os.MkdirAll(filepath.Join(telemetryDir, "debug"), 0755)
},
wantDebugLogs: 1,
wantUploads: 1,
},
{
name: "nodebug",
setup: func(t *testing.T) (string, error) {
return t.TempDir(), nil
},
wantUploads: 1,
},
{
name: "not a directory", // debug log setup error shouldn't prevent uploading.
setup: func(t *testing.T) (string, error) {
telemetryDir := t.TempDir()
return telemetryDir, os.WriteFile(filepath.Join(telemetryDir, "debug"), nil, 0666)
},
wantUploads: 1,
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
telemetryDir, err := test.setup(t)
if err != nil {
t.Fatalf("failed to configure the telemetry and debug directories: %v", err)
}
now := time.Now()
asof := now.Add(-8 * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"counter"}, nil)
if err := upload.Run(cfg); err != nil {
t.Fatal(err)
}
uploads := getUploads()
if gotUploads := len(uploads); gotUploads != test.wantUploads {
t.Errorf("got %d uploads, want %d", gotUploads, test.wantUploads)
}
debugLogs := getDebugLogs(t, filepath.Join(telemetryDir, "debug"))
if gotDebugLogs := len(debugLogs); gotDebugLogs != test.wantDebugLogs {
t.Fatalf("got %d debug logs, want %d", gotDebugLogs, test.wantDebugLogs)
}
})
}
}
func TestRun_Concurrent(t *testing.T) {
testenv.SkipIfUnsupportedPlatform(t)
prog := regtest.NewIncProgram(t, "prog1", "counter")
telemetryDir := t.TempDir()
now := time.Now().UTC()
// Seed two weeks of uploads.
// These should *all* be uploaded as they will be neither too old,
// nor too new.
incCount := 0
for i := -21; i < -7; i++ {
incCount++
asof := now.Add(time.Duration(i) * 24 * time.Hour)
if out, err := regtest.RunProgAsOf(t, telemetryDir, asof, prog); err != nil {
t.Fatalf("failed to run program: %s", out)
}
}
cfg, getUploads := runConfig(t, telemetryDir, []string{"counter"}, nil)
cfg.StartTime = now // avoid date skew with counter time
var wg sync.WaitGroup
for i := 0; i < 5; i++ {
i := i
wg.Add(1)
cfg2 := cfg
cfg2.LogWriter = testWriter{fmt.Sprintf("uploader #%d: ", i), t} // use a unique log prefix for this uploader
go func() {
defer wg.Done()
if err := upload.Run(cfg2); err != nil {
t.Errorf("upload.Run #%d failed: %v", i, err)
}
}()
}
wg.Wait()
uploads := getUploads()
uploadedCount := 0
for i, upload := range uploads {
var got telemetry.Report
if err := json.Unmarshal(upload, &got); err != nil {
t.Fatalf("error unmarshalling uploaded report: %v\ncontents:%s", err, upload)
}
if got, want := len(got.Programs), 1; got != want {
t.Fatalf("got %d programs in upload #%d, want %d", got, i, want)
}
uploadedCount += int(got.Programs[0].Counters["counter"])
}
if uploadedCount != incCount {
t.Errorf("uploaded %d total observations, want %d", uploadedCount, incCount)
}
}
func getDebugLogs(t *testing.T, debugDir string) []string {
t.Helper()
if stat, err := os.Stat(debugDir); err != nil || !stat.IsDir() {
return nil
}
files, err := os.ReadDir(debugDir)
if err != nil {
return nil
}
var ret []string
for _, f := range files {
if !strings.HasSuffix(f.Name(), ".log") {
t.Logf("Ignoring %v", f.Name())
continue
}
contents, err := os.ReadFile(filepath.Join(debugDir, f.Name()))
if err != nil || !bytes.Contains(contents, []byte("mode on")) {
t.Logf("Ignoring %v - unreadable or unexpected contents (err: %v)", f.Name(), err)
continue
}
ret = append(ret, f.Name())
}
return ret
}
@@ -0,0 +1,117 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package upload
import (
"bytes"
"net/http"
"os"
"path/filepath"
"regexp"
"strings"
"time"
"golang.org/x/telemetry/internal/telemetry"
)
var (
dateRE = regexp.MustCompile(`(\d\d\d\d-\d\d-\d\d)[.]json$`)
dateFormat = telemetry.DateOnly
// TODO(rfindley): use dateFormat throughout.
)
// uploadReportDate returns the date component of the upload file name, or "" if the
// date was unmatched.
func (u *uploader) uploadReportDate(fname string) time.Time {
match := dateRE.FindStringSubmatch(fname)
if match == nil || len(match) < 2 {
u.logger.Printf("malformed report name: missing date: %q", filepath.Base(fname))
return time.Time{}
}
d, err := time.Parse(dateFormat, match[1])
if err != nil {
u.logger.Printf("malformed report name: bad date: %q", filepath.Base(fname))
return time.Time{}
}
return d
}
func (u *uploader) uploadReport(fname string) {
thisInstant := u.startTime
// TODO(rfindley): use uploadReportDate here, once we've done a gopls release.
// first make sure it is not in the future
today := thisInstant.Format(telemetry.DateOnly)
match := dateRE.FindStringSubmatch(fname)
if match == nil || len(match) < 2 {
u.logger.Printf("Report name %q missing date", filepath.Base(fname))
} else if match[1] > today {
u.logger.Printf("Report date for %q is later than today (%s)", filepath.Base(fname), today)
return // report is in the future, which shouldn't happen
}
buf, err := os.ReadFile(fname)
if err != nil {
u.logger.Printf("%v reading %s", err, fname)
return
}
if u.uploadReportContents(fname, buf) {
// anything left to do?
}
}
// try to upload the report, 'true' if successful
func (u *uploader) uploadReportContents(fname string, buf []byte) bool {
fdate := strings.TrimSuffix(filepath.Base(fname), ".json")
fdate = fdate[len(fdate)-len(telemetry.DateOnly):]
newname := filepath.Join(u.dir.UploadDir(), fdate+".json")
// Lock the upload, to prevent duplicate uploads.
{
lockname := newname + ".lock"
lockfile, err := os.OpenFile(lockname, os.O_CREATE|os.O_EXCL, 0666)
if err != nil {
u.logger.Printf("Failed to acquire lock %s: %v", lockname, err)
return false
}
_ = lockfile.Close()
defer os.Remove(lockname)
}
if _, err := os.Stat(newname); err == nil {
// Another process uploaded but failed to clean up (or hasn't yet cleaned
// up). Ensure that cleanup occurs.
u.logger.Printf("After acquire: report already uploaded")
_ = os.Remove(fname)
return false
}
endpoint := u.uploadServerURL + "/" + fdate
b := bytes.NewReader(buf)
resp, err := http.Post(endpoint, "application/json", b)
if err != nil {
u.logger.Printf("Error upload %s to %s: %v", filepath.Base(fname), endpoint, err)
return false
}
// hope for a 200, remove file on a 4xx, otherwise it will be retried by another process
if resp.StatusCode != 200 {
u.logger.Printf("Failed to upload %s to %s: %s", filepath.Base(fname), endpoint, resp.Status)
if resp.StatusCode >= 400 && resp.StatusCode < 500 {
err := os.Remove(fname)
if err == nil {
u.logger.Printf("Removed local/%s", filepath.Base(fname))
} else {
u.logger.Printf("Error removing local/%s: %v", filepath.Base(fname), err)
}
}
return false
}
// Store a copy of the uploaded report in the uploaded directory.
if err := os.WriteFile(newname, buf, 0644); err == nil {
os.Remove(fname) // if it exists
}
u.logger.Printf("Uploaded %s to %q", fdate+".json", endpoint)
return true
}