You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@kudu.apache.org by al...@apache.org on 2020/12/14 19:57:47 UTC
[kudu] branch master updated: [rpc] add slow timing logging for
WrapSaslCall
This is an automated email from the ASF dual-hosted git repository.
alexey pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/kudu.git
The following commit(s) were added to refs/heads/master by this push:
new fcd737e [rpc] add slow timing logging for WrapSaslCall
fcd737e is described below
commit fcd737e6ccedd5a91367dc119e773f0b1904b4fa
Author: Alexey Serbin <al...@apache.org>
AuthorDate: Fri Dec 11 22:46:02 2020 -0800
[rpc] add slow timing logging for WrapSaslCall
In the context of KUDU-3217, this patch adds logging on slow SASL calls.
The reason for setting threshold of 250ms is that 250ms is more than
enough for a local call, and it should be long enough for a call to
a robust KDC in the local network.
Change-Id: I3f8cff71c35a4aab0307456b1dc4270520966ece
Reviewed-on: http://gerrit.cloudera.org:8080/16868
Reviewed-by: Grant Henke <gr...@apache.org>
Reviewed-by: Bankim Bhavsar <ba...@cloudera.com>
Tested-by: Kudu Jenkins
---
src/kudu/rpc/client_negotiation.cc | 38 +++++++++++++++++++-------------
src/kudu/rpc/client_negotiation.h | 7 +++---
src/kudu/rpc/sasl_common.cc | 24 ++++++++++++++------
src/kudu/rpc/sasl_common.h | 8 +++++--
src/kudu/rpc/server_negotiation.cc | 16 +++++++++-----
src/kudu/thrift/sasl_client_transport.cc | 7 +++---
6 files changed, 64 insertions(+), 36 deletions(-)
diff --git a/src/kudu/rpc/client_negotiation.cc b/src/kudu/rpc/client_negotiation.cc
index f0edb07..efa69a1 100644
--- a/src/kudu/rpc/client_negotiation.cc
+++ b/src/kudu/rpc/client_negotiation.cc
@@ -49,6 +49,7 @@
#include "kudu/security/gssapi.h"
#include "kudu/security/tls_context.h"
#include "kudu/security/tls_handshake.h"
+#include "kudu/security/token.pb.h"
#include "kudu/util/debug/leakcheck_disabler.h"
#include "kudu/util/faststring.h"
#include "kudu/util/net/sockaddr.h"
@@ -294,17 +295,21 @@ Status ClientNegotiation::InitSaslClient() {
// TODO(KUDU-1922): consider setting SASL_SUCCESS_DATA
unsigned flags = 0;
+ const auto desc = Substitute("creating new SASL $0 client", sasl_proto_name_);
sasl_conn_t* sasl_conn = nullptr;
- RETURN_NOT_OK_PREPEND(WrapSaslCall(nullptr /* no conn */, [&]() {
- return sasl_client_new(
- sasl_proto_name_.c_str(), // Registered name of the service using SASL. Required.
- helper_.server_fqdn(), // The fully qualified domain name of the remote server.
- nullptr, // Local and remote IP address strings. (we don't use
- nullptr, // any mechanisms which require this info.)
- &callbacks_[0], // Connection-specific callbacks.
- flags,
- &sasl_conn);
- }), Substitute("unable to create new SASL $0 client", sasl_proto_name_));
+ RETURN_NOT_OK_PREPEND(WrapSaslCall(
+ nullptr /* no conn */,
+ [&]() {
+ return sasl_client_new(
+ sasl_proto_name_.c_str(), // Registered name of the service using SASL. Required.
+ helper_.server_fqdn(), // The fully qualified domain name of the remote server.
+ nullptr, // Local and remote IP address strings. (we don't use
+ nullptr, // any mechanisms which require this info.)
+ &callbacks_[0], // Connection-specific callbacks.
+ flags,
+ &sasl_conn);
+ },
+ desc.c_str()), desc + " failed");
sasl_conn_.reset(sasl_conn);
return Status::OK();
}
@@ -587,7 +592,8 @@ Status ClientNegotiation::SendSaslInitiate() {
* SASL_NOMECH -- no mechanism meets requested properties
* SASL_INTERACT -- user interaction needed to fill in prompt_need list
*/
- TRACE("Calling sasl_client_start()");
+ static constexpr const char* const kDesc = "calling sasl_client_start()";
+ TRACE(kDesc);
const Status s = WrapSaslCall(sasl_conn_.get(), [&]() {
return sasl_client_start(
sasl_conn_.get(), // The SASL connection context created by init()
@@ -596,7 +602,7 @@ Status ClientNegotiation::SendSaslInitiate() {
&init_msg, // Filled in on success.
&init_msg_len, // Filled in on success.
&negotiated_mech); // Filled in on success.
- });
+ }, kDesc);
if (PREDICT_FALSE(!s.IsIncomplete() && !s.ok())) {
return s;
@@ -697,11 +703,13 @@ Status ClientNegotiation::HandleSaslSuccess(const NegotiatePB& response) {
}
Status ClientNegotiation::DoSaslStep(const string& in, const char** out, unsigned* out_len) {
- TRACE("Calling sasl_client_step()");
+ static constexpr const char* const kDesc = "calling sasl_client_step()";
+ TRACE(kDesc);
return WrapSaslCall(sasl_conn_.get(), [&]() {
- return sasl_client_step(sasl_conn_.get(), in.c_str(), in.length(), nullptr, out, out_len);
- });
+ return sasl_client_step(
+ sasl_conn_.get(), in.c_str(), in.length(), nullptr, out, out_len);
+ }, kDesc);
}
Status ClientNegotiation::SendConnectionContext() {
diff --git a/src/kudu/rpc/client_negotiation.h b/src/kudu/rpc/client_negotiation.h
index 06fb2b8..436d7b6 100644
--- a/src/kudu/rpc/client_negotiation.h
+++ b/src/kudu/rpc/client_negotiation.h
@@ -17,6 +17,8 @@
#pragma once
+#include <sasl/sasl.h>
+
#include <cstdlib>
#include <memory>
#include <set>
@@ -26,8 +28,8 @@
#include <boost/optional/optional.hpp>
#include <glog/logging.h>
-#include <sasl/sasl.h>
+#include "kudu/gutil/port.h"
#include "kudu/rpc/messenger.h"
#include "kudu/rpc/negotiation.h"
#include "kudu/rpc/rpc_header.pb.h"
@@ -35,10 +37,8 @@
#include "kudu/rpc/sasl_helper.h"
#include "kudu/security/security_flags.h"
#include "kudu/security/tls_handshake.h"
-#include "kudu/security/token.pb.h"
#include "kudu/util/monotime.h"
#include "kudu/util/net/socket.h"
-#include "kudu/gutil/port.h"
#include "kudu/util/status.h"
namespace kudu {
@@ -47,6 +47,7 @@ class Slice;
class faststring;
namespace security {
+class SignedTokenPB;
class TlsContext;
}
diff --git a/src/kudu/rpc/sasl_common.cc b/src/kudu/rpc/sasl_common.cc
index cb5ef63..4b60e85 100644
--- a/src/kudu/rpc/sasl_common.cc
+++ b/src/kudu/rpc/sasl_common.cc
@@ -17,6 +17,10 @@
#include "kudu/rpc/sasl_common.h"
+#include <regex.h>
+#include <sasl/sasl.h>
+#include <sasl/saslplug.h>
+
#include <cstdio>
#include <cstring>
#include <limits>
@@ -25,9 +29,6 @@
#include <string>
#include <glog/logging.h>
-#include <regex.h>
-#include <sasl/sasl.h>
-#include <sasl/saslplug.h>
#include "kudu/gutil/macros.h"
#include "kudu/rpc/constants.h"
@@ -35,6 +36,7 @@
#include "kudu/util/mutex.h"
#include "kudu/util/net/sockaddr.h"
#include "kudu/util/rw_mutex.h"
+#include "kudu/util/stopwatch.h"
#include "kudu/util/string_case.h"
#if defined(__APPLE__)
@@ -315,7 +317,11 @@ static string SaslErrDesc(int status, sasl_conn_t* conn) {
return CleanSaslError(err);
}
-Status WrapSaslCall(sasl_conn_t* conn, const std::function<int()>& call) {
+Status WrapSaslCall(sasl_conn_t* conn,
+ const std::function<int()>& call,
+ const char* description) {
+ DCHECK(description);
+ SCOPED_LOG_SLOW_EXECUTION(WARNING, 250, description);
// In many cases, the GSSAPI SASL plugin will generate a nice error
// message as a message logged at SASL_LOG_FAIL logging level, but then
// return a useless one in sasl_errstring(). So, we set a global thread-local
@@ -373,6 +379,7 @@ uint32_t GetMaxSendBufferSize(sasl_conn_t* sasl_conn) {
}
Status SaslEncode(sasl_conn_t* conn, Slice plaintext, Slice* ciphertext) {
+ static constexpr const char* const kDesc = "SASL encoding";
const char* out;
unsigned out_len;
RETURN_NOT_OK_PREPEND(WrapSaslCall(conn, [&] {
@@ -380,12 +387,13 @@ Status SaslEncode(sasl_conn_t* conn, Slice plaintext, Slice* ciphertext) {
reinterpret_cast<const char*>(plaintext.data()),
plaintext.size(),
&out, &out_len);
- }), "SASL encode failed");
+ }, kDesc), string(kDesc) + " failed");
*ciphertext = Slice(out, out_len);
return Status::OK();
}
Status SaslDecode(sasl_conn_t* conn, Slice ciphertext, Slice* plaintext) {
+ static constexpr const char* const kDesc = "SASL decoding";
const char* out;
unsigned out_len;
RETURN_NOT_OK_PREPEND(WrapSaslCall(conn, [&] {
@@ -393,7 +401,7 @@ Status SaslDecode(sasl_conn_t* conn, Slice ciphertext, Slice* plaintext) {
reinterpret_cast<const char*>(ciphertext.data()),
ciphertext.size(),
&out, &out_len);
- }), "SASL decode failed");
+ }, kDesc), string(kDesc) + " failed");
*plaintext = Slice(out, out_len);
return Status::OK();
}
@@ -433,6 +441,8 @@ sasl_callback_t SaslBuildCallback(int id, int (*proc)(void), void* context) {
Status EnableProtection(sasl_conn_t* sasl_conn,
SaslProtection::Type minimum_protection,
size_t max_recv_buf_size) {
+ static constexpr const char* const kDesc = "setting SASL security properties";
+
sasl_security_properties_t sec_props;
memset(&sec_props, 0, sizeof(sec_props));
sec_props.min_ssf = minimum_protection;
@@ -441,7 +451,7 @@ Status EnableProtection(sasl_conn_t* sasl_conn,
RETURN_NOT_OK_PREPEND(WrapSaslCall(sasl_conn, [&] {
return sasl_setprop(sasl_conn, SASL_SEC_PROPS, &sec_props);
- }), "failed to set SASL security properties");
+ }, kDesc), string(kDesc) + " failed");
return Status::OK();
}
diff --git a/src/kudu/rpc/sasl_common.h b/src/kudu/rpc/sasl_common.h
index dcda131..06311e7 100644
--- a/src/kudu/rpc/sasl_common.h
+++ b/src/kudu/rpc/sasl_common.h
@@ -88,7 +88,9 @@ Status SaslInit(bool kerberos_keytab_provided = false) WARN_UNUSED_RESULT;
Status DisableSaslInitialization() WARN_UNUSED_RESULT;
// Wrap a call into the SASL library. 'call' should be a lambda which
-// returns a SASL error code.
+// returns a SASL error code, 'conn' is the SASL connection to perform
+// the operation with (might be null), and 'description' is be a description
+// of the SASL call (e.g., the name of the SASL library function).
//
// The result is translated into a Status as follows:
//
@@ -98,7 +100,9 @@ Status DisableSaslInitialization() WARN_UNUSED_RESULT;
//
// The Status message is beautified to be more user-friendly compared
// to the underlying sasl_errdetails() call.
-Status WrapSaslCall(sasl_conn_t* conn, const std::function<int()>& call) WARN_UNUSED_RESULT;
+Status WrapSaslCall(sasl_conn_t* conn,
+ const std::function<int()>& call,
+ const char* description) WARN_UNUSED_RESULT;
// Return <ip>;<port> string formatted for SASL library use.
std::string SaslIpPortString(const Sockaddr& addr);
diff --git a/src/kudu/rpc/server_negotiation.cc b/src/kudu/rpc/server_negotiation.cc
index 303f0cf..ac55399 100644
--- a/src/kudu/rpc/server_negotiation.cc
+++ b/src/kudu/rpc/server_negotiation.cc
@@ -317,7 +317,7 @@ Status ServerNegotiation::PreflightCheckGSSAPI(const std::string& sasl_proto_nam
kSaslMechGSSAPI,
"", 0, // Pass a 0-length token.
&server_out, &server_out_len);
- });
+ }, "calling sasl_server_start()");
// We expect 'Incomplete' status to indicate that the first step of negotiation
// was correct.
@@ -415,6 +415,8 @@ Status ServerNegotiation::InitSaslServer() {
server_fqdn = default_server_fqdn.c_str();
}
+ static constexpr const char* const kDesc = "creating new SASL server";
+ //static constexpr const char* const kDesc = "create "
RETURN_NOT_OK_PREPEND(WrapSaslCall(nullptr /* no conn */, [&]() {
return sasl_server_new(
// Registered name of the service using SASL. Required.
@@ -432,7 +434,7 @@ Status ServerNegotiation::InitSaslServer() {
// Security flags.
secflags,
&sasl_conn);
- }), "Unable to create new SASL server");
+ }, kDesc), string(kDesc) + " failed");
sasl_conn_.reset(sasl_conn);
return Status::OK();
}
@@ -810,7 +812,8 @@ Status ServerNegotiation::HandleSaslInitiate(const NegotiatePB& request) {
const char* server_out = nullptr;
uint32_t server_out_len = 0;
- TRACE("Calling sasl_server_start()");
+ static constexpr const char* const kDesc = "calling sasl_server_start()";
+ TRACE(kDesc);
Status s = WrapSaslCall(sasl_conn_.get(), [&]() {
return sasl_server_start(
@@ -820,7 +823,7 @@ Status ServerNegotiation::HandleSaslInitiate(const NegotiatePB& request) {
request.token().length(), // Client string len.
&server_out, // The output of the SASL library, might not be NULL terminated
&server_out_len); // Output len.
- });
+ }, kDesc);
if (PREDICT_FALSE(!s.ok() && !s.IsIncomplete())) {
RETURN_NOT_OK(SendError(ErrorStatusPB::FATAL_UNAUTHORIZED, s));
@@ -852,9 +855,10 @@ Status ServerNegotiation::HandleSaslResponse(const NegotiatePB& request) {
return s;
}
+ static constexpr const char* const kDesc = "calling sasl_server_step()";
const char* server_out = nullptr;
uint32_t server_out_len = 0;
- TRACE("Calling sasl_server_step()");
+ TRACE(kDesc);
Status s = WrapSaslCall(sasl_conn_.get(), [&]() {
return sasl_server_step(
sasl_conn_.get(), // The SASL connection context created by init()
@@ -862,7 +866,7 @@ Status ServerNegotiation::HandleSaslResponse(const NegotiatePB& request) {
request.token().length(), // Client string len
&server_out, // The output of the SASL library, might not be NULL terminated
&server_out_len); // Output len
- });
+ }, kDesc);
if (s.ok()) {
DCHECK(server_out_len == 0);
diff --git a/src/kudu/thrift/sasl_client_transport.cc b/src/kudu/thrift/sasl_client_transport.cc
index 5dd05ef..f12045b 100644
--- a/src/kudu/thrift/sasl_client_transport.cc
+++ b/src/kudu/thrift/sasl_client_transport.cc
@@ -265,7 +265,7 @@ void SaslClientTransport::Negotiate() {
nullptr,
&out,
&out_len);
- });
+ }, "calling sasl_client_step()");
if (PREDICT_FALSE(!s.IsIncomplete() && !s.ok())) {
throw SaslException(std::move(s));
@@ -353,7 +353,7 @@ void SaslClientTransport::SendSaslStart() {
&init_msg, // Filled in on success.
&init_msg_len, // Filled in on success.
&negotiated_mech); // Filled in on success.
- });
+ }, "calling sasl_client_start()");
if (PREDICT_FALSE(!s.IsIncomplete() && !s.ok())) {
throw SaslException(std::move(s));
@@ -390,7 +390,8 @@ void SaslClientTransport::SetupSaslContext() {
sasl_callbacks_.data(), // Connection-specific callbacks.
0, // flags
&sasl_conn);
- });
+ },
+ "calling sasl_client_new()");
if (!s.ok()) {
throw SaslException(s);
}