internal/{getproviders,providercache}: improved trace logging

There's a lot going on in these functions that can be hard to follow from
the outside, so we'll add some additional trace logging so that we can
more easily understand why things are behaving the way they are.

internal/getproviders/filesystem_search.go

@@ -36,7 +36,7 @@ func SearchLocalDirectory(baseDir string) (map[addrs.Provider]PackageMetaList, e
 		if err != nil {
 			// This should never happen because the filepath.Walk contract is
 			// for the paths to include the base path.
-			log.Printf("[TRACE] FilesystemMirrorSource: ignoring malformed path %q during walk: %s", fullPath, err)
+			log.Printf("[TRACE] getproviders.SearchLocalDirectory: ignoring malformed path %q during walk: %s", fullPath, err)
 			return nil
 		}
 		relPath := filepath.ToSlash(fsPath)
@@ -88,7 +88,7 @@ func SearchLocalDirectory(baseDir string) (map[addrs.Provider]PackageMetaList, e
 				return nil
 			}
 
-			log.Printf("[TRACE] FilesystemMirrorSource: found %s v%s for %s at %s", providerAddr, version, platform, fullPath)
+			log.Printf("[TRACE] getproviders.SearchLocalDirectory: found %s v%s for %s at %s", providerAddr, version, platform, fullPath)
 
 			meta := PackageMeta{
 				Provider: providerAddr,
@@ -132,11 +132,11 @@ func SearchLocalDirectory(baseDir string) (map[addrs.Provider]PackageMetaList, e
 			prefix := "terraform-provider-" + providerAddr.Type + "_"
 			const suffix = ".zip"
 			if !strings.HasPrefix(normFilename, prefix) {
-				log.Printf("[WARN] ignoring file %q as possible package for %s: lacks expected prefix %q", filename, providerAddr, prefix)
+				log.Printf("[WARN] ignoring file %q as possible package for %s: filename lacks expected prefix %q", fsPath, providerAddr, prefix)
 				return nil
 			}
 			if !strings.HasSuffix(normFilename, suffix) {
-				log.Printf("[WARN] ignoring file %q as possible package for %s: lacks expected suffix %q", filename, providerAddr, suffix)
+				log.Printf("[WARN] ignoring file %q as possible package for %s: filename lacks expected suffix %q", fsPath, providerAddr, suffix)
 				return nil
 			}
 
@@ -145,7 +145,7 @@ func SearchLocalDirectory(baseDir string) (map[addrs.Provider]PackageMetaList, e
 			infoSlice := normFilename[len(prefix) : len(normFilename)-len(suffix)]
 			infoParts := strings.Split(infoSlice, "_")
 			if len(infoParts) < 3 {
-				log.Printf("[WARN] ignoring file %q as possible package for %s: filename does not include version number, target OS, and target architecture", filename, providerAddr)
+				log.Printf("[WARN] ignoring file %q as possible package for %s: filename does not include version number, target OS, and target architecture", fsPath, providerAddr)
 				return nil
 			}
 
@@ -165,7 +165,7 @@ func SearchLocalDirectory(baseDir string) (map[addrs.Provider]PackageMetaList, e
 				return nil
 			}
 
-			log.Printf("[TRACE] FilesystemMirrorSource: found %s v%s for %s at %s", providerAddr, version, platform, fullPath)
+			log.Printf("[TRACE] getproviders.SearchLocalDirectory: found %s v%s for %s at %s", providerAddr, version, platform, fullPath)
 
 			meta := PackageMeta{
 				Provider: providerAddr,

internal/providercache/dir.go

@@ -2,6 +2,7 @@ package providercache
 
 import (
 	"io/ioutil"
+	"log"
 	"path/filepath"
 	"sort"
 	"strings"
@@ -79,6 +80,7 @@ func newDirWithPlatform(baseDir string, platform getproviders.Platform) *Dir {
 // way, even though the Go type system permits it.
 func (d *Dir) AllAvailablePackages() map[addrs.Provider][]CachedProvider {
 	if err := d.fillMetaCache(); err != nil {
+		log.Printf("[WARN] Failed to scan provider cache directory %s: %s", d.baseDir, err)
 		return nil
 	}
 
@@ -127,8 +129,10 @@ func (d *Dir) fillMetaCache() error {
 	// map, so we can distinguish between having scanned and got an empty
 	// result vs. not having scanned successfully at all yet.
 	if d.metaCache != nil {
+		log.Printf("[TRACE] providercache.fillMetaCache: using cached result from previous scan of %s", d.baseDir)
 		return nil
 	}
+	log.Printf("[TRACE] providercache.fillMetaCache: scanning directory %s", d.baseDir)
 
 	allData, err := getproviders.SearchLocalDirectory(d.baseDir)
 	if err != nil {
@@ -149,11 +153,13 @@ func (d *Dir) fillMetaCache() error {
 	for providerAddr, metas := range allData {
 		for _, meta := range metas {
 			if meta.TargetPlatform != d.targetPlatform {
+				log.Printf("[TRACE] providercache.fillMetaCache: ignoring %s because it is for %s, not %s", meta.Location, meta.TargetPlatform, d.targetPlatform)
 				continue
 			}
 			if _, ok := meta.Location.(getproviders.PackageLocalDir); !ok {
 				// PackageLocalDir indicates an unpacked provider package ready
 				// to execute.
+				log.Printf("[TRACE] providercache.fillMetaCache: ignoring %s because it is not an unpacked directory", meta.Location)
 				continue
 			}
 
@@ -162,9 +168,11 @@ func (d *Dir) fillMetaCache() error {
 			if execFile == "" {
 				// If the package doesn't contain a suitable executable then
 				// it isn't considered to be part of our cache.
+				log.Printf("[TRACE] providercache.fillMetaCache: ignoring %s because it is does not seem to contain a suitable plugin executable", meta.Location)
 				continue
 			}
 
+			log.Printf("[TRACE] providercache.fillMetaCache: including %s as a candidate package for %s %s", meta.Location, providerAddr, meta.Version)
 			data[providerAddr] = append(data[providerAddr], CachedProvider{
 				Provider:       providerAddr,
 				Version:        meta.Version,
@@ -174,7 +182,7 @@ func (d *Dir) fillMetaCache() error {
 		}
 	}
 
-	// After we've build our lists per provider, we'll also sort them by
+	// After we've built our lists per provider, we'll also sort them by
 	// version precedence so that the newest available version is always at
 	// index zero. If there are two versions that differ only in build metadata
 	// then it's undefined but deterministic which one we will select here,

internal/providercache/dir_modify.go

@@ -3,6 +3,7 @@ package providercache
 import (
 	"context"
 	"fmt"
+	"log"
 	"os"
 	"path/filepath"
 
@@ -21,6 +22,7 @@ func (d *Dir) InstallPackage(ctx context.Context, meta getproviders.PackageMeta)
 		d.baseDir, meta.Provider, meta.Version, d.targetPlatform,
 	)
 
+	log.Printf("[TRACE] providercache.Dir.InstallPackage: installing %s v%s from %s", meta.Provider, meta.Version, meta.Location)
 	switch location := meta.Location.(type) {
 	case getproviders.PackageHTTPURL:
 		return installFromHTTPURL(ctx, string(location), newPath)
@@ -50,6 +52,7 @@ func (d *Dir) LinkFromOtherCache(entry *CachedProvider) error {
 		d.baseDir, entry.Provider, entry.Version, d.targetPlatform,
 	)
 	currentPath := entry.PackageDir
+	log.Printf("[TRACE] providercache.Dir.LinkFromOtherCache: linking %s v%s from existing cache %s to %s", entry.Provider, entry.Version, currentPath, newPath)
 
 	absNew, err := filepath.Abs(newPath)
 	if err != nil {