services/keepstore/s3_volume.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.0
   4
   5 package main
   6
   7 import (
   8         "bufio"
   9         "bytes"
  10         "context"
  11         "crypto/sha256"
  12         "encoding/base64"
  13         "encoding/hex"
  14         "encoding/json"
  15         "errors"
  16         "fmt"
  17         "io"
  18         "io/ioutil"
  19         "net/http"
  20         "os"
  21         "regexp"
  22         "strings"
  23         "sync"
  24         "sync/atomic"
  25         "time"
  26
  27         "git.arvados.org/arvados.git/sdk/go/arvados"
  28         "github.com/AdRoll/goamz/aws"
  29         "github.com/AdRoll/goamz/s3"
  30         "github.com/prometheus/client_golang/prometheus"
  31         "github.com/sirupsen/logrus"
  32 )
  33
  34 func init() {
  35         driver["S3"] = chooseS3VolumeDriver
  36 }
  37
  38 func newS3Volume(cluster *arvados.Cluster, volume arvados.Volume, logger logrus.FieldLogger, metrics *volumeMetricsVecs) (Volume, error) {
  39         v := &S3Volume{cluster: cluster, volume: volume, metrics: metrics}
  40         err := json.Unmarshal(volume.DriverParameters, v)
  41         if err != nil {
  42                 return nil, err
  43         }
  44         v.logger = logger.WithField("Volume", v.String())
  45         return v, v.check()
  46 }
  47
  48 func (v *S3Volume) check() error {
  49         if v.Bucket == "" {
  50                 return errors.New("DriverParameters: Bucket must be provided")
  51         }
  52         if v.IndexPageSize == 0 {
  53                 v.IndexPageSize = 1000
  54         }
  55         if v.RaceWindow < 0 {
  56                 return errors.New("DriverParameters: RaceWindow must not be negative")
  57         }
  58
  59         var ok bool
  60         v.region, ok = aws.Regions[v.Region]
  61         if v.Endpoint == "" {
  62                 if !ok {
  63                         return fmt.Errorf("unrecognized region %+q; try specifying endpoint instead", v.Region)
  64                 }
  65         } else if ok {
  66                 return fmt.Errorf("refusing to use AWS region name %+q with endpoint %+q; "+
  67                         "specify empty endpoint or use a different region name", v.Region, v.Endpoint)
  68         } else {
  69                 v.region = aws.Region{
  70                         Name:                 v.Region,
  71                         S3Endpoint:           v.Endpoint,
  72                         S3LocationConstraint: v.LocationConstraint,
  73                 }
  74         }
  75
  76         // Zero timeouts mean "wait forever", which is a bad
  77         // default. Default to long timeouts instead.
  78         if v.ConnectTimeout == 0 {
  79                 v.ConnectTimeout = s3DefaultConnectTimeout
  80         }
  81         if v.ReadTimeout == 0 {
  82                 v.ReadTimeout = s3DefaultReadTimeout
  83         }
  84
  85         v.bucket = &s3bucket{
  86                 bucket: &s3.Bucket{
  87                         S3:   v.newS3Client(),
  88                         Name: v.Bucket,
  89                 },
  90         }
  91         // Set up prometheus metrics
  92         lbls := prometheus.Labels{"device_id": v.GetDeviceID()}
  93         v.bucket.stats.opsCounters, v.bucket.stats.errCounters, v.bucket.stats.ioBytes = v.metrics.getCounterVecsFor(lbls)
  94
  95         err := v.bootstrapIAMCredentials()
  96         if err != nil {
  97                 return fmt.Errorf("error getting IAM credentials: %s", err)
  98         }
  99
 100         return nil
 101 }
 102
 103 const (
 104         s3DefaultReadTimeout    = arvados.Duration(10 * time.Minute)
 105         s3DefaultConnectTimeout = arvados.Duration(time.Minute)
 106 )
 107
 108 var (
 109         // ErrS3TrashDisabled is returned by Trash if that operation
 110         // is impossible with the current config.
 111         ErrS3TrashDisabled = fmt.Errorf("trash function is disabled because Collections.BlobTrashLifetime=0 and DriverParameters.UnsafeDelete=false")
 112
 113         s3ACL = s3.Private
 114
 115         zeroTime time.Time
 116 )
 117
 118 const (
 119         maxClockSkew  = 600 * time.Second
 120         nearlyRFC1123 = "Mon, 2 Jan 2006 15:04:05 GMT"
 121 )
 122
 123 func s3regions() (okList []string) {
 124         for r := range aws.Regions {
 125                 okList = append(okList, r)
 126         }
 127         return
 128 }
 129
 130 // S3Volume implements Volume using an S3 bucket.
 131 type S3Volume struct {
 132         arvados.S3VolumeDriverParameters
 133         AuthToken      string    // populated automatically when IAMRole is used
 134         AuthExpiration time.Time // populated automatically when IAMRole is used
 135
 136         cluster   *arvados.Cluster
 137         volume    arvados.Volume
 138         logger    logrus.FieldLogger
 139         metrics   *volumeMetricsVecs
 140         bucket    *s3bucket
 141         region    aws.Region
 142         startOnce sync.Once
 143 }
 144
 145 // GetDeviceID returns a globally unique ID for the storage bucket.
 146 func (v *S3Volume) GetDeviceID() string {
 147         return "s3://" + v.Endpoint + "/" + v.Bucket
 148 }
 149
 150 func (v *S3Volume) bootstrapIAMCredentials() error {
 151         if v.AccessKey != "" || v.SecretKey != "" {
 152                 if v.IAMRole != "" {
 153                         return errors.New("invalid DriverParameters: AccessKey and SecretKey must be blank if IAMRole is specified")
 154                 }
 155                 return nil
 156         }
 157         ttl, err := v.updateIAMCredentials()
 158         if err != nil {
 159                 return err
 160         }
 161         go func() {
 162                 for {
 163                         time.Sleep(ttl)
 164                         ttl, err = v.updateIAMCredentials()
 165                         if err != nil {
 166                                 v.logger.WithError(err).Warnf("failed to update credentials for IAM role %q", v.IAMRole)
 167                                 ttl = time.Second
 168                         } else if ttl < time.Second {
 169                                 v.logger.WithField("TTL", ttl).Warnf("received stale credentials for IAM role %q", v.IAMRole)
 170                                 ttl = time.Second
 171                         }
 172                 }
 173         }()
 174         return nil
 175 }
 176
 177 func (v *S3Volume) newS3Client() *s3.S3 {
 178         auth := aws.NewAuth(v.AccessKey, v.SecretKey, v.AuthToken, v.AuthExpiration)
 179         client := s3.New(*auth, v.region)
 180         if !v.V2Signature {
 181                 client.Signature = aws.V4Signature
 182         }
 183         client.ConnectTimeout = time.Duration(v.ConnectTimeout)
 184         client.ReadTimeout = time.Duration(v.ReadTimeout)
 185         return client
 186 }
 187
 188 // returned by AWS metadata endpoint .../security-credentials/${rolename}
 189 type iamCredentials struct {
 190         Code            string
 191         LastUpdated     time.Time
 192         Type            string
 193         AccessKeyID     string
 194         SecretAccessKey string
 195         Token           string
 196         Expiration      time.Time
 197 }
 198
 199 // Returns TTL of updated credentials, i.e., time to sleep until next
 200 // update.
 201 func (v *S3Volume) updateIAMCredentials() (time.Duration, error) {
 202         ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(time.Minute))
 203         defer cancel()
 204
 205         metadataBaseURL := "http://169.254.169.254/latest/meta-data/iam/security-credentials/"
 206
 207         var url string
 208         if strings.Contains(v.IAMRole, "://") {
 209                 // Configuration provides complete URL (used by tests)
 210                 url = v.IAMRole
 211         } else if v.IAMRole != "" {
 212                 // Configuration provides IAM role name and we use the
 213                 // AWS metadata endpoint
 214                 url = metadataBaseURL + v.IAMRole
 215         } else {
 216                 url = metadataBaseURL
 217                 v.logger.WithField("URL", url).Debug("looking up IAM role name")
 218                 req, err := http.NewRequest("GET", url, nil)
 219                 if err != nil {
 220                         return 0, fmt.Errorf("error setting up request %s: %s", url, err)
 221                 }
 222                 resp, err := http.DefaultClient.Do(req.WithContext(ctx))
 223                 if err != nil {
 224                         return 0, fmt.Errorf("error getting %s: %s", url, err)
 225                 }
 226                 defer resp.Body.Close()
 227                 if resp.StatusCode == http.StatusNotFound {
 228                         return 0, fmt.Errorf("this instance does not have an IAM role assigned -- either assign a role, or configure AccessKey and SecretKey explicitly in DriverParameters (error getting %s: HTTP status %s)", url, resp.Status)
 229                 } else if resp.StatusCode != http.StatusOK {
 230                         return 0, fmt.Errorf("error getting %s: HTTP status %s", url, resp.Status)
 231                 }
 232                 body := bufio.NewReader(resp.Body)
 233                 var role string
 234                 _, err = fmt.Fscanf(body, "%s\n", &role)
 235                 if err != nil {
 236                         return 0, fmt.Errorf("error reading response from %s: %s", url, err)
 237                 }
 238                 if n, _ := body.Read(make([]byte, 64)); n > 0 {
 239                         v.logger.Warnf("ignoring additional data returned by metadata endpoint %s after the single role name that we expected", url)
 240                 }
 241                 v.logger.WithField("Role", role).Debug("looked up IAM role name")
 242                 url = url + role
 243         }
 244
 245         v.logger.WithField("URL", url).Debug("getting credentials")
 246         req, err := http.NewRequest("GET", url, nil)
 247         if err != nil {
 248                 return 0, fmt.Errorf("error setting up request %s: %s", url, err)
 249         }
 250         resp, err := http.DefaultClient.Do(req.WithContext(ctx))
 251         if err != nil {
 252                 return 0, fmt.Errorf("error getting %s: %s", url, err)
 253         }
 254         defer resp.Body.Close()
 255         if resp.StatusCode != http.StatusOK {
 256                 return 0, fmt.Errorf("error getting %s: HTTP status %s", url, resp.Status)
 257         }
 258         var cred iamCredentials
 259         err = json.NewDecoder(resp.Body).Decode(&cred)
 260         if err != nil {
 261                 return 0, fmt.Errorf("error decoding credentials from %s: %s", url, err)
 262         }
 263         v.AccessKey, v.SecretKey, v.AuthToken, v.AuthExpiration = cred.AccessKeyID, cred.SecretAccessKey, cred.Token, cred.Expiration
 264         v.bucket.SetBucket(&s3.Bucket{
 265                 S3:   v.newS3Client(),
 266                 Name: v.Bucket,
 267         })
 268         // TTL is time from now to expiration, minus 5m.  "We make new
 269         // credentials available at least five minutes before the
 270         // expiration of the old credentials."  --
 271         // https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/iam-roles-for-amazon-ec2.html#instance-metadata-security-credentials
 272         // (If that's not true, the returned ttl might be zero or
 273         // negative, which the caller can handle.)
 274         ttl := cred.Expiration.Sub(time.Now()) - 5*time.Minute
 275         v.logger.WithFields(logrus.Fields{
 276                 "AccessKeyID": cred.AccessKeyID,
 277                 "LastUpdated": cred.LastUpdated,
 278                 "Expiration":  cred.Expiration,
 279                 "TTL":         arvados.Duration(ttl),
 280         }).Debug("updated credentials")
 281         return ttl, nil
 282 }
 283
 284 func (v *S3Volume) getReaderWithContext(ctx context.Context, loc string) (rdr io.ReadCloser, err error) {
 285         ready := make(chan bool)
 286         go func() {
 287                 rdr, err = v.getReader(loc)
 288                 close(ready)
 289         }()
 290         select {
 291         case <-ready:
 292                 return
 293         case <-ctx.Done():
 294                 v.logger.Debugf("s3: abandoning getReader(): %s", ctx.Err())
 295                 go func() {
 296                         <-ready
 297                         if err == nil {
 298                                 rdr.Close()
 299                         }
 300                 }()
 301                 return nil, ctx.Err()
 302         }
 303 }
 304
 305 // getReader wraps (Bucket)GetReader.
 306 //
 307 // In situations where (Bucket)GetReader would fail because the block
 308 // disappeared in a Trash race, getReader calls fixRace to recover the
 309 // data, and tries again.
 310 func (v *S3Volume) getReader(loc string) (rdr io.ReadCloser, err error) {
 311         rdr, err = v.bucket.GetReader(loc)
 312         err = v.translateError(err)
 313         if err == nil || !os.IsNotExist(err) {
 314                 return
 315         }
 316
 317         _, err = v.bucket.Head("recent/"+loc, nil)
 318         err = v.translateError(err)
 319         if err != nil {
 320                 // If we can't read recent/X, there's no point in
 321                 // trying fixRace. Give up.
 322                 return
 323         }
 324         if !v.fixRace(loc) {
 325                 err = os.ErrNotExist
 326                 return
 327         }
 328
 329         rdr, err = v.bucket.GetReader(loc)
 330         if err != nil {
 331                 v.logger.Warnf("reading %s after successful fixRace: %s", loc, err)
 332                 err = v.translateError(err)
 333         }
 334         return
 335 }
 336
 337 // Get a block: copy the block data into buf, and return the number of
 338 // bytes copied.
 339 func (v *S3Volume) Get(ctx context.Context, loc string, buf []byte) (int, error) {
 340         rdr, err := v.getReaderWithContext(ctx, loc)
 341         if err != nil {
 342                 return 0, err
 343         }
 344
 345         var n int
 346         ready := make(chan bool)
 347         go func() {
 348                 defer close(ready)
 349
 350                 defer rdr.Close()
 351                 n, err = io.ReadFull(rdr, buf)
 352
 353                 switch err {
 354                 case nil, io.EOF, io.ErrUnexpectedEOF:
 355                         err = nil
 356                 default:
 357                         err = v.translateError(err)
 358                 }
 359         }()
 360         select {
 361         case <-ctx.Done():
 362                 v.logger.Debugf("s3: interrupting ReadFull() with Close() because %s", ctx.Err())
 363                 rdr.Close()
 364                 // Must wait for ReadFull to return, to ensure it
 365                 // doesn't write to buf after we return.
 366                 v.logger.Debug("s3: waiting for ReadFull() to fail")
 367                 <-ready
 368                 return 0, ctx.Err()
 369         case <-ready:
 370                 return n, err
 371         }
 372 }
 373
 374 // Compare the given data with the stored data.
 375 func (v *S3Volume) Compare(ctx context.Context, loc string, expect []byte) error {
 376         errChan := make(chan error, 1)
 377         go func() {
 378                 _, err := v.bucket.Head("recent/"+loc, nil)
 379                 errChan <- err
 380         }()
 381         var err error
 382         select {
 383         case <-ctx.Done():
 384                 return ctx.Err()
 385         case err = <-errChan:
 386         }
 387         if err != nil {
 388                 // Checking for "loc" itself here would interfere with
 389                 // future GET requests.
 390                 //
 391                 // On AWS, if X doesn't exist, a HEAD or GET request
 392                 // for X causes X's non-existence to be cached. Thus,
 393                 // if we test for X, then create X and return a
 394                 // signature to our client, the client might still get
 395                 // 404 from all keepstores when trying to read it.
 396                 //
 397                 // To avoid this, we avoid doing HEAD X or GET X until
 398                 // we know X has been written.
 399                 //
 400                 // Note that X might exist even though recent/X
 401                 // doesn't: for example, the response to HEAD recent/X
 402                 // might itself come from a stale cache. In such
 403                 // cases, we will return a false negative and
 404                 // PutHandler might needlessly create another replica
 405                 // on a different volume. That's not ideal, but it's
 406                 // better than passing the eventually-consistent
 407                 // problem on to our clients.
 408                 return v.translateError(err)
 409         }
 410         rdr, err := v.getReaderWithContext(ctx, loc)
 411         if err != nil {
 412                 return err
 413         }
 414         defer rdr.Close()
 415         return v.translateError(compareReaderWithBuf(ctx, rdr, expect, loc[:32]))
 416 }
 417
 418 // Put writes a block.
 419 func (v *S3Volume) Put(ctx context.Context, loc string, block []byte) error {
 420         if v.volume.ReadOnly {
 421                 return MethodDisabledError
 422         }
 423         var opts s3.Options
 424         size := len(block)
 425         if size > 0 {
 426                 md5, err := hex.DecodeString(loc)
 427                 if err != nil {
 428                         return err
 429                 }
 430                 opts.ContentMD5 = base64.StdEncoding.EncodeToString(md5)
 431                 // In AWS regions that use V4 signatures, we need to
 432                 // provide ContentSHA256 up front. Otherwise, the S3
 433                 // library reads the request body (from our buffer)
 434                 // into another new buffer in order to compute the
 435                 // SHA256 before sending the request -- which would
 436                 // mean consuming 128 MiB of memory for the duration
 437                 // of a 64 MiB write.
 438                 opts.ContentSHA256 = fmt.Sprintf("%x", sha256.Sum256(block))
 439         }
 440
 441         // Send the block data through a pipe, so that (if we need to)
 442         // we can close the pipe early and abandon our PutReader()
 443         // goroutine, without worrying about PutReader() accessing our
 444         // block buffer after we release it.
 445         bufr, bufw := io.Pipe()
 446         go func() {
 447                 io.Copy(bufw, bytes.NewReader(block))
 448                 bufw.Close()
 449         }()
 450
 451         var err error
 452         ready := make(chan bool)
 453         go func() {
 454                 defer func() {
 455                         if ctx.Err() != nil {
 456                                 v.logger.Debugf("abandoned PutReader goroutine finished with err: %s", err)
 457                         }
 458                 }()
 459                 defer close(ready)
 460                 err = v.bucket.PutReader(loc, bufr, int64(size), "application/octet-stream", s3ACL, opts)
 461                 if err != nil {
 462                         return
 463                 }
 464                 err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 465         }()
 466         select {
 467         case <-ctx.Done():
 468                 v.logger.Debugf("taking PutReader's input away: %s", ctx.Err())
 469                 // Our pipe might be stuck in Write(), waiting for
 470                 // PutReader() to read. If so, un-stick it. This means
 471                 // PutReader will get corrupt data, but that's OK: the
 472                 // size and MD5 won't match, so the write will fail.
 473                 go io.Copy(ioutil.Discard, bufr)
 474                 // CloseWithError() will return once pending I/O is done.
 475                 bufw.CloseWithError(ctx.Err())
 476                 v.logger.Debugf("abandoning PutReader goroutine")
 477                 return ctx.Err()
 478         case <-ready:
 479                 // Unblock pipe in case PutReader did not consume it.
 480                 io.Copy(ioutil.Discard, bufr)
 481                 return v.translateError(err)
 482         }
 483 }
 484
 485 // Touch sets the timestamp for the given locator to the current time.
 486 func (v *S3Volume) Touch(loc string) error {
 487         if v.volume.ReadOnly {
 488                 return MethodDisabledError
 489         }
 490         _, err := v.bucket.Head(loc, nil)
 491         err = v.translateError(err)
 492         if os.IsNotExist(err) && v.fixRace(loc) {
 493                 // The data object got trashed in a race, but fixRace
 494                 // rescued it.
 495         } else if err != nil {
 496                 return err
 497         }
 498         err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 499         return v.translateError(err)
 500 }
 501
 502 // Mtime returns the stored timestamp for the given locator.
 503 func (v *S3Volume) Mtime(loc string) (time.Time, error) {
 504         _, err := v.bucket.Head(loc, nil)
 505         if err != nil {
 506                 return zeroTime, v.translateError(err)
 507         }
 508         resp, err := v.bucket.Head("recent/"+loc, nil)
 509         err = v.translateError(err)
 510         if os.IsNotExist(err) {
 511                 // The data object X exists, but recent/X is missing.
 512                 err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 513                 if err != nil {
 514                         v.logger.WithError(err).Errorf("error creating %q", "recent/"+loc)
 515                         return zeroTime, v.translateError(err)
 516                 }
 517                 v.logger.Infof("created %q to migrate existing block to new storage scheme", "recent/"+loc)
 518                 resp, err = v.bucket.Head("recent/"+loc, nil)
 519                 if err != nil {
 520                         v.logger.WithError(err).Errorf("HEAD failed after creating %q", "recent/"+loc)
 521                         return zeroTime, v.translateError(err)
 522                 }
 523         } else if err != nil {
 524                 // HEAD recent/X failed for some other reason.
 525                 return zeroTime, err
 526         }
 527         return v.lastModified(resp)
 528 }
 529
 530 // IndexTo writes a complete list of locators with the given prefix
 531 // for which Get() can retrieve data.
 532 func (v *S3Volume) IndexTo(prefix string, writer io.Writer) error {
 533         // Use a merge sort to find matching sets of X and recent/X.
 534         dataL := s3Lister{
 535                 Logger:   v.logger,
 536                 Bucket:   v.bucket.Bucket(),
 537                 Prefix:   prefix,
 538                 PageSize: v.IndexPageSize,
 539                 Stats:    &v.bucket.stats,
 540         }
 541         recentL := s3Lister{
 542                 Logger:   v.logger,
 543                 Bucket:   v.bucket.Bucket(),
 544                 Prefix:   "recent/" + prefix,
 545                 PageSize: v.IndexPageSize,
 546                 Stats:    &v.bucket.stats,
 547         }
 548         for data, recent := dataL.First(), recentL.First(); data != nil && dataL.Error() == nil; data = dataL.Next() {
 549                 if data.Key >= "g" {
 550                         // Conveniently, "recent/*" and "trash/*" are
 551                         // lexically greater than all hex-encoded data
 552                         // hashes, so stopping here avoids iterating
 553                         // over all of them needlessly with dataL.
 554                         break
 555                 }
 556                 if !v.isKeepBlock(data.Key) {
 557                         continue
 558                 }
 559
 560                 // stamp is the list entry we should use to report the
 561                 // last-modified time for this data block: it will be
 562                 // the recent/X entry if one exists, otherwise the
 563                 // entry for the data block itself.
 564                 stamp := data
 565
 566                 // Advance to the corresponding recent/X marker, if any
 567                 for recent != nil && recentL.Error() == nil {
 568                         if cmp := strings.Compare(recent.Key[7:], data.Key); cmp < 0 {
 569                                 recent = recentL.Next()
 570                                 continue
 571                         } else if cmp == 0 {
 572                                 stamp = recent
 573                                 recent = recentL.Next()
 574                                 break
 575                         } else {
 576                                 // recent/X marker is missing: we'll
 577                                 // use the timestamp on the data
 578                                 // object.
 579                                 break
 580                         }
 581                 }
 582                 if err := recentL.Error(); err != nil {
 583                         return err
 584                 }
 585                 t, err := time.Parse(time.RFC3339, stamp.LastModified)
 586                 if err != nil {
 587                         return err
 588                 }
 589                 // We truncate sub-second precision here. Otherwise
 590                 // timestamps will never match the RFC1123-formatted
 591                 // Last-Modified values parsed by Mtime().
 592                 fmt.Fprintf(writer, "%s+%d %d\n", data.Key, data.Size, t.Unix()*1000000000)
 593         }
 594         return dataL.Error()
 595 }
 596
 597 // Trash a Keep block.
 598 func (v *S3Volume) Trash(loc string) error {
 599         if v.volume.ReadOnly {
 600                 return MethodDisabledError
 601         }
 602         if t, err := v.Mtime(loc); err != nil {
 603                 return err
 604         } else if time.Since(t) < v.cluster.Collections.BlobSigningTTL.Duration() {
 605                 return nil
 606         }
 607         if v.cluster.Collections.BlobTrashLifetime == 0 {
 608                 if !v.UnsafeDelete {
 609                         return ErrS3TrashDisabled
 610                 }
 611                 return v.translateError(v.bucket.Del(loc))
 612         }
 613         err := v.checkRaceWindow(loc)
 614         if err != nil {
 615                 return err
 616         }
 617         err = v.safeCopy("trash/"+loc, loc)
 618         if err != nil {
 619                 return err
 620         }
 621         return v.translateError(v.bucket.Del(loc))
 622 }
 623
 624 // checkRaceWindow returns a non-nil error if trash/loc is, or might
 625 // be, in the race window (i.e., it's not safe to trash loc).
 626 func (v *S3Volume) checkRaceWindow(loc string) error {
 627         resp, err := v.bucket.Head("trash/"+loc, nil)
 628         err = v.translateError(err)
 629         if os.IsNotExist(err) {
 630                 // OK, trash/X doesn't exist so we're not in the race
 631                 // window
 632                 return nil
 633         } else if err != nil {
 634                 // Error looking up trash/X. We don't know whether
 635                 // we're in the race window
 636                 return err
 637         }
 638         t, err := v.lastModified(resp)
 639         if err != nil {
 640                 // Can't parse timestamp
 641                 return err
 642         }
 643         safeWindow := t.Add(v.cluster.Collections.BlobTrashLifetime.Duration()).Sub(time.Now().Add(time.Duration(v.RaceWindow)))
 644         if safeWindow <= 0 {
 645                 // We can't count on "touch trash/X" to prolong
 646                 // trash/X's lifetime. The new timestamp might not
 647                 // become visible until now+raceWindow, and EmptyTrash
 648                 // is allowed to delete trash/X before then.
 649                 return fmt.Errorf("same block is already in trash, and safe window ended %s ago", -safeWindow)
 650         }
 651         // trash/X exists, but it won't be eligible for deletion until
 652         // after now+raceWindow, so it's safe to overwrite it.
 653         return nil
 654 }
 655
 656 // safeCopy calls PutCopy, and checks the response to make sure the
 657 // copy succeeded and updated the timestamp on the destination object
 658 // (PutCopy returns 200 OK if the request was received, even if the
 659 // copy failed).
 660 func (v *S3Volume) safeCopy(dst, src string) error {
 661         resp, err := v.bucket.Bucket().PutCopy(dst, s3ACL, s3.CopyOptions{
 662                 ContentType:       "application/octet-stream",
 663                 MetadataDirective: "REPLACE",
 664         }, v.bucket.Bucket().Name+"/"+src)
 665         err = v.translateError(err)
 666         if os.IsNotExist(err) {
 667                 return err
 668         } else if err != nil {
 669                 return fmt.Errorf("PutCopy(%q ← %q): %s", dst, v.bucket.Bucket().Name+"/"+src, err)
 670         }
 671         if t, err := time.Parse(time.RFC3339Nano, resp.LastModified); err != nil {
 672                 return fmt.Errorf("PutCopy succeeded but did not return a timestamp: %q: %s", resp.LastModified, err)
 673         } else if time.Now().Sub(t) > maxClockSkew {
 674                 return fmt.Errorf("PutCopy succeeded but returned an old timestamp: %q: %s", resp.LastModified, t)
 675         }
 676         return nil
 677 }
 678
 679 // Get the LastModified header from resp, and parse it as RFC1123 or
 680 // -- if it isn't valid RFC1123 -- as Amazon's variant of RFC1123.
 681 func (v *S3Volume) lastModified(resp *http.Response) (t time.Time, err error) {
 682         s := resp.Header.Get("Last-Modified")
 683         t, err = time.Parse(time.RFC1123, s)
 684         if err != nil && s != "" {
 685                 // AWS example is "Sun, 1 Jan 2006 12:00:00 GMT",
 686                 // which isn't quite "Sun, 01 Jan 2006 12:00:00 GMT"
 687                 // as required by HTTP spec. If it's not a valid HTTP
 688                 // header value, it's probably AWS (or s3test) giving
 689                 // us a nearly-RFC1123 timestamp.
 690                 t, err = time.Parse(nearlyRFC1123, s)
 691         }
 692         return
 693 }
 694
 695 // Untrash moves block from trash back into store
 696 func (v *S3Volume) Untrash(loc string) error {
 697         err := v.safeCopy(loc, "trash/"+loc)
 698         if err != nil {
 699                 return err
 700         }
 701         err = v.bucket.PutReader("recent/"+loc, nil, 0, "application/octet-stream", s3ACL, s3.Options{})
 702         return v.translateError(err)
 703 }
 704
 705 // Status returns a *VolumeStatus representing the current in-use
 706 // storage capacity and a fake available capacity that doesn't make
 707 // the volume seem full or nearly-full.
 708 func (v *S3Volume) Status() *VolumeStatus {
 709         return &VolumeStatus{
 710                 DeviceNum: 1,
 711                 BytesFree: BlockSize * 1000,
 712                 BytesUsed: 1,
 713         }
 714 }
 715
 716 // InternalStats returns bucket I/O and API call counters.
 717 func (v *S3Volume) InternalStats() interface{} {
 718         return &v.bucket.stats
 719 }
 720
 721 // String implements fmt.Stringer.
 722 func (v *S3Volume) String() string {
 723         return fmt.Sprintf("s3-bucket:%+q", v.Bucket)
 724 }
 725
 726 var s3KeepBlockRegexp = regexp.MustCompile(`^[0-9a-f]{32}$`)
 727
 728 func (v *S3Volume) isKeepBlock(s string) bool {
 729         return s3KeepBlockRegexp.MatchString(s)
 730 }
 731
 732 // fixRace(X) is called when "recent/X" exists but "X" doesn't
 733 // exist. If the timestamps on "recent/"+loc and "trash/"+loc indicate
 734 // there was a race between Put and Trash, fixRace recovers from the
 735 // race by Untrashing the block.
 736 func (v *S3Volume) fixRace(loc string) bool {
 737         trash, err := v.bucket.Head("trash/"+loc, nil)
 738         if err != nil {
 739                 if !os.IsNotExist(v.translateError(err)) {
 740                         v.logger.WithError(err).Errorf("fixRace: HEAD %q failed", "trash/"+loc)
 741                 }
 742                 return false
 743         }
 744         trashTime, err := v.lastModified(trash)
 745         if err != nil {
 746                 v.logger.WithError(err).Errorf("fixRace: error parsing time %q", trash.Header.Get("Last-Modified"))
 747                 return false
 748         }
 749
 750         recent, err := v.bucket.Head("recent/"+loc, nil)
 751         if err != nil {
 752                 v.logger.WithError(err).Errorf("fixRace: HEAD %q failed", "recent/"+loc)
 753                 return false
 754         }
 755         recentTime, err := v.lastModified(recent)
 756         if err != nil {
 757                 v.logger.WithError(err).Errorf("fixRace: error parsing time %q", recent.Header.Get("Last-Modified"))
 758                 return false
 759         }
 760
 761         ageWhenTrashed := trashTime.Sub(recentTime)
 762         if ageWhenTrashed >= v.cluster.Collections.BlobSigningTTL.Duration() {
 763                 // No evidence of a race: block hasn't been written
 764                 // since it became eligible for Trash. No fix needed.
 765                 return false
 766         }
 767
 768         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)
 769         v.logger.Infof("fixRace: copying %q to %q to recover from race between Put/Touch and Trash", "recent/"+loc, loc)
 770         err = v.safeCopy(loc, "trash/"+loc)
 771         if err != nil {
 772                 v.logger.WithError(err).Error("fixRace: copy failed")
 773                 return false
 774         }
 775         return true
 776 }
 777
 778 func (v *S3Volume) translateError(err error) error {
 779         switch err := err.(type) {
 780         case *s3.Error:
 781                 if (err.StatusCode == http.StatusNotFound && err.Code == "NoSuchKey") ||
 782                         strings.Contains(err.Error(), "Not Found") {
 783                         return os.ErrNotExist
 784                 }
 785                 // Other 404 errors like NoSuchVersion and
 786                 // NoSuchBucket are different problems which should
 787                 // get called out downstream, so we don't convert them
 788                 // to os.ErrNotExist.
 789         }
 790         return err
 791 }
 792
 793 // EmptyTrash looks for trashed blocks that exceeded BlobTrashLifetime
 794 // and deletes them from the volume.
 795 func (v *S3Volume) EmptyTrash() {
 796         if v.cluster.Collections.BlobDeleteConcurrency < 1 {
 797                 return
 798         }
 799
 800         var bytesInTrash, blocksInTrash, bytesDeleted, blocksDeleted int64
 801
 802         // Define "ready to delete" as "...when EmptyTrash started".
 803         startT := time.Now()
 804
 805         emptyOneKey := func(trash *s3.Key) {
 806                 loc := trash.Key[6:]
 807                 if !v.isKeepBlock(loc) {
 808                         return
 809                 }
 810                 atomic.AddInt64(&bytesInTrash, trash.Size)
 811                 atomic.AddInt64(&blocksInTrash, 1)
 812
 813                 trashT, err := time.Parse(time.RFC3339, trash.LastModified)
 814                 if err != nil {
 815                         v.logger.Warnf("EmptyTrash: %q: parse %q: %s", trash.Key, trash.LastModified, err)
 816                         return
 817                 }
 818                 recent, err := v.bucket.Head("recent/"+loc, nil)
 819                 if err != nil && os.IsNotExist(v.translateError(err)) {
 820                         v.logger.Warnf("EmptyTrash: found trash marker %q but no %q (%s); calling Untrash", trash.Key, "recent/"+loc, err)
 821                         err = v.Untrash(loc)
 822                         if err != nil {
 823                                 v.logger.WithError(err).Errorf("EmptyTrash: Untrash(%q) failed", loc)
 824                         }
 825                         return
 826                 } else if err != nil {
 827                         v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", "recent/"+loc)
 828                         return
 829                 }
 830                 recentT, err := v.lastModified(recent)
 831                 if err != nil {
 832                         v.logger.WithError(err).Warnf("EmptyTrash: %q: error parsing %q", "recent/"+loc, recent.Header.Get("Last-Modified"))
 833                         return
 834                 }
 835                 if trashT.Sub(recentT) < v.cluster.Collections.BlobSigningTTL.Duration() {
 836                         if age := startT.Sub(recentT); age >= v.cluster.Collections.BlobSigningTTL.Duration()-time.Duration(v.RaceWindow) {
 837                                 // recent/loc is too old to protect
 838                                 // loc from being Trashed again during
 839                                 // the raceWindow that starts if we
 840                                 // delete trash/X now.
 841                                 //
 842                                 // Note this means (TrashSweepInterval
 843                                 // < BlobSigningTTL - raceWindow) is
 844                                 // necessary to avoid starvation.
 845                                 v.logger.Infof("EmptyTrash: detected old race for %q, calling fixRace + Touch", loc)
 846                                 v.fixRace(loc)
 847                                 v.Touch(loc)
 848                                 return
 849                         }
 850                         _, err := v.bucket.Head(loc, nil)
 851                         if os.IsNotExist(err) {
 852                                 v.logger.Infof("EmptyTrash: detected recent race for %q, calling fixRace", loc)
 853                                 v.fixRace(loc)
 854                                 return
 855                         } else if err != nil {
 856                                 v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", loc)
 857                                 return
 858                         }
 859                 }
 860                 if startT.Sub(trashT) < v.cluster.Collections.BlobTrashLifetime.Duration() {
 861                         return
 862                 }
 863                 err = v.bucket.Del(trash.Key)
 864                 if err != nil {
 865                         v.logger.WithError(err).Errorf("EmptyTrash: error deleting %q", trash.Key)
 866                         return
 867                 }
 868                 atomic.AddInt64(&bytesDeleted, trash.Size)
 869                 atomic.AddInt64(&blocksDeleted, 1)
 870
 871                 _, err = v.bucket.Head(loc, nil)
 872                 if err == nil {
 873                         v.logger.Warnf("EmptyTrash: HEAD %q succeeded immediately after deleting %q", loc, loc)
 874                         return
 875                 }
 876                 if !os.IsNotExist(v.translateError(err)) {
 877                         v.logger.WithError(err).Warnf("EmptyTrash: HEAD %q failed", loc)
 878                         return
 879                 }
 880                 err = v.bucket.Del("recent/" + loc)
 881                 if err != nil {
 882                         v.logger.WithError(err).Warnf("EmptyTrash: error deleting %q", "recent/"+loc)
 883                 }
 884         }
 885
 886         var wg sync.WaitGroup
 887         todo := make(chan *s3.Key, v.cluster.Collections.BlobDeleteConcurrency)
 888         for i := 0; i < v.cluster.Collections.BlobDeleteConcurrency; i++ {
 889                 wg.Add(1)
 890                 go func() {
 891                         defer wg.Done()
 892                         for key := range todo {
 893                                 emptyOneKey(key)
 894                         }
 895                 }()
 896         }
 897
 898         trashL := s3Lister{
 899                 Logger:   v.logger,
 900                 Bucket:   v.bucket.Bucket(),
 901                 Prefix:   "trash/",
 902                 PageSize: v.IndexPageSize,
 903                 Stats:    &v.bucket.stats,
 904         }
 905         for trash := trashL.First(); trash != nil; trash = trashL.Next() {
 906                 todo <- trash
 907         }
 908         close(todo)
 909         wg.Wait()
 910
 911         if err := trashL.Error(); err != nil {
 912                 v.logger.WithError(err).Error("EmptyTrash: lister failed")
 913         }
 914         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)
 915 }
 916
 917 type s3Lister struct {
 918         Logger     logrus.FieldLogger
 919         Bucket     *s3.Bucket
 920         Prefix     string
 921         PageSize   int
 922         Stats      *s3bucketStats
 923         nextMarker string
 924         buf        []s3.Key
 925         err        error
 926 }
 927
 928 // First fetches the first page and returns the first item. It returns
 929 // nil if the response is the empty set or an error occurs.
 930 func (lister *s3Lister) First() *s3.Key {
 931         lister.getPage()
 932         return lister.pop()
 933 }
 934
 935 // Next returns the next item, fetching the next page if necessary. It
 936 // returns nil if the last available item has already been fetched, or
 937 // an error occurs.
 938 func (lister *s3Lister) Next() *s3.Key {
 939         if len(lister.buf) == 0 && lister.nextMarker != "" {
 940                 lister.getPage()
 941         }
 942         return lister.pop()
 943 }
 944
 945 // Return the most recent error encountered by First or Next.
 946 func (lister *s3Lister) Error() error {
 947         return lister.err
 948 }
 949
 950 func (lister *s3Lister) getPage() {
 951         lister.Stats.TickOps("list")
 952         lister.Stats.Tick(&lister.Stats.Ops, &lister.Stats.ListOps)
 953         resp, err := lister.Bucket.List(lister.Prefix, "", lister.nextMarker, lister.PageSize)
 954         lister.nextMarker = ""
 955         if err != nil {
 956                 lister.err = err
 957                 return
 958         }
 959         if resp.IsTruncated {
 960                 lister.nextMarker = resp.NextMarker
 961         }
 962         lister.buf = make([]s3.Key, 0, len(resp.Contents))
 963         for _, key := range resp.Contents {
 964                 if !strings.HasPrefix(key.Key, lister.Prefix) {
 965                         lister.Logger.Warnf("s3Lister: S3 Bucket.List(prefix=%q) returned key %q", lister.Prefix, key.Key)
 966                         continue
 967                 }
 968                 lister.buf = append(lister.buf, key)
 969         }
 970 }
 971
 972 func (lister *s3Lister) pop() (k *s3.Key) {
 973         if len(lister.buf) > 0 {
 974                 k = &lister.buf[0]
 975                 lister.buf = lister.buf[1:]
 976         }
 977         return
 978 }
 979
 980 // s3bucket wraps s3.bucket and counts I/O and API usage stats. The
 981 // wrapped bucket can be replaced atomically with SetBucket in order
 982 // to update credentials.
 983 type s3bucket struct {
 984         bucket *s3.Bucket
 985         stats  s3bucketStats
 986         mu     sync.Mutex
 987 }
 988
 989 func (b *s3bucket) Bucket() *s3.Bucket {
 990         b.mu.Lock()
 991         defer b.mu.Unlock()
 992         return b.bucket
 993 }
 994
 995 func (b *s3bucket) SetBucket(bucket *s3.Bucket) {
 996         b.mu.Lock()
 997         defer b.mu.Unlock()
 998         b.bucket = bucket
 999 }
1000
1001 func (b *s3bucket) GetReader(path string) (io.ReadCloser, error) {
1002         rdr, err := b.Bucket().GetReader(path)
1003         b.stats.TickOps("get")
1004         b.stats.Tick(&b.stats.Ops, &b.stats.GetOps)
1005         b.stats.TickErr(err)
1006         return NewCountingReader(rdr, b.stats.TickInBytes), err
1007 }
1008
1009 func (b *s3bucket) Head(path string, headers map[string][]string) (*http.Response, error) {
1010         resp, err := b.Bucket().Head(path, headers)
1011         b.stats.TickOps("head")
1012         b.stats.Tick(&b.stats.Ops, &b.stats.HeadOps)
1013         b.stats.TickErr(err)
1014         return resp, err
1015 }
1016
1017 func (b *s3bucket) PutReader(path string, r io.Reader, length int64, contType string, perm s3.ACL, options s3.Options) error {
1018         if length == 0 {
1019                 // goamz will only send Content-Length: 0 when reader
1020                 // is nil due to net.http.Request.ContentLength
1021                 // behavior.  Otherwise, Content-Length header is
1022                 // omitted which will cause some S3 services
1023                 // (including AWS and Ceph RadosGW) to fail to create
1024                 // empty objects.
1025                 r = nil
1026         } else {
1027                 r = NewCountingReader(r, b.stats.TickOutBytes)
1028         }
1029         err := b.Bucket().PutReader(path, r, length, contType, perm, options)
1030         b.stats.TickOps("put")
1031         b.stats.Tick(&b.stats.Ops, &b.stats.PutOps)
1032         b.stats.TickErr(err)
1033         return err
1034 }
1035
1036 func (b *s3bucket) Del(path string) error {
1037         err := b.Bucket().Del(path)
1038         b.stats.TickOps("delete")
1039         b.stats.Tick(&b.stats.Ops, &b.stats.DelOps)
1040         b.stats.TickErr(err)
1041         return err
1042 }
1043
1044 type s3bucketStats struct {
1045         statsTicker
1046         Ops     uint64
1047         GetOps  uint64
1048         PutOps  uint64
1049         HeadOps uint64
1050         DelOps  uint64
1051         ListOps uint64
1052 }
1053
1054 func (s *s3bucketStats) TickErr(err error) {
1055         if err == nil {
1056                 return
1057         }
1058         errType := fmt.Sprintf("%T", err)
1059         if err, ok := err.(*s3.Error); ok {
1060                 errType = errType + fmt.Sprintf(" %d %s", err.StatusCode, err.Code)
1061         }
1062         s.statsTicker.TickErr(err, errType)
1063 }