KUDU-3154.diff

From d1d8e6d72209521cc884dde419725c657d86f4ec Mon Sep 17 00:00:00 2001
From: Andrew Wong <awong@cloudera.com>
Date: Thu, 02 Jul 2020 20:08:02 -0700
Subject: [PATCH] ranger: add some logging

Debugging KUDU-3154

Change-Id: I06502d182b88ab1d7c77e842b8986c9228ed8245
---

diff --git a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ProtocolHandler.java b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ProtocolHandler.java
index ac9d44b..7bf029b 100644
--- a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ProtocolHandler.java
+++ b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ProtocolHandler.java
@@ -22,6 +22,8 @@
 import com.google.protobuf.InvalidProtocolBufferException;
 import com.google.protobuf.Message;
 import org.apache.yetus.audience.InterfaceAudience;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import org.apache.kudu.subprocess.Subprocess.SubprocessRequestPB;
 import org.apache.kudu.subprocess.Subprocess.SubprocessResponsePB;
@@ -35,6 +37,7 @@
 @InterfaceAudience.Private
 public abstract class ProtocolHandler<RequestT extends Message,
                                       ResponseT extends Message> {
+  private static final Logger LOG = LoggerFactory.getLogger(ProtocolHandler.class);
 
   /**
    * Unpacks the SubprocessRequestPB message according to the expected request
@@ -46,12 +49,21 @@
    */
   SubprocessResponsePB.Builder unpackAndExecuteRequest(SubprocessRequestPB request)
       throws InvalidProtocolBufferException {
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Unpacking request");
+    }
     Preconditions.checkNotNull(request);
     SubprocessResponsePB.Builder builder = SubprocessResponsePB.newBuilder();
     builder.setId(request.getId());
     Class<RequestT> requestType = getRequestClass();
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Executing request");
+    }
     ResponseT resp = executeRequest(request.getRequest().unpack(requestType));
     builder.setResponse(Any.pack(resp));
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Building response");
+    }
     return builder;
   }
 
diff --git a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/QueueUtil.java b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/QueueUtil.java
index f06efd1..ba215d1 100644
--- a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/QueueUtil.java
+++ b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/QueueUtil.java
@@ -36,6 +36,9 @@
     // propagate it up the call stack.
     DataT data;
     try {
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Message being taken from the queue");
+      }
       data = queue.take();
       if (LOG.isDebugEnabled()) {
         LOG.debug("Message: {} has been taken from the queue", data);
@@ -51,6 +54,9 @@
     // during the put, consider it to be fatal (as a signal to shutdown
     // the task), and propagate it up the call stack.
     try {
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Message being put onto the queue");
+      }
       queue.put(data);
       if (LOG.isDebugEnabled()) {
         LOG.debug("Message: {} has been put on the queue", data);
diff --git a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/RangerProtocolHandler.java b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/RangerProtocolHandler.java
index e57041e..f9f7f3e 100644
--- a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/RangerProtocolHandler.java
+++ b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/RangerProtocolHandler.java
@@ -49,6 +49,9 @@
 
   @Override
   protected RangerResponseListPB executeRequest(RangerRequestListPB requests) {
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Executing request");
+    }
     RangerResponseListPB.Builder responses = RangerResponseListPB.newBuilder();
     for (RangerAccessResult result : authz.authorize(requests)) {
       // The result can be null when Ranger plugin fails to load the policies
diff --git a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/authorization/RangerKuduAuthorizer.java b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/authorization/RangerKuduAuthorizer.java
index 1e895a5..8d611e5 100644
--- a/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/authorization/RangerKuduAuthorizer.java
+++ b/java/kudu-subprocess/src/main/java/org/apache/kudu/subprocess/ranger/authorization/RangerKuduAuthorizer.java
@@ -106,6 +106,9 @@
     Collection<RangerAccessRequest> rangerRequests = createRequests(requests);
     // Reject requests if user field is empty.
     if (!requests.hasUser() || requests.getUser().isEmpty()) {
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("empty user");
+      }
       Collection<RangerAccessResult> results = new ArrayList<>();
       for (RangerAccessRequest request : rangerRequests) {
         // Create a 'dummy' RangerAccessResult that denies the request (to have
@@ -118,6 +121,9 @@
       }
       return results;
     }
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("calling plugin");
+    }
     return plugin.isAccessAllowed(rangerRequests);
   }
 
diff --git a/src/kudu/ranger/ranger_client-test.cc b/src/kudu/ranger/ranger_client-test.cc
index c08dd75..7479d35 100644
--- a/src/kudu/ranger/ranger_client-test.cc
+++ b/src/kudu/ranger/ranger_client-test.cc
@@ -347,6 +347,7 @@
 
   Status InitializeRanger() {
     ranger_.reset(new MiniRanger("127.0.0.1"));
+    ranger_->set_policy_poll_interval_ms(500);
     RETURN_NOT_OK(ranger_->Start());
     RETURN_NOT_OK(ranger_->CreateClientConfig(test_dir_));
     client_.reset(new RangerClient(env_, metric_entity_));