os::cmd sometimes doesn't find text in output

[stevekuznetsov]

e.g.

FAILURE after 0.214s: test/cmd/router.sh:32: executing 'oadm router --dry-run --host-network=false --stats-port=1937 -o yaml' expecting failure and text 'hostPort: 1937': the output content test failed
Standard output from the command:
...
          - containerPort: 1937
            hostPort: 1937
...

Standard error from the command:
error: router could not be created; service account "router" is not allowed to access host ports on nodes, grant access with oadm policy add-scc-to-user hostnetwork -z router

[stevekuznetsov]

Sample std{err,out} logs for a failed run:

• stderr
• stdout

[stevekuznetsov]

Downloading the logs above, I can't reproduce this error.

$ wget https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_check/2943/artifact/origin/artifacts/test-cmd/tmp_stdout.log
$ wget https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_check/2943/artifact/origin/artifacts/test-cmd/tmp_stderr.log
$ export os_cmd_internal_tmpout=./tmp_stdout.log 
$ export os_cmd_internal_tmperr=./tmp_stderr.log 
$ export grep_args='containerPort: 80'
$ test_result=$( os::cmd::internal::run_collecting_output 'os::cmd::internal::get_results | grep -Eq "${grep_args}"'; echo $? )
$ export test_eval_func=os::cmd::internal::success_func
$ test_succeeded=$( ${test_eval_func} "${test_result}"; echo $? )
$ cause=$(os::cmd::internal::assemble_causes "1" "${test_succeeded}")
$

@Miciah the broken line is here and the functions called there are here and here ... any thoughts on how to better debug?

[Miciah]

@stevekuznetsov, don't you need to expand $grep_args in os::cmd::internal::expect_exit_code_run_grep when you invoke os::cmd::internal::run_collecting_output? Looks like it won't be expanded because it's in a single-quoted string in os::cmd::internal::expect_exit_code_run_grep, and it will be undefined in os::cmd::internal::run_collecting_output, so you'll be grepping for the empty string, which will always match.

It's a bit weird that you're telling os::cmd::internal::run_collecting_output to invoke os::cmd::internal::get_results because the former sets up redirection to ${os_cmd_internal_tmpout} and ${os_cmd_internal_tmperr}, and the latter cats ${os_cmd_internal_tmpout} and ${os_cmd_internal_tmperr}. I guess this is OK because you are appending, not truncating, in os::cmd::internal::run_collecting_output, but it looks weird, boggles the mind a bit, and makes me wonder whether it is really doing what was intended.

[Miciah]

Oh, disregard my first paragraph:

$ bar() { declare -p x; }; foo() { eval bar; local x=y; eval bar; }; foo; eval bar
bash: declare: x: not found
declare -- x="y"
bash: declare: x: not found

[stevekuznetsov]

Yeah, re: your second paragraph... I'm not really sure why that happens the way it does. But if it ain't broke... :)

[juanvallejo]

Running test/cmd/basicresources.sh:74: executing 'oc get' expecting failure and text 'deploymentconfig'...
[DEBUG] Output content test failed. Debugging information follows:
[DEBUG] ${grep_args}=deploymentconfig
[DEBUG] ${test_result}=141
[DEBUG] ${test_eval_func}=os::cmd::internal::success_func
FAILURE after 0.121s: test/cmd/basicresources.sh:74: executing 'oc get' expecting failure and text 'deploymentconfig': the output content test failed
Standard output from the command:
You must specify the type of resource to get. Valid resource types include:
   * buildconfigs (aka 'bc')
   * builds
   * componentstatuses (aka 'cs')
   * configmaps
   * daemonsets (aka 'ds')
   * deploymentconfigs (aka 'dc')
   * deployments
   * events (aka 'ev')
   * endpoints (aka 'ep')
   * horizontalpodautoscalers (aka 'hpa')
   * imagestreamimages (aka 'isimage')
   * imagestreams (aka 'is')
   * imagestreamtags (aka 'istag')
   * ingress (aka 'ing')
   * groups
   * jobs
   * limitranges (aka 'limits')
   * nodes (aka 'no')
   * namespaces (aka 'ns')
   * pods (aka 'po')
   * persistentvolumes (aka 'pv')
   * persistentvolumeclaims (aka 'pvc')
   * policies
   * projects
   * quota
   * resourcequotas (aka 'quota')
   * replicasets (aka 'rs')
   * replicationcontrollers (aka 'rc')
   * rolebindings
   * routes
   * secrets
   * serviceaccounts (aka 'sa')
   * services (aka 'svc')
   * users

Standard error from the command:
error: Required resource not specified.
See 'oc get -h' for help and examples.
[ERROR] PID 20087: hack/lib/cmd.sh:238: `return "${return_code}"` exited with status 1.
[INFO]          Stack Trace:
[INFO]            1: hack/lib/cmd.sh:238: `return "${return_code}"`
[INFO]            2: test/cmd/basicresources.sh:74: os::cmd::expect_failure_and_text
[INFO]   Exiting with code 1.
[ERROR] PID 10026: hack/test-cmd.sh:377: `${test}` exited with status 1.
[INFO]          Stack Trace:
[INFO]            1: hack/test-cmd.sh:377: `${test}`
[INFO]   Exiting with code 1.
[INFO] Dumping etcd contents to /tmp/openshift/test-cmd//artifacts/etcd_dump.json

[stevekuznetsov]

Very interesting ... grep -q exits with 0 as soon as it finds a match, which leaves the cat that's feeding it without a reader on the other side of the pipe, so it gets SIGPIPE and the shell fails with 141. @Miciah thoughts on how to work around this while keeping grep quiet?

[liggitt]

just redirect the grep stderr/stdout to /dev/null?

[stevekuznetsov]

@liggitt not sure I understand what you mean -- the SIGPIPE is happening from inside Bash, simply ignoring the error output of grep won't help us

[liggitt]

instead of running grep in quiet mode

[stevekuznetsov]

@liggitt I see. I think without changing the grep behavior we can instead do this since it's smarter about pipes:

# old
$ os::cmd::internal::get_results | grep -Eq "${grep_args}"
# new
$ grep -Eq "${grep_args}" <(os::cmd::internal::get_results)