Whitelists are not working #9402

KevinKlinger · 2018-10-18T14:37:48Z

Describe the bug
I performed all actions as described in the docs.
The thing is I can get reviews with stars, which is definitely not intended.

It seems like all of my whitelists are not working since I tried others like the one described in #7766

Expected behavior
For the example in the docs I expected to see the productpage without stars, if I am not logged in as user jason.
For the example of #7766 I expected to get a 404 until I send requests with the correct x-api-key header.

Both configurations don't have any effect to the system.

Version
Istio: 1.0.2
K8s: 1.11.3

Installation
helm template install/kubernetes/helm/istio --name istio --namespace istio-system \
--set global.configValidation=false \
--set sidecarInjectorWebhook.enabled=false \
--set tracing.enabled=true \
--set tracing.jaeger.enabled=true \
--set kiali.enabled=false \
--set grafana.enabled=true

Environment
K8s, AWS

The text was updated successfully, but these errors were encountered:

oulinbao · 2018-10-22T02:21:47Z

I encountered this problem on 1.0.0 too.

clyang82 · 2018-11-08T08:55:07Z

@KevinKlinger & @oulinbao I have tried 1.0.2 and 1.0.3. they are not working. But it works in istio-1.1.0-snapshot.2. so this issue should be fixed in release-1.1. I cannot test release-1.1, because there is a blocking issue - #9593. We can have a try after unblocking.

kyessenov · 2018-11-08T18:55:45Z

/assign @kyessenov
I'll take a look at this. @mandarjog given that 1.0.4 is imminent, we should back-port the fix.

kyessenov · 2018-11-08T22:57:36Z

I have tried the task but failed to reproduce the issue on 1.0.3. After creating the handler/instance/rule, I can see black starts only when I login as user "jason", and no stars, otherwise. A few things that can help us to debug further:

make sure to create handler/instance/rule in the same namespace as bookinfo application
it would help us to get complete policy logs:

Bump up logging level by editing kubectl edit deployment istio-policy -n istio-system, and adding --log_output_level=api:debug to mixer container, e.g.:

      - args:
        - --address
        - unix:///sock/mixer.socket
        - --configStoreURL=k8s://
        - --configDefaultNamespace=istio-system
        - --trace_zipkin_url=http://zipkin:9411/api/v1/spans
        - --log_output_level=api:debug

After observing the misbehavior, report the logs from policy mixer: kubectl logs -l istio-mixer-type=policy -n istio-system -c mixer

clyang82 · 2018-11-09T09:45:59Z

I guess that is relevant with the cache. I meet this issue in the first time, it works after. Then I delete kubectl delete -f /tmp/whitelist-handler.yaml ; kubectl delete -f /tmp/appversion-instance.yaml ; kubectl delete -f /tmp/checkversion-rule.yaml . the page is still shown Ratings service is currently unavailable. it works after 5 or more minutes.

clyang82 · 2018-11-09T09:48:42Z

Logout the productpage. re-apply the whitelist handler, it still show red stars. Here are logs:

