Merge pull request #107044 from pohly/cli-invalid-command

cli: avoid logging command line errors in more cases

cmd/kubectl/kubectl.go

@@ -17,10 +17,9 @@ limitations under the License.
 package main
 
 import (
-	"os"
-
 	"k8s.io/component-base/cli"
 	"k8s.io/kubectl/pkg/cmd"
+	"k8s.io/kubectl/pkg/cmd/util"
 
 	// Import to initialize client auth plugins.
 	_ "k8s.io/client-go/plugin/pkg/client/auth"
@@ -28,6 +27,8 @@ import (
 
 func main() {
 	command := cmd.NewDefaultKubectlCommand()
-	code := cli.Run(command)
+	if err := cli.RunNoErrOutput(command); err != nil {
-	os.Exit(code)
+		// Pretty-print the error and exit with an error.
+		util.CheckErr(err)
+	}
 }

hack/lib/test.sh

@@ -451,10 +451,16 @@ kube::test::version::diff_assert() {
         return 1
   fi
 
-  sort "${original}" > "${original}.sorted"
+  if [ "${comparator}" == "exact" ]; then
-  sort "${latest}" > "${latest}.sorted"
+      # Skip sorting of file content for exact comparison.
+      cp "${original}" "${original}.sorted"
+      cp "${latest}" "${latest}.sorted"
+  else
+      sort "${original}" > "${original}.sorted"
+      sort "${latest}" > "${latest}.sorted"
+  fi
 
-  if [ "${comparator}" == "eq" ]; then
+  if [ "${comparator}" == "eq" ] || [ "${comparator}" == "exact" ]; then
     if [ "$(diff -iwB "${original}".sorted "${latest}".sorted)" == "" ] ; then
         echo -n "${green}"
         echo "Successful: ${diff_msg}"
@@ -493,3 +499,47 @@ kube::test::version::diff_assert() {
   fi
 }
 
+# Force exact match of kubectl stdout, stderr, and return code.
+# $1: file with actual stdout
+# $2: file with actual stderr
+# $3: the actual return code
+# $4: file with expected stdout
+# $5: file with expected stderr
+# $6: expected return code
+# $7: additional message describing the invocation
+kube::test::results::diff() {
+  local actualstdout=$1
+  local actualstderr=$2
+  local actualcode=$3
+  local expectedstdout=$4
+  local expectedstderr=$5
+  local expectedcode=$6
+  local message=$7
+  local result=0
+
+  if ! kube::test::version::diff_assert "${expectedstdout}" "exact" "${actualstdout}" "stdout for ${message}"; then
+      result=1
+  fi
+  if ! kube::test::version::diff_assert "${expectedstderr}" "exact" "${actualstderr}" "stderr for ${message}"; then
+      result=1
+  fi
+  if [ "${actualcode}" -ne "${expectedcode}" ]; then
+      echo "${bold}${red}"
+      echo "$(kube::test::get_caller): FAIL!"
+      echo "Return code for ${message}"
+      echo "  Expected: ${expectedcode}"
+      echo "  Got:      ${actualcode}"
+      echo "${reset}${red}"
+      caller
+      echo "${reset}"
+      result=1
+  fi
+
+  if [ "${result}" -eq 0 ]; then
+     echo -n "${green}"
+     echo "$(kube::test::get_caller): Successful: ${message}"
+     echo -n "${reset}"
+  fi
+
+  return "$result"
+}

staging/src/k8s.io/component-base/cli/run.go

@@ -34,7 +34,58 @@ import (
 // flags get added to the command line if not added already. Flags get normalized
 // so that help texts show them with hyphens. Underscores are accepted
 // as alternative for the command parameters.
+//
+// Run tries to be smart about how to print errors that are returned by the
+// command: before logging is known to be set up, it prints them as plain text
+// to stderr. This covers command line flag parse errors and unknown commands.
+// Afterwards it logs them. This covers runtime errors.
+//
+// Commands like kubectl where logging is not normally part of the runtime output
+// should use RunNoErrOutput instead and deal with the returned error themselves.
 func Run(cmd *cobra.Command) int {
+	if logsInitialized, err := run(cmd); err != nil {
+		// If the error is about flag parsing, then printing that error
+		// with the decoration that klog would add ("E0923
+		// 23:02:03.219216 4168816 run.go:61] unknown shorthand flag")
+		// is less readable. Using klog.Fatal is even worse because it
+		// dumps a stack trace that isn't about the error.
+		//
+		// But if it is some other error encountered at runtime, then
+		// we want to log it as error, at least in most commands because
+		// their output is a log event stream.
+		//
+		// We can distinguish these two cases depending on whether
+		// we got to logs.InitLogs() above.
+		//
+		// This heuristic might be problematic for command line
+		// tools like kubectl where the output is carefully controlled
+		// and not a log by default. They should use RunNoErrOutput
+		// instead.
+		//
+		// The usage of klog is problematic also because we don't know
+		// whether the command has managed to configure it. This cannot
+		// be checked right now, but may become possible when the early
+		// logging proposal from
+		// https://github.com/kubernetes/enhancements/pull/3078
+		// ("contextual logging") is implemented.
+		if !logsInitialized {
+			fmt.Fprintf(os.Stderr, "Error: %v\n", err)
+		} else {
+			klog.ErrorS(err, "command failed")
+		}
+		return 1
+	}
+	return 0
+}
+
+// RunNoErrOutput is a version of Run which returns the cobra command error
+// instead of printing it.
+func RunNoErrOutput(cmd *cobra.Command) error {
+	_, err := run(cmd)
+	return err
+}
+
+func run(cmd *cobra.Command) (logsInitialized bool, err error) {
 	rand.Seed(time.Now().UnixNano())
 	defer logs.FlushLogs()
 
@@ -51,24 +102,11 @@ func Run(cmd *cobra.Command) int {
 	// execution fails for other reasons than parsing. We detect this via
 	// the FlagParseError callback.
 	//
-	// A variable is used instead of wrapping the error with a special
+	// Some commands, like kubectl, already deal with this themselves.
-	// error type because the variable is simpler and less fragile: the
+	// We don't change the behavior for those.
-	// original FlagErrorFunc might replace the wrapped error.
+	if !cmd.SilenceUsage {
-	parsingFailed := false
-	if cmd.SilenceUsage {
-		// Some commands, like kubectl, already deal with this themselves.
-		// We don't change the behavior for those and just track whether
-		// parsing failed for the error output below.
-		flagErrorFunc := cmd.FlagErrorFunc()
-		cmd.SetFlagErrorFunc(func(c *cobra.Command, err error) error {
-			parsingFailed = true
-			return flagErrorFunc(c, err)
-		})
-	} else {
 		cmd.SilenceUsage = true
 		cmd.SetFlagErrorFunc(func(c *cobra.Command, err error) error {
-			parsingFailed = true
-
 			// Re-enable usage printing.
 			c.SilenceUsage = false
 			return err
@@ -88,38 +126,23 @@ func Run(cmd *cobra.Command) int {
 		pre := cmd.PersistentPreRun
 		cmd.PersistentPreRun = func(cmd *cobra.Command, args []string) {
 			logs.InitLogs()
+			logsInitialized = true
 			pre(cmd, args)
 		}
 	case cmd.PersistentPreRunE != nil:
 		pre := cmd.PersistentPreRunE
 		cmd.PersistentPreRunE = func(cmd *cobra.Command, args []string) error {
 			logs.InitLogs()
+			logsInitialized = true
 			return pre(cmd, args)
 		}
 	default:
 		cmd.PersistentPreRun = func(cmd *cobra.Command, args []string) {
 			logs.InitLogs()
+			logsInitialized = true
 		}
 	}
 
-	if err := cmd.Execute(); err != nil {
+	err = cmd.Execute()
-		// If the error is about flag parsing, then printing that error
+	return
-		// with the decoration that klog would add ("E0923
-		// 23:02:03.219216 4168816 run.go:61] unknown shorthand flag")
-		// is less readable. Using klog.Fatal is even worse because it
-		// dumps a stack trace that isn't about the error.
-		//
-		// But if it is some other error encountered at runtime, then
-		// we want to log it as error.
-		//
-		// We can distinguish these two cases depending on whether
-		// our FlagErrorFunc above was called.
-		if parsingFailed {
-			fmt.Fprintf(os.Stderr, "Error: %v\n", err)
-		} else {
-			klog.ErrorS(err, "command failed")
-		}
-		return 1
-	}
-	return 0
 }

test/cmd/get.sh

@@ -421,7 +421,7 @@ run_deprecated_api_tests() {
   kube::test::if_has_string "${output_message}" 'PodSecurityPolicy is deprecated'
   output_message=$(! kubectl get podsecuritypolicies.v1beta1.policy --warnings-as-errors 2>&1 "${kube_flags[@]}")
   kube::test::if_has_string "${output_message}" 'PodSecurityPolicy is deprecated'
-  kube::test::if_has_string "${output_message}" 'err="1 warning received"'
+  kube::test::if_has_string "${output_message}" 'error: 1 warning received'
 
   set +o nounset
   set +o errexit

test/cmd/legacy-script.sh

@@ -50,6 +50,7 @@ source "${KUBE_ROOT}/test/cmd/plugins.sh"
 source "${KUBE_ROOT}/test/cmd/proxy.sh"
 source "${KUBE_ROOT}/test/cmd/rbac.sh"
 source "${KUBE_ROOT}/test/cmd/request-timeout.sh"
+source "${KUBE_ROOT}/test/cmd/results.sh"
 source "${KUBE_ROOT}/test/cmd/run.sh"
 source "${KUBE_ROOT}/test/cmd/save-config.sh"
 source "${KUBE_ROOT}/test/cmd/storage.sh"
@@ -436,6 +437,12 @@ runTests() {
 
   record_command run_kubectl_version_tests
 
+  ############################
+  # Kubectl result reporting #
+  ############################
+
+  record_command run_kubectl_results_tests
+
   #######################
   # kubectl config set #
   #######################

test/cmd/results.sh

@@ -0,0 +1,58 @@
+#!/usr/bin/env bash
+
+# Copyright 2022 The Kubernetes Authors.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+set -o errexit
+set -o nounset
+set -o pipefail
+
+
+############################################################
+# Kubectl result reporting for different failure scenarios #
+############################################################
+run_kubectl_results_tests() {
+  set -o nounset
+  set -o errexit
+
+  kube::log::status "Testing kubectl result output"
+  TEMP="${KUBE_TEMP}"
+  rm -f "${TEMP}/empty"
+  touch "${TEMP}/empty"
+
+  set +o errexit
+  kubectl list >"${TEMP}/actual_stdout" 2>"${TEMP}/actual_stderr"
+  res=$?
+  set -o errexit
+  cat >"${TEMP}/expected_stderr" <<EOF
+error: unknown command "list" for "kubectl"
+
+Did you mean this?
+	get
+	wait
+EOF
+  kube::test::results::diff "${TEMP}/actual_stdout" "${TEMP}/actual_stderr" "$res" "${TEMP}/empty" "${TEMP}/expected_stderr" 1 "kubectl list"
+
+  set +o errexit
+  kubectl get pod/no-such-pod >"${TEMP}/actual_stdout" 2>"${TEMP}/actual_stderr"
+  res=$?
+  set -o errexit
+  cat >"${TEMP}/expected_stderr" <<EOF
+Error from server (NotFound): pods "no-such-pod" not found
+EOF
+  kube::test::results::diff "${TEMP}/actual_stdout" "${TEMP}/actual_stderr" "$res" "${TEMP}/empty" "${TEMP}/expected_stderr" 1 "kubectl get pod/no-such-pod"
+
+  set +o nounset
+  set +o errexit
+}