find_*: Add debug logging infrastructure

Enable debug messages a new `--find-debug` command-line option or via
the `CMAKE_FIND_DEBUG_MODE` variable.

This work was started by Chris Wilson, continued by Ray Donnelly, and
then refactored by Robert Maynard to collect information into a single
message per find query.

Co-Author: Ray Donnelly <[email protected]>
Co-Author: Chris Wilson <[email protected]>

Help/manual/cmake.1.rst

@@ -241,6 +241,12 @@ Options
  Print extra information during the cmake run like stack traces with
  :command:`message(SEND_ERROR)` calls.
 
+``--debug-find``
+ Put cmake find in a debug mode.
+
+ Print extra find call information during the cmake run to standard
+ error. Output is designed for human consumption and not for parsing.
+
 ``--trace``
  Put cmake in trace mode.
 

Source/cmFindBase.cxx

@@ -4,8 +4,8 @@
 
 #include <cstddef>
 #include <deque>
-#include <iostream>
 #include <map>
+#include <utility>
 
 #include "cmAlgorithms.h"
 #include "cmMakefile.h"
@@ -116,17 +116,19 @@ bool cmFindBase::ParseArguments(std::vector<std::string> const& argsIn)
       this->NoDefaultPath = true;
     } else if (this->CheckCommonArgument(args[j])) {
       doing = DoingNone;
+    } else {
       // Some common arguments were accidentally supported by CMake
       // 2.4 and 2.6.0 in the short-hand form of the command, so we
       // must support it even though it is not documented.
-    } else if (doing == DoingNames) {
-      this->Names.push_back(args[j]);
-    } else if (doing == DoingPaths) {
-      this->UserGuessArgs.push_back(args[j]);
-    } else if (doing == DoingHints) {
-      this->UserHintsArgs.push_back(args[j]);
-    } else if (doing == DoingPathSuffixes) {
-      this->AddPathSuffix(args[j]);
+      if (doing == DoingNames) {
+        this->Names.push_back(args[j]);
+      } else if (doing == DoingPaths) {
+        this->UserGuessArgs.push_back(args[j]);
+      } else if (doing == DoingHints) {
+        this->UserHintsArgs.push_back(args[j]);
+      } else if (doing == DoingPathSuffixes) {
+        this->AddPathSuffix(args[j]);
+      }
     }
   }
 
@@ -288,33 +290,6 @@ void cmFindBase::FillUserGuessPath()
   paths.AddSuffixes(this->SearchPathSuffixes);
 }
 
-void cmFindBase::PrintFindStuff()
-{
-  std::cerr << "SearchFrameworkLast: " << this->SearchFrameworkLast << "\n";
-  std::cerr << "SearchFrameworkOnly: " << this->SearchFrameworkOnly << "\n";
-  std::cerr << "SearchFrameworkFirst: " << this->SearchFrameworkFirst << "\n";
-  std::cerr << "SearchAppBundleLast: " << this->SearchAppBundleLast << "\n";
-  std::cerr << "SearchAppBundleOnly: " << this->SearchAppBundleOnly << "\n";
-  std::cerr << "SearchAppBundleFirst: " << this->SearchAppBundleFirst << "\n";
-  std::cerr << "VariableName " << this->VariableName << "\n";
-  std::cerr << "VariableDocumentation " << this->VariableDocumentation << "\n";
-  std::cerr << "NoDefaultPath " << this->NoDefaultPath << "\n";
-  std::cerr << "NoCMakeEnvironmentPath " << this->NoCMakeEnvironmentPath
-            << "\n";
-  std::cerr << "NoCMakePath " << this->NoCMakePath << "\n";
-  std::cerr << "NoSystemEnvironmentPath " << this->NoSystemEnvironmentPath
-            << "\n";
-  std::cerr << "NoCMakeSystemPath " << this->NoCMakeSystemPath << "\n";
-  std::cerr << "EnvironmentPath " << this->EnvironmentPath << "\n";
-  std::cerr << "CMakePathName " << this->CMakePathName << "\n";
-  std::cerr << "Names  " << cmJoin(this->Names, " ") << "\n";
-  std::cerr << "\n";
-  std::cerr << "SearchPathSuffixes  ";
-  std::cerr << cmJoin(this->SearchPathSuffixes, "\n") << "\n";
-  std::cerr << "SearchPaths\n";
-  std::cerr << cmWrap("[", this->SearchPaths, "]", "\n") << "\n";
-}
-
 bool cmFindBase::CheckForVariableInCache()
 {
   if (const char* cacheValue =
@@ -343,3 +318,87 @@ bool cmFindBase::CheckForVariableInCache()
   }
   return false;
 }
+
+cmFindBaseDebugState::cmFindBaseDebugState(std::string commandName,
+                                           cmFindBase const* findBase)
+  : FindCommand(findBase)
+  , CommandName(std::move(commandName))
+{
+}
+
+cmFindBaseDebugState::~cmFindBaseDebugState()
+{
+  if (this->FindCommand->DebugMode) {
+    std::string buffer =
+      cmStrCat(this->CommandName, " called with the following settings:\n");
+    buffer += cmStrCat("  VAR: ", this->FindCommand->VariableName, "\n");
+    buffer += cmStrCat(
+      "  NAMES: ", cmWrap("\"", this->FindCommand->Names, "\"", "\n         "),
+      "\n");
+    buffer += cmStrCat(
+      "  Documentation: ", this->FindCommand->VariableDocumentation, "\n");
+    buffer += "  Framework\n";
+    buffer += cmStrCat("    Only Search Frameworks: ",
+                       this->FindCommand->SearchFrameworkOnly, "\n");
+
+    buffer += cmStrCat("    Search Frameworks Last: ",
+                       this->FindCommand->SearchFrameworkLast, "\n");
+    buffer += cmStrCat("    Search Frameworks First: ",
+                       this->FindCommand->SearchFrameworkFirst, "\n");
+    buffer += "  AppBundle\n";
+    buffer += cmStrCat("    Only Search AppBundle: ",
+                       this->FindCommand->SearchAppBundleOnly, "\n");
+    buffer += cmStrCat("    Search AppBundle Last: ",
+                       this->FindCommand->SearchAppBundleLast, "\n");
+    buffer += cmStrCat("    Search AppBundle First: ",
+                       this->FindCommand->SearchAppBundleFirst, "\n");
+
+    if (this->FindCommand->NoDefaultPath) {
+      buffer += "  NO_DEFAULT_PATH Enabled\n";
+    } else {
+      buffer += cmStrCat(
+        "  CMAKE_FIND_USE_CMAKE_PATH: ", !this->FindCommand->NoCMakePath, "\n",
+        "  CMAKE_FIND_USE_CMAKE_ENVIRONMENT_PATH: ",
+        !this->FindCommand->NoCMakeEnvironmentPath, "\n",
+        "  CMAKE_FIND_USE_SYSTEM_ENVIRONMENT_PATH: ",
+        !this->FindCommand->NoSystemEnvironmentPath, "\n",
+        "  CMAKE_FIND_USE_CMAKE_SYSTEM_PATH: ",
+        !this->FindCommand->NoCMakeSystemPath, "\n");
+    }
+
+    buffer +=
+      cmStrCat(this->CommandName, " considered the following locations:\n");
+    for (auto const& state : this->FailedSearchLocations) {
+      std::string path = cmStrCat("  ", state.path);
+      if (!state.regexName.empty()) {
+        path = cmStrCat(path, "/", state.regexName);
+      }
+      buffer += cmStrCat(path, "\n");
+    }
+
+    if (!this->FoundSearchLocation.path.empty()) {
+      buffer += cmStrCat("The item was found at\n  ",
+                         this->FoundSearchLocation.path, "\n");
+    } else {
+      buffer += "The item was not found.\n";
+    }
+
+    this->FindCommand->DebugMessage(buffer);
+  }
+}
+
+void cmFindBaseDebugState::FoundAt(std::string const& path,
+                                   std::string regexName)
+{
+  if (this->FindCommand->DebugMode) {
+    this->FoundSearchLocation = DebugLibState{ std::move(regexName), path };
+  }
+}
+
+void cmFindBaseDebugState::FailedAt(std::string const& path,
+                                    std::string regexName)
+{
+  if (this->FindCommand->DebugMode) {
+    this->FailedSearchLocations.emplace_back(std::move(regexName), path);
+  }
+}

Source/cmFindBase.h

@@ -6,6 +6,7 @@
 #include "cmConfigure.h" // IWYU pragma: keep
 
 #include <string>
+#include <utility>
 #include <vector>
 
 #include "cmFindCommon.h"
@@ -31,7 +32,7 @@ public:
   virtual bool ParseArguments(std::vector<std::string> const& args);
 
 protected:
