New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[kubernetes] Log errors to stderr #419

Open
wants to merge 1 commit into
base: master
from

Conversation

Projects
None yet
1 participant
@janpieper
Copy link

janpieper commented Feb 6, 2019

Scenario

$ bw apply br0ken
i br0ken  started at 2019-02-06 17:39:12
✘ br0ken  br0ken  k8s_deployment:br0ken/nginx failed (manifest)
i br0ken  completed after 1s  (2 OK, 0 fixed, 0 skipped, 1 failed)
i ╭────────┬───────┬────┬───────┬─────────┬────────┬──────╮
i │ node   │ items │ OK │ fixed │ skipped │ failed │ time │
i ├────────┼───────┼────┼───────┼─────────┼────────┼──────┤
i │ br0ken │     3 │  2 │     0 │       0 │      1 │   1s │
i ╰────────┴───────┴────┴───────┴─────────┴────────┴──────╯

🤔 🤔 🤔 🤔 🤔

Related to #397.

Problem

As you can see in the output above, there is NO information about why bw apply has failed...

Current "solution"

You need to run the same command with debug mode enabled (bw -d apply <node>):

[2019-02-06 17:41:00.702995] [DEBUG] invocation: /tmp/bw/venv/bin/bw -d apply br0ken
[2019-02-06 17:41:00.782474] [DEBUG] node br0ken gets its dummy attribute from: default
[2019-02-06 17:41:00.782885] [DEBUG] spinning up worker pool apply
[2019-02-06 17:41:00.782933] [DEBUG] worker pool apply is starting task br0ken on worker #0
[2019-02-06 17:41:00.783161] i br0ken  started at 2019-02-06 17:41:00
[2019-02-06 17:41:00.783203] [DEBUG] worker pool apply waiting for next task to complete
[2019-02-06 17:41:00.783284] [DEBUG] node br0ken gets its os attribute from: node
[2019-02-06 17:41:00.783421] [DEBUG] node br0ken gets its os_version attribute from: default
[2019-02-06 17:41:00.783664] [DEBUG] spinning up worker pool apply_br0ken
[2019-02-06 17:41:00.783714] [DEBUG] worker pool apply_br0ken is starting task br0ken:k8s_namespace:br0ken on worker #0
[2019-02-06 17:41:00.783924] [DEBUG] node br0ken gets its kubectl_context attribute from: node
[2019-02-06 17:41:00.783994] [DEBUG] running command with ID K8WC: kubectl --context=msh-one --namespace=br0ken get -o json Namespace br0ken
[2019-02-06 17:41:00.784040] [DEBUG] worker pool apply_br0ken waiting for next task to complete
[2019-02-06 17:41:01.087247] [DEBUG] command with ID K8WC finished with return code 0
[2019-02-06 17:41:01.088506] [DEBUG] worker pool apply_br0ken delivering result of br0ken:k8s_namespace:br0ken on worker #0
[2019-02-06 17:41:01.088844] [DEBUG] worker pool apply_br0ken is starting task br0ken:k8s_namespace: on worker #1
[2019-02-06 17:41:01.089384] [DEBUG] worker pool apply_br0ken is starting task br0ken:k8s_service:br0ken/nginx on worker #2
[2019-02-06 17:41:01.090364] [DEBUG] worker pool apply_br0ken is starting task br0ken:k8s_deployment:br0ken/nginx on worker #3
[2019-02-06 17:41:01.096744] [DEBUG] br0ken:br0ken:k8s_service:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:01.096978] [DEBUG] br0ken:br0ken:k8s_service:br0ken/nginx: rendered in 8.5e-05s
[2019-02-06 17:41:01.099823] [DEBUG] worker pool apply_br0ken waiting for next task to complete
[2019-02-06 17:41:01.100070] [DEBUG] running command with ID 1SAU: kubectl --context=msh-one --namespace=br0ken get -o json Service nginx
[2019-02-06 17:41:01.100206] [DEBUG] worker pool apply_br0ken delivering result of br0ken:k8s_namespace: on worker #1
[2019-02-06 17:41:01.101193] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:01.103705] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendered in 0.000245s
[2019-02-06 17:41:01.103913] [DEBUG] worker pool apply_br0ken waiting for next task to complete
[2019-02-06 17:41:01.110396] [DEBUG] running command with ID BHVA: kubectl --context=msh-one --namespace=br0ken get -o json Deployment nginx
[2019-02-06 17:41:01.511416] [DEBUG] command with ID 1SAU finished with return code 0
[2019-02-06 17:41:01.513942] [DEBUG] br0ken:br0ken:k8s_service:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:01.514158] [DEBUG] br0ken:br0ken:k8s_service:br0ken/nginx: rendered in 8.4e-05s
[2019-02-06 17:41:01.518299] [DEBUG] worker pool apply_br0ken delivering result of br0ken:k8s_service:br0ken/nginx on worker #2
[2019-02-06 17:41:01.518700] [DEBUG] worker pool apply_br0ken is starting task br0ken:k8s_service: on worker #0
[2019-02-06 17:41:01.518839] [DEBUG] worker pool apply_br0ken waiting for next task to complete
[2019-02-06 17:41:01.519051] [DEBUG] worker pool apply_br0ken delivering result of br0ken:k8s_service: on worker #0
[2019-02-06 17:41:01.519133] [DEBUG] command with ID BHVA finished with return code 0
[2019-02-06 17:41:01.519718] [DEBUG] worker pool apply_br0ken waiting for next task to complete
[2019-02-06 17:41:01.520904] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:01.521043] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendered in 4.5e-05s
[2019-02-06 17:41:01.529187] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:01.529310] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendered in 3e-05s
[2019-02-06 17:41:01.534017] [DEBUG] running command with ID IKHW: kubectl --context=msh-one --namespace=br0ken apply -f -
[2019-02-06 17:41:01.994870] [DEBUG] command with ID IKHW finished with return code 1
[2019-02-06 17:41:01.995125] [DEBUG] 
[2019-02-06 17:41:01.995182] [DEBUG] The Deployment "nginx" is invalid: 
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain only alpha-numeric characters (a-z, 0-9), and hyphens (-)
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain at least one letter or number (a-z, 0-9)

