[
https://issues.apache.org/jira/browse/KUDU-3154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17152223#comment-17152223
]
Andrew Wong commented on KUDU-3154:
-----------------------------------
I added some logging (see
[here|https://gist.github.com/andrwng/a4bfb48c779890e1839e7671b7356020]) to the
internal build, and found the following logs:
{code:java}
2020-07-03 09:21:25.791 [DEBUG - main] (RangerPerfTracer.java:101) [PERF]
PolicyRefresher.loadPolicy(serviceName=kudu): 577
2020-07-03 09:21:25.791 [DEBUG - main] (PolicyRefresher.java:287) <==
PolicyRefresher(serviceName=kudu).loadPolicy()
2020-07-03 09:21:25.792 [DEBUG - PolicyRefresher(serviceName=kudu)-12]
(PolicyRefresher.java:200) ==> PolicyRefresher(serviceName=kudu).run()
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 {code}
Notably, nothing gets logged after the {{calling plugin}} message. This makes
me think it's somehow getting stuck in the plugin.
Full logs: [^ranger_client-test.txt]
> 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, 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)
