From f2cf71d914a070d697bdc6a00ac7be3fdfee2bcb Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Wed, 16 Sep 2020 20:04:26 -0700 Subject: [PATCH] logging: revamped logs from content manager to be machine parseable (#617) * logging: revamped logs from content manager to be machine parseable Logs from the content manager (except reads) are sent to separate log file that is always free from personally-identifiable information (e.g. no file names, just content IDs and blob IDs). Also moved CLI logs to a subdirectory (cli-logs) and put content logs in a parallel directory (content-logs) Also, the log file name will now include the type of the command that was invoked: kopia-20200913-134157-16110-snapshot-create.log Fixes #588 * tests: moved all logs from tests to a separate directory --- internal/logfile/logfile.go | 187 +++++++++++++-------- repo/content/committed_content_index.go | 2 - repo/content/content_manager.go | 20 ++- repo/content/content_manager_indexes.go | 23 +-- repo/content/content_manager_lock_free.go | 6 +- repo/content/content_manager_own_writes.go | 14 +- repo/content/index_blob_manager.go | 33 +++- repo/content/list_cache.go | 2 +- tests/testenv/cli_test_env.go | 15 +- 9 files changed, 197 insertions(+), 105 deletions(-) diff --git a/internal/logfile/logfile.go b/internal/logfile/logfile.go index ef188e79c..5972b92c2 100644 --- a/internal/logfile/logfile.go +++ b/internal/logfile/logfile.go @@ -20,9 +20,13 @@ "github.com/kopia/kopia/cli" "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/ospath" + "github.com/kopia/kopia/repo/content" repologging "github.com/kopia/kopia/repo/logging" ) +var contentLogFormat = logging.MustStringFormatter( + `%{time:2006-01-02 15:04:05.0000000} %{message}`) + var fileLogFormat = logging.MustStringFormatter( `%{time:2006-01-02 15:04:05.000} %{level:.1s} [%{shortfile}] %{message}`) @@ -31,12 +35,16 @@ var logLevels = []string{"debug", "info", "warning", "error"} var ( - logFile = cli.App().Flag("log-file", "Log file name.").String() - logDir = cli.App().Flag("log-dir", "Directory where log files should be written.").Envar("KOPIA_LOG_DIR").Default(ospath.LogsDir()).String() - logDirMaxFiles = cli.App().Flag("log-dir-max-files", "Maximum number of log files to retain").Envar("KOPIA_LOG_DIR_MAX_FILES").Default("1000").Hidden().Int() - logDirMaxAge = cli.App().Flag("log-dir-max-age", "Maximum age of log files to retain").Envar("KOPIA_LOG_DIR_MAX_AGE").Hidden().Duration() - logLevel = cli.App().Flag("log-level", "Console log level").Default("info").Enum(logLevels...) - fileLogLevel = cli.App().Flag("file-log-level", "File log level").Default("debug").Enum(logLevels...) + logFile = cli.App().Flag("log-file", "Override log file.").String() + contentLogFile = cli.App().Flag("content-log-file", "Override content log file.").String() + + logDir = cli.App().Flag("log-dir", "Directory where log files should be written.").Envar("KOPIA_LOG_DIR").Default(ospath.LogsDir()).String() + logDirMaxFiles = cli.App().Flag("log-dir-max-files", "Maximum number of log files to retain").Envar("KOPIA_LOG_DIR_MAX_FILES").Default("1000").Hidden().Int() + logDirMaxAge = cli.App().Flag("log-dir-max-age", "Maximum age of log files to retain").Envar("KOPIA_LOG_DIR_MAX_AGE").Hidden().Default("720h").Duration() + contentLogDirMaxFiles = cli.App().Flag("content-log-dir-max-files", "Maximum number of content log files to retain").Envar("KOPIA_CONTENT_LOG_DIR_MAX_FILES").Default("5000").Hidden().Int() + contentLogDirMaxAge = cli.App().Flag("content-log-dir-max-age", "Maximum age of content log files to retain").Envar("KOPIA_CONTENT_LOG_DIR_MAX_AGE").Default("720h").Hidden().Duration() + logLevel = cli.App().Flag("log-level", "Console log level").Default("info").Enum(logLevels...) + fileLogLevel = cli.App().Flag("file-log-level", "File log level").Default("debug").Enum(logLevels...) ) var log = repologging.GetContextLoggerFunc("kopia") @@ -48,67 +56,108 @@ // Initialize is invoked as part of command execution to create log file just before it's needed. func Initialize(ctx *kingpin.ParseContext) error { - var logBackends []logging.Backend + now := clock.Now() - var logFileName, symlinkName string - - if lfn := *logFile; lfn != "" { - var err error - - logFileName, err = filepath.Abs(lfn) - if err != nil { - return err - } + suffix := "unknown" + if c := ctx.SelectedCommand; c != nil { + suffix = strings.ReplaceAll(c.FullCommand(), " ", "-") } - var shouldSweepLogs bool - - if logFileName == "" && *logDir != "" { - logBaseName := fmt.Sprintf("%v%v-%v%v", logFileNamePrefix, clock.Now().Format("20060102-150405"), os.Getpid(), logFileNameSuffix) - logFileName = filepath.Join(*logDir, logBaseName) - symlinkName = "kopia.latest.log" - - if *logDirMaxAge > 0 || *logDirMaxFiles > 0 { - shouldSweepLogs = true - } - } - - if logFileName != "" { - logFileDir := filepath.Dir(logFileName) - logFileBaseName := filepath.Base(logFileName) - - if err := os.MkdirAll(logFileDir, 0o700); err != nil { - fmt.Fprintln(os.Stderr, "Unable to create logs directory:", err) - } - - logBackends = append( - logBackends, - levelFilter( - *fileLogLevel, - logging.NewBackendFormatter( - &onDemandBackend{ - logDir: logFileDir, - logFileBaseName: logFileBaseName, - symlinkName: symlinkName, - }, fileLogFormat))) - } - - logBackends = append(logBackends, - levelFilter( - *logLevel, - logging.NewBackendFormatter( - logging.NewLogBackend(os.Stderr, "", 0), - consoleLogFormat))) - - logging.SetBackend(logBackends...) - - if shouldSweepLogs { - go sweepLogDir(context.TODO(), *logDir, *logDirMaxFiles, *logDirMaxAge) - } + // activate backends + logging.SetBackend( + setupConsoleBackend(), + setupLogFileBackend(now, suffix), + setupContentLogFileBackend(now, suffix), + ) return nil } +func setupConsoleBackend() logging.Backend { + l := logging.AddModuleLevel(logging.NewBackendFormatter( + logging.NewLogBackend(os.Stderr, "", 0), + consoleLogFormat)) + + // do not output content logs to the console + l.SetLevel(logging.CRITICAL, content.FormatLogModule) + + // log everything else at a level specified using --log-level + l.SetLevel(logLevelFromFlag(*logLevel), "") + + return l +} + +func setupLogFileBasedLogger(now time.Time, subdir, suffix, logFileOverride string, maxFiles int, maxAge time.Duration) logging.Backend { + var logFileName, symlinkName string + + if logFileOverride != "" { + var err error + + logFileName, err = filepath.Abs(logFileOverride) + if err != nil { + fmt.Fprintln(os.Stderr, "Unable to resolve logs path", err) + } + } + + if logFileName == "" { + logBaseName := fmt.Sprintf("%v%v-%v-%v%v", logFileNamePrefix, now.Format("20060102-150405"), os.Getpid(), suffix, logFileNameSuffix) + logFileName = filepath.Join(*logDir, subdir, logBaseName) + symlinkName = "latest.log" + } + + logDir := filepath.Dir(logFileName) + logFileBaseName := filepath.Base(logFileName) + + if err := os.MkdirAll(logDir, 0o700); err != nil { + fmt.Fprintln(os.Stderr, "Unable to create logs directory:", err) + } + + // do not scrub directory if custom log file has been provided. + if logFileOverride == "" && shouldSweepLog(maxFiles, maxAge) { + go sweepLogDir(context.TODO(), logDir, maxFiles, maxAge) + } + + return &onDemandBackend{ + logDir: logDir, + logFileBaseName: logFileBaseName, + symlinkName: symlinkName, + } +} + +func setupLogFileBackend(now time.Time, suffix string) logging.Backend { + l := logging.AddModuleLevel( + logging.NewBackendFormatter( + setupLogFileBasedLogger(now, "cli-logs", suffix, *logFile, *logDirMaxFiles, *logDirMaxAge), + fileLogFormat)) + + // do not output content logs to the regular log file + l.SetLevel(logging.CRITICAL, content.FormatLogModule) + + // log everything else at a level specified using --file-level + l.SetLevel(logLevelFromFlag(*fileLogLevel), "") + + return l +} + +func setupContentLogFileBackend(now time.Time, suffix string) logging.Backend { + l := logging.AddModuleLevel( + logging.NewBackendFormatter( + setupLogFileBasedLogger(now, "content-logs", suffix, *contentLogFile, *contentLogDirMaxFiles, *contentLogDirMaxAge), + contentLogFormat)) + + // only log content entries + l.SetLevel(logging.DEBUG, content.FormatLogModule) + + // do not log anything else + l.SetLevel(logging.CRITICAL, "") + + return l +} + +func shouldSweepLog(maxFiles int, maxAge time.Duration) bool { + return maxFiles > 0 || maxAge > 0 +} + func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time.Duration) { var timeCutoff time.Time if maxAge > 0 { @@ -150,23 +199,19 @@ func sweepLogDir(ctx context.Context, dirname string, maxCount int, maxAge time. } } -func levelFilter(level string, writer logging.Backend) logging.Backend { - l := logging.AddModuleLevel(writer) - - switch level { +func logLevelFromFlag(levelString string) logging.Level { + switch levelString { case "debug": - l.SetLevel(logging.DEBUG, "") + return logging.DEBUG case "info": - l.SetLevel(logging.INFO, "") + return logging.INFO case "warning": - l.SetLevel(logging.WARNING, "") + return logging.WARNING case "error": - l.SetLevel(logging.ERROR, "") + return logging.ERROR default: - l.SetLevel(logging.CRITICAL, "") + return logging.CRITICAL } - - return l } type onDemandBackend struct { diff --git a/repo/content/committed_content_index.go b/repo/content/committed_content_index.go index a772f700a..b49c985ee 100644 --- a/repo/content/committed_content_index.go +++ b/repo/content/committed_content_index.go @@ -101,8 +101,6 @@ func (b *committedContentIndex) use(ctx context.Context, packFiles []blob.ID) (b return false, nil } - log(ctx).Debugf("set of index files has changed (had %v, now %v)", len(b.inUse), len(packFiles)) - var newMerged mergedIndex newInUse := map[blob.ID]packIndex{} diff --git a/repo/content/content_manager.go b/repo/content/content_manager.go index d4d19f818..d8fbed0e4 100644 --- a/repo/content/content_manager.go +++ b/repo/content/content_manager.go @@ -24,7 +24,7 @@ var ( log = logging.GetContextLoggerFunc("kopia/content") - formatLog = logging.GetContextLoggerFunc("kopia/content/format") + formatLog = logging.GetContextLoggerFunc(FormatLogModule) ) // Prefixes for pack blobs. @@ -32,6 +32,8 @@ PackBlobIDPrefixRegular blob.ID = "p" PackBlobIDPrefixSpecial blob.ID = "q" + FormatLogModule = "kopia/format" + maxHashSize = 64 defaultEncryptionBufferPoolSegmentSize = 8 << 20 // 8 MB ) @@ -104,7 +106,7 @@ func (bm *Manager) DeleteContent(ctx context.Context, contentID ID) error { bm.lock() defer bm.unlock() - log(ctx).Debugf("DeleteContent(%q)", contentID) + formatLog(ctx).Debugf("delete-content %v", contentID) // remove from all pending packs for _, pp := range bm.pendingPacks { @@ -161,7 +163,7 @@ func (bm *Manager) addToPackUnlocked(ctx context.Context, contentID ID, data []b // do not start new uploads while flushing for bm.flushing { - formatLog(ctx).Debugf("waiting before flush completes") + formatLog(ctx).Debugf("wait-before-flush") bm.cond.Wait() } @@ -378,10 +380,11 @@ func (bm *Manager) prepareAndWritePackInternal(ctx context.Context, pp *pendingP if pp.currentPackData.Length() > 0 { if err := bm.writePackFileNotLocked(ctx, pp.packBlobID, pp.currentPackData.Bytes); err != nil { + formatLog(ctx).Debugf("failed-pack %v %v", pp.packBlobID, err) return nil, errors.Wrap(err, "can't save pack data content") } - formatLog(ctx).Debugf("wrote pack file: %v (%v bytes)", pp.packBlobID, pp.currentPackData.Length()) + formatLog(ctx).Debugf("wrote-pack %v %v", pp.packBlobID, pp.currentPackData.Length()) } return packFileIndex, nil @@ -423,6 +426,8 @@ func (bm *Manager) Flush(ctx context.Context) error { bm.lock() defer bm.unlock() + formatLog(ctx).Debugf("flush") + bm.flushing = true defer func() { @@ -453,7 +458,7 @@ func (bm *Manager) Flush(ctx context.Context) error { // RewriteContent causes reads and re-writes a given content using the most recent format. func (bm *Manager) RewriteContent(ctx context.Context, contentID ID) error { - log(ctx).Debugf("RewriteContent(%q)", contentID) + formatLog(ctx).Debugf("rewrite-content %v", contentID) pp, bi, err := bm.getContentInfo(contentID) if err != nil { @@ -543,8 +548,13 @@ func (bm *Manager) WriteContent(ctx context.Context, data []byte, prefix ID) (ID // content already tracked if _, bi, err := bm.getContentInfo(contentID); err == nil { if !bi.Deleted { + formatLog(ctx).Debugf("write-content %v already-exists", contentID) return contentID, nil } + + formatLog(ctx).Debugf("write-content %v previously-deleted", contentID) + } else { + formatLog(ctx).Debugf("write-content %v new", contentID) } err := bm.addToPackUnlocked(ctx, contentID, data, false) diff --git a/repo/content/content_manager_indexes.go b/repo/content/content_manager_indexes.go index 0f434f09d..98bfd7299 100644 --- a/repo/content/content_manager_indexes.go +++ b/repo/content/content_manager_indexes.go @@ -33,7 +33,6 @@ func (bm *Manager) CompactIndexes(ctx context.Context, opt CompactOptions) error } blobsToCompact := bm.getBlobsToCompact(ctx, indexBlobs, opt) - log(ctx).Debugf("blobs to compact: %v", blobsToCompact) if err := bm.compactIndexBlobs(ctx, blobsToCompact, opt); err != nil { return errors.Wrap(err, "error performing compaction") @@ -68,16 +67,16 @@ func (bm *Manager) getBlobsToCompact(ctx context.Context, indexBlobs []IndexBlob if len(nonCompactedBlobs) < opt.MaxSmallBlobs { // current count is below min allowed - nothing to do - formatLog(ctx).Debugf("no small contents to compact") + log(ctx).Debugf("no small contents to compact") return nil } if len(verySmallBlobs) > len(nonCompactedBlobs)/2 && mediumSizedBlobCount+1 < opt.MaxSmallBlobs { - formatLog(ctx).Debugf("compacting %v very small contents", len(verySmallBlobs)) + log(ctx).Debugf("compacting %v very small contents", len(verySmallBlobs)) return verySmallBlobs } - formatLog(ctx).Debugf("compacting all %v non-compacted contents", len(nonCompactedBlobs)) + log(ctx).Debugf("compacting all %v non-compacted contents", len(nonCompactedBlobs)) return nonCompactedBlobs } @@ -87,14 +86,12 @@ func (bm *Manager) compactIndexBlobs(ctx context.Context, indexBlobs []IndexBlob return nil } - formatLog(ctx).Debugf("compacting %v index blobs", len(indexBlobs)) - bld := make(packIndexBuilder) var inputs, outputs []blob.Metadata - for _, indexBlob := range indexBlobs { - formatLog(ctx).Debugf("adding index entries %v to compacted index", indexBlob) + for i, indexBlob := range indexBlobs { + formatLog(ctx).Debugf("compacting-entries[%v/%v] %v", i, len(indexBlobs), indexBlob) if err := bm.addIndexBlobsToBuilder(ctx, bld, indexBlob); err != nil { return errors.Wrap(err, "error adding index to builder") @@ -121,7 +118,7 @@ func (bm *Manager) compactIndexBlobs(ctx context.Context, indexBlobs []IndexBlob // it must be a no-op. for _, indexBlob := range indexBlobs { if indexBlob.BlobID == compactedIndexBlob.BlobID { - formatLog(ctx).Debugf("compaction was a no-op") + formatLog(ctx).Debugf("compaction-noop") return nil } } @@ -138,18 +135,22 @@ func (bm *Manager) compactIndexBlobs(ctx context.Context, indexBlobs []IndexBlob func dropContentsFromBuilder(ctx context.Context, bld packIndexBuilder, opt CompactOptions) { for _, dc := range opt.DropContents { if _, ok := bld[dc]; ok { - log(ctx).Debugf("dropping content %v", dc) + formatLog(ctx).Debugf("manual-drop-from-index %v", dc) delete(bld, dc) } } if !opt.DropDeletedBefore.IsZero() { + formatLog(ctx).Debugf("drop-content-deleted-before %v", opt.DropDeletedBefore) + for _, i := range bld { if i.Deleted && i.Timestamp().Before(opt.DropDeletedBefore) { - log(ctx).Debugf("dropping content %v deleted at %v", i.ID, i.Timestamp()) + formatLog(ctx).Debugf("drop-from-index-old-deleted %v %v", i.ID, i.Timestamp()) delete(bld, i.ID) } } + + formatLog(ctx).Debugf("finished drop-content-deleted-before %v", opt.DropDeletedBefore) } } diff --git a/repo/content/content_manager_lock_free.go b/repo/content/content_manager_lock_free.go index c2a146678..edee70b0c 100644 --- a/repo/content/content_manager_lock_free.go +++ b/repo/content/content_manager_lock_free.go @@ -197,7 +197,7 @@ func (bm *lockFreeManager) unprocessedIndexBlobsUnlocked(ctx context.Context, co } if has { - log(ctx).Debugf("index blob %q already in cache, skipping", c.BlobID) + formatLog(ctx).Debugf("index-already-cached %v", c.BlobID) continue } @@ -280,8 +280,6 @@ func (bm *lockFreeManager) decryptAndVerify(encrypted, iv []byte) ([]byte, error } func (bm *lockFreeManager) preparePackDataContent(ctx context.Context, pp *pendingPackInfo) (packIndexBuilder, error) { - formatLog(ctx).Debugf("preparing content data with %v items (contents %v)", len(pp.currentPackItems), pp.currentPackData.Length()) - packFileIndex := packIndexBuilder{} haveContent := false @@ -290,6 +288,8 @@ func (bm *lockFreeManager) preparePackDataContent(ctx context.Context, pp *pendi haveContent = true } + formatLog(ctx).Debugf("add-to-pack %v %v p:%v %v d:%v", pp.packBlobID, info.ID, info.PackBlobID, info.Length, info.Deleted) + packFileIndex.Add(info) } diff --git a/repo/content/content_manager_own_writes.go b/repo/content/content_manager_own_writes.go index b51b4b037..d1982e67f 100644 --- a/repo/content/content_manager_own_writes.go +++ b/repo/content/content_manager_own_writes.go @@ -47,7 +47,7 @@ type memoryOwnWritesCache struct { } func (n *memoryOwnWritesCache) add(ctx context.Context, mb blob.Metadata) error { - log(ctx).Debugf("adding %v to own-writes cache", mb.BlobID) + formatLog(ctx).Debugf("own-writes-cache-add %v", mb) n.entries.Store(mb.BlobID, mb) return nil @@ -73,7 +73,7 @@ func (n *memoryOwnWritesCache) merge(ctx context.Context, prefix blob.ID, source if age := n.timeNow().Sub(md.Timestamp); age < ownWritesCacheRetention { result = append(result, md) } else { - log(ctx).Debugf("deleting stale own writes cache entry: %v (%v)", key, age) + formatLog(ctx).Debugf("own-writes-cache-expired %v %v", key, age) n.entries.Delete(key) } @@ -81,7 +81,7 @@ func (n *memoryOwnWritesCache) merge(ctx context.Context, prefix blob.ID, source return true }) - return mergeOwnWrites(ctx, source, result), nil + return mergeOwnWrites(source, result), nil } // persistentOwnWritesCache is an implementation of ownWritesCache that caches entries to strongly consistent blob storage. @@ -123,7 +123,7 @@ func (d *persistentOwnWritesCache) merge(ctx context.Context, prefix blob.ID, so if age := d.timeNow().Sub(md.Timestamp); age < ownWritesCacheRetention { myWrites = append(myWrites, originalMD) } else { - log(ctx).Debugf("deleting blob %v from own-write cache because it's too old: %v (%v)", md.BlobID, age, originalMD.Timestamp) + log(ctx).Debugf("own-writes-cache-expired: %v (%v)", md, age) if err := d.st.DeleteBlob(ctx, md.BlobID); err != nil && !errors.Is(err, blob.ErrBlobNotFound) { return errors.Wrap(err, "error deleting stale blob") @@ -133,7 +133,7 @@ func (d *persistentOwnWritesCache) merge(ctx context.Context, prefix blob.ID, so return nil }) - return mergeOwnWrites(ctx, source, myWrites), err + return mergeOwnWrites(source, myWrites), err } func (d *persistentOwnWritesCache) delete(ctx context.Context, blobID blob.ID) error { @@ -144,7 +144,7 @@ func (d *persistentOwnWritesCache) delete(ctx context.Context, blobID blob.ID) e }) } -func mergeOwnWrites(ctx context.Context, source, own []blob.Metadata) []blob.Metadata { +func mergeOwnWrites(source, own []blob.Metadata) []blob.Metadata { m := map[blob.ID]blob.Metadata{} for _, v := range source { @@ -165,8 +165,6 @@ func mergeOwnWrites(ctx context.Context, source, own []blob.Metadata) []blob.Met s = append(s, v) } - log(ctx).Debugf("merged %v backend blobs and %v local blobs into %v", source, own, s) - return s } diff --git a/repo/content/index_blob_manager.go b/repo/content/index_blob_manager.go index e2e2c5b10..44e925fd7 100644 --- a/repo/content/index_blob_manager.go +++ b/repo/content/index_blob_manager.go @@ -90,6 +90,14 @@ func (m *indexBlobManagerImpl) listIndexBlobs(ctx context.Context, includeInacti return nil, errors.Wrap(err, "error merging local writes for index blobs") } + for i, sib := range storageIndexBlobs { + formatLog(ctx).Debugf("found-index-blobs[%v] = %v", i, sib) + } + + for i, clm := range compactionLogMetadata { + formatLog(ctx).Debugf("found-compaction-blobs[%v] %v", i, clm) + } + indexMap := map[blob.ID]*IndexBlobInfo{} addBlobsToIndex(indexMap, storageIndexBlobs) @@ -106,6 +114,10 @@ func (m *indexBlobManagerImpl) listIndexBlobs(ctx context.Context, includeInacti results = append(results, *v) } + for i, res := range results { + formatLog(ctx).Debugf("active-index-blobs[%v] = %v", i, res) + } + return results, nil } @@ -128,7 +140,15 @@ func (m *indexBlobManagerImpl) registerCompaction(ctx context.Context, inputs, o return errors.Wrap(err, "unable to write compaction log") } - formatLog(ctx).Debugf("compacted indexes %v into %v and wrote log %v", inputs, outputs, compactionLogBlobMetadata) + for i, input := range inputs { + formatLog(ctx).Debugf("compacted-input[%v/%v] %v", i, len(inputs), input) + } + + for i, output := range outputs { + formatLog(ctx).Debugf("compacted-output[%v/%v] %v", i, len(outputs), output) + } + + formatLog(ctx).Debugf("compaction-log %v %v", compactionLogBlobMetadata.BlobID, compactionLogBlobMetadata.Timestamp) if err := m.deleteOldBlobs(ctx, compactionLogBlobMetadata); err != nil { return errors.Wrap(err, "error deleting old index blobs") @@ -204,16 +224,20 @@ func (m *indexBlobManagerImpl) encryptAndWriteBlob(ctx context.Context, data []b err = m.st.PutBlob(ctx, blobID, gather.FromSlice(data2)) if err != nil { + formatLog(ctx).Debugf("write-index-blob %v failed %v", blobID, err) return blob.Metadata{}, err } bm, err := m.st.GetMetadata(ctx, blobID) if err != nil { + formatLog(ctx).Debugf("write-index-blob-get-metadata %v failed %v", blobID, err) return blob.Metadata{}, errors.Wrap(err, "unable to get blob metadata") } + formatLog(ctx).Debugf("write-index-blob %v %v %v", blobID, bm.Length, bm.Timestamp) + if err := m.ownWritesCache.add(ctx, bm); err != nil { - log(ctx).Warningf("unable to cache own write: %v", err) + formatLog(ctx).Warningf("own-writes-cache failure: %v", err) } return bm, nil @@ -381,9 +405,12 @@ func (m *indexBlobManagerImpl) delayCleanupBlobs(ctx context.Context, blobIDs [] func (m *indexBlobManagerImpl) deleteBlobsFromStorageAndCache(ctx context.Context, blobIDs []blob.ID) error { for _, blobID := range blobIDs { if err := m.st.DeleteBlob(ctx, blobID); err != nil && !errors.Is(err, blob.ErrBlobNotFound) { + formatLog(ctx).Debugf("delete-blob failed %v %v", blobID, err) return errors.Wrapf(err, "unable to delete blob %v", blobID) } + formatLog(ctx).Debugf("delete-blob succeeded %v", blobID) + if err := m.ownWritesCache.delete(ctx, blobID); err != nil { return errors.Wrapf(err, "unable to delete blob %v from own-writes cache", blobID) } @@ -475,7 +502,7 @@ func removeCompactedIndexes(ctx context.Context, m map[blob.ID]*IndexBlobInfo, c for _, cl := range validCompactionLogs { for _, ib := range cl.InputMetadata { if md := m[ib.BlobID]; md != nil && md.Superseded == nil { - log(ctx).Debugf("ignoring index blob %v (%v) because it's been compacted to %v", ib, md.Timestamp, cl.OutputMetadata) + formatLog(ctx).Debugf("ignore-index-blob %v compacted to %v", ib, cl.OutputMetadata) if markAsSuperseded { md.Superseded = cl.OutputMetadata diff --git a/repo/content/list_cache.go b/repo/content/list_cache.go index 270927219..a20b33701 100644 --- a/repo/content/list_cache.go +++ b/repo/content/list_cache.go @@ -30,7 +30,7 @@ func (c *listCache) listBlobs(ctx context.Context, prefix blob.ID) ([]blob.Metad if err == nil { expirationTime := ci.Timestamp.Add(c.listCacheDuration) if clock.Now().Before(expirationTime) { - log(ctx).Debugf("retrieved list of %v '%v' index blobs from cache", len(ci.Blobs), prefix) + formatLog(ctx).Debugf("list-from-cache '%v' found %v", prefix, len(ci.Blobs)) return ci.Blobs, nil } } else if !errors.Is(err, blob.ErrBlobNotFound) { diff --git a/tests/testenv/cli_test_env.go b/tests/testenv/cli_test_env.go index 21ae0a61a..c08716d3a 100644 --- a/tests/testenv/cli_test_env.go +++ b/tests/testenv/cli_test_env.go @@ -41,6 +41,8 @@ type CLITest struct { Environment []string PassthroughStderr bool + + LogsDir string } // SourceInfo reprents a single source (user@host:/path) with its snapshots. @@ -76,9 +78,15 @@ func NewCLITest(t *testing.T) *CLITest { t.Fatalf("can't create temp directory: %v", err) } + logsDir, err := ioutil.TempDir("", "kopia-logs") + if err != nil { + t.Fatalf("can't create temp directory: %v", err) + } + fixedArgs := []string{ // use per-test config file, to avoid clobbering current user's setup. "--config-file", filepath.Join(ConfigDir, ".kopia.config"), + "--log-dir", logsDir, } // disable the use of keyring @@ -97,6 +105,7 @@ func NewCLITest(t *testing.T) *CLITest { ConfigDir: ConfigDir, Exe: filepath.FromSlash(exe), fixedArgs: fixedArgs, + LogsDir: logsDir, Environment: []string{ "KOPIA_PASSWORD=" + repoPassword, "KOPIA_ADVANCED_COMMANDS=enabled", @@ -107,7 +116,7 @@ func NewCLITest(t *testing.T) *CLITest { // Cleanup cleans up the test Environment unless the test has failed. func (e *CLITest) Cleanup(t *testing.T) { if t.Failed() { - t.Logf("skipped cleanup for failed test, examine repository: %v", e.RepoDir) + t.Logf("skipped cleanup for failed test, examine repository: %v and logs %v", e.RepoDir, e.LogsDir) return } @@ -118,6 +127,10 @@ func (e *CLITest) Cleanup(t *testing.T) { if e.ConfigDir != "" { os.RemoveAll(e.ConfigDir) } + + if e.LogsDir != "" { + os.RemoveAll(e.LogsDir) + } } // RunAndExpectSuccess runs the given command, expects it to succeed and returns its output lines.