[2019-02-06 17:41:01.995462] [DEBUG] running command with ID 61WH: kubectl --context=msh-one --namespace=br0ken get -o json Deployment nginx
[2019-02-06 17:41:02.300708] [DEBUG] command with ID 61WH finished with return code 0
[2019-02-06 17:41:02.304595] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendering with Jinja2...
[2019-02-06 17:41:02.304919] [DEBUG] br0ken:br0ken:k8s_deployment:br0ken/nginx: rendered in 0.00012s
[2019-02-06 17:41:02.312977] [DEBUG] worker pool apply_br0ken delivering result of br0ken:k8s_deployment:br0ken/nginx on worker #3
[2019-02-06 17:41:02.313161] [DEBUG] skipped these items because they depend on k8s_deployment:br0ken/nginx, which was skipped previously: bundle:br0ken, k8s_deployment:
[2019-02-06 17:41:02.313227] [DEBUG] skipped these items because they depend on bundle:br0ken, which was skipped previously: bundle:
[2019-02-06 17:41:02.313423] [DEBUG] shutting down worker pool apply_br0ken
[2019-02-06 17:41:02.313877] [DEBUG] worker pool apply_br0ken has been shut down
[2019-02-06 17:41:02.314088] i br0ken  completed after 1s  (2 OK, 0 fixed, 0 skipped, 1 failed)
[2019-02-06 17:41:02.314273] [DEBUG] worker pool apply delivering result of br0ken on worker #0
[2019-02-06 17:41:02.314380] [DEBUG] shutting down worker pool apply
[2019-02-06 17:41:02.314499] [DEBUG] worker pool apply has been shut down
[2019-02-06 17:41:02.314724] i ╭────────┬───────┬────┬───────┬─────────┬────────┬──────╮
[2019-02-06 17:41:02.314824] i │ node   │ items │ OK │ fixed │ skipped │ failed │ time │
[2019-02-06 17:41:02.314900] i ├────────┼───────┼────┼───────┼─────────┼────────┼──────┤
[2019-02-06 17:41:02.314982] i │ br0ken │     3 │  2 │     0 │       0 │      1 │   1s │
[2019-02-06 17:41:02.315039] i ╰────────┴───────┴────┴───────┴─────────┴────────┴──────╯

Now you can see the error that caused bw apply to fail. Okay, you need to check all the lines to find the relevant error message(s)... Here is the relevant part:

[2019-02-06 17:41:01.995182] [DEBUG] The Deployment "nginx" is invalid: 
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain only alpha-numeric characters (a-z, 0-9), and hyphens (-)
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain at least one letter or number (a-z, 0-9)

As you can see, running bw -d apply is quite too verbose. And that's just a very very small example application with one namespace, one deployment and one service... (see #397 for further details).

New solution

I've updated log_errors in bundlewrap.items.kubernetes to log errors to STDERR instead of logging it via io.debug("...").

i br0ken  started at 2019-02-06 17:51:33
[ERROR] The Deployment "nginx" is invalid: 
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain only alpha-numeric characters (a-z, 0-9), and hyphens (-)
* spec.template.spec.containers[0].ports[0].name: Invalid value: "\\/": must contain at least one letter or number (a-z, 0-9)

✘ br0ken  br0ken  k8s_deployment:br0ken/nginx failed (manifest)
i br0ken  completed after 1s  (2 OK, 0 fixed, 0 skipped, 1 failed)
i ╭────────┬───────┬────┬───────┬─────────┬────────┬──────╮
i │ node   │ items │ OK │ fixed │ skipped │ failed │ time │
i ├────────┼───────┼────┼───────┼─────────┼────────┼──────┤
i │ br0ken │     3 │  2 │     0 │       0 │      1 │   1s │
i ╰────────┴───────┴────┴───────┴─────────┴────────┴──────╯

Now you are able to see the error that caused bw apply to fail without being forced to enable the debug mode.

Discussion

I am really new to bundlewrap and I don't know if this is the best way to solve this problem, especially because it might be a breaking change due to writing to STDERR...

Maybe we could add something like -d, --debug for this case. Something like -e, --show-errors. Or maybe something more generic like a log level that can be configured via --log-level=(debug|...|error).

What do you think?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment