FAIL: TestDenials (159.34s) mixer_test.go:301: Bad metric value: got 0.000000, want at least 1

[ldemailly]

Unearthed in #361

The TestDenials keeps failing
--- FAIL: TestDenials (159.34s)
mixer_test.go:301: Bad metric value: got 0.000000, want at least 1

@douglas-reid wrote "
when I look at the reported results for this test, I see no 4xx responses when a denial rule is in place. Is this related to the change in error reporting (are we still forwarding rpc statuses to mixer, rather than the internal status messages)? "

[ldemailly]

@geeknoid replied "In the new world, the Check RPC no longer returns 4xx results. Instead, the RPC itself succeeds, and the check yes/no indication is contained in the CheckResponse.status field instead."

so we need to update the caller ?

[geeknoid]

Yes, the client needs to look in the right place for the yes/no signal.

[douglas-reid]

Ok. I've found mixer logs for this:

I0606 17:23:03.836452       1 grpcServer.go:148] Dispatching Check
I0606 17:23:03.836510       1 runtime.go:208] resolveRules (aspects:<kind:"attributes" adapter:"default" params:&AttributesGeneratorParams{InputExpressions:map[string]string{originUID: origin.uid | "",sourceUID: source.uid | "",targetService: request.headers["authority"] | request.host | "",targetUID: target.uid | "",},AttributeBindings:map[string]string{source.ip: sourcePodIp,source.labels: sourceLabels,source.name: sourcePodName,source.namespace: sourceNamespace,source.service: sourceService,source.serviceAccount: sourceServiceAccountName,target.ip: targetPodIp,target.labels: targetLabels,target.name: targetPodName,target.namespace: targetNamespace,target.service: targetService,target.serviceAccount: targetServiceAccountName,},} > aspects:<kind:"quotas" adapter:"default" params:&QuotasParams{Quotas:[&QuotasParams_Quota{DescriptorName:RequestCount,Labels:map[string]string{},MaxAmount:5000,Expiration:1s,}],} > aspects:<kind:"metrics" adapter:"prometheus" params:&MetricsParams{Metrics:[&MetricsParams_Metric{DescriptorName:request_count,Value:1,Labels:map[string]string{method: request.path | "unknown",response_code: response.code | 200,service: target.labels["app"] | "unknown",source: source.labels["app"] | "unknown",target: target.service | "unknown",version: target.labels["version"] | "unknown",},} &MetricsParams_Metric{DescriptorName:request_duration,Value:response.latency | response.duration | "0ms",Labels:map[string]string{method: request.path | "unknown",response_code: response.code | 200,service: target.labels["app"] | "unknown",source: source.labels["app"] | "unknown",target: target.service | "unknown",version: target.labels["version"] | "unknown",},}],} > aspects:<kind:"access-logs" adapter:"default" params:&AccessLogsParams{LogName:access_log,Log:AccessLogsParams_AccessLog{DescriptorName:accesslog.common,TemplateExpressions:map[string]string{method: request.method,originIp: origin.ip,protocol: request.scheme,responseCode: response.code,responseSize: response.size,sourceUser: origin.user,timestamp: request.time,url: request.path,},Labels:map[string]string{method: request.method,originIp: origin.ip,protocol: request.scheme,responseCode: response.code,responseSize: response.size,sourceUser: origin.user,timestamp: request.time,url: request.path,},},} > ) ==> / 
I0606 17:23:03.836751       1 runtime.go:248] Rule () applies, using aspect kinds [denials, lists]:
- did not select aspect kind attributes named 'default', wrong kind
- did not select aspect kind quotas named 'default', wrong kind
- did not select aspect kind metrics named 'prometheus', wrong kind
- did not select aspect kind access-logs named 'default', wrong kind
I0606 17:23:03.836817       1 runtime.go:154] no rules for global/mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local
I0606 17:23:03.836852       1 runtime.go:208] resolveRules (selector:"source.labels[\"app\"]==\"reviews\" && source.labels[\"version\"] == \"v3\"" aspects:<kind:"denials" adapter:"default" params:&DenialsParams{} > ) ==> / 
I0606 17:23:03.836947       1 runtime.go:248] Rule (source.labels["app"]=="reviews" && source.labels["version"] == "v3") applies, using aspect kinds [lists, denials]:
- selected aspect kind denials with config: name:"default" impl:"denyChecker" params:&Params{Error:google_rpc.Status{Code:9,Message:,Details:[],},} 
I0606 17:23:03.837013       1 runtime.go:154] no rules for mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local/mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local
I0606 17:23:03.837082       1 runtime.go:154] no rules for mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local/ratings.mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local
I0606 17:23:03.837116       1 runtime.go:154] no rules for ratings.mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local/ratings.mixer-test-4ead6d3d6ab44859b8034b6fed.svc.cluster.local
I0606 17:23:03.837166       1 manager.go:203] Resolved 1 configs: [builder: name:"default" impl:"denyChecker" params:&Params{Error:google_rpc.Status{Code:9,Message:,Details:[],},}  aspect: kind:"denials" adapter:"default" params:&DenialsParams{} ] 
I0606 17:23:03.837360       1 grpcServer.go:150] Check returned with: FAILED_PRECONDITION builder: name:"default" impl:"denyChecker" params:&Params{Error:google_rpc.Status{Code:9,Message:,Details:[],},}  aspect: kind:"denials" adapter:"default" params:&DenialsParams{} :

