[RANGER-2899] Ranger Kudu plugin seems to hang when authorizing requests in certain environments

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.1.0
• Component/s: plugins
• Assignee: Unassigned
• Reporter: Andrew Wong
• Created: 06/Jul/20 20:12
• Updated: 08/Jul/20 22:38

Description

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.

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:

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

The Ranger server is running on commit 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?

Issue Links

• causes: KUDU-3154 RangerClientTestBase.TestLogging sometimes fails