Enable request log flag support by skonto · Pull Request #8958 · knative/serving

skonto · 2020-08-07T11:45:39Z

Proposed Changes

According to the discussion in Add a new toggle to config observability to trigger log collection. #8644 we check in activator and queue proxy if we should enable request logging
based on a new flag.

Release Note

NONE

/assign @vagababov

knative-prow-robot · 2020-08-07T11:45:52Z

Hi @skonto. Thanks for your PR.

I'm waiting for a knative member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

julz

/ok-to-test

julz · 2020-08-07T12:42:03Z

pkg/reconciler/revision/resources/queue.go

 			Value: observabilityConfig.RequestLogTemplate,
+		}, {
+			Name:  "SERVING_ENABLE_REQUEST_LOG",
+			Value: strconv.FormatBool(observabilityConfig.EnableRequestLog),


this seems worth adding a quick test for

julz · 2020-08-07T12:45:13Z

cmd/activator/request_log.go

@@ -29,11 +30,20 @@ import (

 func updateRequestLogFromConfigMap(logger *zap.SugaredLogger, h *pkghttp.RequestLogHandler) func(configMap *corev1.ConfigMap) {


this seems like it'll need updates to request_log_test.go

Actually it was queue_test.go, for 0.17 we want things to work as previously so unit tests shouldnt break.

queue_test.go failed because of the changes to queue.go. This requires changes to request_log_test.go because it changes the behaviour so should probably at least result in a new row in the table test or something :-).

Yes I was referring to the failures.

ah right, gotcha. I was just meaning "we probably need to add a test for the new logic here"

julz · 2020-08-07T12:46:49Z

cmd/activator/request_log.go

+		var newTemplate string // default is an empty template, disables logging
+		obsconfig, err := metrics.NewObservabilityConfigFromConfigMap(configMap)
+		if err != nil {
+			logger.Errorw("Failed to get observability configmap.", zap.Error(err), "configmap", configMap)


probably better to do this as a guard clause at the top with a return, then the rest of the method can be out-dented

yanweiguo · 2020-08-07T23:30:19Z

cmd/activator/request_log.go

+			logger.Errorw("Failed to get observability configmap.", zap.Error(err), "configmap", configMap)
 		} else {
-			logger.Infow("Updated the request log template.", "template", newTemplate)
+			if obsconfig.EnableRequestLog {


If EnableRequestLog is false, newTemplate will always be empty. I think this is the logic we will roll out in 0.18, but not 0.17. Is my understanding correct?

@yanweiguo right now the logic in observability config sets everything as expected for 0.17 and 0.18. However, we need this check here so we dont pass a template that is kept in the cm while the only thing that the user changed was the flag value to false. In the latter case we have a template that is not empty but flag is false now with the new cm update, if we dont check here we will accidentally enable logging.
In the general case the observability config will set the enableRequestLog flag to true when it is needed (for 0.17, 0.18) so that is the source of truth for enabling/disabling logging at the client side.

julz · 2020-08-10T09:04:46Z

cmd/activator/request_log.go

+		if err != nil {
+			logger.Errorw("Failed to get observability configmap.", zap.Error(err), "configmap", configMap)
+			return
+		}


total nit, but nicer to have a newline after a guard clause I think

Suggested change

}

}

skonto · 2020-08-10T10:26:33Z

cmd/activator/request_log_test.go

+	*ptr = val
+	return ptr
+}
+


Maybe there is an option impl to use.

There is knative.dev/pkg/ptr and then ptr.Bool.

skonto · 2020-08-10T10:26:50Z

cmd/activator/request_log_test.go

+		body:             "test",
+		template:         "",
+		want:             "",
+		enableRequestLog: getBoolPtr(true),


@julz tests added.

julz · 2020-08-10T10:51:22Z

cmd/activator/request_log_test.go

+		body:             "test",
+		template:         "",
+		want:             "",
+		enableRequestLog: ptr.Bool(true),


could also just explicitly put the data map in the test table, i.e. add data map[string]string as a field in the table, and then you can explicitly show the keys there/not there in each test. e.g. a row might look like

{ name: "explicitly disable request logging", url: "http://example.com/testpage", body: "test", data: map[string]string{ "logging.request-log-template": "disable_request_log", "logging.enable-request-log": "false", }, want: "", }

avoids the ptr stuff and the if block/dereference below, and is maybe a bit clearer? I don't feel super strongly though if you prefer this way

let me check :)

julz · 2020-08-10T10:56:39Z

cmd/activator/request_log.go

 func updateRequestLogFromConfigMap(logger *zap.SugaredLogger, h *pkghttp.RequestLogHandler) func(configMap *corev1.ConfigMap) {
 	return func(configMap *corev1.ConfigMap) {
-		newTemplate := configMap.Data["logging.request-log-template"]
+		var newTemplate string


again bit of a nit sorry, but could we move this down to just above if obsconfig.EnableRequestLog? that way the defaulting of that variable is in one place (and I think it's best if a guard is the first thing if possible anyway)

skonto · 2020-08-10T11:25:19Z

@julz its now updated.

julz · 2020-08-10T11:44:46Z

cmd/activator/request_log_test.go

+		name: "empty template",
+		url:  "http://example.com/testpage",
+		body: "test",
+		data: map[string]string{"logging.request-log-template": ""},


nice, let's touch up the formatting though since the lines get pretty long otherwise (same for all the rows in the table):

Suggested change

data: map[string]string{"logging.request-log-template": ""},

data: map[string]string{

"logging.request-log-template": "",

},

@julz go fmt does this. Will the format you suggest pass the ci checks?

it will do what I typed above if you add a newline at the right places (go fmt doesn't split long initialisers automatically, but it's definitely the right thing here and consistent with the rest of the code base, e.g. 1, 2, 3)

just run go fmt after adding some newlines as above and it'll do the right thing :)

correct I have already done it for some of them. Let me update it.

julz · 2020-08-10T11:50:47Z

cmd/queue/main.go


 func pushRequestLogHandler(currentHandler http.Handler, env config) http.Handler {
-	if env.ServingRequestLogTemplate == "" {
+	if !env.ServingEnableRequestLog {


do we want to handle the case where ServiceEnableRequestLog is true but ServingRequestLogTemplate is ""? (e.g. maybe this would happen with default settings in 0.17 and we'd still want to avoid bothering with the request log handler, even though it'll eventually be a no-op?)

@julz in config_overvability.go:

if raw, ok := configMap.Data["logging.enable-request-log"]; ok { if strings.EqualFold(raw, "true") && oc.RequestLogTemplate != "" { oc.EnableRequestLog = true } }

Afaik what you describe cannot happen. We only set it to true internally in 0.17 if the template is not empty.
So even if the configmap has a value of true we push down (activator, QP) a false value.

ok cool, sounds good to me then

skonto · 2020-08-10T13:14:25Z

I am wondering why TestRunLatestService fails the first time. Rebasing to master just in case (although its flaky).

knative-metrics-robot · 2020-08-10T13:20:58Z

The following is the coverage report on the affected files.
Say /test pull-knative-serving-go-coverage to re-run this coverage report

File	Old Coverage	New Coverage	Delta
cmd/activator/request_log.go	100.0%	95.0%	-5.0

knative-test-reporter-robot · 2020-08-10T14:02:32Z

The following jobs failed:

Test name	Triggers	Retries
pull-knative-serving-integration-tests	2020-08-10 14:02:20.149 +0000 UTC	1/3

Automatically retrying due to test flakiness...
/test pull-knative-serving-integration-tests

skonto · 2020-08-10T15:14:08Z

@markusthoemmes @julz @yanweiguo I believe this is mergeable now.

julz

/lgtm

vagababov · 2020-08-10T18:18:58Z

/lgtm
/approve

yanweiguo

/lgtm

knative-prow-robot · 2020-08-10T18:28:48Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: julz, skonto, vagababov, yanweiguo

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

~~cmd/activator/OWNERS~~ [vagababov]
~~cmd/queue/OWNERS~~ [vagababov]
~~pkg/reconciler/OWNERS~~ [vagababov]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

googlebot added the cla: yes Indicates the PR's author has signed the CLA. label Aug 7, 2020

knative-prow-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Aug 7, 2020

knative-prow-robot requested review from markusthoemmes, vagababov and yanweiguo August 7, 2020 11:45

knative-prow-robot added needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. area/API API objects and controllers area/networking labels Aug 7, 2020

julz reviewed Aug 7, 2020

View reviewed changes

knative-prow-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Aug 7, 2020

yanweiguo reviewed Aug 7, 2020

View reviewed changes

knative-prow-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Aug 10, 2020

julz reviewed Aug 10, 2020

View reviewed changes

skonto commented Aug 10, 2020

View reviewed changes

julz reviewed Aug 10, 2020

View reviewed changes

knative-prow-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Aug 10, 2020

julz reviewed Aug 10, 2020

View reviewed changes

Stavros Kontopoulos added 5 commits August 10, 2020 16:12

enable request log flag

349c864

fix unit tests

cbc6aee

remove activator check

a5b1ab8

use guard clause

654235e

add test

5ad5d27

Stavros Kontopoulos added 6 commits August 10, 2020 16:12

fix activator logic

632b7fa

add request log unit tests

46c1bde

fix order

dc6bc38

fix ptr

3cd302c

minor fixes

8c4693a

fix test case

a25e53f

skonto force-pushed the add_flag_log branch from 1b7933e to a25e53f Compare August 10, 2020 13:13

julz approved these changes Aug 10, 2020

View reviewed changes

knative-prow-robot assigned julz Aug 10, 2020

knative-prow-robot added the lgtm Indicates that a PR is ready to be merged. label Aug 10, 2020

knative-prow-robot assigned vagababov Aug 10, 2020

knative-prow-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Aug 10, 2020

yanweiguo approved these changes Aug 10, 2020

View reviewed changes

knative-prow-robot assigned yanweiguo Aug 10, 2020

knative-prow-robot merged commit b901d34 into knative:master Aug 10, 2020

julz mentioned this pull request Apr 15, 2021

Add julz to API Approvers knative/community#573

Merged

		@@ -29,11 +30,20 @@ import (

		func updateRequestLogFromConfigMap(logger zap.SugaredLogger, h pkghttp.RequestLogHandler) func(configMap *corev1.ConfigMap) {

Conversation

skonto commented Aug 7, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Proposed Changes

Uh oh!

knative-prow-robot commented Aug 7, 2020

Uh oh!

julz left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

julz Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto commented Aug 10, 2020

Uh oh!

julz Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

julz Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto Aug 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skonto commented Aug 7, 2020 •

edited

Loading

skonto Aug 10, 2020 •

edited

Loading

skonto Aug 10, 2020 •

edited

Loading

julz Aug 10, 2020 •

edited

Loading

julz Aug 10, 2020 •

edited

Loading

skonto Aug 10, 2020 •

edited

Loading

julz Aug 10, 2020 •

edited

Loading

skonto Aug 10, 2020 •

edited

Loading

skonto Aug 10, 2020 •

edited

Loading

skonto commented Aug 10, 2020 •

edited

Loading