It appears that mixer is sending back FAILED_PRECONDITION responses, but those are not getting back to Mixer in the corresponding Report() calls as anything but 200s:

request_count{method="/ratings",response_code="200",service="ratings",source="reviews",target="ratings.mixer-test-03aa4fa67c1d4f3cbf6a94fa1e.svc.cluster.local",version="v1"} 5

@qiwzhang @geeknoid thoughts on how to fix this?

[douglas-reid]

To replicate: $ tests/e2e.sh -test.run TestDenials

[geeknoid]

Doug, why did you reassign this to me? Mixer is returning the right result, right?

[douglas-reid]

@geeknoid because you worked on the protocol change. I don't care who fixes it, just that we fix it.

[qiwzhang]

@geeknoid

my understanding is any rpc status is networking status. server status should be returned in response.status. Please make sure mixer is returning all errors in response.status.

For network status, there is another flag network_failure_policy to use, default is open, any network error will mean open.

[qiwzhang]

@douglas-reid Please make sure mixer is returning all errors in response.status. That is what protocol required.

[douglas-reid]

@qiwzhang I'm not sure what you mean. We have the log message saying that it is returning FAILED_PRECONDITION. Are you suggesting the log doesn't match the behavior? @geeknoid can you confirm behavior, based on your changes to grpcServer.go ?

[qiwzhang]

There are two status: rpc status from the unary call, and status inside the response body. client treats the rpc status error as network error, and only extract response.status.

[mandarjog]

is there a log that we can enable to see what mixer_client is seeing?

[geeknoid]

With current Mixer bits, the expected behavior is:

• The Check method's RPC status should reflect network connectivity issues only. If the RPC returns OK, it means Mixer ran the request. If the result != OK, then Mixer didn't understand the request or the network failed.

• The CheckResponse.status field carries an rpc.Status object representing the semantic result of the Check operation. It'll be OK or non-OK to reflect whether the preconditions passed or not.

Within the grpcServer.go code in Mixer, this is handled here:

	// do the actual work for the message
	out = worker(ctx, preprocResponseBag, responseBag)

	if dState.result != nil {
		*dState.result = out
		out = status.OK
	}

In this case for the Check call, it takes the Status value obtained from running the adapters, sticks it in CheckResponse.Status, and has the RPC proper return OK.

As we've had problems with this kind of stuff in the past, what exact version of the Mixer is being used in these tests? The latest bits, or some snapshot from last week?

[geeknoid]

When I run Doug's command-line to replicate this, I get a bunch of console output and two instances of this error:

I0606 16:10:35.855202   98556 kubernetes.go:99] Setting up kubeInfo
I0606 16:10:35.855254   98556 commonUtils.go:53] Running command kubectl create namespace demo-test-1ed55a0d60b54aa9a599a431399
E0606 16:10:35.908361   98556 kubernetes.go:106] Failed to create namespace.
E0606 16:10:35.910386   98556 framework.go:192] Failed to complete Init. Error command failed: "The connection to the server 104.198.106.38 was refused - did you specify the right host or port?\n" exit status 1
I0606 16:10:35.910432   98556 framework.go:176] Saving logs

So I don't think it's getting to the point of running Mixer. Is there some extra setup voodoo necessary?

[mandarjog]

@geeknoid looks like you could not create a new namespace, so the test did not run at all.
there is a small chance that you need to refetch your cluster creds; or something similar is wrong locally.

I am looking at this problem as well.

[mandarjog]

latest bits are being used from mixer / proxy / manager and mixer client.
mixer build from Jun 5, 2017.

[douglas-reid]

@geeknoid @qiwzhang @mandarjog can I help with anything more here? should I try to grab logs from proxies?

[kyessenov]

this should be P0. If anything, we should be adding tests, not removing tests.

[douglas-reid]

Is it possible we are running into potentially new issues with caching?

