X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/224f384d411bb1b4cccc7165c55bb64fd5c695ad..e99f026d040c6020dfcc51c6d988cf18d325a530:/services/keepstore/s3_volume.go

diff --git a/services/keepstore/s3_volume.go b/services/keepstore/s3_volume.go
index 1a2a47b0df..fdc2ed56ad 100644
--- a/services/keepstore/s3_volume.go
+++ b/services/keepstore/s3_volume.go
@@ -1,36 +1,118 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
 package main
 
 import (
+	"bufio"
+	"bytes"
+	"context"
+	"crypto/sha256"
 	"encoding/base64"
 	"encoding/hex"
-	"flag"
+	"encoding/json"
+	"errors"
 	"fmt"
 	"io"
-	"log"
+	"io/ioutil"
 	"net/http"
 	"os"
 	"regexp"
 	"strings"
+	"sync"
+	"sync/atomic"
 	"time"
 
+	"git.arvados.org/arvados.git/sdk/go/arvados"
 	"github.com/AdRoll/goamz/aws"
 	"github.com/AdRoll/goamz/s3"
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/sirupsen/logrus"
+)
+
+func init() {
+	driver["S3"] = chooseS3VolumeDriver
+}
+
+func newS3Volume(cluster *arvados.Cluster, volume arvados.Volume, logger logrus.FieldLogger, metrics *volumeMetricsVecs) (Volume, error) {
+	v := &S3Volume{cluster: cluster, volume: volume, metrics: metrics}
+	err := json.Unmarshal(volume.DriverParameters, v)
+	if err != nil {
+		return nil, err
+	}
+	v.logger = logger.WithField("Volume", v.String())
+	return v, v.check()
+}
+
+func (v *S3Volume) check() error {
+	if v.Bucket == "" {
+		return errors.New("DriverParameters: Bucket must be provided")
+	}
+	if v.IndexPageSize == 0 {
+		v.IndexPageSize = 1000
+	}
+	if v.RaceWindow < 0 {
+		return errors.New("DriverParameters: RaceWindow must not be negative")
+	}
+
+	var ok bool
+	v.region, ok = aws.Regions[v.Region]
+	if v.Endpoint == "" {
+		if !ok {
+			return fmt.Errorf("unrecognized region %+q; try specifying endpoint instead", v.Region)
+		}
+	} else if ok {
+		return fmt.Errorf("refusing to use AWS region name %+q with endpoint %+q; "+
+			"specify empty endpoint or use a different region name", v.Region, v.Endpoint)
+	} else {
+		v.region = aws.Region{
+			Name:                 v.Region,
+			S3Endpoint:           v.Endpoint,
+			S3LocationConstraint: v.LocationConstraint,
+		}
+	}
+
+	// Zero timeouts mean "wait forever", which is a bad
+	// default. Default to long timeouts instead.
+	if v.ConnectTimeout == 0 {
+		v.ConnectTimeout = s3DefaultConnectTimeout
+	}
+	if v.ReadTimeout == 0 {
+		v.ReadTimeout = s3DefaultReadTimeout
+	}
+
+	v.bucket = &s3bucket{
+		bucket: &s3.Bucket{
+			S3:   v.newS3Client(),
+			Name: v.Bucket,
+		},
+	}
+	// Set up prometheus metrics
+	lbls := prometheus.Labels{"device_id": v.GetDeviceID()}
+	v.bucket.stats.opsCounters, v.bucket.stats.errCounters, v.bucket.stats.ioBytes = v.metrics.getCounterVecsFor(lbls)
+
+	err := v.bootstrapIAMCredentials()
+	if err != nil {
+		return fmt.Errorf("error getting IAM credentials: %s", err)
+	}
+
+	return nil
+}
+
+const (
+	s3DefaultReadTimeout    = arvados.Duration(10 * time.Minute)
+	s3DefaultConnectTimeout = arvados.Duration(time.Minute)
 )
 
 var (
 	// ErrS3TrashDisabled is returned by Trash if that operation
 	// is impossible with the current config.
-	ErrS3TrashDisabled = fmt.Errorf("trash function is disabled because -trash-lifetime=0 and -s3-unsafe-delete=false")
-
-	s3AccessKeyFile string
-	s3SecretKeyFile string
-	s3RegionName    string
-	s3Endpoint      string
-	s3Replication   int
-	s3UnsafeDelete  bool
-	s3RaceWindow    time.Duration
+	ErrS3TrashDisabled = fmt.Errorf("trash function is disabled because Collections.BlobTrashLifetime=0 and DriverParameters.UnsafeDelete=false")
 
 	s3ACL = s3.Private
+
+	zeroTime time.Time
 )
 
 const (
@@ -38,130 +120,186 @@ const (
 	nearlyRFC1123 = "Mon, 2 Jan 2006 15:04:05 GMT"
 )
 
-type s3VolumeAdder struct {
-	*volumeSet
+func s3regions() (okList []string) {
+	for r := range aws.Regions {
+		okList = append(okList, r)
+	}
+	return
 }
 
-func (s *s3VolumeAdder) Set(bucketName string) error {
-	if bucketName == "" {
-		return fmt.Errorf("no container name given")
-	}
-	if s3AccessKeyFile == "" || s3SecretKeyFile == "" {
-		return fmt.Errorf("-s3-access-key-file and -s3-secret-key-file arguments must given before -s3-bucket-volume")
-	}
-	region, ok := aws.Regions[s3RegionName]
-	if s3Endpoint == "" {
-		if !ok {
-			return fmt.Errorf("unrecognized region %+q; try specifying -s3-endpoint instead", s3RegionName)
-		}
-	} else {
-		if ok {
-			return fmt.Errorf("refusing to use AWS region name %+q with endpoint %+q; "+
-				"specify empty endpoint (\"-s3-endpoint=\") or use a different region name", s3RegionName, s3Endpoint)
-		}
-		region = aws.Region{
-			Name:       s3RegionName,
-			S3Endpoint: s3Endpoint,
+// S3Volume implements Volume using an S3 bucket.
+type S3Volume struct {
+	arvados.S3VolumeDriverParameters
+	AuthToken      string    // populated automatically when IAMRole is used
+	AuthExpiration time.Time // populated automatically when IAMRole is used
+
+	cluster   *arvados.Cluster
+	volume    arvados.Volume
+	logger    logrus.FieldLogger
+	metrics   *volumeMetricsVecs
+	bucket    *s3bucket
+	region    aws.Region
+	startOnce sync.Once
+}
+
+// GetDeviceID returns a globally unique ID for the storage bucket.
+func (v *S3Volume) GetDeviceID() string {
+	return "s3://" + v.Endpoint + "/" + v.Bucket
+}
+
+func (v *S3Volume) bootstrapIAMCredentials() error {
+	if v.AccessKeyID != "" || v.SecretAccessKey != "" {
+		if v.IAMRole != "" {
+			return errors.New("invalid DriverParameters: AccessKeyID and SecretAccessKey must be blank if IAMRole is specified")
 		}
+		return nil
 	}
-	var err error
-	var auth aws.Auth
-	auth.AccessKey, err = readKeyFromFile(s3AccessKeyFile)
-	if err != nil {
-		return err
-	}
-	auth.SecretKey, err = readKeyFromFile(s3SecretKeyFile)
+	ttl, err := v.updateIAMCredentials()
 	if err != nil {
 		return err
 	}
-	if flagSerializeIO {
-		log.Print("Notice: -serialize is not supported by s3-bucket volumes.")
-	}
-	v := NewS3Volume(auth, region, bucketName, s3RaceWindow, flagReadonly, s3Replication)
-	if err := v.Check(); err != nil {
-		return err
-	}
-	*s.volumeSet = append(*s.volumeSet, v)
+	go func() {
+		for {
+			time.Sleep(ttl)
+			ttl, err = v.updateIAMCredentials()
+			if err != nil {
+				v.logger.WithError(err).Warnf("failed to update credentials for IAM role %q", v.IAMRole)
+				ttl = time.Second
+			} else if ttl < time.Second {
+				v.logger.WithField("TTL", ttl).Warnf("received stale credentials for IAM role %q", v.IAMRole)
+				ttl = time.Second
+			}
+		}
+	}()
 	return nil
 }
 
-func s3regions() (okList []string) {
-	for r := range aws.Regions {
-		okList = append(okList, r)
+func (v *S3Volume) newS3Client() *s3.S3 {
+	auth := aws.NewAuth(v.AccessKeyID, v.SecretAccessKey, v.AuthToken, v.AuthExpiration)
+	client := s3.New(*auth, v.region)
+	if !v.V2Signature {
+		client.Signature = aws.V4Signature
 	}
-	return
+	client.ConnectTimeout = time.Duration(v.ConnectTimeout)
+	client.ReadTimeout = time.Duration(v.ReadTimeout)
+	return client
 }
 
-func init() {
-	flag.Var(&s3VolumeAdder{&volumes},
-		"s3-bucket-volume",
-		"Use the given bucket as a storage volume. Can be given multiple times.")
-	flag.StringVar(
-		&s3RegionName,
-		"s3-region",
-		"",
-		fmt.Sprintf("AWS region used for subsequent -s3-bucket-volume arguments. Allowed values are %+q.", s3regions()))
-	flag.StringVar(
-		&s3Endpoint,
-		"s3-endpoint",
-		"",
-		"Endpoint URL used for subsequent -s3-bucket-volume arguments. If blank, use the AWS endpoint corresponding to the -s3-region argument. For Google Storage, use \"https://storage.googleapis.com\".")
-	flag.StringVar(
-		&s3AccessKeyFile,
-		"s3-access-key-file",
-		"",
-		"File containing the access key used for subsequent -s3-bucket-volume arguments.")
-	flag.StringVar(
-		&s3SecretKeyFile,
-		"s3-secret-key-file",
-		"",
-		"File containing the secret key used for subsequent -s3-bucket-volume arguments.")
-	flag.DurationVar(
-		&s3RaceWindow,
-		"s3-race-window",
-		24*time.Hour,
-		"Maximum eventual consistency latency for subsequent -s3-bucket-volume arguments.")
-	flag.IntVar(
-		&s3Replication,
-		"s3-replication",
-		2,
-		"Replication level reported to clients for subsequent -s3-bucket-volume arguments.")
-	flag.BoolVar(
-		&s3UnsafeDelete,
-		"s3-unsafe-delete",
-		false,
-		"EXPERIMENTAL. Enable deletion (garbage collection), even though there are known race conditions that can cause data loss.")
+// returned by AWS metadata endpoint .../security-credentials/${rolename}
+type iamCredentials struct {
+	Code            string
+	LastUpdated     time.Time
+	Type            string
+	AccessKeyID     string
+	SecretAccessKey string
+	Token           string
+	Expiration      time.Time
 }
 
-// S3Volume implements Volume using an S3 bucket.
-type S3Volume struct {
-	*s3.Bucket
-	raceWindow    time.Duration
-	readonly      bool
-	replication   int
-	indexPageSize int
-}
-
-// NewS3Volume returns a new S3Volume using the given auth, region,
-// and bucket name. The replication argument specifies the replication
-// level to report when writing data.
-func NewS3Volume(auth aws.Auth, region aws.Region, bucket string, raceWindow time.Duration, readonly bool, replication int) *S3Volume {
-	return &S3Volume{
-		Bucket: &s3.Bucket{
-			S3:   s3.New(auth, region),
-			Name: bucket,
-		},
-		raceWindow:    raceWindow,
-		readonly:      readonly,
-		replication:   replication,
-		indexPageSize: 1000,
+// Returns TTL of updated credentials, i.e., time to sleep until next
+// update.
+func (v *S3Volume) updateIAMCredentials() (time.Duration, error) {
+	ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(time.Minute))
+	defer cancel()
+
+	metadataBaseURL := "http://169.254.169.254/latest/meta-data/iam/security-credentials/"
+
+	var url string
+	if strings.Contains(v.IAMRole, "://") {
+		// Configuration provides complete URL (used by tests)
+		url = v.IAMRole
+	} else if v.IAMRole != "" {
+		// Configuration provides IAM role name and we use the
+		// AWS metadata endpoint
+		url = metadataBaseURL + v.IAMRole
+	} else {
+		url = metadataBaseURL
+		v.logger.WithField("URL", url).Debug("looking up IAM role name")
+		req, err := http.NewRequest("GET", url, nil)
+		if err != nil {
+			return 0, fmt.Errorf("error setting up request %s: %s", url, err)
+		}
+		resp, err := http.DefaultClient.Do(req.WithContext(ctx))
+		if err != nil {
+			return 0, fmt.Errorf("error getting %s: %s", url, err)
+		}
+		defer resp.Body.Close()
+		if resp.StatusCode == http.StatusNotFound {
+			return 0, fmt.Errorf("this instance does not have an IAM role assigned -- either assign a role, or configure AccessKeyID and SecretAccessKey explicitly in DriverParameters (error getting %s: HTTP status %s)", url, resp.Status)
+		} else if resp.StatusCode != http.StatusOK {
+			return 0, fmt.Errorf("error getting %s: HTTP status %s", url, resp.Status)
+		}
+		body := bufio.NewReader(resp.Body)
+		var role string
+		_, err = fmt.Fscanf(body, "%s\n", &role)
+		if err != nil {
+			return 0, fmt.Errorf("error reading response from %s: %s", url, err)
+		}
+		if n, _ := body.Read(make([]byte, 64)); n > 0 {
+			v.logger.Warnf("ignoring additional data returned by metadata endpoint %s after the single role name that we expected", url)
+		}
+		v.logger.WithField("Role", role).Debug("looked up IAM role name")
+		url = url + role
 	}
+
+	v.logger.WithField("URL", url).Debug("getting credentials")
+	req, err := http.NewRequest("GET", url, nil)
+	if err != nil {
+		return 0, fmt.Errorf("error setting up request %s: %s", url, err)
+	}
+	resp, err := http.DefaultClient.Do(req.WithContext(ctx))
+	if err != nil {
+		return 0, fmt.Errorf("error getting %s: %s", url, err)
+	}
+	defer resp.Body.Close()
+	if resp.StatusCode != http.StatusOK {
+		return 0, fmt.Errorf("error getting %s: HTTP status %s", url, resp.Status)
+	}
+	var cred iamCredentials
+	err = json.NewDecoder(resp.Body).Decode(&cred)
+	if err != nil {
+		return 0, fmt.Errorf("error decoding credentials from %s: %s", url, err)
+	}
+	v.AccessKeyID, v.SecretAccessKey, v.AuthToken, v.AuthExpiration = cred.AccessKeyID, cred.SecretAccessKey, cred.Token, cred.Expiration
+	v.bucket.SetBucket(&s3.Bucket{
+		S3:   v.newS3Client(),
+		Name: v.Bucket,
+	})
+	// TTL is time from now to expiration, minus 5m.  "We make new
+	// credentials available at least five minutes before the
+	// expiration of the old credentials."  --
+	// https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/iam-roles-for-amazon-ec2.html#instance-metadata-security-credentials
+	// (If that's not true, the returned ttl might be zero or
+	// negative, which the caller can handle.)
+	ttl := cred.Expiration.Sub(time.Now()) - 5*time.Minute
+	v.logger.WithFields(logrus.Fields{
+		"AccessKeyID": cred.AccessKeyID,
+		"LastUpdated": cred.LastUpdated,
+		"Expiration":  cred.Expiration,
+		"TTL":         arvados.Duration(ttl),
+	}).Debug("updated credentials")
+	return ttl, nil
 }
 
-// Check returns an error if the volume is inaccessible (e.g., config
-// error).
-func (v *S3Volume) Check() 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():
+		v.logger.Debugf("s3: abandoning getReader(): %s", ctx.Err())
+		go func() {
+			<-ready
+			if err == nil {
+				rdr.Close()
+			}
+		}()
+		return nil, ctx.Err()
+	}
 }
 
 // getReader wraps (Bucket)GetReader.
@@ -170,12 +308,13 @@ func (v *S3Volume) Check() error {
 // 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) {
-	rdr, err = v.Bucket.GetReader(loc)
+	rdr, err = v.bucket.GetReader(loc)
 	err = v.translateError(err)
 	if err == nil || !os.IsNotExist(err) {
 		return
 	}
-	_, err = v.Bucket.Head("recent/"+loc, nil)
+
+	_, err = v.bucket.Head("recent/"+loc, nil)
 	err = v.translateError(err)
 	if err != nil {
 		// If we can't read recent/X, there's no point in
@@ -186,9 +325,10 @@ func (v *S3Volume) getReader(loc string) (rdr io.ReadCloser, err error) {
 		err = os.ErrNotExist
 		return
 	}
-	rdr, err = v.Bucket.GetReader(loc)
+
+	rdr, err = v.bucket.GetReader(loc)
 	if err != nil {
-		log.Printf("warning: reading %s after successful fixRace: %s", loc, err)
+		v.logger.Warnf("reading %s after successful fixRace: %s", loc, err)
 		err = v.translateError(err)
 	}
 	return
@@ -196,58 +336,158 @@ func (v *S3Volume) getReader(loc string) (rdr io.ReadCloser, err error) {
 
 // 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():
+		v.logger.Debugf("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.
+		v.logger.Debug("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 {
+	errChan := make(chan error, 1)
+	go func() {
+		_, err := v.bucket.Head("recent/"+loc, nil)
+		errChan <- err
+	}()
+	var err error
+	select {
+	case <-ctx.Done():
+		return ctx.Err()
+	case err = <-errChan:
+	}
+	if err != nil {
+		// Checking for "loc" itself here would interfere with
+		// future GET requests.
+		//
+		// On AWS, if X doesn't exist, a HEAD or GET request
+		// for X causes X's non-existence to be cached. Thus,
+		// if we test for X, then create X and return a
+		// signature to our client, the client might still get
+		// 404 from all keepstores when trying to read it.
+		//
+		// To avoid this, we avoid doing HEAD X or GET X until
+		// we know X has been written.
+		//
+		// Note that X might exist even though recent/X
+		// doesn't: for example, the response to HEAD recent/X
+		// might itself come from a stale cache. In such
+		// cases, we will return a false negative and
+		// PutHandler might needlessly create another replica
+		// on a different volume. That's not ideal, but it's
+		// better than passing the eventually-consistent
+		// problem on to our clients.
+		return v.translateError(err)
+	}
+	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 {
-	if v.readonly {
+func (v *S3Volume) Put(ctx context.Context, loc string, block []byte) error {
+	if v.volume.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)
+		// In AWS regions that use V4 signatures, we need to
+		// provide ContentSHA256 up front. Otherwise, the S3
+		// library reads the request body (from our buffer)
+		// into another new buffer in order to compute the
+		// SHA256 before sending the request -- which would
+		// mean consuming 128 MiB of memory for the duration
+		// of a 64 MiB write.
+		opts.ContentSHA256 = fmt.Sprintf("%x", sha256.Sum256(block))
 	}
-	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 {
+				v.logger.Debugf("abandoned PutReader goroutine finished with err: %s", err)
+			}
+		}()
+		defer close(ready)
+		err = v.bucket.PutReader(loc, bufr, int64(size), "application/octet-stream", s3ACL, opts)
+		if err != nil {
+			return
+		}
+		err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
+	}()
+	select {
+	case <-ctx.Done():
+		v.logger.Debugf("taking PutReader's input away: %s", ctx.Err())
+		// Our pipe might be stuck in Write(), waiting for
+		// PutReader() 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())
+		v.logger.Debugf("abandoning PutReader goroutine")
+		return ctx.Err()
+	case <-ready:
+		// Unblock pipe in case PutReader did not consume it.
+		io.Copy(ioutil.Discard, bufr)
 		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.
 func (v *S3Volume) Touch(loc string) error {
-	if v.readonly {
+	if v.volume.ReadOnly {
 		return MethodDisabledError
 	}
-	_, err := v.Bucket.Head(loc, nil)
+	_, err := v.bucket.Head(loc, nil)
 	err = v.translateError(err)
 	if os.IsNotExist(err) && v.fixRace(loc) {
 		// The data object got trashed in a race, but fixRace
@@ -255,29 +495,29 @@ func (v *S3Volume) Touch(loc string) error {
 	} else if err != nil {
 		return err
 	}
-	err = v.Bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
+	err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 	return v.translateError(err)
 }
 
 // Mtime returns the stored timestamp for the given locator.
 func (v *S3Volume) Mtime(loc string) (time.Time, error) {
-	_, err := v.Bucket.Head(loc, nil)
+	_, err := v.bucket.Head(loc, nil)
 	if err != nil {
 		return zeroTime, v.translateError(err)
 	}
-	resp, err := v.Bucket.Head("recent/"+loc, nil)
+	resp, err := v.bucket.Head("recent/"+loc, nil)
 	err = v.translateError(err)
 	if os.IsNotExist(err) {
 		// The data object X exists, but recent/X is missing.
-		err = v.Bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
+		err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 		if err != nil {
-			log.Printf("error: creating %q: %s", "recent/"+loc, err)
+			v.logger.WithError(err).Errorf("error creating %q", "recent/"+loc)
 			return zeroTime, v.translateError(err)
 		}
-		log.Printf("info: created %q to migrate existing block to new storage scheme", "recent/"+loc)
-		resp, err = v.Bucket.Head("recent/"+loc, nil)
+		v.logger.Infof("created %q to migrate existing block to new storage scheme", "recent/"+loc)
+		resp, err = v.bucket.Head("recent/"+loc, nil)
 		if err != nil {
-			log.Printf("error: created %q but HEAD failed: %s", "recent/"+loc, err)
+			v.logger.WithError(err).Errorf("HEAD failed after creating %q", "recent/"+loc)
 			return zeroTime, v.translateError(err)
 		}
 	} else if err != nil {
@@ -292,16 +532,20 @@ func (v *S3Volume) Mtime(loc string) (time.Time, error) {
 func (v *S3Volume) IndexTo(prefix string, writer io.Writer) error {
 	// Use a merge sort to find matching sets of X and recent/X.
 	dataL := s3Lister{
-		Bucket:   v.Bucket,
+		Logger:   v.logger,
+		Bucket:   v.bucket.Bucket(),
 		Prefix:   prefix,
-		PageSize: v.indexPageSize,
+		PageSize: v.IndexPageSize,
+		Stats:    &v.bucket.stats,
 	}
 	recentL := s3Lister{
-		Bucket:   v.Bucket,
+		Logger:   v.logger,
+		Bucket:   v.bucket.Bucket(),
 		Prefix:   "recent/" + prefix,
-		PageSize: v.indexPageSize,
+		PageSize: v.IndexPageSize,
+		Stats:    &v.bucket.stats,
 	}
-	for data, recent := dataL.First(), recentL.First(); data != nil; data = dataL.Next() {
+	for data, recent := dataL.First(), recentL.First(); data != nil && dataL.Error() == nil; data = dataL.Next() {
 		if data.Key >= "g" {
 			// Conveniently, "recent/*" and "trash/*" are
 			// lexically greater than all hex-encoded data
@@ -320,7 +564,7 @@ func (v *S3Volume) IndexTo(prefix string, writer io.Writer) error {
 		stamp := data
 
 		// Advance to the corresponding recent/X marker, if any
-		for recent != nil {
+		for recent != nil && recentL.Error() == nil {
 			if cmp := strings.Compare(recent.Key[7:], data.Key); cmp < 0 {
 				recent = recentL.Next()
 				continue
@@ -335,30 +579,36 @@ func (v *S3Volume) IndexTo(prefix string, writer io.Writer) error {
 				break
 			}
 		}
+		if err := recentL.Error(); err != nil {
+			return err
+		}
 		t, err := time.Parse(time.RFC3339, stamp.LastModified)
 		if err != nil {
 			return err
 		}
-		fmt.Fprintf(writer, "%s+%d %d\n", data.Key, data.Size, t.UnixNano())
+		// We truncate sub-second precision here. Otherwise
+		// timestamps will never match the RFC1123-formatted
+		// Last-Modified values parsed by Mtime().
+		fmt.Fprintf(writer, "%s+%d %d\n", data.Key, data.Size, t.Unix()*1000000000)
 	}
-	return nil
+	return dataL.Error()
 }
 
 // Trash a Keep block.
 func (v *S3Volume) Trash(loc string) error {
-	if v.readonly {
+	if v.volume.ReadOnly {
 		return MethodDisabledError
 	}
 	if t, err := v.Mtime(loc); err != nil {
 		return err
-	} else if time.Since(t) < blobSignatureTTL {
+	} else if time.Since(t) < v.cluster.Collections.BlobSigningTTL.Duration() {
 		return nil
 	}
-	if trashLifetime == 0 {
-		if !s3UnsafeDelete {
+	if v.cluster.Collections.BlobTrashLifetime == 0 {
+		if !v.UnsafeDelete {
 			return ErrS3TrashDisabled
 		}
-		return v.Bucket.Del(loc)
+		return v.translateError(v.bucket.Del(loc))
 	}
 	err := v.checkRaceWindow(loc)
 	if err != nil {
@@ -368,13 +618,13 @@ func (v *S3Volume) Trash(loc string) error {
 	if err != nil {
 		return err
 	}
-	return v.translateError(v.Bucket.Del(loc))
+	return v.translateError(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 {
-	resp, err := v.Bucket.Head("trash/"+loc, nil)
+	resp, err := v.bucket.Head("trash/"+loc, nil)
 	err = v.translateError(err)
 	if os.IsNotExist(err) {
 		// OK, trash/X doesn't exist so we're not in the race
@@ -390,7 +640,7 @@ func (v *S3Volume) checkRaceWindow(loc string) error {
 		// Can't parse timestamp
 		return err
 	}
-	safeWindow := t.Add(trashLifetime).Sub(time.Now().Add(v.raceWindow))
+	safeWindow := t.Add(v.cluster.Collections.BlobTrashLifetime.Duration()).Sub(time.Now().Add(time.Duration(v.RaceWindow)))
 	if safeWindow <= 0 {
 		// We can't count on "touch trash/X" to prolong
 		// trash/X's lifetime. The new timestamp might not
@@ -408,13 +658,15 @@ 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 {
-	resp, err := v.Bucket.PutCopy(dst, s3ACL, s3.CopyOptions{
+	resp, err := v.bucket.Bucket().PutCopy(dst, s3ACL, s3.CopyOptions{
 		ContentType:       "application/octet-stream",
 		MetadataDirective: "REPLACE",
-	}, v.Bucket.Name+"/"+src)
+	}, v.bucket.Bucket().Name+"/"+src)
 	err = v.translateError(err)
-	if err != nil {
+	if os.IsNotExist(err) {
 		return err
+	} else if err != nil {
+		return fmt.Errorf("PutCopy(%q ← %q): %s", dst, v.bucket.Bucket().Name+"/"+src, err)
 	}
 	if t, err := time.Parse(time.RFC3339Nano, resp.LastModified); err != nil {
 		return fmt.Errorf("PutCopy succeeded but did not return a timestamp: %q: %s", resp.LastModified, err)
@@ -446,7 +698,7 @@ func (v *S3Volume) Untrash(loc string) error {
 	if err != nil {
 		return err
 	}
-	err = v.Bucket.Put("recent/"+loc, nil, "application/octet-stream", s3ACL, s3.Options{})
+	err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 	return v.translateError(err)
 }
 
@@ -461,21 +713,14 @@ func (v *S3Volume) Status() *VolumeStatus {
 	}
 }
 
-// String implements fmt.Stringer.
-func (v *S3Volume) String() string {
-	return fmt.Sprintf("s3-bucket:%+q", v.Bucket.Name)
-}
-
-// Writable returns false if all future Put, Mtime, and Delete calls
-// are expected to fail.
-func (v *S3Volume) Writable() bool {
-	return !v.readonly
+// InternalStats returns bucket I/O and API call counters.
+func (v *S3Volume) InternalStats() interface{} {
+	return &v.bucket.stats
 }
 
-// Replication returns the storage redundancy of the underlying
-// device. Configured via command line flag.
-func (v *S3Volume) Replication() int {
-	return v.replication
+// String implements fmt.Stringer.
+func (v *S3Volume) String() string {
+	return fmt.Sprintf("s3-bucket:%+q", v.Bucket)
 }
 
 var s3KeepBlockRegexp = regexp.MustCompile(`^[0-9a-f]{32}$`)
@@ -489,42 +734,42 @@ 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 {
-	trash, err := v.Bucket.Head("trash/"+loc, nil)
+	trash, err := v.bucket.Head("trash/"+loc, nil)
 	if err != nil {
 		if !os.IsNotExist(v.translateError(err)) {
-			log.Printf("error: fixRace: HEAD %q: %s", "trash/"+loc, err)
+			v.logger.WithError(err).Errorf("fixRace: HEAD %q failed", "trash/"+loc)
 		}
 		return false
 	}
 	trashTime, err := v.lastModified(trash)
 	if err != nil {
-		log.Printf("error: fixRace: parse %q: %s", trash.Header.Get("Last-Modified"), err)
+		v.logger.WithError(err).Errorf("fixRace: error parsing time %q", trash.Header.Get("Last-Modified"))
 		return false
 	}
 
-	recent, err := v.Bucket.Head("recent/"+loc, nil)
+	recent, err := v.bucket.Head("recent/"+loc, nil)
 	if err != nil {
-		log.Printf("error: fixRace: HEAD %q: %s", "recent/"+loc, err)
+		v.logger.WithError(err).Errorf("fixRace: HEAD %q failed", "recent/"+loc)
 		return false
 	}
 	recentTime, err := v.lastModified(recent)
 	if err != nil {
-		log.Printf("error: fixRace: parse %q: %s", recent.Header.Get("Last-Modified"), err)
+		v.logger.WithError(err).Errorf("fixRace: error parsing time %q", recent.Header.Get("Last-Modified"))
 		return false
 	}
 
 	ageWhenTrashed := trashTime.Sub(recentTime)
-	if ageWhenTrashed >= blobSignatureTTL {
+	if ageWhenTrashed >= v.cluster.Collections.BlobSigningTTL.Duration() {
 		// No evidence of a race: block hasn't been written
 		// since it became eligible for Trash. No fix needed.
 		return false
 	}
 
-	log.Printf("notice: fixRace: %q: trashed at %s but touched at %s (age when trashed = %s < %s)", loc, trashTime, recentTime, ageWhenTrashed, blobSignatureTTL)
-	log.Printf("notice: fixRace: copying %q to %q to recover from race between Put/Touch and Trash", "recent/"+loc, loc)
+	v.logger.Infof("fixRace: %q: trashed at %s but touched at %s (age when trashed = %s < %s)", loc, trashTime, recentTime, ageWhenTrashed, v.cluster.Collections.BlobSigningTTL)
+	v.logger.Infof("fixRace: copying %q to %q to recover from race between Put/Touch and Trash", "recent/"+loc, loc)
 	err = v.safeCopy(loc, "trash/"+loc)
 	if err != nil {
-		log.Printf("error: fixRace: %s", err)
+		v.logger.WithError(err).Error("fixRace: copy failed")
 		return false
 	}
 	return true
@@ -545,103 +790,136 @@ func (v *S3Volume) translateError(err error) error {
 	return err
 }
 
-// EmptyTrash looks for trashed blocks that exceeded trashLifetime
+// EmptyTrash looks for trashed blocks that exceeded BlobTrashLifetime
 // and deletes them from the volume.
 func (v *S3Volume) EmptyTrash() {
+	if v.cluster.Collections.BlobDeleteConcurrency < 1 {
+		return
+	}
+
 	var bytesInTrash, blocksInTrash, bytesDeleted, blocksDeleted int64
 
-	// Use a merge sort to find matching sets of trash/X and recent/X.
-	trashL := s3Lister{
-		Bucket:   v.Bucket,
-		Prefix:   "trash/",
-		PageSize: v.indexPageSize,
-	}
 	// Define "ready to delete" as "...when EmptyTrash started".
 	startT := time.Now()
-	for trash := trashL.First(); trash != nil; trash = trashL.Next() {
+
+	emptyOneKey := func(trash *s3.Key) {
 		loc := trash.Key[6:]
 		if !v.isKeepBlock(loc) {
-			continue
+			return
 		}
-		bytesInTrash += trash.Size
-		blocksInTrash++
+		atomic.AddInt64(&bytesInTrash, trash.Size)
+		atomic.AddInt64(&blocksInTrash, 1)
 
 		trashT, err := time.Parse(time.RFC3339, trash.LastModified)
 		if err != nil {
-			log.Printf("warning: %s: EmptyTrash: %q: parse %q: %s", v, trash.Key, trash.LastModified, err)
-			continue
+			v.logger.Warnf("EmptyTrash: %q: parse %q: %s", trash.Key, trash.LastModified, err)
+			return
 		}
-		recent, err := v.Bucket.Head("recent/"+loc, nil)
+		recent, err := v.bucket.Head("recent/"+loc, nil)
 		if err != nil && os.IsNotExist(v.translateError(err)) {
-			log.Printf("warning: %s: EmptyTrash: found trash marker %q but no %q (%s); calling Untrash", v, trash.Key, "recent/"+loc, err)
+			v.logger.Warnf("EmptyTrash: found trash marker %q but no %q (%s); calling Untrash", trash.Key, "recent/"+loc, err)
 			err = v.Untrash(loc)
 			if err != nil {
-				log.Printf("error: %s: EmptyTrash: Untrash(%q): %s", v, loc, err)
+				v.logger.WithError(err).Errorf("EmptyTrash: Untrash(%q) failed", loc)
 			}
-			continue
+			return
 		} else if err != nil {
-			log.Printf("warning: %s: EmptyTrash: HEAD %q: %s", v, "recent/"+loc, err)
-			continue
+			v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", "recent/"+loc)
+			return
 		}
 		recentT, err := v.lastModified(recent)
 		if err != nil {
-			log.Printf("warning: %s: EmptyTrash: %q: parse %q: %s", v, "recent/"+loc, recent.Header.Get("Last-Modified"), err)
-			continue
+			v.logger.WithError(err).Warnf("EmptyTrash: %q: error parsing %q", "recent/"+loc, recent.Header.Get("Last-Modified"))
+			return
 		}
-		if trashT.Sub(recentT) < blobSignatureTTL {
-			if age := startT.Sub(recentT); age >= blobSignatureTTL-v.raceWindow {
+		if trashT.Sub(recentT) < v.cluster.Collections.BlobSigningTTL.Duration() {
+			if age := startT.Sub(recentT); age >= v.cluster.Collections.BlobSigningTTL.Duration()-time.Duration(v.RaceWindow) {
 				// recent/loc is too old to protect
 				// loc from being Trashed again during
 				// the raceWindow that starts if we
 				// delete trash/X now.
 				//
-				// Note this means (trashCheckInterval
-				// < blobSignatureTTL - raceWindow) is
+				// Note this means (TrashSweepInterval
+				// < BlobSigningTTL - raceWindow) is
 				// necessary to avoid starvation.
-				log.Printf("notice: %s: EmptyTrash: detected old race for %q, calling fixRace + Touch", v, loc)
+				v.logger.Infof("EmptyTrash: detected old race for %q, calling fixRace + Touch", loc)
 				v.fixRace(loc)
 				v.Touch(loc)
-				continue
-			} else if _, err := v.Bucket.Head(loc, nil); os.IsNotExist(err) {
-				log.Printf("notice: %s: EmptyTrash: detected recent race for %q, calling fixRace", v, loc)
+				return
+			}
+			_, err := v.bucket.Head(loc, nil)
+			if os.IsNotExist(err) {
+				v.logger.Infof("EmptyTrash: detected recent race for %q, calling fixRace", loc)
 				v.fixRace(loc)
-				continue
+				return
 			} else if err != nil {
-				log.Printf("warning: %s: EmptyTrash: HEAD %q: %s", v, loc, err)
-				continue
+				v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", loc)
+				return
 			}
 		}
-		if startT.Sub(trashT) < trashLifetime {
-			continue
+		if startT.Sub(trashT) < v.cluster.Collections.BlobTrashLifetime.Duration() {
+			return
 		}
-		err = v.Bucket.Del(trash.Key)
+		err = v.bucket.Del(trash.Key)
 		if err != nil {
-			log.Printf("warning: %s: EmptyTrash: deleting %q: %s", v, trash.Key, err)
-			continue
+			v.logger.WithError(err).Errorf("EmptyTrash: error deleting %q", trash.Key)
+			return
 		}
-		bytesDeleted += trash.Size
-		blocksDeleted++
+		atomic.AddInt64(&bytesDeleted, trash.Size)
+		atomic.AddInt64(&blocksDeleted, 1)
 
-		_, err = v.Bucket.Head(loc, nil)
-		if os.IsNotExist(err) {
-			err = v.Bucket.Del("recent/" + loc)
-			if err != nil {
-				log.Printf("warning: %s: EmptyTrash: deleting %q: %s", v, "recent/"+loc, err)
-			}
-		} else if err != nil {
-			log.Printf("warning: %s: EmptyTrash: HEAD %q: %s", v, "recent/"+loc, err)
+		_, err = v.bucket.Head(loc, nil)
+		if err == nil {
+			v.logger.Warnf("EmptyTrash: HEAD %q succeeded immediately after deleting %q", loc, loc)
+			return
+		}
+		if !os.IsNotExist(v.translateError(err)) {
+			v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", loc)
+			return
+		}
+		err = v.bucket.Del("recent/" + loc)
+		if err != nil {
+			v.logger.WithError(err).Warnf("EmptyTrash: error deleting %q", "recent/"+loc)
 		}
 	}
+
+	var wg sync.WaitGroup
+	todo := make(chan *s3.Key, v.cluster.Collections.BlobDeleteConcurrency)
+	for i := 0; i < v.cluster.Collections.BlobDeleteConcurrency; i++ {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			for key := range todo {
+				emptyOneKey(key)
+			}
+		}()
+	}
+
+	trashL := s3Lister{
+		Logger:   v.logger,
+		Bucket:   v.bucket.Bucket(),
+		Prefix:   "trash/",
+		PageSize: v.IndexPageSize,
+		Stats:    &v.bucket.stats,
+	}
+	for trash := trashL.First(); trash != nil; trash = trashL.Next() {
+		todo <- trash
+	}
+	close(todo)
+	wg.Wait()
+
 	if err := trashL.Error(); err != nil {
-		log.Printf("error: %s: EmptyTrash: lister: %s", v, err)
+		v.logger.WithError(err).Error("EmptyTrash: lister failed")
 	}
-	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)
+	v.logger.Infof("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)
 }
 
 type s3Lister struct {
+	Logger     logrus.FieldLogger
 	Bucket     *s3.Bucket
 	Prefix     string
 	PageSize   int
+	Stats      *s3bucketStats
 	nextMarker string
 	buf        []s3.Key
 	err        error
@@ -670,6 +948,8 @@ func (lister *s3Lister) Error() error {
 }
 
 func (lister *s3Lister) getPage() {
+	lister.Stats.TickOps("list")
+	lister.Stats.Tick(&lister.Stats.Ops, &lister.Stats.ListOps)
 	resp, err := lister.Bucket.List(lister.Prefix, "", lister.nextMarker, lister.PageSize)
 	lister.nextMarker = ""
 	if err != nil {
@@ -682,7 +962,7 @@ func (lister *s3Lister) getPage() {
 	lister.buf = make([]s3.Key, 0, len(resp.Contents))
 	for _, key := range resp.Contents {
 		if !strings.HasPrefix(key.Key, lister.Prefix) {
-			log.Printf("warning: s3Lister: S3 Bucket.List(prefix=%q) returned key %q", lister.Prefix, key.Key)
+			lister.Logger.Warnf("s3Lister: S3 Bucket.List(prefix=%q) returned key %q", lister.Prefix, key.Key)
 			continue
 		}
 		lister.buf = append(lister.buf, key)
@@ -696,3 +976,88 @@ func (lister *s3Lister) pop() (k *s3.Key) {
 	}
 	return
 }
+
+// s3bucket wraps s3.bucket and counts I/O and API usage stats. The
+// wrapped bucket can be replaced atomically with SetBucket in order
+// to update credentials.
+type s3bucket struct {
+	bucket *s3.Bucket
+	stats  s3bucketStats
+	mu     sync.Mutex
+}
+
+func (b *s3bucket) Bucket() *s3.Bucket {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.bucket
+}
+
+func (b *s3bucket) SetBucket(bucket *s3.Bucket) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	b.bucket = bucket
+}
+
+func (b *s3bucket) GetReader(path string) (io.ReadCloser, error) {
+	rdr, err := b.Bucket().GetReader(path)
+	b.stats.TickOps("get")
+	b.stats.Tick(&b.stats.Ops, &b.stats.GetOps)
+	b.stats.TickErr(err)
+	return NewCountingReader(rdr, b.stats.TickInBytes), err
+}
+
+func (b *s3bucket) Head(path string, headers map[string][]string) (*http.Response, error) {
+	resp, err := b.Bucket().Head(path, headers)
+	b.stats.TickOps("head")
+	b.stats.Tick(&b.stats.Ops, &b.stats.HeadOps)
+	b.stats.TickErr(err)
+	return resp, err
+}
+
+func (b *s3bucket) PutReader(path string, r io.Reader, length int64, contType string, perm s3.ACL, options s3.Options) error {
+	if length == 0 {
+		// goamz will only send Content-Length: 0 when reader
+		// is nil due to net.http.Request.ContentLength
+		// behavior.  Otherwise, Content-Length header is
+		// omitted which will cause some S3 services
+		// (including AWS and Ceph RadosGW) to fail to create
+		// empty objects.
+		r = nil
+	} else {
+		r = NewCountingReader(r, b.stats.TickOutBytes)
+	}
+	err := b.Bucket().PutReader(path, r, length, contType, perm, options)
+	b.stats.TickOps("put")
+	b.stats.Tick(&b.stats.Ops, &b.stats.PutOps)
+	b.stats.TickErr(err)
+	return err
+}
+
+func (b *s3bucket) Del(path string) error {
+	err := b.Bucket().Del(path)
+	b.stats.TickOps("delete")
+	b.stats.Tick(&b.stats.Ops, &b.stats.DelOps)
+	b.stats.TickErr(err)
+	return err
+}
+
+type s3bucketStats struct {
+	statsTicker
+	Ops     uint64
+	GetOps  uint64
+	PutOps  uint64
+	HeadOps uint64
+	DelOps  uint64
+	ListOps uint64
+}
+
+func (s *s3bucketStats) TickErr(err error) {
+	if err == nil {
+		return
+	}
+	errType := fmt.Sprintf("%T", err)
+	if err, ok := err.(*s3.Error); ok {
+		errType = errType + fmt.Sprintf(" %d %s", err.StatusCode, err.Code)
+	}
+	s.statsTicker.TickErr(err, errType)
+}