You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@kudu.apache.org by "Andrew Wong (Jira)" <ji...@apache.org> on 2020/06/20 19:44:00 UTC
[jira] [Commented] (KUDU-3154) RangerClientTestBase.TestLogging
sometimes fails
[ https://issues.apache.org/jira/browse/KUDU-3154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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:
> I0620 07:06:02.910984 1139 server.cc:317] get failed, inbound queue shut down: Aborted:
> {noformat}
> The log is attached.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)