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

@@ -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")
 }

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

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=<set>",
 	})
 }
+
+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")
+}

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
+}