-  void PrintFindStuff();
+  friend class cmFindBaseDebugState;
   void ExpandPaths();
 
   // see if the VariableName is already set in the cache,
@@ -63,4 +64,33 @@ private:
   void FillUserGuessPath();
 };
 
+class cmFindBaseDebugState
+{
+public:
+  explicit cmFindBaseDebugState(std::string name, cmFindBase const* findBase);
+  ~cmFindBaseDebugState();
+
+  void FoundAt(std::string const& path, std::string regexName = std::string());
+  void FailedAt(std::string const& path,
+                std::string regexName = std::string());
+
+private:
+  struct DebugLibState
+  {
+    DebugLibState() = default;
+    DebugLibState(std::string&& n, std::string p)
+      : regexName(n)
+      , path(std::move(p))
+    {
+    }
+    std::string regexName;
+    std::string path;
+  };
+
+  cmFindBase const* FindCommand;
+  std::string CommandName;
+  std::vector<DebugLibState> FailedSearchLocations;
+  DebugLibState FoundSearchLocation;
+};
+
 #endif

Source/cmFindCommon.cxx

@@ -10,8 +10,10 @@
 #include "cmAlgorithms.h"
 #include "cmExecutionStatus.h"
 #include "cmMakefile.h"
+#include "cmMessageType.h"
 #include "cmStringAlgorithms.h"
 #include "cmSystemTools.h"
+#include "cmake.h"
 
 cmFindCommon::PathGroup cmFindCommon::PathGroup::All("ALL");
 cmFindCommon::PathLabel cmFindCommon::PathLabel::PackageRoot(
@@ -52,6 +54,8 @@ cmFindCommon::cmFindCommon(cmExecutionStatus& status)
   this->SearchAppBundleLast = false;
 
   this->InitializeSearchPathGroups();
+
+  this->DebugMode = false;
 }
 
 void cmFindCommon::SetError(std::string const& e)
@@ -59,6 +63,19 @@ void cmFindCommon::SetError(std::string const& e)
   this->Status.SetError(e);
 }
 
+void cmFindCommon::DebugMessage(std::string const& msg) const
+{
+  if (this->Makefile) {
+    this->Makefile->IssueMessage(MessageType::LOG, msg);
+  }
+}
+
+bool cmFindCommon::ComputeIfDebugModeWanted()
+{
+  return this->Makefile->IsOn("CMAKE_FIND_DEBUG_MODE") ||
+    this->Makefile->GetCMakeInstance()->GetDebugFindOutput();
+}
+
 void cmFindCommon::InitializeSearchPathGroups()
 {
   std::vector<PathLabel>* labels;

Source/cmFindCommon.h

@@ -30,8 +30,11 @@ public:
 
   void SetError(std::string const& e);
 
+  bool DebugModeEnabled() const { return this->DebugMode; }
+
 protected:
   friend class cmSearchPath;
+  friend class cmFindBaseDebugState;
 
   /** Used to define groups of path labels */
   class PathGroup : public cmPathLabel
@@ -96,6 +99,10 @@ protected:
   /** Compute the current default search modes based on global variables.  */
   void SelectDefaultSearchModes();
 
+  /** The `InitialPass` functions of the child classes should set
+      this->DebugMode to the result of this.  */
+  bool ComputeIfDebugModeWanted();
+
   // Path arguments prior to path manipulation routines
   std::vector<std::string> UserHintsArgs;
   std::vector<std::string> UserGuessArgs;
@@ -106,6 +113,8 @@ protected:
   bool CheckCommonArgument(std::string const& arg);
   void AddPathSuffix(std::string const& arg);
 
+  void DebugMessage(std::string const& msg) const;
+  bool DebugMode;
   bool NoDefaultPath;
   bool NoPackageRootPath;
   bool NoCMakePath;

Source/cmMakefile.cxx

@@ -3728,7 +3728,8 @@ void cmMakefile::DisplayStatus(const std::string& message, float s) const
 }
 
 std::string cmMakefile::GetModulesFile(const std::string& filename,
-                                       bool& system) const
+                                       bool& system, bool debug,
+                                       std::string& debugBuffer) const
 {
   std::string result;
 
@@ -3759,6 +3760,9 @@ std::string cmMakefile::GetModulesFile(const std::string& filename,
         moduleInCMakeModulePath = itempl;
         break;
       }
+      if (debug) {
+        debugBuffer = cmStrCat(debugBuffer, "  ", itempl, "\n");
+      }
     }
   }
 
