Operator-sdk: Error Failed to parse %v from environment. is faced when we start the Ansible Operators upgraded to 0.12

[camilamacedo86]

Bug Report

What did you do?
Upgrade the sample to use the SDK O.12

What did you expect to see?
All worked without issues

What did you see instead? Under which circumstances?
The following error when we run the project

{"level":"info","ts":1573605040.3003905,"logger":"watches","msg":"Failed to parse %v from environment. Using default %v","WORKER_MEMCACHED_CACHE_EXAMPLE_COM":1}
{"level":"info","ts":1573605040.3004255,"logger":"watches","msg":"Failed to parse %v from environment. Using default %v","ANSIBLE_VERBOSITY_MEMCACHED_CACHE_EXAMPLE_COM":2}

Environment

• operator-sdk version: 0.12

• go version: 1.13.4

• Kubernetes version information:

Client Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.0", GitCommit:"2bd9643cee5b3b3a5ecbd3af49d09018f0773c77", GitTreeState:"clean", BuildDate:"2019-09-18T14:36:53Z", GoVersion:"go1.12.9", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.2", GitCommit:"c97fe5036ef3df2967d086711e6c0c405941e14b", GitTreeState:"clean", BuildDate:"2019-10-15T19:09:08Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"}

• Kubernetes cluster kind:minikube

• Are you writing your operator in ansible, helm, or go?
  /ansible-operator

Possible Solution

Additional context
Following the steps to reproduce

• clone the PR https://github.com/operator-framework/operator-sdk-samples/pull/91
• Use operator-sdk build to do a new image
• Push the image and update the operator.yaml with
• Run make install
• Check the operator container logs

Shows that it was introduced in : https://github.com/operator-framework/operator-sdk/pull/2087

[camilamacedo86]

c/c @djzager

[djzager]

Looking into this today.

[djzager]

One question. Are either of these environment variables being set?WORKER_MEMCACHED_CACH_EXAMPLE_COM or ANSIBLE_VERBOSITY_MEMCACHED_CACHE_EXAMPLE_COM

[djzager]

Looking at the code for maxWorkers (same thing for the ansible verbosity):

    maxWorkers, err := strconv.Atoi(os.Getenv(envVar))
    if err != nil {
        // we don't care why we couldn't parse it just use default
        log.Info("Failed to parse %v from environment. Using default %v", envVar, defValue)
        return defValue
    }

Looks like we are trying to get the environment variable and simply returning the default when we can't convert it to an int. So, if the environment variable is unset...I think you would see this message.

Is there a value add in additionally checking if the environment variable is set?

[camilamacedo86]

Hi @djzager,

Thank you for check it as well. See that default values are attributed to it here:

https://github.com/operator-framework/operator-sdk/blob/d94ad3ea7d1547fdc2b2312e42da3455168d1e43/pkg/ansible/flags/flag.go#L44-L57

The problem is that after #2087 the code impl is face an issue to parse them: (just covert the int to string should solve that)

"Failed to parse %v from the environment. Using default %v","WORKER_MEMCACHED_CACHE_EXAMPLE_COM":1

Failed to parse %v from environment. Using default %v","ANSIBLE_VERBOSITY_MEMCACHED_CACHE_EXAMPLE_COM":2

So, IHMO following what we need to here to close this issue:

NOTE:

• The logs have been done as info when should be errors. See : {"level":"info"}
• The e2e test probably does not get it because of "level":"info"

• So, we need to change the log level to error and ensure that the e2e test would fail here:

https://github.com/operator-framework/operator-sdk/blob/bad0ca5d4fe03c221f395e5698e92f04b2d0be88/pkg/ansible/watches/watches.go#L291-L312

• Then, we need to fix the issue Failed to parse %v which shows introduced in #2087. The code implementation should be able to parse the default values like any other. (Note that may it is happening in all scenarios, I mean with the default or not values)

[djzager]

I think there may be a bit of a misunderstanding about what is happening here. Let's start with the log message that you shared.

