Skip to content
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

add timestamps to json log output of controller #800

Closed
csantanapr opened this issue Oct 14, 2020 · 2 comments · Fixed by #802
Closed

add timestamps to json log output of controller #800

csantanapr opened this issue Oct 14, 2020 · 2 comments · Fixed by #802

Comments

@csantanapr
Copy link

csantanapr commented Oct 14, 2020

Expected Behavior

Easy to detect via logs how long it took from receiving the webhook HTTP request until is done creating resources and replying back to the webhook originator (ie github)

Actual Behavior

Sometimes github would complain that the request time out because the response from the trigger listener controller didn't reply in time.

This is based on my vague understanding

Steps to Reproduce the Problem

  1. Create event listener with proper trigger template and bindings
  2. Expose to github the rul
  3. Create webhook and generate a push event.
  4. Check the logs of the eventlisternet pod to check how long it takes to perform the tasks
  5. The json log lines do not contain a timestamp to help debug and troubleshoot to get an idea how long is the controller taking to process the request, interceptors, and create resources

Additional Info

Using tekton triggers provided via stable channel on OpenShift Pipelines Operator

@AlanGreene
Copy link
Member

AlanGreene commented Oct 15, 2020

Having the timestamp included in the logs definitely seems like a useful addition. In the meantime you can pass the --timestamps flag to kubectl logs to prepend each log line with the timestamp, e.g.:

$ kubectl logs el-webhook-listener-interceptor-7947c8c588-bsp8k --timestamps
2020-10-15T12:59:30.8667788Z {"level":"info","caller":"logging/config.go:111","msg":"Successfully created the logger."}
2020-10-15T12:59:30.8668347Z {"level":"info","caller":"logging/config.go:112","msg":"Logging level set to info"}
2020-10-15T12:59:30.8668583Z {"level":"info","caller":"logging/config.go:79","msg":"Fetch GitHub commit ID from kodata failed","error":"open /var/run/ko/HEAD: no such file or directory"}
2020-10-15T12:59:30.86688Z {"level":"info","logger":"eventlistener","caller":"logging/logging.go:46","msg":"Starting the Configuration eventlistener","knative.dev/controller":"eventlistener"}
2020-10-15T12:59:30.9689176Z {"level":"info","logger":"eventlistener","caller":"eventlistenersink/main.go:72","msg":"EventListener pod started","knative.dev/controller":"eventlistener"}
2020-10-15T12:59:30.9755192Z {"level":"info","logger":"eventlistener","caller":"eventlistenersink/main.go:98","msg":"Listen and serve on port 8080","knative.dev/controller":"eventlistener"}

@dibyom dibyom mentioned this issue Oct 15, 2020
2 tasks
afrittoli added a commit to afrittoli/triggers that referenced this issue Oct 15, 2020
The controller and webhook logs do not include timestamps, which
makes troubleshooting issues much harder.
Adding the timestamps into the default logging configuration.

Fixes: tektoncd#800

Signed-off-by: Andrea Frittoli <andrea.frittoli@gmail.com>
tekton-robot pushed a commit that referenced this issue Oct 16, 2020
The controller and webhook logs do not include timestamps, which
makes troubleshooting issues much harder.
Adding the timestamps into the default logging configuration.

Fixes: #800

Signed-off-by: Andrea Frittoli <andrea.frittoli@gmail.com>
@csantanapr
Copy link
Author

Thank you @afrittoli for the quick fix 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants