X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/1267366d66cadcc09972721bf7381f96f8fe73d6..87f3da84318306184165dae50f75ac6721d89285:/services/keepstore/unix_volume.go diff --git a/services/keepstore/unix_volume.go b/services/keepstore/unix_volume.go index 6504f9c16b..dd62cf1319 100644 --- a/services/keepstore/unix_volume.go +++ b/services/keepstore/unix_volume.go @@ -2,7 +2,7 @@ // // SPDX-License-Identifier: AGPL-3.0 -package main +package keepstore import ( "context" @@ -11,7 +11,6 @@ import ( "fmt" "io" "io/ioutil" - "log" "os" "os/exec" "path/filepath" @@ -23,7 +22,7 @@ import ( "syscall" "time" - "git.curoverse.com/arvados.git/sdk/go/arvados" + "git.arvados.org/arvados.git/sdk/go/arvados" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" ) @@ -38,6 +37,7 @@ func newDirectoryVolume(cluster *arvados.Cluster, volume arvados.Volume, logger if err != nil { return nil, err } + v.logger = v.logger.WithField("Volume", v.String()) return v, v.check() } @@ -84,7 +84,7 @@ type UnixVolume struct { // "fa0b6166-3b55-4994-bd3f-92f4e00a1bb0/keep". func (v *UnixVolume) GetDeviceID() string { giveup := func(f string, args ...interface{}) string { - log.Printf(f+"; using blank DeviceID for volume %s", append(args, v)...) + v.logger.Infof(f+"; using blank DeviceID for volume %s", append(args, v)...) return "" } buf, err := exec.Command("findmnt", "--noheadings", "--target", v.Root).CombinedOutput() @@ -135,6 +135,7 @@ func (v *UnixVolume) GetDeviceID() string { if err != nil { return giveup("opening %q: %s", udir, err) } + defer d.Close() uuids, err := d.Readdirnames(0) if err != nil { return giveup("reading %q: %s", udir, err) @@ -143,7 +144,7 @@ func (v *UnixVolume) GetDeviceID() string { link := filepath.Join(udir, uuid) fi, err = os.Stat(link) if err != nil { - log.Printf("error: stat %q: %s", link, err) + v.logger.WithError(err).Errorf("stat(%q) failed", link) continue } if fi.Sys().(*syscall.Stat_t).Ino == ino { @@ -172,10 +173,10 @@ func (v *UnixVolume) Touch(loc string) error { return e } defer v.unlockfile(f) - ts := syscall.NsecToTimespec(time.Now().UnixNano()) + ts := time.Now() v.os.stats.TickOps("utimes") v.os.stats.Tick(&v.os.stats.UtimesOps) - err = syscall.UtimesNano(p, []syscall.Timespec{ts, ts}) + err = os.Chtimes(p, ts, ts) v.os.stats.TickErr(err) return err } @@ -271,39 +272,42 @@ func (v *UnixVolume) WriteBlock(ctx context.Context, loc string, rdr io.Reader) } bdir := v.blockDir(loc) if err := os.MkdirAll(bdir, 0755); err != nil { - log.Printf("%s: could not create directory %s: %s", - loc, bdir, err) - return err - } - - tmpfile, tmperr := v.os.TempFile(bdir, "tmp"+loc) - if tmperr != nil { - log.Printf("ioutil.TempFile(%s, tmp%s): %s", bdir, loc, tmperr) - return tmperr + return fmt.Errorf("error creating directory %s: %s", bdir, err) } bpath := v.blockPath(loc) + tmpfile, err := v.os.TempFile(bdir, "tmp"+loc) + if err != nil { + return fmt.Errorf("TempFile(%s, tmp%s) failed: %s", bdir, loc, err) + } + defer v.os.Remove(tmpfile.Name()) + defer tmpfile.Close() - if err := v.lock(ctx); err != nil { + if err = v.lock(ctx); err != nil { return err } defer v.unlock() n, err := io.Copy(tmpfile, rdr) v.os.stats.TickOutBytes(uint64(n)) if err != nil { - log.Printf("%s: writing to %s: %s", v, bpath, err) - tmpfile.Close() - v.os.Remove(tmpfile.Name()) - return err + return fmt.Errorf("error writing %s: %s", bpath, err) } - if err := tmpfile.Close(); err != nil { - log.Printf("closing %s: %s", tmpfile.Name(), err) - v.os.Remove(tmpfile.Name()) - return err + if err = tmpfile.Close(); err != nil { + return fmt.Errorf("error closing %s: %s", tmpfile.Name(), err) } - if err := v.os.Rename(tmpfile.Name(), bpath); err != nil { - log.Printf("rename %s %s: %s", tmpfile.Name(), bpath, err) - return v.os.Remove(tmpfile.Name()) + // ext4 uses a low-precision clock and effectively backdates + // files by up to 10 ms, sometimes across a 1-second boundary, + // which produces confusing results in logs and tests. We + // avoid this by setting the output file's timestamps + // explicitly, using a higher resolution clock. + ts := time.Now() + v.os.stats.TickOps("utimes") + v.os.stats.Tick(&v.os.stats.UtimesOps) + if err = os.Chtimes(tmpfile.Name(), ts, ts); err != nil { + return fmt.Errorf("error setting timestamps on %s: %s", tmpfile.Name(), err) + } + if err = v.os.Rename(tmpfile.Name(), bpath); err != nil { + return fmt.Errorf("error renaming %s to %s: %s", tmpfile.Name(), bpath, err) } return nil } @@ -314,14 +318,19 @@ func (v *UnixVolume) WriteBlock(ctx context.Context, loc string, rdr io.Reader) func (v *UnixVolume) Status() *VolumeStatus { fi, err := v.os.Stat(v.Root) if err != nil { - log.Printf("%s: os.Stat: %s", v, err) + v.logger.WithError(err).Error("stat failed") return nil } - devnum := fi.Sys().(*syscall.Stat_t).Dev + // uint64() cast here supports GOOS=darwin where Dev is + // int32. If the device number is negative, the unsigned + // devnum won't be the real device number any more, but that's + // fine -- all we care about is getting the same number each + // time. + devnum := uint64(fi.Sys().(*syscall.Stat_t).Dev) var fs syscall.Statfs_t if err := syscall.Statfs(v.Root, &fs); err != nil { - log.Printf("%s: statfs: %s", v, err) + v.logger.WithError(err).Error("statfs failed") return nil } // These calculations match the way df calculates disk usage: @@ -355,47 +364,55 @@ var blockFileRe = regexp.MustCompile(`^[0-9a-f]{32}$`) // e4de7a2810f5554cd39b36d8ddb132ff+67108864 1388701136 // func (v *UnixVolume) IndexTo(prefix string, w io.Writer) error { - var lastErr error rootdir, err := v.os.Open(v.Root) if err != nil { return err } - defer rootdir.Close() v.os.stats.TickOps("readdir") v.os.stats.Tick(&v.os.stats.ReaddirOps) - for { - names, err := rootdir.Readdirnames(1) - if err == io.EOF { - return lastErr - } else if err != nil { - return err - } - if !strings.HasPrefix(names[0], prefix) && !strings.HasPrefix(prefix, names[0]) { + subdirs, err := rootdir.Readdirnames(-1) + rootdir.Close() + if err != nil { + return err + } + for _, subdir := range subdirs { + if !strings.HasPrefix(subdir, prefix) && !strings.HasPrefix(prefix, subdir) { // prefix excludes all blocks stored in this dir continue } - if !blockDirRe.MatchString(names[0]) { + if !blockDirRe.MatchString(subdir) { continue } - blockdirpath := filepath.Join(v.Root, names[0]) - blockdir, err := v.os.Open(blockdirpath) - if err != nil { - log.Print("Error reading ", blockdirpath, ": ", err) - lastErr = err - continue - } - v.os.stats.TickOps("readdir") - v.os.stats.Tick(&v.os.stats.ReaddirOps) - for { - fileInfo, err := blockdir.Readdir(1) - if err == io.EOF { + blockdirpath := filepath.Join(v.Root, subdir) + + var dirents []os.DirEntry + for attempt := 0; ; attempt++ { + v.os.stats.TickOps("readdir") + v.os.stats.Tick(&v.os.stats.ReaddirOps) + dirents, err = os.ReadDir(blockdirpath) + if err == nil { break + } else if attempt < 5 && strings.Contains(err.Error(), "errno 523") { + // EBADCOOKIE (NFS stopped accepting + // our readdirent cookie) -- retry a + // few times before giving up + v.logger.WithError(err).Printf("retry after error reading %s", blockdirpath) + continue + } else { + return err + } + } + + for _, dirent := range dirents { + fileInfo, err := dirent.Info() + if os.IsNotExist(err) { + // File disappeared between ReadDir() and now + continue } else if err != nil { - log.Print("Error reading ", blockdirpath, ": ", err) - lastErr = err - break + v.logger.WithError(err).Errorf("error getting FileInfo for %q in %q", dirent.Name(), blockdirpath) + return err } - name := fileInfo[0].Name() + name := fileInfo.Name() if !strings.HasPrefix(name, prefix) { continue } @@ -404,17 +421,15 @@ func (v *UnixVolume) IndexTo(prefix string, w io.Writer) error { } _, err = fmt.Fprint(w, name, - "+", fileInfo[0].Size(), - " ", fileInfo[0].ModTime().UnixNano(), + "+", fileInfo.Size(), + " ", fileInfo.ModTime().UnixNano(), "\n") if err != nil { - log.Print("Error writing : ", err) - lastErr = err - break + return fmt.Errorf("error writing: %s", err) } } - blockdir.Close() } + return nil } // Trash trashes the block data from the unix storage @@ -534,7 +549,7 @@ func (v *UnixVolume) IsFull() (isFull bool) { if avail, err := v.FreeDiskSpace(); err == nil { isFull = avail < MinFreeKilobytes } else { - log.Printf("%s: FreeDiskSpace: %s", v, err) + v.logger.WithError(err).Errorf("%s: FreeDiskSpace failed", v) isFull = false } @@ -584,7 +599,7 @@ func (v *UnixVolume) lock(ctx context.Context) error { }() select { case <-ctx.Done(): - log.Printf("%s: client hung up while waiting for Serialize lock (%s)", v, time.Since(t0)) + v.logger.Infof("client hung up while waiting for Serialize lock (%s)", time.Since(t0)) go func() { <-locked v.locker.Unlock() @@ -653,7 +668,7 @@ func (v *UnixVolume) EmptyTrash() { } deadline, err := strconv.ParseInt(matches[2], 10, 64) if err != nil { - log.Printf("EmptyTrash: %v: ParseInt(%v): %v", path, matches[2], err) + v.logger.WithError(err).Errorf("EmptyTrash: %v: ParseInt(%q) failed", path, matches[2]) return } atomic.AddInt64(&bytesInTrash, info.Size()) @@ -663,7 +678,7 @@ func (v *UnixVolume) EmptyTrash() { } err = v.os.Remove(path) if err != nil { - log.Printf("EmptyTrash: Remove %v: %v", path, err) + v.logger.WithError(err).Errorf("EmptyTrash: Remove(%q) failed", path) return } atomic.AddInt64(&bytesDeleted, info.Size()) @@ -688,20 +703,30 @@ func (v *UnixVolume) EmptyTrash() { err := filepath.Walk(v.Root, func(path string, info os.FileInfo, err error) error { if err != nil { - log.Printf("EmptyTrash: filepath.Walk: %v: %v", path, err) + v.logger.WithError(err).Errorf("EmptyTrash: filepath.Walk(%q) failed", path) + // Don't give up -- keep walking other + // files/dirs return nil + } else if !info.Mode().IsDir() { + todo <- dirent{path, info} + return nil + } else if path == v.Root || blockDirRe.MatchString(info.Name()) { + // Descend into a directory that we might have + // put trash in. + return nil + } else { + // Don't descend into other dirs. + return filepath.SkipDir } - todo <- dirent{path, info} - return nil }) close(todo) wg.Wait() if err != nil { - log.Printf("EmptyTrash error for %v: %v", v.String(), err) + v.logger.WithError(err).Error("EmptyTrash 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: Deleted %v bytes in %v blocks. Remaining in trash: %v bytes in %v blocks.", bytesDeleted, blocksDeleted, bytesInTrash-bytesDeleted, blocksInTrash-blocksDeleted) } type unixStats struct {