{"level":"info","ts":1573605040.3003905,"logger":"watches","msg":"Failed to parse %v from environment. Using default %v","WORKER_MEMCACHED_CACHE_EXAMPLE_COM":1}
{"level":"info","ts":1573605040.3004255,"logger":"watches","msg":"Failed to parse %v from environment. Using default %v","ANSIBLE_VERBOSITY_MEMCACHED_CACHE_EXAMPLE_COM":2}

Going back to the code:

    maxWorkers, err := strconv.Atoi(os.Getenv(envVar))
    if err != nil {
        // we don't care why we couldn't parse it just use default
        log.Info("Failed to parse %v from environment. Using default %v", envVar, defValue)
        return defValue
    }

and:

    ansibleVerbosity, err := strconv.Atoi(os.Getenv(envVar)) 
    if err != nil { 
        log.Info("Failed to parse %v from environment. Using default %v", envVar, defValue) 
        return defValue 
    } 

Specifically, log.Info("Failed to parse %v from environment. Using default %v", envVar, defValue). Is saying that we couldn't parse the envVar (don't care why we can't parse it, maybe it's not there, maybe the user put in "foobar") and we are using the defValue. What is defValue? According to the logs you have shared the default values are 1 (in the case of maxWorkers) and 2 (in the case of ansibleVerbosity). That aligns with what you are showing from the command line flags:

https://github.com/operator-framework/operator-sdk/blob/d94ad3ea7d1547fdc2b2312e42da3455168d1e43/pkg/ansible/flags/flag.go#L44-L57

To recap:

The problem is that after #2087 the code impl is face an issue to parse them: (just covert the int to string should solve that)

Well, in the logs what you are seeing is we are trying to parse workers/ansibleVerbosity from an environment variable. We haven't failed to parse the default values.

• So, we need to change the log level to error and ensure that the e2e test would fail here:

We haven't failed, we are returning the default because we couldn't get a legit value from the environment (either because the environment variable wasn't set or the value inside was bogus).

• Then, we need to fix the issue Failed to parse %v which shows introduced in #2087. The code implementation should be able to parse the default values like any other. (Note that may it is happening in all scenarios, I mean with the default or not values)

We are returning the default value.

[joelanford]

There _is_ one bug here.

The log line:

log.Info("Failed to parse %v from environment. Using default %v", envVar, defValue)

is not correct (it doesn't support Printf style formatting). Rather, the signature is:

Info(msg string, keysAndValues ...interface{})

[jmrodri]

@camilamacedo86 @djzager the logic is correct. This is behaving exactly as expected. The log should be info because it is not a failure but information. We failed to see or parse anything from the environment variable. But if you did not set them then you can ignore this message and move on. If you did set them this should alert you that this might be your problem.

The failure is really what @joelanford just posted above. I would change the log statement to be the following:

log.Info(fmt.Sprintf("Failed to parse %v from environment. Using default %v", envVar, defValue))

That is the only problem with this bug.

[camilamacedo86]

Hi @jmrodri. @joelanford @djzager,

I understood what is happening now. Thank you for the clarification.
However, the text Failed to parse %v from environment. -> It is not good for the users.
In POV it leads to us believe that something is wrong when is not.

The goal is just to inform that the default values were used because not ENV VARs were found. So, I would suggest the msg be changed to avoid misunderstandings.

So, IHMO it could be something as Using default value for ENVVAR since not env set in the env was found

[jmrodri]

Okay fair enough. I suggest we use the original message I used when I wrote the first iteration of maxWorkers:

envvar := formatEnvVar(gvk.Kind, gvk.Group)
    maxWorkers, err := strconv.Atoi(os.Getenv(envvar))
    if err != nil {
        // we don't care why we couldn't parse it just use one.
        // maybe we should log that we are defaulting to 1.
        logf.Log.WithName("manager").V(0).Info("Using default value for workers %d", defvalue)

[jmrodri]

So the fix for this is:
1) Use an fmt.Sprintf inside the log.Info
2) use a more user friendly message for the worker parsing like: "Using default value for workers %d", defvalue"
3) use a more user friendly message for ansible verbosity like : "Using default value for ansible verbosity %d", defValue"

[bharathi-tenneti]

/assign @bharathi-tenneti