10484: Track s3 errors by response code.
[arvados.git] / services / keepstore / s3_volume.go
index ed1161c38d7bf977358de642aed390b1f410e089..48ba95b4887ee03e2b245faa1ab96cd2c868cdff 100644 (file)
@@ -1,17 +1,21 @@
 package main
 
 import (
+       "bytes"
+       "context"
        "encoding/base64"
        "encoding/hex"
        "flag"
        "fmt"
        "io"
+       "io/ioutil"
        "log"
        "net/http"
        "os"
        "regexp"
        "strings"
        "sync"
+       "sync/atomic"
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
@@ -145,11 +149,28 @@ type S3Volume struct {
        ReadOnly           bool
        UnsafeDelete       bool
 
-       bucket *s3.Bucket
+       bucket      *s3.Bucket
+       bucketStats bucketStats
+       volumeStats ioStats
 
        startOnce sync.Once
 }
 
+type bucketStats struct {
+       Errors   uint64
+       Ops      uint64
+       GetOps   uint64
+       PutOps   uint64
+       HeadOps  uint64
+       DelOps   uint64
+       InBytes  uint64
+       OutBytes uint64
+
+       ErrorCodes map[string]uint64 `json:",omitempty"`
+
+       lock sync.Mutex
+}
+
 // Examples implements VolumeWithExamples.
 func (*S3Volume) Examples() []Volume {
        return []Volume{
@@ -234,19 +255,46 @@ func (v *S3Volume) Start() error {
        return nil
 }
 
+func (v *S3Volume) getReaderWithContext(ctx context.Context, loc string) (rdr io.ReadCloser, err error) {
+       ready := make(chan bool)
+       go func() {
+               rdr, err = v.getReader(loc)
+               close(ready)
+       }()
+       select {
+       case <-ready:
+               return
+       case <-ctx.Done():
+               theConfig.debugLogf("s3: abandoning getReader(): %s", ctx.Err())
+               go func() {
+                       <-ready
+                       if err == nil {
+                               rdr.Close()
+                       }
+               }()
+               return nil, ctx.Err()
+       }
+}
+
 // getReader wraps (Bucket)GetReader.
 //
 // In situations where (Bucket)GetReader would fail because the block
 // disappeared in a Trash race, getReader calls fixRace to recover the
 // data, and tries again.
 func (v *S3Volume) getReader(loc string) (rdr io.ReadCloser, err error) {
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.GetOps)
        rdr, err = v.bucket.GetReader(loc)
        err = v.translateError(err)
-       if err == nil || !os.IsNotExist(err) {
+       if err == nil {
+               rdr = NewCountingReader(rdr, v.tickInBytes)
+               return
+       } else if !os.IsNotExist(v.tickErr(err)) {
                return
        }
+
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        _, err = v.bucket.Head("recent/"+loc, nil)
-       err = v.translateError(err)
+       err = v.translateError(v.tickErr(err))
        if err != nil {
                // If we can't read recent/X, there's no point in
                // trying fixRace. Give up.
@@ -256,60 +304,124 @@ func (v *S3Volume) getReader(loc string) (rdr io.ReadCloser, err error) {
                err = os.ErrNotExist
                return
        }
+
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.GetOps)
        rdr, err = v.bucket.GetReader(loc)
        if err != nil {
                log.Printf("warning: reading %s after successful fixRace: %s", loc, err)
-               err = v.translateError(err)
+               err = v.translateError(v.tickErr(err))
        }
+       rdr = NewCountingReader(rdr, v.tickInBytes)
        return
 }
 
 // Get a block: copy the block data into buf, and return the number of
 // bytes copied.
-func (v *S3Volume) Get(loc string, buf []byte) (int, error) {
-       rdr, err := v.getReader(loc)
+func (v *S3Volume) Get(ctx context.Context, loc string, buf []byte) (int, error) {
+       rdr, err := v.getReaderWithContext(ctx, loc)
        if err != nil {
                return 0, err
        }
-       defer rdr.Close()
-       n, err := io.ReadFull(rdr, buf)
-       switch err {
-       case nil, io.EOF, io.ErrUnexpectedEOF:
-               return n, nil
-       default:
-               return 0, v.translateError(err)
+
+       var n int
+       ready := make(chan bool)
+       go func() {
+               defer close(ready)
+
+               defer rdr.Close()
+               n, err = io.ReadFull(rdr, buf)
+
+               switch err {
+               case nil, io.EOF, io.ErrUnexpectedEOF:
+                       err = nil
+               default:
+                       err = v.translateError(err)
+               }
+       }()
+       select {
+       case <-ctx.Done():
+               theConfig.debugLogf("s3: interrupting ReadFull() with Close() because %s", ctx.Err())
+               rdr.Close()
+               // Must wait for ReadFull to return, to ensure it
+               // doesn't write to buf after we return.
+               theConfig.debugLogf("s3: waiting for ReadFull() to fail")
+               <-ready
+               return 0, ctx.Err()
+       case <-ready:
+               return n, err
        }
 }
 
 // Compare the given data with the stored data.
-func (v *S3Volume) Compare(loc string, expect []byte) error {
-       rdr, err := v.getReader(loc)
+func (v *S3Volume) Compare(ctx context.Context, loc string, expect []byte) error {
+       rdr, err := v.getReaderWithContext(ctx, loc)
        if err != nil {
                return err
        }
        defer rdr.Close()
-       return v.translateError(compareReaderWithBuf(rdr, expect, loc[:32]))
+       return v.translateError(compareReaderWithBuf(ctx, rdr, expect, loc[:32]))
 }
 
 // Put writes a block.
-func (v *S3Volume) Put(loc string, block []byte) error {
+func (v *S3Volume) Put(ctx context.Context, loc string, block []byte) error {
        if v.ReadOnly {
                return MethodDisabledError
        }
        var opts s3.Options
-       if len(block) > 0 {
+       size := len(block)
+       if size > 0 {
                md5, err := hex.DecodeString(loc)
                if err != nil {
                        return err
                }
                opts.ContentMD5 = base64.StdEncoding.EncodeToString(md5)
        }
-       err := v.bucket.Put(loc, block, "application/octet-stream", s3ACL, opts)
-       if err != nil {
+
+       // Send the block data through a pipe, so that (if we need to)
+       // we can close the pipe early and abandon our PutReader()
+       // goroutine, without worrying about PutReader() accessing our
+       // block buffer after we release it.
+       bufr, bufw := io.Pipe()
+       go func() {
+               io.Copy(bufw, bytes.NewReader(block))
+               bufw.Close()
+       }()
+
+       var err error
+       ready := make(chan bool)
+       go func() {
+               defer func() {
+                       if ctx.Err() != nil {
+                               theConfig.debugLogf("%s: abandoned PutReader goroutine finished with err: %s", v, err)
+                       }
+               }()
+               defer close(ready)
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
+               rdr := NewCountingReader(bufr, v.tickOutBytes)
+               err = v.bucket.PutReader(loc, rdr, int64(size), "application/octet-stream", s3ACL, opts)
+               if err != nil {
+                       v.tickErr(err)
+                       return
+               }
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
+               err = v.bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
+               v.tickErr(err)
+       }()
+       select {
+       case <-ctx.Done():
+               theConfig.debugLogf("%s: taking PutReader's input away: %s", v, ctx.Err())
+               // Our pipe might be stuck in Write(), waiting for
+               // io.Copy() to read. If so, un-stick it. This means
+               // PutReader will get corrupt data, but that's OK: the
+               // size and MD5 won't match, so the write will fail.
+               go io.Copy(ioutil.Discard, bufr)
+               // CloseWithError() will return once pending I/O is done.
+               bufw.CloseWithError(ctx.Err())
+               theConfig.debugLogf("%s: abandoning PutReader goroutine", v)
+               return ctx.Err()
+       case <-ready:
                return v.translateError(err)
        }
-       err = v.bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
-       return v.translateError(err)
 }
 
 // Touch sets the timestamp for the given locator to the current time.
@@ -317,38 +429,44 @@ func (v *S3Volume) Touch(loc string) error {
        if v.ReadOnly {
                return MethodDisabledError
        }
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        _, err := v.bucket.Head(loc, nil)
-       err = v.translateError(err)
+       err = v.translateError(v.tickErr(err))
        if os.IsNotExist(err) && v.fixRace(loc) {
                // The data object got trashed in a race, but fixRace
                // rescued it.
        } else if err != nil {
                return err
        }
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
        err = v.bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
-       return v.translateError(err)
+       return v.translateError(v.tickErr(err))
 }
 
 // Mtime returns the stored timestamp for the given locator.
 func (v *S3Volume) Mtime(loc string) (time.Time, error) {
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        _, err := v.bucket.Head(loc, nil)
        if err != nil {
-               return zeroTime, v.translateError(err)
+               return zeroTime, v.translateError(v.tickErr(err))
        }
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        resp, err := v.bucket.Head("recent/"+loc, nil)
-       err = v.translateError(err)
+       err = v.translateError(v.tickErr(err))
        if os.IsNotExist(err) {
                // The data object X exists, but recent/X is missing.
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
                err = v.bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
                if err != nil {
                        log.Printf("error: creating %q: %s", "recent/"+loc, err)
-                       return zeroTime, v.translateError(err)
+                       return zeroTime, v.translateError(v.tickErr(err))
                }
                log.Printf("info: created %q to migrate existing block to new storage scheme", "recent/"+loc)
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
                resp, err = v.bucket.Head("recent/"+loc, nil)
                if err != nil {
                        log.Printf("error: created %q but HEAD failed: %s", "recent/"+loc, err)
-                       return zeroTime, v.translateError(err)
+                       return zeroTime, v.translateError(v.tickErr(err))
                }
        } else if err != nil {
                // HEAD recent/X failed for some other reason.
@@ -428,7 +546,8 @@ func (v *S3Volume) Trash(loc string) error {
                if !s3UnsafeDelete {
                        return ErrS3TrashDisabled
                }
-               return v.bucket.Del(loc)
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.DelOps)
+               return v.translateError(v.tickErr(v.bucket.Del(loc)))
        }
        err := v.checkRaceWindow(loc)
        if err != nil {
@@ -438,14 +557,16 @@ func (v *S3Volume) Trash(loc string) error {
        if err != nil {
                return err
        }
-       return v.translateError(v.bucket.Del(loc))
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.DelOps)
+       return v.translateError(v.tickErr(v.bucket.Del(loc)))
 }
 
 // checkRaceWindow returns a non-nil error if trash/loc is, or might
 // be, in the race window (i.e., it's not safe to trash loc).
 func (v *S3Volume) checkRaceWindow(loc string) error {
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        resp, err := v.bucket.Head("trash/"+loc, nil)
-       err = v.translateError(err)
+       err = v.translateError(v.tickErr(err))
        if os.IsNotExist(err) {
                // OK, trash/X doesn't exist so we're not in the race
                // window
@@ -478,11 +599,12 @@ func (v *S3Volume) checkRaceWindow(loc string) error {
 // (PutCopy returns 200 OK if the request was received, even if the
 // copy failed).
 func (v *S3Volume) safeCopy(dst, src string) error {
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
        resp, err := v.bucket.PutCopy(dst, s3ACL, s3.CopyOptions{
                ContentType:       "application/octet-stream",
                MetadataDirective: "REPLACE",
        }, v.bucket.Name+"/"+src)
-       err = v.translateError(err)
+       err = v.translateError(v.tickErr(err))
        if err != nil {
                return err
        }
@@ -516,8 +638,9 @@ func (v *S3Volume) Untrash(loc string) error {
        if err != nil {
                return err
        }
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.PutOps)
        err = v.bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
-       return v.translateError(err)
+       return v.translateError(v.tickErr(err))
 }
 
 // Status returns a *VolumeStatus representing the current in-use
@@ -531,9 +654,14 @@ func (v *S3Volume) Status() *VolumeStatus {
        }
 }
 
+// IOStatus implements InternalStatser.
+func (v *S3Volume) InternalStats() interface{} {
+       return &v.bucketStats
+}
+
 // String implements fmt.Stringer.
 func (v *S3Volume) String() string {
-       return fmt.Sprintf("s3-bucket:%+q", v.bucket.Name)
+       return fmt.Sprintf("s3-bucket:%+q", v.Bucket)
 }
 
 // Writable returns false if all future Put, Mtime, and Delete calls
@@ -559,9 +687,10 @@ func (v *S3Volume) isKeepBlock(s string) bool {
 // there was a race between Put and Trash, fixRace recovers from the
 // race by Untrashing the block.
 func (v *S3Volume) fixRace(loc string) bool {
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        trash, err := v.bucket.Head("trash/"+loc, nil)
        if err != nil {
-               if !os.IsNotExist(v.translateError(err)) {
+               if !os.IsNotExist(v.translateError(v.tickErr(err))) {
                        log.Printf("error: fixRace: HEAD %q: %s", "trash/"+loc, err)
                }
                return false
@@ -572,8 +701,10 @@ func (v *S3Volume) fixRace(loc string) bool {
                return false
        }
 
+       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
        recent, err := v.bucket.Head("recent/"+loc, nil)
        if err != nil {
+               v.tickErr(err)
                log.Printf("error: fixRace: HEAD %q: %s", "recent/"+loc, err)
                return false
        }
@@ -641,8 +772,9 @@ func (v *S3Volume) EmptyTrash() {
                        log.Printf("warning: %s: EmptyTrash: %q: parse %q: %s", v, trash.Key, trash.LastModified, err)
                        continue
                }
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
                recent, err := v.bucket.Head("recent/"+loc, nil)
-               if err != nil && os.IsNotExist(v.translateError(err)) {
+               if err != nil && os.IsNotExist(v.translateError(v.tickErr(err))) {
                        log.Printf("warning: %s: EmptyTrash: found trash marker %q but no %q (%s); calling Untrash", v, trash.Key, "recent/"+loc, err)
                        err = v.Untrash(loc)
                        if err != nil {
@@ -672,7 +804,10 @@ func (v *S3Volume) EmptyTrash() {
                                v.fixRace(loc)
                                v.Touch(loc)
                                continue
-                       } else if _, err := v.bucket.Head(loc, nil); os.IsNotExist(err) {
+                       }
+                       v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
+                       _, err := v.bucket.Head(loc, nil)
+                       if os.IsNotExist(v.tickErr(err)) {
                                log.Printf("notice: %s: EmptyTrash: detected recent race for %q, calling fixRace", v, loc)
                                v.fixRace(loc)
                                continue
@@ -684,18 +819,23 @@ func (v *S3Volume) EmptyTrash() {
                if startT.Sub(trashT) < theConfig.TrashLifetime.Duration() {
                        continue
                }
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.DelOps)
                err = v.bucket.Del(trash.Key)
                if err != nil {
+                       v.tickErr(err)
                        log.Printf("warning: %s: EmptyTrash: deleting %q: %s", v, trash.Key, err)
                        continue
                }
                bytesDeleted += trash.Size
                blocksDeleted++
 
+               v.tick(&v.bucketStats.Ops, &v.bucketStats.HeadOps)
                _, err = v.bucket.Head(loc, nil)
-               if os.IsNotExist(err) {
+               if os.IsNotExist(v.tickErr(err)) {
+                       v.tick(&v.bucketStats.Ops, &v.bucketStats.DelOps)
                        err = v.bucket.Del("recent/" + loc)
                        if err != nil {
+                               v.tickErr(err)
                                log.Printf("warning: %s: EmptyTrash: deleting %q: %s", v, "recent/"+loc, err)
                        }
                } else if err != nil {
@@ -708,6 +848,37 @@ func (v *S3Volume) EmptyTrash() {
        log.Printf("EmptyTrash stats for %v: Deleted %v bytes in %v blocks. Remaining in trash: %v bytes in %v blocks.", v.String(), bytesDeleted, blocksDeleted, bytesInTrash-bytesDeleted, blocksInTrash-blocksDeleted)
 }
 
+func (v *S3Volume) tick(counters ...*uint64) {
+       for _, counter := range counters {
+               atomic.AddUint64(counter, 1)
+       }
+}
+
+func (v *S3Volume) tickErr(err error) error {
+       if err == nil {
+               return nil
+       }
+       atomic.AddUint64(&v.bucketStats.Errors, 1)
+       if err, ok := err.(*s3.Error); ok {
+               errStr := fmt.Sprintf("%d %s", err.StatusCode, err.Code)
+               v.bucketStats.lock.Lock()
+               if v.bucketStats.ErrorCodes == nil {
+                       v.bucketStats.ErrorCodes = make(map[string]uint64)
+               }
+               v.bucketStats.ErrorCodes[errStr]++
+               v.bucketStats.lock.Unlock()
+       }
+       return err
+}
+
+func (v *S3Volume) tickInBytes(n uint64) {
+       atomic.AddUint64(&v.bucketStats.InBytes, n)
+}
+
+func (v *S3Volume) tickOutBytes(n uint64) {
+       atomic.AddUint64(&v.bucketStats.OutBytes, n)
+}
+
 type s3Lister struct {
        Bucket     *s3.Bucket
        Prefix     string