2018-11-09T09:44:19.549263Z	debug	api	Dispatching Check
2018-11-09T09:44:19.549271Z	debug	api	Check approved
2018-11-09T09:44:20.652688Z	debug	api	Check (GlobalWordCount:203, DeduplicationID:49712f54-c81b-4c9b-a614-7276d7a2d4eb16, Quota:map[])
2018-11-09T09:44:20.652708Z	debug	api	Dispatching Preprocess Check
2018-11-09T09:44:20.652919Z	debug	api	Dispatching to main adapters after running processors
2018-11-09T09:44:20.653011Z	debug	api	Attribute Bag: 
connection.mtls               : false
context.protocol              : http
context.reporter.kind         : inbound
context.reporter.uid          : kubernetes://details-v1-6764bbc7f7-wd4fg.default
destination.ip                : [0 0 0 0 0 0 0 0 0 0 255 255 10 1 90 240]
destination.namespace         : default
destination.port              : 9080
destination.service           : details.default.svc.cluster.local
destination.service.host      : details.default.svc.cluster.local
destination.service.name      : details
destination.service.namespace : default
destination.service.uid       : istio://default/services/details
destination.uid               : kubernetes://details-v1-6764bbc7f7-wd4fg.default
origin.ip                     : [10 1 162 156]
request.headers               : {request.headers map[x-forwarded-proto:http x-request-id:3f4ab2fa-b0f4-9d55-9af6-af67572255db accept-encoding:gzip, deflate x-b3-parentspanid:ea13023b6683b8a3 user-agent:python-requests/2.18.4 x-b3-traceid:ea13023b6683b8a3 sec-istio-authn-payload: :path:/details/0 content-length:0 x-b3-spanid:50d344c4691f1a08 :authority:details:9080 accept:*/* :method:GET x-b3-sampled:1] 0xc42b68c480}
request.host                  : details:9080
request.method                : GET
request.path                  : /details/0
request.scheme                : http
request.time                  : 2018-11-09 09:44:20.651866062 +0000 UTC
request.useragent             : python-requests/2.18.4
source.uid                    : kubernetes://productpage-v1-54b8b9f55-2lwlt.default
---
destination.container.name    : details
destination.labels            : map[version:v1 app:details pod-template-hash:2320667393]
destination.name              : details-v1-6764bbc7f7-wd4fg
destination.owner             : kubernetes://apis/apps/v1/namespaces/default/deployments/details-v1
destination.serviceAccount    : default
destination.workload.name     : details-v1
destination.workload.namespace: default
destination.workload.uid      : istio://default/workloads/details-v1
source.ip                     : [10 1 162 156]
source.labels                 : map[app:productpage pod-template-hash:106465911 version:v1]
source.name                   : productpage-v1-54b8b9f55-2lwlt
source.namespace              : default
source.owner                  : kubernetes://apis/apps/v1/namespaces/default/deployments/productpage-v1
source.serviceAccount         : default
source.workload.name          : productpage-v1
source.workload.namespace     : default
source.workload.uid           : istio://default/workloads/productpage-v1

2018-11-09T09:44:20.653022Z	debug	api	Dispatching Check
2018-11-09T09:44:20.653031Z	debug	api	Check approved
2018-11-09T09:44:21.421107Z	debug	api	Check (GlobalWordCount:203, DeduplicationID:42a4234d-268a-4560-9ef5-79cb6e26b84210, Quota:map[])
2018-11-09T09:44:21.421132Z	debug	api	Dispatching Preprocess Check
2018-11-09T09:44:27.651344Z	debug	api	Check (GlobalWordCount:203, DeduplicationID:0b7effa6-9fae-443d-879c-d3d6ebb2d73a12, Quota:map[])
2018-11-09T09:44:27.651364Z	debug	api	Dispatching Preprocess Check
2018-11-09T09:44:27.651575Z	debug	api	Dispatching to main adapters after running processors
2018-11-09T09:44:27.651671Z	debug	api	Attribute Bag: 
connection.mtls               : false
context.protocol              : http
context.reporter.kind         : inbound
context.reporter.uid          : kubernetes://reviews-v2-5bdc5877d6-ps97k.default
destination.ip                : [0 0 0 0 0 0 0 0 0 0 255 255 10 1 162 139]
destination.namespace         : default
destination.port              : 9080
destination.service           : reviews.default.svc.cluster.local
destination.service.host      : reviews.default.svc.cluster.local
destination.service.name      : reviews
destination.service.namespace : default
destination.service.uid       : istio://default/services/reviews
destination.uid               : kubernetes://reviews-v2-5bdc5877d6-ps97k.default
origin.ip                     : [10 1 162 156]
request.headers               : {request.headers map[x-forwarded-proto:http x-b3-parentspanid:143201962f0b4dce x-request-id:3092a2c7-07be-440b-9cea-bf5d7aa028e2 sec-istio-authn-payload: content-length:0 x-b3-spanid:2a431d3e87bcefdd :path:/reviews/0 x-b3-traceid:143201962f0b4dce accept:*/* end-user:jason user-agent:python-requests/2.18.4 x-b3-sampled:0 :method:GET :authority:reviews:9080 accept-encoding:gzip, deflate] 0xc42a5ee840}
request.host                  : reviews:9080
request.method                : GET
request.path                  : /reviews/0
request.scheme                : http
request.time                  : 2018-11-09 09:44:27.630399602 +0000 UTC
request.useragent             : python-requests/2.18.4
source.uid                    : kubernetes://productpage-v1-54b8b9f55-2lwlt.default
---
destination.container.name    : reviews
destination.labels            : map[app:reviews pod-template-hash:1687143382 version:v2]
destination.name              : reviews-v2-5bdc5877d6-ps97k
destination.owner             : kubernetes://apis/apps/v1/namespaces/default/deployments/reviews-v2
destination.serviceAccount    : default
destination.workload.name     : reviews-v2
destination.workload.namespace: default
destination.workload.uid      : istio://default/workloads/reviews-v2
source.ip                     : [10 1 162 156]
source.labels                 : map[version:v1 app:productpage pod-template-hash:106465911]
source.name                   : productpage-v1-54b8b9f55-2lwlt
source.namespace              : default
source.owner                  : kubernetes://apis/apps/v1/namespaces/default/deployments/productpage-v1
source.serviceAccount         : default
source.workload.name          : productpage-v1
source.workload.namespace     : default
source.workload.uid           : istio://default/workloads/productpage-v1

