[
https://issues.apache.org/jira/browse/RANGER-2899?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17153158#comment-17153158
]
Andrew Wong commented on RANGER-2899:
-------------------------------------
Cross-posting my comment:
I was able to reproduce this on an Ubuntu 14.04 container with openJDK 8.
Running jstack (see [^kudu-3154_jstacks.txt]) on the subprocess, I saw the
following:
{code:java}
"policyDownloadTimer" #14 daemon prio=5 os_prio=0 tid=0x00007f71c0941000
nid=0x4c8de in Object.wait() [0x00007f716f4e2000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000006c0235468> (a
org.apache.ranger.plugin.util.DownloadTrigger)
at java.lang.Object.wait(Object.java:502)
at
org.apache.ranger.plugin.util.DownloadTrigger.waitForCompletion(DownloadTrigger.java:27)
- locked <0x00000006c0235468> (a
org.apache.ranger.plugin.util.DownloadTrigger)
at
org.apache.ranger.plugin.util.DownloaderTask.run(DownloaderTask.java:42)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)
{code}
This appears to be
[waiting|https://github.com/apache/ranger/blob/master/agents-common/src/main/java/org/apache/ranger/plugin/util/DownloadTrigger.java#L25]
for the [download trigger to
fire|https://github.com/apache/ranger/blob/95a1aa57a96b392227a4f0aa4e7ecc396dca2261/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java#L214],
but for some reason that isn't happening. It's true that the policy refresher
in my logs doesn't successfully refresh the policy, but the trigger should
still fire.
> Ranger Kudu plugin seems to hang when authorizing requests in certain
> environments
> ----------------------------------------------------------------------------------
>
> Key: RANGER-2899
> URL: https://issues.apache.org/jira/browse/RANGER-2899
> Project: Ranger
> Issue Type: Bug
> Components: plugins
> Affects Versions: 2.1.0
> Reporter: Andrew Wong
> Priority: Major
> Attachments: kudu-3154_jstacks.txt
>
>
> Kudu's authorization provider is a Java process that communicates with the
> Kudu master processes with IPC going over a pipe. The Java process enqueues
> requests to be authorized by a ["kudu"-typed
> RangerBasePlugin|https://github.com/apache/kudu/blob/master/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/authorization/RangerKuduAuthorizer.java].
> In some of our pre-commit tests that run on Ubuntu 14.04, the plugin appears
> to hang, periodically refreshing privileges (we've seen the issue with a
> refresh interval of 200ms and 500ms) until the request eventually times out
> on the Kudu side:
> {code:java}
> 2020-07-03 09:21:25.793 [DEBUG - main] (PolicyRefresher.java:154) Scheduled
> policyDownloadRefresher to download policies every 500 milliseconds
> 2020-07-03 09:21:25.794 [INFO - main] (RangerKuduAuthorizer.java:92) Finished
> Ranger Kudu plugin initialization
> 2020-07-03 09:21:25.814 [DEBUG - pool-3-thread-1] (QueueUtil.java:40) Message
> being taken from the queue
> 2020-07-03 09:21:25.829 [DEBUG - pool-2-thread-1] (QueueUtil.java:58) Message
> being put onto the queue
> 2020-07-03 09:21:25.830 [DEBUG - pool-3-thread-2] (QueueUtil.java:40) Message
> being taken from the queue
> 2020-07-03 09:21:25.834 [DEBUG - pool-3-thread-3] (QueueUtil.java:40) Message
> being taken from the queue
> 2020-07-03 09:21:25.838 [DEBUG - pool-3-thread-1] (QueueUtil.java:44)
> Message: org.apache.kudu.subprocess.InboundRequest@6a0874e7 has been taken
> from the queue
> 2020-07-03 09:21:25.841 [DEBUG - pool-4-thread-1] (QueueUtil.java:40) Message
> being taken from the queue
> 2020-07-03 09:21:25.845 [DEBUG - pool-2-thread-1] (QueueUtil.java:62)
> Message: org.apache.kudu.subprocess.InboundRequest@6a0874e7 has been put on
> the queue
> 2020-07-03 09:21:25.866 [DEBUG - pool-3-thread-1] (ProtocolHandler.java:53)
> Unpacking request
> 2020-07-03 09:21:25.869 [DEBUG - pool-3-thread-1] (ProtocolHandler.java:60)
> Executing request
> 2020-07-03 09:21:26.012 [DEBUG - pool-3-thread-1]
> (RangerProtocolHandler.java:53) Executing request
> 2020-07-03 09:21:26.021 [DEBUG - pool-3-thread-1] (Groups.java:312)
> GroupCacheLoader - load.
> 2020-07-03 09:21:26.037 [DEBUG - pool-3-thread-1]
> (UserGroupInformation.java:1737) Failed to get groups for user user by
> java.io.IOException: No groups found for user user
> 2020-07-03 09:21:26.040 [DEBUG - pool-3-thread-1]
> (RangerKuduAuthorizer.java:125) calling plugin
> 2020-07-03 09:21:26.294 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (PolicyRefresher.java:489) ==> PolicyRefresher(serviceName=kudu).loadRoles()
> 2020-07-03 09:21:26.294 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (RangerRolesProvider.java:109) ==> RangerRolesProvider(serviceName= kudu
> serviceType= kudu).loadUserGroupRoles()
> 2020-07-03 09:21:26.294 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (RangerRolesProvider.java:118) In-Use memory: 14500632, Free memory:223526120
> 2020-07-03 09:21:26.294 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (RangerRolesProvider.java:171) ==>
> RangerRolesProvider(serviceName=kudu).loadUserGroupRolesFromAdmin()
> 2020-07-03 09:21:26.294 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (RangerAdminRESTClient.java:204) ==>
> RangerAdminRESTClient.getRolesIfUpdated(-1, 1593768085212)
> 2020-07-03 09:21:26.295 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
> (RangerAdminRESTClient.java:238) Checking Roles updated as user : slave
> (auth:SIMPLE)
> Jul 03, 2020 9:21:26 AM com.sun.jersey.api.client.ClientResponse getEntity
> SEVERE: A message body reader for Java class java.lang.String, and Java type
> class java.lang.String, and MIME media type application/octet-stream was not
> found
> Jul 03, 2020 9:21:26 AM com.sun.jersey.api.client.ClientResponse getEntity
> SEVERE: The registered message body readers compatible with the MIME media
> type are:
> */* ->
> com.sun.jersey.json.impl.provider.entity.JSONJAXBElementProvider$General
> com.sun.jersey.json.impl.provider.entity.JSONArrayProvider$General
> com.sun.jersey.json.impl.provider.entity.JSONObjectProvider$General
> ... the rest of the logs seem to be Ranger refreshing policies until Kudu
> times out{code}
> The Ranger server is running on [commit
> f37f5407eee8d2627a4306a25938b151f8e2ba31|https://github.com/apache/ranger/commits/f37f5407eee8d2627a4306a25938b151f8e2ba31]
> and the Ranger plugin version is 2.0.0. More logs are attached in KUDU-3154.
> Are there known issues with the plugin when refreshing the privilege interval
> at high frequencies that can cause such hanging behavior?
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
