[
https://issues.apache.org/jira/browse/RANGER-3513?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
ruiliang updated RANGER-3513:
-----------------------------
Description:
add new policy ，All Ranger requests are 10s+.Print jstatck: some threads are
locked.Does the external request lastKnownVersion not change?
* A lot of these threads
{code:java}
KiB Swap: 0 total, 0 free, 0 used. 57020896 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
61905 root 20 0 20.748g 4.689g 23760 R 99.3 7.6 4:32.52 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
3500 root 20 0 20.748g 4.689g 23760 S 8.3 7.6 0:00.31 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
45584 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.76 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
62387 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.32 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
7230 root 20 0 20.748g 4.689g 23760 S 5.3 7.6 0:00.42 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
3412 root 20 0 20.748g 4.689g 23760 S 5.0 7.6 0:00.53 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
45616 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:03.50 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
3498 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.92 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
7238 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.28 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
7096 root 20 0 20.748g 4.689g 23760 S 1.3 7.6 0:00.05 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52641 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 1:33.20 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
7229 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 0:00.30 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52032 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.00 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52034 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.84 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52035 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:40.21 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52036 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.32 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52037 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:36.96 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52038 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.96 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52039 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.80 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52040 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.05 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52041 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.59 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52042 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.29 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52043 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.88 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52044 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:39.19 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
52045 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.46 java
-Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
-Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
-Dhostname=fs-hiido-range+
root@fs-hiido-ranger-21-117-150:/home/liangrui# printf "%x\n" 61905
f1d1
root@fs-hiido-ranger-21-117-150:/home/liangrui#
root@fs-hiido-ranger-21-117-150:/home/liangrui# jstack 52032 | grep -20 f1d1
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
"http-bio-6080-exec-9692" #9852 daemon prio=5 os_prio=0 tid=0x00007f0bf003a800
nid=0xf3b2 waiting on condition [0x00007f0c287cc000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c72df908> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32)
at
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
"Thread-114" #9851 daemon prio=5 os_prio=0 tid=0x00007f0a14006800 nid=0xf1d1
runnable [0x00007f0c295d7000]
java.lang.Thread.State: RUNNABLE
at java.lang.reflect.Field.get(Field.java:393)
at
org.eclipse.persistence.internal.descriptors.InstanceVariableAttributeAccessor.getAttributeValueFromObject(InstanceVariableAttributeAccessor.java:76)
at
org.eclipse.persistence.mappings.DatabaseMapping.getAttributeValueFromObject(DatabaseMapping.java:630)
at
org.eclipse.persistence.mappings.foundation.AbstractDirectMapping.valueFromObject(AbstractDirectMapping.java:1176)
at
org.eclipse.persistence.internal.descriptors.ObjectBuilder.extractPrimaryKeyFromObject(ObjectBuilder.java:3011)
at
org.eclipse.persistence.internal.descriptors.ObjectBuilder.createObjectChangeSet(ObjectBuilder.java:2885)
at
org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSetThroughComparison(DeferredChangeDetectionPolicy.java:155)
at
org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSet(DeferredChangeDetectionPolicy.java:146)
at
org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChanges(DeferredChangeDetectionPolicy.java:91)
at
org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChangesForExistingObject(DeferredChangeDetectionPolicy.java:56)
at
org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:664)
at
org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:438)
at
org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:863)
at
org.eclipse.persistence.internal.jpa.QueryImpl.performPreQueryFlush(QueryImpl.java:963)
at
org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:207)
at
org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:469)
at
org.apache.ranger.db.XXPolicyResourceMapDao.findByPolicyId(XXPolicyResourceMapDao.java:56)
at
org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.<init>(RangerPolicyRetriever.java:552)
at
org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.getAllPoliciesBySecondary(RangerPolicyRetriever.java:671)
{code}
* Many such request logs
spark app run
{{10.12.11.16 - - [11/Nov/2021:17:12:28 +0800] "GET
/service/plugins/secure/policies/download/spark_offline?lastKnownVersion=29397&lastActivationTime=1636621258729&pluginId=sparkSql%40fs-hiido-dn-12-11-16.hiido.host.yydevops.com-spark_offline&clusterName=
HTTP/1.1" 304 - "-" "Java/1.8.0_201"}}
practical
{code:java}
//
{{ { "configs": \{ "jdbc.driverClassName": "org.apache.hive.jdbc.HiveDriver",
"jdbc.url": "jdbc:hive2://10.21.112.3:30000", "password": "*****",
"policy.download.auth.users": "*", "policy.grantrevoke.auth.users": "*",
"tag.download.auth.users": "*", "username": "hdfs" }
, "createTime": 1573165348000, "createdBy": "Admin", "description":
"spark_offline cluster", "guid": "ddb5305b-d145-44f7-af09-77b41d28959f", "id":
17, "isEnabled": true, "name": "spark_offline", "policyUpdateTime":
1636621544000, "policyVersion": 29412, "tagUpdateTime": 1573194148000,
"tagVersion": 1, "type": "hive", "updateTime": 1573432854000, "updatedBy":
"Admin", "version": 13 },}}
{code}
lastKnownVersion=29397 >policyVersion": 29412 ?? When does this happen
After the ranger service is restarted, the ranger service is restored
The request log becomes lastKnownVersion=29412
lastKnownVersion Where did you get it from? Is the cache not flushed yet?
` boolean getLatestOrCached(String serviceName, ServiceStore serviceStore)
throws Exception {
boolean ret = false;
{code:java}
//
try {
ret = lock.tryLock(waitTimeInSeconds, TimeUnit.SECONDS);
if (ret) {
getLatest(serviceName, serviceStore);
}
} catch (InterruptedException exception) {
LOG.error("getLatestOrCached:lock got interrupted..",
exception);
} finally {
if (ret) {
lock.unlock();
}
}
return ret;
} {code}
If the policy name is marked with an asterisk (*), the deadlock will be
triggered, and all requests will wait for 10s+ example add policy name
"name":"udf-resource-policy-*-com.xx.ent.hive.udf.DecryptUDF_presto.decrypt-2147454847",
* This is the full JStack in question
[^ranger_1_1115.jstack]
was:
add new policy ，All Ranger requests are 10s+.Print jstatck: some threads are
locked.Does the external request lastKnownVersion not change?
* A lot of these threads
{code:java}
//
http-bio-6080-exec-41522" #44501 daemon prio=5 os_prio=0 tid=0x00007f3ad8003800
nid=0xa5b waiting on condition [0x00007f3db3ffc000] java.lang.Thread.State:
TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to
wait for <0x00000006c8fd07d0> (a
java.util.concurrent.locks.ReentrantLock$NonfairSync) at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireNanos(AbstractQueuedSynchronizer.java:934)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1247)
at java.util.concurrent.locks.ReentrantLock.tryLock(ReentrantLock.java:442) at
org.apache.ranger.common.RangerServicePoliciesCache$ServicePoliciesWrapper.getLatestOrCached(RangerServicePoliciesCache.java:198)
at
org.apache.ranger.common.RangerServicePoliciesCache.getServicePolicies(RangerServicePoliciesCache.java:142)
at
org.apache.ranger.biz.ServiceDBStore.getServicePoliciesIfUpdated(ServiceDBStore.java:2534)
at
org.apache.ranger.rest.ServiceREST.getSecureServicePoliciesIfUpdated(ServiceREST.java:3078)
at
org.apache.ranger.rest.ServiceREST$$FastClassBySpringCGLIB$$92dab672.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) at
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at
org.apache.ranger.rest.ServiceREST$$EnhancerBySpringCGLIB$$7fd1c842.getSecureServicePoliciesIfUpdated(<generated>)
at sun.reflect.GeneratedMethodAccessor208.invoke(Unknown Source) at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at
com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at
com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at
com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
at
com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at
com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at
com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at
com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at
com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542)
at
com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473)
at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
at
com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)
at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
at
org.apache.ranger.security.web.filter.RangerSecurityContextFormationFilter.doFilter(RangerSecurityContextFormationFilter.java:145)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.apache.ranger.security.web.filter.RangerCSRFPreventionFilter$ServletFilterHttpInteraction.proceed(RangerCSRFPreventionFilter.java:210)
at
org.apache.ranger.security.web.filter.RangerCSRFPreventionFilter.handleHttpInteraction(RangerCSRFPreventionFilter.java:155)
at
org.apache.ranger.security.web.filter.RangerCSRFPreventionFilter.doFilter(RangerCSRFPreventionFilter.java:165)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.apache.ranger.security.web.filter.RangerKRBAuthenticationFilter.doFilter(RangerKRBAuthenticationFilter.java:313)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.apache.ranger.security.web.filter.RangerSSOAuthenticationFilter.doFilter(RangerSSOAuthenticationFilter.java:234)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:215)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at
org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
at
org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
at
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
at
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:494)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1136)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
at
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
- locked <0x00000007beb60460> (a org.apache.tomcat.util.net.SocketWrapper) at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
{code}
* Many such request logs
spark app run
{{10.12.11.16 - - [11/Nov/2021:17:12:28 +0800] "GET
/service/plugins/secure/policies/download/spark_offline?lastKnownVersion=29397&lastActivationTime=1636621258729&pluginId=sparkSql%40fs-hiido-dn-12-11-16.hiido.host.yydevops.com-spark_offline&clusterName=
HTTP/1.1" 304 - "-" "Java/1.8.0_201"}}
practical
{code:java}
//
{{ { "configs": \{ "jdbc.driverClassName": "org.apache.hive.jdbc.HiveDriver",
"jdbc.url": "jdbc:hive2://10.21.112.3:30000", "password": "*****",
"policy.download.auth.users": "*", "policy.grantrevoke.auth.users": "*",
"tag.download.auth.users": "*", "username": "hdfs" }
, "createTime": 1573165348000, "createdBy": "Admin", "description":
"spark_offline cluster", "guid": "ddb5305b-d145-44f7-af09-77b41d28959f", "id":
17, "isEnabled": true, "name": "spark_offline", "policyUpdateTime":
1636621544000, "policyVersion": 29412, "tagUpdateTime": 1573194148000,
"tagVersion": 1, "type": "hive", "updateTime": 1573432854000, "updatedBy":
"Admin", "version": 13 },}}
{code}
lastKnownVersion=29397 >policyVersion": 29412 ?? When does this happen
After the ranger service is restarted, the ranger service is restored
The request log becomes lastKnownVersion=29412
lastKnownVersion Where did you get it from? Is the cache not flushed yet?
` boolean getLatestOrCached(String serviceName, ServiceStore serviceStore)
throws Exception {
boolean ret = false;
{code:java}
//
try {
ret = lock.tryLock(waitTimeInSeconds, TimeUnit.SECONDS);
if (ret) {
getLatest(serviceName, serviceStore);
}
} catch (InterruptedException exception) {
LOG.error("getLatestOrCached:lock got interrupted..",
exception);
} finally {
if (ret) {
lock.unlock();
}
}
return ret;
} {code}
If the policy name is marked with an asterisk (*), the deadlock will be
triggered, and all requests will wait for 10s+ example add policy name
"name":"udf-resource-policy-*-com.xx.ent.hive.udf.DecryptUDF_presto.decrypt-2147454847",
* This is the full JStack in question
https://issues.apache.org/jira/secure/attachment/13036102/ranger_1_1115.jstack
> locks getLatestOrCached(RangerServicePoliciesCache.java:198) (ranger 1.2)
> -------------------------------------------------------------------------
>
> Key: RANGER-3513
> URL: https://issues.apache.org/jira/browse/RANGER-3513
> Project: Ranger
> Issue Type: Bug
> Components: admin
> Affects Versions: 1.2.0
> Reporter: ruiliang
> Priority: Major
> Attachments: ranger_1_1115.jstack
>
> Original Estimate: 12h
> Remaining Estimate: 12h
>
> add new policy ，All Ranger requests are 10s+.Print jstatck: some threads are
> locked.Does the external request lastKnownVersion not change?
> * A lot of these threads
> {code:java}
> KiB Swap: 0 total, 0 free, 0 used. 57020896 avail Mem
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
>
>
>
> 61905 root 20 0 20.748g 4.689g 23760 R 99.3 7.6 4:32.52 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 3500 root 20 0 20.748g 4.689g 23760 S 8.3 7.6 0:00.31 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 45584 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.76 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 62387 root 20 0 20.748g 4.689g 23760 S 6.3 7.6 0:02.32 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 7230 root 20 0 20.748g 4.689g 23760 S 5.3 7.6 0:00.42 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 3412 root 20 0 20.748g 4.689g 23760 S 5.0 7.6 0:00.53 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 45616 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:03.50 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 3498 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.92 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 7238 root 20 0 20.748g 4.689g 23760 S 4.3 7.6 0:00.28 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 7096 root 20 0 20.748g 4.689g 23760 S 1.3 7.6 0:00.05 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52641 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 1:33.20 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 7229 root 20 0 20.748g 4.689g 23760 S 0.3 7.6 0:00.30 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52032 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.00 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52034 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 0:00.84 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52035 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:40.21 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52036 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.32 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52037 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:36.96 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52038 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.96 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52039 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.80 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52040 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.05 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52041 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.59 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52042 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.29 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52043 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:37.88 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52044 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:39.19 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> 52045 root 20 0 20.748g 4.689g 23760 S 0.0 7.6 7:38.46 java
> -Dproc_rangeradmin -XX:MetaspaceSize=512M -Xmx4024m -Xms4024m
> -Duser.timezone=UTC -Dzookeeper.sasl.client.username=zookeeper -Duser=root
> -Dhostname=fs-hiido-range+
> root@fs-hiido-ranger-21-117-150:/home/liangrui# printf "%x\n" 61905
> f1d1
> root@fs-hiido-ranger-21-117-150:/home/liangrui#
> root@fs-hiido-ranger-21-117-150:/home/liangrui# jstack 52032 | grep -20 f1d1
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)
> "http-bio-6080-exec-9692" #9852 daemon prio=5 os_prio=0
> tid=0x00007f0bf003a800 nid=0xf3b2 waiting on condition [0x00007f0c287cc000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000006c72df908> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> at
> java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
> at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86)
> at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32)
> at
> java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:748)
> "Thread-114" #9851 daemon prio=5 os_prio=0 tid=0x00007f0a14006800 nid=0xf1d1
> runnable [0x00007f0c295d7000]
> java.lang.Thread.State: RUNNABLE
> at java.lang.reflect.Field.get(Field.java:393)
> at
> org.eclipse.persistence.internal.descriptors.InstanceVariableAttributeAccessor.getAttributeValueFromObject(InstanceVariableAttributeAccessor.java:76)
> at
> org.eclipse.persistence.mappings.DatabaseMapping.getAttributeValueFromObject(DatabaseMapping.java:630)
> at
> org.eclipse.persistence.mappings.foundation.AbstractDirectMapping.valueFromObject(AbstractDirectMapping.java:1176)
> at
> org.eclipse.persistence.internal.descriptors.ObjectBuilder.extractPrimaryKeyFromObject(ObjectBuilder.java:3011)
> at
> org.eclipse.persistence.internal.descriptors.ObjectBuilder.createObjectChangeSet(ObjectBuilder.java:2885)
> at
> org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSetThroughComparison(DeferredChangeDetectionPolicy.java:155)
> at
> org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.createObjectChangeSet(DeferredChangeDetectionPolicy.java:146)
> at
> org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChanges(DeferredChangeDetectionPolicy.java:91)
> at
> org.eclipse.persistence.descriptors.changetracking.DeferredChangeDetectionPolicy.calculateChangesForExistingObject(DeferredChangeDetectionPolicy.java:56)
> at
> org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:664)
> at
> org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:438)
> at
> org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:863)
> at
> org.eclipse.persistence.internal.jpa.QueryImpl.performPreQueryFlush(QueryImpl.java:963)
> at
> org.eclipse.persistence.internal.jpa.QueryImpl.executeReadQuery(QueryImpl.java:207)
> at
> org.eclipse.persistence.internal.jpa.QueryImpl.getResultList(QueryImpl.java:469)
> at
> org.apache.ranger.db.XXPolicyResourceMapDao.findByPolicyId(XXPolicyResourceMapDao.java:56)
> at
> org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.<init>(RangerPolicyRetriever.java:552)
> at
> org.apache.ranger.biz.RangerPolicyRetriever$RetrieverContext.getAllPoliciesBySecondary(RangerPolicyRetriever.java:671)
> {code}
> * Many such request logs
> spark app run
> {{10.12.11.16 - - [11/Nov/2021:17:12:28 +0800] "GET
> /service/plugins/secure/policies/download/spark_offline?lastKnownVersion=29397&lastActivationTime=1636621258729&pluginId=sparkSql%40fs-hiido-dn-12-11-16.hiido.host.yydevops.com-spark_offline&clusterName=
> HTTP/1.1" 304 - "-" "Java/1.8.0_201"}}
> practical
> {code:java}
> //
> {{ { "configs": \{ "jdbc.driverClassName": "org.apache.hive.jdbc.HiveDriver",
> "jdbc.url": "jdbc:hive2://10.21.112.3:30000", "password": "*****",
> "policy.download.auth.users": "*", "policy.grantrevoke.auth.users": "*",
> "tag.download.auth.users": "*", "username": "hdfs" }
> , "createTime": 1573165348000, "createdBy": "Admin", "description":
> "spark_offline cluster", "guid": "ddb5305b-d145-44f7-af09-77b41d28959f",
> "id": 17, "isEnabled": true, "name": "spark_offline", "policyUpdateTime":
> 1636621544000, "policyVersion": 29412, "tagUpdateTime": 1573194148000,
> "tagVersion": 1, "type": "hive", "updateTime": 1573432854000, "updatedBy":
> "Admin", "version": 13 },}}
> {code}
> lastKnownVersion=29397 >policyVersion": 29412 ?? When does this happen
> After the ranger service is restarted, the ranger service is restored
> The request log becomes lastKnownVersion=29412
> lastKnownVersion Where did you get it from? Is the cache not flushed yet?
> ` boolean getLatestOrCached(String serviceName, ServiceStore serviceStore)
> throws Exception {
> boolean ret = false;
> {code:java}
> //
> try {
> ret = lock.tryLock(waitTimeInSeconds, TimeUnit.SECONDS);
> if (ret) {
> getLatest(serviceName, serviceStore);
> }
> } catch (InterruptedException exception) {
> LOG.error("getLatestOrCached:lock got interrupted..",
> exception);
> } finally {
> if (ret) {
> lock.unlock();
> }
> }
> return ret;
> } {code}
>
> If the policy name is marked with an asterisk (*), the deadlock will be
> triggered, and all requests will wait for 10s+ example add policy name
>
> "name":"udf-resource-policy-*-com.xx.ent.hive.udf.DecryptUDF_presto.decrypt-2147454847",
>
> * This is the full JStack in question
> [^ranger_1_1115.jstack]
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
