From b94b0e321f021eb8232a32a78bb0f41eb9e04852 Mon Sep 17 00:00:00 2001
From: rillig <rillig@NetBSD.org>
Date: Mon, 10 Jan 2022 20:32:28 +0000
Subject: [PATCH] make: add debug logging for capturing the output of external
 commands

This applies to all 4 situations in which the output of an external
command is used for modifying a variable or an expression:

* the assignment operator '!='
* the assignment modifier '::!='
* the SUN shell modifier ':sh'
* the other shell modifier ':!cmd!'

Previously, only the shell modifier ':!cmd!' had debug logging.

Suggested by Christoph Badura.
---
 usr.bin/make/main.c                               |  5 +++--
 usr.bin/make/unit-tests/directive-export-impl.exp |  2 ++
 usr.bin/make/unit-tests/var-op-shell.exp          |  4 ++++
 usr.bin/make/unit-tests/var-op-shell.mk           |  8 +++++++-
 usr.bin/make/unit-tests/varmod-assign-shell.exp   |  9 +++++++++
 usr.bin/make/unit-tests/varmod-assign-shell.mk    |  6 ++++--
 usr.bin/make/unit-tests/varmod-shell.exp          | 10 ++++++++++
 usr.bin/make/unit-tests/varmod-shell.mk           | 10 +++++++---
 usr.bin/make/unit-tests/varmod-sun-shell.exp      | 11 +++++++++++
 usr.bin/make/unit-tests/varmod-sun-shell.mk       |  7 ++++++-
 usr.bin/make/unit-tests/varname-empty.exp         |  1 +
 11 files changed, 64 insertions(+), 9 deletions(-)

diff --git a/usr.bin/make/main.c b/usr.bin/make/main.c
index c43eedcf0b6a..2eb7a8c5862c 100644
--- a/usr.bin/make/main.c
+++ b/usr.bin/make/main.c
@@ -1,4 +1,4 @@
-/*	$NetBSD: main.c,v 1.568 2022/01/09 18:49:28 rillig Exp $	*/
+/*	$NetBSD: main.c,v 1.569 2022/01/10 20:32:28 rillig Exp $	*/
 
 /*
  * Copyright (c) 1988, 1989, 1990, 1993
@@ -111,7 +111,7 @@
 #include "trace.h"
 
 /*	"@(#)main.c	8.3 (Berkeley) 3/19/94"	*/