I see the following in the CheckResponse: Cachability:CachabilityInfo{Duration:5s,UseCount:10000,}. Maybe we need more sleeps in TestDenials ?

[douglas-reid]

If I add time.Sleep(15 * time.Second) to TestDenials's request loop, I see:

request_count{method="/details",response_code="200",service="details",source="productpage",target="details.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v1"} 6
request_count{method="/productpage",response_code="200",service="productpage",source="unknown",target="productpage.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v1"} 6
request_count{method="/ratings",response_code="200",service="ratings",source="reviews",target="ratings.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v1"} 4
request_count{method="/reviews",response_code="200",service="reviews",source="productpage",target="reviews.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v1"} 2
request_count{method="/reviews",response_code="200",service="reviews",source="productpage",target="reviews.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v2"} 2
request_count{method="/reviews",response_code="200",service="reviews",source="productpage",target="reviews.mixer-test-607e9aced2ca45518457942eb8.svc.cluster.local",version="v3"} 2

To translate, it looks like the 2 requests from reviews-v3 to ratings that should have FAILED_PRECONDITION show up in the Report()s to Mixer as successes.

@qiwzhang can you please help debug why the statuses are translated to 200s?

[douglas-reid]

I've looked at TestRateLimit. I see RESOURCE_EXHAUSTEDs in the response codes:

request_count{method="/ratings",response_code="200",service="ratings",source="reviews",target="ratings.mixer-test-d93bb1944c63420c8db1c2e4fb.svc.cluster.local",version="v1"} 54
request_count{method="/ratings",response_code="429",service="ratings",source="reviews",target="ratings.mixer-test-d93bb1944c63420c8db1c2e4fb.svc.cluster.local",version="v1"} 43
request_count{method="/ratings",response_code="500",service="ratings",source="reviews",target="ratings.mixer-test-d93bb1944c63420c8db1c2e4fb.svc.cluster.local",version="v1"} 6

Not entirely sure what the difference is. I think we need a thorough regression review of the Report() mechanism from Envoy to Mixer.

[qiwzhang]

Are you using check_cache? Did you set "check_cache_keys" in the envoy config?

[douglas-reid]

All of these tests are with the default configuration for everything. As far as I know, the e2e tests don't explicitly set any non-default values.

You can check by starting up a test: $ tests/e2e.sh -test.run TestDenials --skip_cleanup.

[qiwzhang]

I need to study this whole e2e test in order to debug it. It will be great if someone can help.

I have a integration test making sure error status from mixer are passed to client.

https://github.com/istio/proxy/blob/master/src/envoy/mixer/integration_test/failed_request_test.go#L147

[douglas-reid]

the e2e test is how we validate releases. it uses the images as indicated in istio.VERSION. the particular test in question TestDenials sets up the bookinfo sample (samples/apps/bookinfo) in a test namespace and sends 6 requests to the productpage. 2 of those requests should result in 400s. We check that we get at least 1.

[ldemailly]

ping - we shouldn't leave trunk broken for so long if at all possible

[qiwzhang]

Can someone try with latest proxy/mixer build? It is easier to debug with latest proxy since I added debug log to print status from mixer. If still have problem, I will debug.

[ldemailly]

@qiwzhang let's see what jenkins shows on #400 with your new debug - but this should be easy to repro on your own env no ? (why not?)

[qiwzhang]

In my own integration test with just proxy/mixer, I could not reproduce it.

In the mixer config, I added

• • kind: denials

Mixer did get 400

"logName":"access_log","labels":{"method":"GET","protocol":"http","responseCode":400,"responseSize":200,"timestamp":"2017-06-09T01:23:36.583137929Z","url":"/echo"},"textPayload":"- - - [09/Jun/2017:01:23:36 +0000] "GET /echo http" 400 200"}

[ldemailly]

@qiwzhang
https://testing.istio.io/job/istio/job/presubmit/663/console
browser search for "FAIL: TestDenials"

do you see your additional info and does it help ?

[qiwzhang]

It confirmed that it still fails with latest proxy. The Jenkins log did not have debug proxy log. Not sure how easy to capture mixer debug log and proxy debug log in this e2e test.

Otherwise, I have to manually run it to debug it.

[sebastienvas]

We currently do not capture debug logs at the moment. I have an issue created for that. In the mean time can you run the thing manually ? Do you have minikube set up or a cluster that you can use ?

[douglas-reid]

OK. We figured this out. We were stuck on a version of the client that, while supporting unary, did not use the response code from within the CheckResponse. This was patched in the very next PR on the same day. Unfortunately, that detail was very hard to tease out of all of the SHA deps.

[ldemailly]

fixed in #400