@@ -3767,6 +3771,9 @@ std::string cmMakefile::GetModulesFile(const std::string& filename,
     cmStrCat(cmSystemTools::GetCMakeRoot(), "/Modules/", filename);
   cmSystemTools::ConvertToUnixSlashes(moduleInCMakeRoot);
   if (!cmSystemTools::FileExists(moduleInCMakeRoot)) {
+    if (debug) {
+      debugBuffer = cmStrCat(debugBuffer, "  ", moduleInCMakeRoot, "\n");
+    }
     moduleInCMakeRoot.clear();
   }
 

Source/cmMakefile.h

@@ -766,10 +766,21 @@ public:
   std::string GetModulesFile(const std::string& name) const
   {
     bool system;
-    return this->GetModulesFile(name, system);
+    std::string debugBuffer;
+    return this->GetModulesFile(name, system, false, debugBuffer);
   }
 
-  std::string GetModulesFile(const std::string& name, bool& system) const;
+  /**
+   * Return a location of a file in cmake or custom modules directory
+   */
+  std::string GetModulesFile(const std::string& name, bool& system) const
+  {
+    std::string debugBuffer;
+    return this->GetModulesFile(name, system, false, debugBuffer);
+  }
+
+  std::string GetModulesFile(const std::string& name, bool& system, bool debug,
+                             std::string& debugBuffer) const;
 
   //! Set/Get a property of this directory
   void SetProperty(const std::string& prop, const char* value);

Source/cmSearchPath.h

@@ -5,6 +5,7 @@
 
 #include "cmConfigure.h" // IWYU pragma: keep
 
+#include <cstddef>
 #include <set>
 #include <string>
 #include <vector>
@@ -27,6 +28,7 @@ public:
   ~cmSearchPath();
 
   const std::vector<std::string>& GetPaths() const { return this->Paths; }
+  std::size_t size() const { return this->Paths.size(); }
 
   void ExtractWithout(const std::set<std::string>& ignore,
                       std::vector<std::string>& outPaths,

Source/cmake.cxx

@@ -749,6 +749,9 @@ void cmake::SetArgs(const std::vector<std::string>& args)
       this->LogLevelWasSetViaCLI = true;
     } else if (arg == "--log-context") {
       this->SetShowLogContext(true);
+    } else if (arg.find("--debug-find", 0) == 0) {
+      std::cout << "Running with debug output on for the `find` commands.\n";
+      this->SetDebugFindOutputOn(true);
     } else if (arg.find("--trace-expand", 0) == 0) {
       std::cout << "Running with expanded trace output on.\n";
       this->SetTrace(true);

Source/cmake.h

@@ -409,13 +409,17 @@ public:
     this->CheckInProgressMessages.emplace(std::move(message));
   }
 
+  //! Should `message` command display context.
+  bool GetShowLogContext() const { return this->LogContext; }
+  void SetShowLogContext(bool b) { this->LogContext = b; }
+
   //! Do we want debug output during the cmake run.
   bool GetDebugOutput() { return this->DebugOutput; }
   void SetDebugOutputOn(bool b) { this->DebugOutput = b; }
 
-  //! Should `message` command display context.
-  bool GetShowLogContext() const { return this->LogContext; }
-  void SetShowLogContext(bool b) { this->LogContext = b; }
+  //! Do we want debug output from the find commands during the cmake run.
+  bool GetDebugFindOutput() { return this->DebugFindOutput; }
+  void SetDebugFindOutputOn(bool b) { this->DebugFindOutput = b; }
 
   //! Do we want trace output during the cmake run.
   bool GetTrace() { return this->Trace; }
@@ -577,6 +581,7 @@ private:
   ProgressCallbackType ProgressCallback;
   WorkingMode CurrentWorkingMode = NORMAL_MODE;
   bool DebugOutput = false;
+  bool DebugFindOutput = false;
   bool Trace = false;
   bool TraceExpand = false;
   cmGeneratedFileStream TraceFile;

Source/cmakemain.cxx

@@ -78,6 +78,7 @@ const char* cmDocumentationOptions[][2] = {
     "Do not delete the try_compile build tree. Only "
     "useful on one try_compile at a time." },
   { "--debug-output", "Put cmake in a debug mode." },
+  { "--debug-find", "Put cmake find in a debug mode." },
   { "--trace", "Put cmake in trace mode." },
   { "--trace-expand", "Put cmake in trace mode with variable expansion." },
   { "--trace-source=<file>",