ConfigureLog: Add infrastructure for structured configure event logging

Add infrastructure for a "configure log".  Use YAML for a balance of
machine- and human-readability to records details of configure-time
events in a structured format.

Teach the RunCMake test framework to support matching the configure log.

Issue: #23200

Help/index.rst

@@ -57,6 +57,7 @@ Reference Manuals
    /manual/cmake-buildsystem.7
    /manual/cmake-commands.7
    /manual/cmake-compile-features.7
+   /manual/cmake-configure-log.7
    /manual/cmake-developer.7
    /manual/cmake-env-variables.7
    /manual/cmake-file-api.7

Help/manual/cmake-configure-log.7.rst

@@ -0,0 +1,102 @@
+.. cmake-manual-description: CMake Configure Log
+
+cmake-configure-log(7)
+**********************
+
+.. versionadded:: 3.26
+
+.. only:: html
+
+   .. contents::
+
+Introduction
+============
+
+CMake writes a running log, known as the configure log,
+of certain events that occur during the "configure" step.
+The log file is located at::
+
+  ${CMAKE_BINARY_DIR}/CMakeFiles/CMakeConfigureLog.yaml
+
+The configure log does *not* contain a log of all output, errors,
+or messages printed while configuring a project.  It is a log of
+detailed information about specific events, such as toolchain inspection
+by :command:`try_compile`, meant for use in debugging the configuration
+of a build tree.
+
+Log Structure
+=============
+
+The configure log is designed to be both machine- and human-readable.
+
+The log file is a YAML document stream containing zero or more YAML
+documents separated by document markers.  Each document begins
+with a ``---`` document marker line, contains a single YAML mapping
+that logs events from one CMake "configure" step, and, if the configure
+step finished normally, ends with a ``...`` document marker line:
+
+.. code-block:: yaml
+
+  ---
+  version:
+    major: 1
+    minor: 0
+  events:
+    -
+      kind: "..."
+      # (other fields omitted)
+    -
+      kind: "..."
+      # (other fields omitted)
+  ...
+
+A new document is appended to the log every time CMake configures
+the build tree and logs new events.
+
+The keys of the each document root mapping are:
+
+``version``
+  A YAML mapping that describes the schema version of the log document.
+  It has keys ``major`` and ``minor`` holding non-negative integer values.
+
+``events``
+  A YAML block sequence of nodes corresponding to events logged during
+  one CMake "configure" step.  Each event is a YAML node containing one
+  of the `Event Kinds`_ documented below.
+
+Text Block Encoding
+-------------------
+
+In order to make the log human-readable, text blocks are always
+represented using YAML literal block scalars (``|``).
+Since literal block scalars do not support escaping, backslashes
+and non-printable characters are encoded at the application layer:
+
+* ``\\`` encodes a backslash.
+* ``\xXX`` encodes a byte using two hexadecimal digits, ``XX``.
+
+.. _`configure-log event kinds`:
+
+Event Kinds
+===========
+
+Every event kind is represented by a YAML mapping of the form:
+
+.. code-block:: yaml
+
+  kind: "<kind>"
+  backtrace:
+    - "<file>:<line> (<function>)"
+  #...event-specific keys...
+
+The keys common to all events are:
+
+``kind``
+  A string identifying the event kind.
+
+``backtrace``
+  A YAML block sequence reporting the call stack of CMake source
+  locations at which the event occurred.  Each node is a string
+  specifying one location formatted as ``<file>:<line> (<function>)``.
+
+Additional mapping keys are specific to each event kind.

Help/release/dev/configure-log.rst

@@ -0,0 +1,5 @@
+Configure Log
+-------------
+
+* CMake now writes a YAML log of configure-time checks.
+  See the :manual:`cmake-configure-log(7)` manual.

Source/CMakeLists.txt

@@ -160,6 +160,8 @@ add_library(
   cmComputeLinkInformation.h
   cmComputeTargetDepends.h
   cmComputeTargetDepends.cxx
+  cmConfigureLog.h
+  cmConfigureLog.cxx
   cmConsoleBuf.h
   cmConsoleBuf.cxx
   cmConstStack.h

Source/cmConfigureLog.cxx

@@ -0,0 +1,238 @@
+/* Distributed under the OSI-approved BSD 3-Clause License.  See accompanying
+   file Copyright.txt or https://cmake.org/licensing for details.  */
+#include "cmConfigureLog.h"
+
+#include <cassert>
+#include <cstdio>
+#include <iterator>
+#include <sstream>
+#include <utility>
+
+#include <cmext/string_view>
+
+#include <cm3p/json/writer.h>
+
+#include "cm_utf8.h"
+
+#include "cmListFileCache.h"
+#include "cmMakefile.h"
+#include "cmStringAlgorithms.h"
+#include "cmSystemTools.h"
+#include "cmake.h"
+
+cmConfigureLog::cmConfigureLog(std::string logDir)
+  : LogDir(std::move(logDir))
+{
+  Json::StreamWriterBuilder builder;
+  this->Encoder.reset(builder.newStreamWriter());
+}
+
+cmConfigureLog::~cmConfigureLog()
+{
+  if (this->Opened) {
+    this->EndObject();
+    this->Stream << "...\n";
+  }
+}
+
+void cmConfigureLog::WriteBacktrace(cmMakefile const& mf)
+{
+  std::vector<std::string> backtrace;
+  auto root = mf.GetCMakeInstance()->GetHomeDirectory();
+  for (auto bt = mf.GetBacktrace(); !bt.Empty(); bt = bt.Pop()) {
+    auto t = bt.Top();
+    if (!t.Name.empty() || t.Line == cmListFileContext::DeferPlaceholderLine) {
+      t.FilePath = cmSystemTools::RelativeIfUnder(root, t.FilePath);
+      std::ostringstream s;
+      s << t;
+      backtrace.emplace_back(s.str());
+    }
+  }
+  this->WriteValue("backtrace"_s, backtrace);
+}
+
+void cmConfigureLog::EnsureInit()
+{
+  if (this->Opened) {
+    return;
+  }
+  assert(!this->Stream.is_open());
+
+  std::string name = cmStrCat(this->LogDir, "/CMakeConfigureLog.yaml");
+  this->Stream.open(name.c_str(), std::ios::out | std::ios::app);
+
+  this->Opened = true;
+
+  this->Stream << "\n---\n";
+  this->BeginObject("version"_s);
+  this->WriteValue("major"_s, 1);
+  this->WriteValue("minor"_s, 0);
+  this->EndObject();
+  this->BeginObject("events"_s);
+}
+
+cmsys::ofstream& cmConfigureLog::BeginLine()
+{
+  for (unsigned i = 0; i < this->Indent; ++i) {
+    this->Stream << "  ";
+  }
+  return this->Stream;
+}
+
+void cmConfigureLog::EndLine()
+{
+  this->Stream << std::endl;
+}
+
+void cmConfigureLog::BeginObject(cm::string_view key)
+{
+  this->BeginLine() << key << ':';
+  this->EndLine();
+  ++this->Indent;
+}
+
+void cmConfigureLog::EndObject()
+{
+  assert(this->Indent);
+  --this->Indent;
+}
+
+void cmConfigureLog::BeginEvent(std::string const& kind)
+{
+  this->EnsureInit();
+
+  this->BeginLine() << '-';
+  this->EndLine();
+
+  ++this->Indent;
+
+  this->WriteValue("kind"_s, kind);
+}
+
+void cmConfigureLog::EndEvent()
+{
+  assert(this->Indent);
+  --this->Indent;
+}
+
+void cmConfigureLog::WriteValue(cm::string_view key, std::nullptr_t)
+{
+  this->BeginLine() << key << ": null";
+  this->EndLine();
+}
+
+void cmConfigureLog::WriteValue(cm::string_view key, bool value)
+{
+  this->BeginLine() << key << ": " << (value ? "true" : "false");
+  this->EndLine();
+}
+
+void cmConfigureLog::WriteValue(cm::string_view key, int value)
+{
+  this->BeginLine() << key << ": " << value;
+  this->EndLine();
+}
+
+void cmConfigureLog::WriteValue(cm::string_view key, std::string const& value)
+{
+  this->BeginLine() << key << ": ";
+  this->Encoder->write(value, &this->Stream);
+  this->EndLine();
+}
+
+void cmConfigureLog::WriteValue(cm::string_view key,
+                                std::vector<std::string> const& list)
+{
+  this->BeginObject(key);
+  for (auto const& value : list) {
+    this->BeginLine() << "- ";
+    this->Encoder->write(value, &this->Stream);
+    this->EndLine();
+  }
+  this->EndObject();
+}
+
+void cmConfigureLog::WriteLiteralTextBlock(cm::string_view key,
+                                           cm::string_view text)
+{
+  this->BeginLine() << key << ": |";
+  this->EndLine();
+
+  auto const l = text.length();
+  if (l) {
+    ++this->Indent;
+    this->BeginLine();
+
+    auto i = decltype(l){ 0 };
+    while (i < l) {
+      // YAML allows ' ', '\t' and "printable characters", but NOT other
+      // ASCII whitespace; those must be escaped, as must the upper UNICODE
+      // control characters (U+0080 - U+009F)
+      static constexpr unsigned int C1_LAST = 0x9F;
+      auto const c = static_cast<unsigned char>(text[i]);
+      switch (c) {
+        case '\r':
+          // Print a carriage return only if it is not followed by a line feed.
+          ++i;
+          if (i == l || text[i] != '\n') {
+            this->WriteEscape(c);
+          }
+          break;
+        case '\n':
+          // Print any line feeds except the very last one
+          if (i + 1 < l) {
+            this->EndLine();
+            this->BeginLine();
+          }
+          ++i;
+          break;
+        case '\t':
+          // Print horizontal tab verbatim
+          this->Stream.put('\t');
+          ++i;
+          break;
+        case '\\':
+          // Escape backslash for disambiguation
+          this->Stream << "\\\\";
+          ++i;
+          break;
+        default:
+          if (c >= 32 && c < 127) {
+            // Print ascii byte.
+            this->Stream.put(text[i]);
+            ++i;
+            break;
+          } else if (c > 127) {
+            // Decode a UTF-8 sequence.
+            unsigned int c32;
+            auto const* const s = text.data() + i;
+            auto const* const e = text.data() + l;
+            auto const* const n = cm_utf8_decode_character(s, e, &c32);
+            if (n > s && c32 > C1_LAST) {
+              auto const k = std::distance(s, n);
+              this->Stream.write(s, static_cast<std::streamsize>(k));
+              i += static_cast<unsigned>(k);
+              break;
+            }
+          }
+
+          // Escape non-printable byte.
+          this->WriteEscape(c);
+          ++i;
+          break;
+      }
+    }
+
+    this->EndLine();
+    --this->Indent;
+  }
+}
+
+void cmConfigureLog::WriteEscape(unsigned char c)
+{
+  char buffer[6];
+  int n = snprintf(buffer, sizeof(buffer), "\\x%02x", c);
+  if (n > 0) {
+    this->Stream.write(buffer, n);
+  }
+}

Source/cmConfigureLog.h

@@ -0,0 +1,61 @@
+/* Distributed under the OSI-approved BSD 3-Clause License.  See accompanying
+   file Copyright.txt or https://cmake.org/licensing for details.  */
+#pragma once
+
+#include <memory>
+#include <string>
+#include <vector>
+
+#include <cm/string_view>
+
+#include "cmsys/FStream.hxx"
+
+namespace Json {
+class StreamWriter;
+}
+
+class cmMakefile;
+
+class cmConfigureLog
+{
+public:
+  cmConfigureLog(std::string logDir);
+  ~cmConfigureLog();
+
+  void WriteBacktrace(cmMakefile const& mf);
+
+  void EnsureInit();
+
+  void BeginEvent(std::string const& kind);
+  void EndEvent();
+
+  void BeginObject(cm::string_view key);
+  void EndObject();
+
+  // TODO other value types
+  void WriteValue(cm::string_view key, std::nullptr_t);
+  void WriteValue(cm::string_view key, bool value);
+  void WriteValue(cm::string_view key, int value);
+  void WriteValue(cm::string_view key, std::string const& value);
+  void WriteValue(cm::string_view key, std::vector<std::string> const& list);
+
+  void WriteTextBlock(cm::string_view key, cm::string_view text);
+  void WriteLiteralTextBlock(cm::string_view key, cm::string_view text);
+
+  void WriteLiteralTextBlock(cm::string_view key, std::string const& text)
+  {
+    this->WriteLiteralTextBlock(key, cm::string_view{ text });
+  }
+
+private:
+  std::string LogDir;
+  cmsys::ofstream Stream;
+  unsigned Indent = 0;
+  bool Opened = false;
+
+  std::unique_ptr<Json::StreamWriter> Encoder;
+
+  cmsys::ofstream& BeginLine();
+  void EndLine();
+  void WriteEscape(unsigned char c);
+};

Source/cmake.cxx

@@ -70,6 +70,7 @@
 #  include <cm3p/curl/curl.h>
 #  include <cm3p/json/writer.h>
 
+#  include "cmConfigureLog.h"
 #  include "cmFileAPI.h"
 #  include "cmGraphVizWriter.h"
 #  include "cmVariableWatch.h"
@@ -2423,10 +2424,21 @@ int cmake::ActualConfigure()
 #if !defined(CMAKE_BOOTSTRAP)
   this->FileAPI = cm::make_unique<cmFileAPI>(this);
   this->FileAPI->ReadQueries();
+
+  if (!this->GetIsInTryCompile()) {
+    this->TruncateOutputLog("CMakeConfigureLog.yaml");
+    this->ConfigureLog = cm::make_unique<cmConfigureLog>(
+      cmStrCat(this->GetHomeOutputDirectory(), "/CMakeFiles"_s));
+  }
 #endif
 
   // actually do the configure
   this->GlobalGenerator->Configure();
+
+#if !defined(CMAKE_BOOTSTRAP)
+  this->ConfigureLog.reset();
+#endif
+
   // Before saving the cache
   // if the project did not define one of the entries below, add them now
   // so users can edit the values in the cache:

Source/cmake.h

@@ -37,6 +37,7 @@
 #  include "cmMakefileProfilingData.h"
 #endif
 
+class cmConfigureLog;
 class cmExternalMakefileProjectGeneratorFactory;
 class cmFileAPI;
 class cmFileTimeCache;
@@ -521,6 +522,10 @@ public:
   void SetTraceFile(std::string const& file);
   void PrintTraceFormatVersion();
 
+#ifndef CMAKE_BOOTSTRAP
+  cmConfigureLog* GetConfigureLog() const { return this->ConfigureLog.get(); }
+#endif
+
   //! Use trace from another ::cmake instance.
   void SetTraceRedirect(cmake* other);
 
@@ -714,6 +719,9 @@ private:
   TraceFormat TraceFormatVar = TRACE_HUMAN;
   cmGeneratedFileStream TraceFile;
   cmake* TraceRedirect = nullptr;
+#ifndef CMAKE_BOOTSTRAP
+  std::unique_ptr<cmConfigureLog> ConfigureLog;
+#endif
   bool WarnUninitialized = false;
   bool WarnUnusedCli = true;
   bool CheckSystemVars = false;

Tests/RunCMake/RunCMake.cmake

@@ -33,7 +33,7 @@ function(run_cmake test)
     set(platform_name msys)
   endif()
 
-  foreach(o IN ITEMS stdout stderr)
+  foreach(o IN ITEMS stdout stderr config)
     if(RunCMake-${o}-file AND EXISTS ${top_src}/${RunCMake-${o}-file})
       file(READ ${top_src}/${RunCMake-${o}-file} expect_${o})
       string(REGEX REPLACE "\n+$" "" expect_${o} "${expect_${o}}")
@@ -144,6 +144,12 @@ function(run_cmake test)
   if(NOT "${actual_result}" MATCHES "${expect_result}")
     string(APPEND msg "Result is [${actual_result}], not [${expect_result}].\n")
   endif()
+  set(config_file "${RunCMake_TEST_COMMAND_WORKING_DIRECTORY}/CMakeFiles/CMakeConfigureLog.yaml")
+  if(EXISTS "${config_file}")
+    file(READ "${config_file}" actual_config)
+  else()
+    set(actual_config "")
+  endif()
 
   # Special case: remove ninja no-op line from stderr, but not stdout.
   # Test cases that look for it should use RunCMake_TEST_OUTPUT_MERGE.
@@ -180,7 +186,7 @@ function(run_cmake test)
     "|[^\n]*Bullseye Testing Technology"
     ")[^\n]*\n)+"
     )