-MAKE_RCSID("$NetBSD: main.c,v 1.568 2022/01/09 18:49:28 rillig Exp $");
+MAKE_RCSID("$NetBSD: main.c,v 1.569 2022/01/10 20:32:28 rillig Exp $");
 #if defined(MAKE_NATIVE) && !defined(lint)
 __COPYRIGHT("@(#) Copyright (c) 1988, 1989, 1990, 1993 "
 	    "The Regents of the University of California.  "
@@ -1720,6 +1720,7 @@ Cmd_Exec(const char *cmd, char **error)
 	args[1] = "-c";
 	args[2] = cmd;
 	args[3] = NULL;
+	DEBUG1(VAR, "Capturing the output of command \"%s\"\n", cmd);
 
 	if (pipe(pipefds) == -1) {
 		*error = str_concat3(
diff --git a/usr.bin/make/unit-tests/directive-export-impl.exp b/usr.bin/make/unit-tests/directive-export-impl.exp
index 66690d124f14..778d825996ff 100644
--- a/usr.bin/make/unit-tests/directive-export-impl.exp
+++ b/usr.bin/make/unit-tests/directive-export-impl.exp
@@ -14,6 +14,7 @@ CondParser_Eval: ${:!echo "\$UT_VAR"!} != "<>"
 Var_Parse: ${:!echo "\$UT_VAR"!} != "<>" (eval-defined)
 Evaluating modifier ${:!...} on value "" (eval-defined, undefined)
 Modifier part: "echo "$UT_VAR""
+Capturing the output of command "echo "$UT_VAR""
 Var_Parse: ${.MAKE.EXPORTED:O:u} (eval)
 Evaluating modifier ${.MAKE.EXPORTED:O} on value "UT_VAR"
 Result of ${.MAKE.EXPORTED:O} is "UT_VAR"
@@ -37,6 +38,7 @@ CondParser_Eval: ${:!echo "\$UT_VAR"!} != "<defined>"
 Var_Parse: ${:!echo "\$UT_VAR"!} != "<defined>" (eval-defined)
 Evaluating modifier ${:!...} on value "" (eval-defined, undefined)
 Modifier part: "echo "$UT_VAR""
+Capturing the output of command "echo "$UT_VAR""
 Var_Parse: ${.MAKE.EXPORTED:O:u} (eval)
 Evaluating modifier ${.MAKE.EXPORTED:O} on value "UT_VAR"
 Result of ${.MAKE.EXPORTED:O} is "UT_VAR"
diff --git a/usr.bin/make/unit-tests/var-op-shell.exp b/usr.bin/make/unit-tests/var-op-shell.exp
index 532521977e1e..07e394491c46 100644
--- a/usr.bin/make/unit-tests/var-op-shell.exp
+++ b/usr.bin/make/unit-tests/var-op-shell.exp
@@ -4,4 +4,8 @@ make: "var-op-shell.mk" line 59: warning: "kill $$" exited on a signal
 /bin/no/such/command: not found
 make: "var-op-shell.mk" line 65: warning: "/bin/no/such/command" returned non-zero status
 stderr
+Capturing the output of command "echo '$$$$'"
+Global: OUTPUT = $$$$
+Global: .MAKEFLAGS =  -r -k -d v -d
+Global: .MAKEFLAGS =  -r -k -d v -d 0
 exit status 0
diff --git a/usr.bin/make/unit-tests/var-op-shell.mk b/usr.bin/make/unit-tests/var-op-shell.mk
index 544f0014d32a..bd2a48f17cc4 100644
--- a/usr.bin/make/unit-tests/var-op-shell.mk
+++ b/usr.bin/make/unit-tests/var-op-shell.mk
@@ -1,4 +1,4 @@
-# $NetBSD: var-op-shell.mk,v 1.5 2022/01/09 18:22:31 rillig Exp $
+# $NetBSD: var-op-shell.mk,v 1.6 2022/01/10 20:32:29 rillig Exp $
 #
 # Tests for the != variable assignment operator, which runs its right-hand
 # side through the shell.
@@ -81,4 +81,10 @@ OUTPUT!=	echo '$$$$$$$$'
 .  error
 .endif
 
+
+# As a debugging aid, log the exact command that is run via the shell.
+.MAKEFLAGS: -dv
+OUTPUT!=	echo '$$$$$$$$'
+.MAKEFLAGS: -d0
+
 all:
diff --git a/usr.bin/make/unit-tests/varmod-assign-shell.exp b/usr.bin/make/unit-tests/varmod-assign-shell.exp
index c0c86d5983b8..3d4a90fb1be4 100644
--- a/usr.bin/make/unit-tests/varmod-assign-shell.exp
+++ b/usr.bin/make/unit-tests/varmod-assign-shell.exp
@@ -1,5 +1,14 @@
 make: "varmod-assign-shell.mk" line 27: warning: "echo output; false" returned non-zero status
+Global: _ = 
+Var_Parse: ${ASSIGNED::!=echo output; ${:Ufalse}} (eval-keep-dollar-and-undefined)
+Evaluating modifier ${ASSIGNED::...} on value "previous" (eval-keep-dollar-and-undefined, regular)
+Modifier part: "echo output; false"
+Capturing the output of command "echo output; false"
 make: "echo output; false" returned non-zero status
+Result of ${ASSIGNED::!=echo output; ${:Ufalse}} is "" (eval-keep-dollar-and-undefined, regular)
+Global: _ = 
+Global: .MAKEFLAGS =  -r -k -d v -d
+Global: .MAKEFLAGS =  -r -k -d v -d 0
 DIRECT=output
 ASSIGNED=previous
 exit status 0
diff --git a/usr.bin/make/unit-tests/varmod-assign-shell.mk b/usr.bin/make/unit-tests/varmod-assign-shell.mk
index 86fc6fa8083d..d03692942d5b 100644
--- a/usr.bin/make/unit-tests/varmod-assign-shell.mk
+++ b/usr.bin/make/unit-tests/varmod-assign-shell.mk
@@ -1,4 +1,4 @@
-# $NetBSD: varmod-assign-shell.mk,v 1.3 2022/01/09 18:22:31 rillig Exp $
+# $NetBSD: varmod-assign-shell.mk,v 1.4 2022/01/10 20:32:29 rillig Exp $
 #
 # Tests for the variable modifier '::!=', which assigns the output of a shell
 # command to the variable, but only if the command exited successfully.  This
@@ -27,7 +27,9 @@ DIRECT=		previous
 DIRECT!=	echo output; false
 
 ASSIGNED=	previous
-_:=		${ASSIGNED::!=echo output; false}
+.MAKEFLAGS: -dv			# to see the actual command
+_:=		${ASSIGNED::!=echo output; ${:Ufalse}}
+.MAKEFLAGS: -d0
 
 all:
 	@echo DIRECT=${DIRECT:Q}
diff --git a/usr.bin/make/unit-tests/varmod-shell.exp b/usr.bin/make/unit-tests/varmod-shell.exp
index 9aef0c9e5acc..adcfe7f251a9 100644
--- a/usr.bin/make/unit-tests/varmod-shell.exp
+++ b/usr.bin/make/unit-tests/varmod-shell.exp
@@ -1,3 +1,13 @@
 make: "echo word; false" returned non-zero status
 make: "echo word; false" returned non-zero status
+Global: _ = 
+Var_Parse: ${:!echo word; ${:Ufalse}!} (eval-keep-dollar-and-undefined)
+Evaluating modifier ${:!...} on value "" (eval-keep-dollar-and-undefined, undefined)
+Modifier part: "echo word; false"
+Capturing the output of command "echo word; false"
+make: "echo word; false" returned non-zero status
+Result of ${:!echo word; ${:Ufalse}!} is "word" (eval-keep-dollar-and-undefined, defined)
+Global: _ = word
+Global: .MAKEFLAGS =  -r -k -d v -d
+Global: .MAKEFLAGS =  -r -k -d v -d 0
 exit status 0
diff --git a/usr.bin/make/unit-tests/varmod-shell.mk b/usr.bin/make/unit-tests/varmod-shell.mk
index c736042f80a0..d449709cee0f 100644
--- a/usr.bin/make/unit-tests/varmod-shell.mk
+++ b/usr.bin/make/unit-tests/varmod-shell.mk
@@ -1,4 +1,4 @@
-# $NetBSD: varmod-shell.mk,v 1.6 2021/02/14 20:16:17 rillig Exp $
+# $NetBSD: varmod-shell.mk,v 1.7 2022/01/10 20:32:29 rillig Exp $
 #
 # Tests for the ':!cmd!' variable modifier, which runs the shell command
 # given by the variable modifier and returns its output.
@@ -20,8 +20,7 @@
 #
 # Between 2000-04-29 and 2020-11-17, the error message mentioned the previous
 # value of the expression (which is usually an empty string) instead of the
-# command that was executed.  It's strange that such a simple bug could
-# survive such a long time.
+# command that was executed.
 .if ${:!echo word; false!} != "word"
 .  error
 .endif
@@ -29,4 +28,9 @@
 .  error
 .endif
 
+
+.MAKEFLAGS: -dv			# to see the actual command
+_:=	${:!echo word; ${:Ufalse}!}
+.MAKEFLAGS: -d0
+
 all:
diff --git a/usr.bin/make/unit-tests/varmod-sun-shell.exp b/usr.bin/make/unit-tests/varmod-sun-shell.exp
index 5087bc66d943..4954458b13e1 100644
--- a/usr.bin/make/unit-tests/varmod-sun-shell.exp
+++ b/usr.bin/make/unit-tests/varmod-sun-shell.exp
@@ -1,2 +1,13 @@
 make: "echo word; false" returned non-zero status
+Global: _ = 
+Var_Parse: ${echo word; ${:Ufalse}:L:sh} (eval-keep-dollar-and-undefined)
+Evaluating modifier ${echo word; false:L} on value "" (eval-keep-dollar-and-undefined, undefined)
+Result of ${echo word; false:L} is "echo word; false" (eval-keep-dollar-and-undefined, defined)
+Evaluating modifier ${echo word; false:s...} on value "echo word; false" (eval-keep-dollar-and-undefined, defined)
+Capturing the output of command "echo word; false"
+make: "echo word; false" returned non-zero status
+Result of ${echo word; false:sh} is "word" (eval-keep-dollar-and-undefined, defined)
+Global: _ = word
+Global: .MAKEFLAGS =  -r -k -d v -d
+Global: .MAKEFLAGS =  -r -k -d v -d 0
 exit status 0
diff --git a/usr.bin/make/unit-tests/varmod-sun-shell.mk b/usr.bin/make/unit-tests/varmod-sun-shell.mk
index 712b36bc7030..97acc5bd8c0f 100644
--- a/usr.bin/make/unit-tests/varmod-sun-shell.mk
+++ b/usr.bin/make/unit-tests/varmod-sun-shell.mk
@@ -1,4 +1,4 @@
-# $NetBSD: varmod-sun-shell.mk,v 1.1 2021/02/14 20:16:17 rillig Exp $
+# $NetBSD: varmod-sun-shell.mk,v 1.2 2022/01/10 20:32:29 rillig Exp $
 #
 # Tests for the :sh variable modifier, which runs the shell command
 # given by the variable value and returns its output.
@@ -18,4 +18,9 @@
 .  error
 .endif
 
+
+.MAKEFLAGS: -dv			# to see the actual command
+_:=	${echo word; ${:Ufalse}:L:sh}
+.MAKEFLAGS: -d0
+
 all:
diff --git a/usr.bin/make/unit-tests/varname-empty.exp b/usr.bin/make/unit-tests/varname-empty.exp
index 75a3f4151a8c..72e79abe1ea9 100644
--- a/usr.bin/make/unit-tests/varname-empty.exp
+++ b/usr.bin/make/unit-tests/varname-empty.exp
@@ -13,6 +13,7 @@ Var_SetExpand: variable name "" expands to empty string, with value "assigned" -
 SetVar: variable name is empty - ignored
 Var_SetExpand: variable name "" expands to empty string, with value "" - ignored
 Var_SetExpand: variable name "" expands to empty string, with value "subst" - ignored
+Capturing the output of command "echo 'shell-output'"
 Var_SetExpand: variable name "" expands to empty string, with value "shell-output" - ignored
 Var_SetExpand: variable name "${:U}" expands to empty string, with value "assigned indirectly" - ignored
 Var_AppendExpand: variable name "${:U}" expands to empty string, with value "appended indirectly" - ignored