From 8fc7a9bce9ecad38197b5e65341c639cf830f7d2 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 15 Dec 2021 09:50:45 +0100 Subject: [PATCH 1/3] cli: avoid logging command line errors in more cases "kubectl list" should print a plain text explanation ("Unknown command "list" for kubectl. ...") without treating that multi-line error as a log message. The previous heuristic didn't work here because the command itself was not found. A better one is to check that command execution really started. This is still not perfect: what if a command hasn't started logging yet or never uses logging for its output and then returns an error? That works in kubectl because it does its own error checking at runtime and then doesn't return, but a more robust solution might be an explicit parameter that prevents using klog. --- staging/src/k8s.io/component-base/cli/run.go | 42 +++++++++++--------- 1 file changed, 23 insertions(+), 19 deletions(-) diff --git a/staging/src/k8s.io/component-base/cli/run.go b/staging/src/k8s.io/component-base/cli/run.go index cc2c977e386..06fc367dd92 100644 --- a/staging/src/k8s.io/component-base/cli/run.go +++ b/staging/src/k8s.io/component-base/cli/run.go @@ -51,24 +51,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 - // error type because the variable is simpler and less fragile: the - // original FlagErrorFunc might replace the wrapped error. - 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 { + // Some commands, like kubectl, already deal with this themselves. + // We don't change the behavior for those. + if !cmd.SilenceUsage { cmd.SilenceUsage = true cmd.SetFlagErrorFunc(func(c *cobra.Command, err error) error { - parsingFailed = true - // Re-enable usage printing. c.SilenceUsage = false return err @@ -83,22 +70,26 @@ func Run(cmd *cobra.Command) int { // Inject logs.InitLogs after command line parsing into one of the // PersistentPre* functions. + logsInitialized := false switch { case cmd.PersistentPreRun != nil: 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 } } @@ -110,11 +101,24 @@ func Run(cmd *cobra.Command) int { // 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 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 - // our FlagErrorFunc above was called. - if parsingFailed { + // 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. It works because kubectl has + // its own error handling once a command runs. + // + // 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") From a5d2d6fec3a1a9538255d796eaf58e0777940135 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 15 Dec 2021 10:44:39 +0100 Subject: [PATCH 2/3] cli: let kubectl handle error printing cli.Run was an attempt to elliminate error handling in Kubernetes commands. However, it had to rely on heuristics that are not necessarily right for all commands. kubectl is one example which has its own error printing code that should be used in all cases after a command failure. It now gets used also for `--warnings-as-errors`. Previously, that caused the following message to be logged at the end: E0110 16:56:01.987555 202060 run.go:120] "command failed" err="1 warning received" Now it ends with: error: 1 warning received --- cmd/kubectl/kubectl.go | 9 +- staging/src/k8s.io/component-base/cli/run.go | 87 ++++++++++++-------- test/cmd/get.sh | 2 +- 3 files changed, 59 insertions(+), 39 deletions(-) diff --git a/cmd/kubectl/kubectl.go b/cmd/kubectl/kubectl.go index 7c7924a5f5f..09c18cfa209 100644 --- a/cmd/kubectl/kubectl.go +++ b/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) - os.Exit(code) + if err := cli.RunNoErrOutput(command); err != nil { + // Pretty-print the error and exit with an error. + util.CheckErr(err) + } } diff --git a/staging/src/k8s.io/component-base/cli/run.go b/staging/src/k8s.io/component-base/cli/run.go index 06fc367dd92..c72b303e2dc 100644 --- a/staging/src/k8s.io/component-base/cli/run.go +++ b/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() @@ -70,7 +121,6 @@ func Run(cmd *cobra.Command) int { // Inject logs.InitLogs after command line parsing into one of the // PersistentPre* functions. - logsInitialized := false switch { case cmd.PersistentPreRun != nil: pre := cmd.PersistentPreRun @@ -93,37 +143,6 @@ func Run(cmd *cobra.Command) int { } } - if err := cmd.Execute(); 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. It works because kubectl has - // its own error handling once a command runs. - // - // 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 + err = cmd.Execute() + return } diff --git a/test/cmd/get.sh b/test/cmd/get.sh index 36e1472eb24..be24af42c10 100755 --- a/test/cmd/get.sh +++ b/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 From 798bdab3d0064551543a5d0e4aa49009faa313d3 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 11 Jan 2022 09:03:19 +0100 Subject: [PATCH 3/3] kubectl: add integration test for result reporting This currently covers two cases: - "kubectl list" (the regression from https://github.com/kubernetes/kubernetes/issues/107012) - "kubectl get pods/no-such-pod" (no particular reason except that the output should be deterministic) In contrast to some other tests that check for strings inside the output (run_deprecated_api_tests) or compare after sorting (run_kubectl_version_tests), stdout, stderr and the return code must match exactly. This ensures that there is no extra, unexpected output and that the right output stream is used. --- hack/lib/test.sh | 56 +++++++++++++++++++++++++++++++++++-- test/cmd/legacy-script.sh | 7 +++++ test/cmd/results.sh | 58 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 118 insertions(+), 3 deletions(-) create mode 100644 test/cmd/results.sh diff --git a/hack/lib/test.sh b/hack/lib/test.sh index 4af4b52a7e6..fb7a3901fcc 100644 --- a/hack/lib/test.sh +++ b/hack/lib/test.sh @@ -451,10 +451,16 @@ kube::test::version::diff_assert() { return 1 fi - sort "${original}" > "${original}.sorted" - sort "${latest}" > "${latest}.sorted" + if [ "${comparator}" == "exact" ]; then + # 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" +} diff --git a/test/cmd/legacy-script.sh b/test/cmd/legacy-script.sh index 1d55570aadb..6ce6d67edf0 100755 --- a/test/cmd/legacy-script.sh +++ b/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 # ####################### diff --git a/test/cmd/results.sh b/test/cmd/results.sh new file mode 100644 index 00000000000..a34253f20c2 --- /dev/null +++ b/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" <"${TEMP}/actual_stdout" 2>"${TEMP}/actual_stderr" + res=$? + set -o errexit + cat >"${TEMP}/expected_stderr" <