-  foreach(o IN ITEMS stdout stderr)
+  foreach(o IN ITEMS stdout stderr config)
     string(REGEX REPLACE "\r\n" "\n" actual_${o} "${actual_${o}}")
     string(REGEX REPLACE "${ignore_line_regex}" "\\1" actual_${o} "${actual_${o}}")
     string(REGEX REPLACE "\n+$" "" actual_${o} "${actual_${o}}")
@@ -211,13 +217,15 @@ function(run_cmake test)
     string(APPEND msg "Command was:\n command> ${command}\n")
   endif()
   if(msg)
-    foreach(o IN ITEMS stdout stderr)
+    foreach(o IN ITEMS stdout stderr config)
       if(DEFINED expect_${o})
         string(REGEX REPLACE "\n" "\n expect-${o}> " expect_${o} " expect-${o}> ${expect_${o}}")
         string(APPEND msg "Expected ${o} to match:\n${expect_${o}}\n")
       endif()
-      string(REGEX REPLACE "\n" "\n actual-${o}> " actual_${o} " actual-${o}> ${actual_${o}}")
-      string(APPEND msg "Actual ${o}:\n${actual_${o}}\n")
+      if(NOT o STREQUAL "config" OR DEFINED expect_${o})
+        string(REGEX REPLACE "\n" "\n actual-${o}> " actual_${o} " actual-${o}> ${actual_${o}}")
+        string(APPEND msg "Actual ${o}:\n${actual_${o}}\n")
+      endif()
     endforeach()
     message(SEND_ERROR "${test}${RunCMake_TEST_VARIANT_DESCRIPTION} - FAILED:\n${msg}")
   else()