2018-11-09T09:44:27.651681Z	debug	api	Dispatching Check
2018-11-09T09:44:27.651691Z	debug	api	Check approved
2018-11-09T09:44:31.702874Z	debug	api	Check (GlobalWordCount:203, DeduplicationID:c22675cd-2bed-4d8e-89c7-065a736ca84f15, Quota:map[])
2018-11-09T09:44:31.702898Z	debug	api	Dispatching Preprocess Check
2018-11-09T09:44:31.703105Z	debug	api	Dispatching to main adapters after running processors
2018-11-09T09:44:31.703192Z	debug	api	Attribute Bag: 
connection.mtls               : false
context.protocol              : http
context.reporter.kind         : inbound
context.reporter.uid          : kubernetes://details-v1-6764bbc7f7-wd4fg.default
destination.ip                : [0 0 0 0 0 0 0 0 0 0 255 255 10 1 90 240]
destination.namespace         : default
destination.port              : 9080
destination.service           : details.default.svc.cluster.local
destination.service.host      : details.default.svc.cluster.local
destination.service.name      : details
destination.service.namespace : default
destination.service.uid       : istio://default/services/details
destination.uid               : kubernetes://details-v1-6764bbc7f7-wd4fg.default
origin.ip                     : [10 1 162 156]
request.headers               : {request.headers map[x-forwarded-proto:http accept:*/* x-b3-traceid:4b58577e06bfe4f9 :method:GET user-agent:python-requests/2.18.4 x-b3-sampled:0 accept-encoding:gzip, deflate x-b3-spanid:e3d9e66d8ed4fee9 sec-istio-authn-payload: :authority:details:9080 x-request-id:923f8cfb-7f11-4758-a01d-89e0b8b3ae76 :path:/details/0 x-b3-parentspanid:4b58577e06bfe4f9 content-length:0] 0xc42baac180}
request.host                  : details:9080
request.method                : GET
request.path                  : /details/0
request.scheme                : http
request.time                  : 2018-11-09 09:44:31.702206384 +0000 UTC
request.useragent             : python-requests/2.18.4
source.uid                    : kubernetes://productpage-v1-54b8b9f55-2lwlt.default
---
destination.container.name    : details
destination.labels            : map[app:details pod-template-hash:2320667393 version:v1]
destination.name              : details-v1-6764bbc7f7-wd4fg
destination.owner             : kubernetes://apis/apps/v1/namespaces/default/deployments/details-v1
destination.serviceAccount    : default
destination.workload.name     : details-v1
destination.workload.namespace: default
destination.workload.uid      : istio://default/workloads/details-v1
source.ip                     : [10 1 162 156]
source.labels                 : map[app:productpage pod-template-hash:106465911 version:v1]
source.name                   : productpage-v1-54b8b9f55-2lwlt
source.namespace              : default
source.owner                  : kubernetes://apis/apps/v1/namespaces/default/deployments/productpage-v1
source.serviceAccount         : default
source.workload.name          : productpage-v1
source.workload.namespace     : default
source.workload.uid           : istio://default/workloads/productpage-v1

2018-11-09T09:44:31.703201Z	debug	api	Dispatching Check
2018-11-09T09:44:31.703209Z	debug	api	Check approved
GC forced
gc 14 @688.484s 0%: 0.019+21+13 ms clock, 0.15+0/41/50+105 ms cpu, 170->170->144 MB, 289 MB goal, 8 P
2018-11-09T09:44:55.561889Z	info	Publishing 3 events
2018-11-09T09:44:55.563534Z	info	Built new config.Snapshot: id='13'
2018-11-09T09:44:55.563599Z	info	adapters	getting kubeconfig from: ""	{"adapter": "handler.kubernetesenv.istio-system"}
2018-11-09T09:44:55.563606Z	warn	Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
2018-11-09T09:44:55.565037Z	info	adapters	Waiting for kubernetes cache sync...	{"adapter": "handler.kubernetesenv.istio-system"}
2018-11-09T09:44:55.766550Z	info	adapters	Cache sync successful.	{"adapter": "handler.kubernetesenv.istio-system"}
2018-11-09T09:44:55.766742Z	info	adapters	Installing updated list with 2 entries	{"adapter": "whitelist.listchecker.default"}
2018-11-09T09:44:55.769397Z	warn	No destination sets found for the default namespace 'istio-system'.
2018-11-09T09:44:55.769411Z	info	Cleaning up handler table, with config ID:12
2018-11-09T09:44:55.769425Z	error	adapters	adapter did not close all the scheduled daemons	{"adapter": "handler.kubernetesenv.istio-system"}

It works after a few minutes.

kyessenov · 2018-11-09T19:12:14Z

Thanks for the logs. The log line that stands out to me is at the bottom "Publishing 3 events". It seems that Mixer received the config deletion events fairly late in the log. That means Mixer was operating with the old config state prior to receiving the events. This happens with a loaded API server that introduces a significant latency between kubectl commands and clients actually receiving the new state.

Note that check decisions are indeed cached:

Mixer has a central check cache. This doesn't happen here (you should see "Check approved from cache" if the cache is hit)
Each adapter also sets a caching interval for proxies. By default, it is 5 minutes for listchecker adapter:

istio/mixer/adapter/list/list.go

Line 269 in 405f47f

CachingInterval: 300 * time.Second,

You can change it with caching_duration field in params.

clyang82 · 2018-11-12T05:15:49Z

@kyessenov Thanks for your explanations.

kyessenov · 2018-11-12T21:13:39Z

Is there still an issue observed if we eliminate API server latency and caching duration?

clyang82 · 2018-11-13T01:24:55Z

There is no an issue from my view. I think we can close this issue if the Author (@KevinKlinger ) has no concerns.

KevinKlinger · 2018-11-13T12:54:14Z

I'm fine with your explanation.
Thank you for stating out the issue.

douglas-reid added the area/extensions and telemetry label Oct 19, 2018

douglas-reid assigned mandarjog and geeknoid Oct 19, 2018

kyessenov self-assigned this Nov 8, 2018

kyessenov added the kind/need more info Need more info or followup from the issue reporter label Nov 8, 2018

KevinKlinger closed this as completed Nov 13, 2018

clyang82 mentioned this issue Nov 20, 2018

REQUEST: New membership for clyang82 istio/community#102

Closed

7 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Whitelists are not working #9402

Whitelists are not working #9402

KevinKlinger commented Oct 18, 2018

oulinbao commented Oct 22, 2018

clyang82 commented Nov 8, 2018

kyessenov commented Nov 8, 2018

kyessenov commented Nov 8, 2018 •

edited

clyang82 commented Nov 9, 2018

clyang82 commented Nov 9, 2018

kyessenov commented Nov 9, 2018

clyang82 commented Nov 12, 2018 •

edited

kyessenov commented Nov 12, 2018

clyang82 commented Nov 13, 2018

KevinKlinger commented Nov 13, 2018

Whitelists are not working #9402

Whitelists are not working #9402

Comments

KevinKlinger commented Oct 18, 2018

oulinbao commented Oct 22, 2018

clyang82 commented Nov 8, 2018

kyessenov commented Nov 8, 2018

kyessenov commented Nov 8, 2018 • edited

clyang82 commented Nov 9, 2018

clyang82 commented Nov 9, 2018

kyessenov commented Nov 9, 2018

clyang82 commented Nov 12, 2018 • edited

kyessenov commented Nov 12, 2018

clyang82 commented Nov 13, 2018

KevinKlinger commented Nov 13, 2018

kyessenov commented Nov 8, 2018 •

edited

clyang82 commented Nov 12, 2018 •

edited