[
https://issues.apache.org/jira/browse/KUDU-3154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17141178#comment-17141178
]
Andrew Wong commented on KUDU-3154:
---
It's interesting, in the dumped Java logs, there's:
{code}
2020-06-20 07:05:49.472 [DEBUG - main] (PolicyRefresher.java:154) Scheduled
policyDownloadRefresher to download policies every 200 milliseconds
2020-06-20 07:05:49.472 [INFO - main] (RangerKuduAuthorizer.java:92) Finished
Ranger Kudu plugin initialization
2020-06-20 07:05:49.505 [DEBUG - pool-3-thread-1] (QueueUtil.java:41) Message:
org.apache.kudu.subprocess.InboundRequest@7e331671 has been taken from the queue
2020-06-20 07:05:49.507 [DEBUG - pool-2-thread-1] (QueueUtil.java:56) Message:
org.apache.kudu.subprocess.InboundRequest@7e331671 has been put on the queue
2020-06-20 07:05:49.640 [DEBUG - pool-3-thread-1] (Groups.java:312)
GroupCacheLoader - load.
2020-06-20 07:05:49.654 [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-06-20 07:05:49.672 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(PolicyRefresher.java:489) ==> PolicyRefresher(serviceName=kudu).loadRoles()
2020-06-20 07:05:49.672 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerRolesProvider.java:109) ==> RangerRolesProvider(serviceName= kudu
serviceType= kudu).loadUserGroupRoles()
2020-06-20 07:05:49.673 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerRolesProvider.java:118) In-Use memory: 15693968, Free memory:230197104
2020-06-20 07:05:49.673 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerRolesProvider.java:171) ==>
RangerRolesProvider(serviceName=kudu).loadUserGroupRolesFromAdmin()
2020-06-20 07:05:49.673 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerAdminRESTClient.java:204) ==>
RangerAdminRESTClient.getRolesIfUpdated(-1, 1592636749068)
2020-06-20 07:05:49.673 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerAdminRESTClient.java:238) Checking Roles updated as user : slave
(auth:SIMPLE)
2020-06-20 07:05:49.689 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerAdminRESTClient.java:250) No change in Roles. secureMode=false,
user=slave (auth:SIMPLE), response={"httpStatusCode":304,"statusCode":0},
serviceName=kudu, lastKnownRoleVersion=-1,
lastActivationTimeInMillis=1592636749068
2020-06-20 07:05:49.692 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerAdminRESTClient.java:277) <==
RangerAdminRESTClient.getRolesIfUpdated(-1, 1592636749068):
2020-06-20 07:05:49.693 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerRolesProvider.java:193) RangerRolesProvider(serviceName=kudu).run(): no
update found. lastKnownRoleVersion=-1
2020-06-20 07:05:49.693 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(RangerPerfTracer.java:101) [PERF]
RangerRolesProvider.loadUserGroupRolesFromAdmin(serviceName=kudu): 20
{code}
I would have expected the order of logs to reflect that a message to the
inbound queue was first [put by the
MessageReader|https://github.com/apache/kudu/blob/master/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/MessageReader.java#L87],
and then [taken by the
MessageParser|https://github.com/apache/kudu/blob/master/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/MessageParser.java#L59]
-- though maybe that's an issue with multithreaded logging.
Otherwise, after those calls, the Ranger subprocess appears to just be
refreshing policies until the request times out. The MessageParser doesn't
appear to put the request on the outbound queue. Perhaps the fact that the
Ranger client is refreshing privileges so frequently is interfering with the
ability to evaluate the request?
> RangerClientTestBase.TestLogging sometimes fails
>
>
> Key: KUDU-3154
> URL: https://issues.apache.org/jira/browse/KUDU-3154
> Project: Kudu
> Issue Type: Bug
> Components: ranger, test
>Affects Versions: 1.13.0
>Reporter: Alexey Serbin
>Priority: Major
> Attachments: ranger_client-test.txt.xz
>
>
> The {{RangerClientTestBase.TestLogging}} scenario of the
> {{ranger_client-test}} sometimes fails (all types of builds) with error
> message like below:
> {noformat}
> src/kudu/ranger/ranger_client-test.cc:398: Failure
> Failed
>
> Bad status: Timed out: timed out while in flight
>
> I0620 07:06:02.907177 1140 server.cc:247] Received an EOF from the
> subprocess
> I0620 07:06:02.910923 1137 server.cc:317] get failed, inbound queue shut
> down: Aborted:
> I0620 07:06:02.910964 1141 server.cc:380] outbound queue shut down: Aborted:
>
> I0620 07:06:02.910995 1138 server.cc:317] get failed, inbound queue shut
> down: Aborted:
