From 2cc3480fa1a370a35edb2a49f70213a764ccf013 Mon Sep 17 00:00:00 2001 From: Michael Vogt Date: Thu, 7 Jun 2018 21:41:40 +0200 Subject: [PATCH] errtracker: do not send duplicated reports (#5263) * errtracker: do not send duplicated reports This will add a 7 day history for the error tracker. It will not send the same report over and over again but instead skip reports that were already send. Reviews asked for locking and this means we need something better than the hand implmented DB. Switch to boltdb because we already use it for the advisor interface. --- dirs/dirs.go | 4 ++ errtracker/errtracker.go | 124 +++++++++++++++++++++++++++++++++- errtracker/errtracker_test.go | 56 ++++++++++++++- errtracker/export_test.go | 5 ++ 4 files changed, 185 insertions(+), 4 deletions(-) diff --git a/dirs/dirs.go b/dirs/dirs.go index bd748c2cfdc..df4c028083c 100644 --- a/dirs/dirs.go +++ b/dirs/dirs.go @@ -104,6 +104,8 @@ var ( FreezerCgroupDir string SnapshotsDir string + + ErrtrackerDbDir string ) const ( @@ -261,4 +263,6 @@ func SetRootDir(rootdir string) { FreezerCgroupDir = filepath.Join(rootdir, "/sys/fs/cgroup/freezer/") SnapshotsDir = filepath.Join(rootdir, snappyDir, "snapshots") + + ErrtrackerDbDir = filepath.Join(rootdir, snappyDir, "errtracker.db") } diff --git a/errtracker/errtracker.go b/errtracker/errtracker.go index 168f4b525a8..86f19f9f75d 100644 --- a/errtracker/errtracker.go +++ b/errtracker/errtracker.go @@ -24,6 +24,7 @@ import ( "crypto/md5" "crypto/sha512" "fmt" + "io" "io/ioutil" "net/http" "os" @@ -32,6 +33,7 @@ import ( "strings" "time" + "github.com/snapcore/bolt" "gopkg.in/mgo.v2/bson" "github.com/snapcore/snapd/arch" @@ -67,6 +69,106 @@ var ( timeNow = time.Now ) +type reportsDB struct { + db *bolt.DB + + // map of hash(dupsig) -> time-of-report + reportedBucket *bolt.Bucket + + // time until an error report is cleaned from the database, + // usually 7 days + cleanupTime time.Duration +} + +func hashString(s string) string { + h := sha512.New() + io.WriteString(h, s) + return fmt.Sprintf("%x", h.Sum(nil)) +} + +func newReportsDB(fname string) (*reportsDB, error) { + if err := os.MkdirAll(filepath.Dir(fname), 0755); err != nil { + return nil, err + } + bdb, err := bolt.Open(fname, 0600, &bolt.Options{ + Timeout: 10 * time.Second, + }) + if err != nil { + return nil, err + } + bdb.Update(func(tx *bolt.Tx) error { + _, err := tx.CreateBucketIfNotExists([]byte("reported")) + if err != nil { + return fmt.Errorf("create bucket: %s", err) + } + return nil + }) + + db := &reportsDB{ + db: bdb, + cleanupTime: time.Duration(7 * 24 * time.Hour), + } + + return db, nil +} + +func (db *reportsDB) Close() error { + return db.db.Close() +} + +// AlreadyReported returns true if an identical report has been sent recently +func (db *reportsDB) AlreadyReported(dupSig string) bool { + // robustness + if db == nil { + return false + } + var reported []byte + db.db.View(func(tx *bolt.Tx) error { + b := tx.Bucket([]byte("reported")) + reported = b.Get([]byte(hashString(dupSig))) + return nil + }) + return len(reported) > 0 +} + +func (db *reportsDB) cleanupOldRecords() { + db.db.Update(func(tx *bolt.Tx) error { + now := time.Now() + + b := tx.Bucket([]byte("reported")) + b.ForEach(func(dupSigHash, reportTime []byte) error { + var t time.Time + t.UnmarshalBinary(reportTime) + + if now.After(t.Add(db.cleanupTime)) { + if err := b.Delete(dupSigHash); err != nil { + return err + } + } + return nil + }) + return nil + }) +} + +// MarkReported marks an error report as reported to the error tracker +func (db *reportsDB) MarkReported(dupSig string) error { + // robustness + if db == nil { + return fmt.Errorf("cannot mark error report as reported with an uninitialized reports database") + } + db.cleanupOldRecords() + + return db.db.Update(func(tx *bolt.Tx) error { + b := tx.Bucket([]byte("reported")) + tb, err := time.Now().MarshalBinary() + if err != nil { + return err + } + return b.Put([]byte(hashString(dupSig)), tb) + }) +} + func whoopsieEnabled() bool { cmd := exec.Command("systemctl", "is-enabled", "whoopsie.service") output, _ := cmd.CombinedOutput() @@ -133,7 +235,27 @@ func Report(snap, errMsg, dupSig string, extra map[string]string) (string, error extra["ProblemType"] = "Snap" extra["Snap"] = snap - return report(errMsg, dupSig, extra) + // check if we haven't already reported this error + db, err := newReportsDB(dirs.ErrtrackerDbDir) + if err != nil { + logger.Noticef("cannot open error reports database: %v", err) + } + defer db.Close() + + if db.AlreadyReported(dupSig) { + return "already-reported", nil + } + + // do the actual report + oopsID, err := report(errMsg, dupSig, extra) + if err != nil { + return "", err + } + if err := db.MarkReported(dupSig); err != nil { + logger.Noticef("cannot mark %s as reported", oopsID) + } + + return oopsID, nil } // ReportRepair reports an error with the given repair assertion script diff --git a/errtracker/errtracker_test.go b/errtracker/errtracker_test.go index 9cd38eb545c..92f0a73ad20 100644 --- a/errtracker/errtracker_test.go +++ b/errtracker/errtracker_test.go @@ -193,7 +193,7 @@ func (s *ErrtrackerTestSuite) TestReport(c *C) { case 1: c.Check(r.Method, Equals, "POST") c.Check(r.URL.Path, Matches, identifier) - fmt.Fprintf(w, "c14388aa-f78d-11e6-8df0-fa163eaf9b83 OOPSID") + fmt.Fprintf(w, "xxxxx-f78d-11e6-8df0-fa163eaf9b83 OOPSID") default: c.Fatalf("expected one request, got %d", n+1) } @@ -215,10 +215,19 @@ func (s *ErrtrackerTestSuite) TestReport(c *C) { c.Check(id, Equals, "c14388aa-f78d-11e6-8df0-fa163eaf9b83 OOPSID") c.Check(n, Equals, 1) - // run again, verify identifier is unchanged + // run again with the *same* dupSig and verify that it won't send + // that again + id, err = errtracker.Report("some-snap", "failed to do stuff", "[failed to do stuff]", map[string]string{ + "Channel": "beta", + }) + c.Check(err, IsNil) + c.Check(id, Equals, "already-reported") + c.Check(n, Equals, 1) + + // run again with different data, verify identifier is unchanged id, err = errtracker.Report("some-other-snap", "failed to do more stuff", "[failed to do more stuff]", nil) c.Check(err, IsNil) - c.Check(id, Equals, "c14388aa-f78d-11e6-8df0-fa163eaf9b83 OOPSID") + c.Check(id, Equals, "xxxxx-f78d-11e6-8df0-fa163eaf9b83 OOPSID") c.Check(n, Equals, 2) } @@ -492,3 +501,44 @@ func (s *ErrtrackerTestSuite) TestEnviron(c *C) { "XDG_RUNTIME_DIR=", }) } + +func (s *ErrtrackerTestSuite) TestReportsDB(c *C) { + db, err := errtracker.NewReportsDB(filepath.Join(s.tmpdir, "foo.db")) + c.Assert(err, IsNil) + + c.Check(db.AlreadyReported("some-dup-sig"), Equals, false) + + err = db.MarkReported("some-dup-sig") + c.Check(err, IsNil) + + c.Check(db.AlreadyReported("some-dup-sig"), Equals, true) + c.Check(db.AlreadyReported("other-dup-sig"), Equals, false) +} + +func (s *ErrtrackerTestSuite) TestReportsDBCleanup(c *C) { + db, err := errtracker.NewReportsDB(filepath.Join(s.tmpdir, "foo.db")) + c.Assert(err, IsNil) + + errtracker.SetReportDBCleanupTime(db, 1*time.Millisecond) + + err = db.MarkReported("some-dup-sig") + c.Check(err, IsNil) + + time.Sleep(10 * time.Millisecond) + err = db.MarkReported("other-dup-sig") + c.Check(err, IsNil) + + // this one got cleaned out + c.Check(db.AlreadyReported("some-dup-sig"), Equals, false) + // this one is still fresh + c.Check(db.AlreadyReported("other-dup-sig"), Equals, true) +} + +func (s *ErrtrackerTestSuite) TestReportsDBnilDoesNotCrash(c *C) { + db, err := errtracker.NewReportsDB("/proc/1/environ") + c.Assert(err, NotNil) + c.Check(db, IsNil) + + c.Check(db.AlreadyReported("dupSig"), Equals, false) + c.Check(db.MarkReported("dupSig"), ErrorMatches, "cannot mark error report as reported with an uninitialized reports database") +} diff --git a/errtracker/export_test.go b/errtracker/export_test.go index a17177a46ec..ff3ac0b60a1 100644 --- a/errtracker/export_test.go +++ b/errtracker/export_test.go @@ -118,4 +118,9 @@ var ( JournalError = journalError ProcCpuinfoMinimal = procCpuinfoMinimal Environ = environ + NewReportsDB = newReportsDB ) + +func SetReportDBCleanupTime(db *reportsDB, d time.Duration) { + db.cleanupTime = d +}