You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@nifi.apache.org by sz...@apache.org on 2022/03/28 14:51:43 UTC
[nifi-minifi-cpp] branch main updated: MINIFICPP-1758 - Log c2 server response
This is an automated email from the ASF dual-hosted git repository.
szaszm pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/nifi-minifi-cpp.git
The following commit(s) were added to refs/heads/main by this push:
new 4971b1b MINIFICPP-1758 - Log c2 server response
4971b1b is described below
commit 4971b1b328c6b4d5782ec28c6912f159475c5459
Author: Adam Debreceni <ad...@apache.org>
AuthorDate: Mon Mar 28 16:44:07 2022 +0200
MINIFICPP-1758 - Log c2 server response
Closes #1267
Signed-off-by: Marton Szasz <sz...@apache.org>
---
extensions/http-curl/protocols/RESTSender.cpp | 1 +
libminifi/include/c2/C2Agent.h | 4 +-
libminifi/include/c2/C2Payload.h | 12 ++++
libminifi/include/core/PropertyValue.h | 7 +++
libminifi/include/core/logging/Logger.h | 73 ++++++++++++----------
libminifi/include/core/state/Value.h | 4 ++
libminifi/include/utils/StringUtils.h | 2 +
libminifi/include/utils/crypto/ciphers/Aes256Ecb.h | 2 +-
libminifi/src/c2/C2Agent.cpp | 8 ++-
libminifi/src/c2/C2Payload.cpp | 67 ++++++++++++++++++++
libminifi/src/utils/StringUtils.cpp | 26 ++++++++
libminifi/test/unit/LoggerTests.cpp | 47 ++++++++++++--
libminifi/test/unit/StringUtilsTests.cpp | 12 ++++
13 files changed, 222 insertions(+), 43 deletions(-)
diff --git a/extensions/http-curl/protocols/RESTSender.cpp b/extensions/http-curl/protocols/RESTSender.cpp
index e1dabcb..ca98223 100644
--- a/extensions/http-curl/protocols/RESTSender.cpp
+++ b/extensions/http-curl/protocols/RESTSender.cpp
@@ -162,6 +162,7 @@ C2Payload RESTSender::sendPayload(const std::string url, const Direction directi
logger_->log_debug("Response code '" "%" PRId64 "' from '%s'", respCode, url);
}
const auto response_body_bytes = gsl::make_span(client.getResponseBody()).as_span<const std::byte>();
+ logger_->log_trace("Received response: \"%s\"", [&] {return utils::StringUtils::escapeUnprintableBytes(response_body_bytes);});
if (isOkay && respCode) {
if (payload.isRaw()) {
C2Payload response_payload(payload.getOperation(), state::UpdateState::READ_COMPLETE, true);
diff --git a/libminifi/include/c2/C2Agent.h b/libminifi/include/c2/C2Agent.h
index 0aa4934..b8fcb9e 100644
--- a/libminifi/include/c2/C2Agent.h
+++ b/libminifi/include/c2/C2Agent.h
@@ -120,9 +120,7 @@ class C2Agent : public state::UpdateController {
/**
* Enqueues a C2 server response for us to evaluate and parse.
*/
- void enqueue_c2_server_response(C2Payload &&resp) {
- responses.enqueue(std::move(resp));
- }
+ void enqueue_c2_server_response(C2Payload &&resp);
/**
* Enqueues a c2 payload for a response to the C2 server.
diff --git a/libminifi/include/c2/C2Payload.h b/libminifi/include/c2/C2Payload.h
index 94666ee..f347de5 100644
--- a/libminifi/include/c2/C2Payload.h
+++ b/libminifi/include/c2/C2Payload.h
@@ -95,6 +95,8 @@ struct AnnotatedValue : state::response::ValueNode {
return std::cref(it->second);
}
+ friend std::ostream& operator<<(std::ostream& out, const AnnotatedValue& val);
+
std::map<std::string, AnnotatedValue> annotations;
};
@@ -115,6 +117,8 @@ struct C2ContentResponse {
bool operator!=(const C2ContentResponse &rhs) const { return !(*this == rhs); }
+ friend std::ostream& operator<<(std::ostream& out, const C2ContentResponse& response);
+
Operation op;
// determines if the operation is required
bool required{ false };
@@ -225,6 +229,14 @@ class C2Payload : public state::Update {
bool operator!=(const C2Payload &rhs) const { return !(*this == rhs); }
+ friend std::ostream& operator<<(std::ostream& out, const C2Payload& payload);
+
+ std::string str() const {
+ std::stringstream ss;
+ ss << *this;
+ return std::move(ss).str();
+ }
+
protected:
std::string ident_; // identifier for this payload.
std::string label_;
diff --git a/libminifi/include/core/PropertyValue.h b/libminifi/include/core/PropertyValue.h
index c1efbfc..fc1af9f 100644
--- a/libminifi/include/core/PropertyValue.h
+++ b/libminifi/include/core/PropertyValue.h
@@ -106,6 +106,13 @@ class PropertyValue : public state::response::ValueNode {
return convertImpl<bool>("bool");
}
+ const char* c_str() const {
+ if (!isValueUsable()) {
+ throw utils::internal::InvalidValueException("Cannot convert invalid value");
+ }
+ return value_ ? value_->c_str() : "";
+ }
+
operator std::string() const {
if (!isValueUsable()) {
throw utils::internal::InvalidValueException("Cannot convert invalid value");
diff --git a/libminifi/include/core/logging/Logger.h b/libminifi/include/core/logging/Logger.h
index 14e977e..24ef908 100644
--- a/libminifi/include/core/logging/Logger.h
+++ b/libminifi/include/core/logging/Logger.h
@@ -31,6 +31,7 @@
#include "spdlog/logger.h"
#include "utils/gsl.h"
#include "utils/SmallString.h"
+#include "utils/meta/detected.h"
namespace org {
namespace apache {
@@ -53,28 +54,32 @@ class LoggerControl {
std::atomic<bool> is_enabled_;
};
-inline char const* conditional_conversion(std::string const& str) {
- return str.c_str();
-}
+template<typename Arg>
+using has_const_c_str_method = decltype(std::declval<const Arg&>().c_str());
-template<size_t N>
-inline char const* conditional_conversion(const utils::SmallString<N>& arr) {
- return arr.c_str();
+template<typename Arg>
+inline decltype(auto) conditional_stringify(Arg&& arg) {
+ if constexpr (utils::meta::is_detected_v<has_const_c_str_method, Arg> || std::is_scalar_v<std::decay_t<Arg>>) {
+ return std::forward<Arg>(arg);
+ } else if constexpr (std::is_invocable_v<Arg>) {
+ return std::forward<Arg>(arg)();
+ }
}
-template<typename T, typename = typename std::enable_if<
- std::is_arithmetic<T>::value ||
- std::is_enum<T>::value ||
- std::is_pointer<T>::value>::type>
-inline T conditional_conversion(T t) {
- return t;
+template<typename Arg>
+inline decltype(auto) conditional_convert(const Arg& val) {
+ if constexpr (std::is_scalar_v<std::decay_t<Arg>>) {
+ return val;
+ } else if constexpr (std::is_same_v<decltype(std::declval<const Arg&>().c_str()), const char*>) {
+ return val.c_str();
+ }
}
-template<typename ... Args>
-std::string format_string(int max_size, char const* format_str, Args&&... args) {
+template<typename ...Args>
+std::string format_string(int max_size, char const* format_str, const Args& ...args) {
// try to use static buffer
char buf[LOG_BUFFER_SIZE + 1];
- int result = std::snprintf(buf, LOG_BUFFER_SIZE + 1, format_str, conditional_conversion(std::forward<Args>(args))...);
+ int result = std::snprintf(buf, LOG_BUFFER_SIZE + 1, format_str, conditional_convert(args)...);
if (result < 0) {
return "Error while formatting log message";
}
@@ -89,7 +94,7 @@ std::string format_string(int max_size, char const* format_str, Args&&... args)
// try to use dynamic buffer
size_t dynamic_buffer_size = max_size < 0 ? gsl::narrow<size_t>(result) : gsl::narrow<size_t>(std::min(result, max_size));
std::vector<char> buffer(dynamic_buffer_size + 1); // extra '\0' character
- result = std::snprintf(buffer.data(), buffer.size(), format_str, conditional_conversion(std::forward<Args>(args))...);
+ result = std::snprintf(buffer.data(), buffer.size(), format_str, conditional_convert(args)...);
if (result < 0) {
return "Error while formatting log message";
}
@@ -153,9 +158,9 @@ class Logger : public BaseLogger {
* @param format format string ('man printf' for syntax)
* @warning does not check @p log or @p format for null. Caller must ensure parameters and format string lengths match
*/
- template<typename ... Args>
- void log_error(const char * const format, const Args& ... args) {
- log(spdlog::level::err, format, args...);
+ template<typename ...Args>
+ void log_error(const char * const format, Args&& ...args) {
+ log(spdlog::level::err, format, std::forward<Args>(args)...);
}
/**
@@ -163,9 +168,9 @@ class Logger : public BaseLogger {
* @param format format string ('man printf' for syntax)
* @warning does not check @p log or @p format for null. Caller must ensure parameters and format string lengths match
*/
- template<typename ... Args>
- void log_warn(const char * const format, const Args& ... args) {
- log(spdlog::level::warn, format, args...);
+ template<typename ...Args>
+ void log_warn(const char * const format, Args&& ...args) {
+ log(spdlog::level::warn, format, std::forward<Args>(args)...);
}
/**
@@ -173,9 +178,9 @@ class Logger : public BaseLogger {
* @param format format string ('man printf' for syntax)
* @warning does not check @p log or @p format for null. Caller must ensure parameters and format string lengths match
*/
- template<typename ... Args>
- void log_info(const char * const format, const Args& ... args) {
- log(spdlog::level::info, format, args...);
+ template<typename ...Args>
+ void log_info(const char * const format, Args&& ...args) {
+ log(spdlog::level::info, format, std::forward<Args>(args)...);
}
/**
@@ -183,9 +188,9 @@ class Logger : public BaseLogger {
* @param format format string ('man printf' for syntax)
* @warning does not check @p log or @p format for null. Caller must ensure parameters and format string lengths match
*/
- template<typename ... Args>
- void log_debug(const char * const format, const Args& ... args) {
- log(spdlog::level::debug, format, args...);
+ template<typename ...Args>
+ void log_debug(const char * const format, Args&& ...args) {
+ log(spdlog::level::debug, format, std::forward<Args>(args)...);
}
/**
@@ -193,9 +198,9 @@ class Logger : public BaseLogger {
* @param format format string ('man printf' for syntax)
* @warning does not check @p log or @p format for null. Caller must ensure parameters and format string lengths match
*/
- template<typename ... Args>
- void log_trace(const char * const format, const Args& ... args) {
- log(spdlog::level::trace, format, args...);
+ template<typename ...Args>
+ void log_trace(const char * const format, Args&& ...args) {
+ log(spdlog::level::trace, format, std::forward<Args>(args)...);
}
void set_max_log_size(int size) {
@@ -218,15 +223,15 @@ class Logger : public BaseLogger {
std::mutex mutex_;
private:
- template<typename ... Args>
- inline void log(spdlog::level::level_enum level, const char * const format, const Args& ... args) {
+ template<typename ...Args>
+ inline void log(spdlog::level::level_enum level, const char* const format, Args&& ...args) {
if (controller_ && !controller_->is_enabled())
return;
std::lock_guard<std::mutex> lock(mutex_);
if (!delegate_->should_log(level)) {
return;
}
- const auto str = format_string(max_log_size_.load(), format, conditional_conversion(args)...);
+ const auto str = format_string(max_log_size_.load(), format, conditional_stringify(std::forward<Args>(args))...);
delegate_->log(level, str);
}
diff --git a/libminifi/include/core/state/Value.h b/libminifi/include/core/state/Value.h
index b728e6f..230eb6f 100644
--- a/libminifi/include/core/state/Value.h
+++ b/libminifi/include/core/state/Value.h
@@ -58,6 +58,10 @@ class Value {
return string_value;
}
+ const char* c_str() const {
+ return string_value.c_str();
+ }
+
template<typename T>
bool convertValue(T &ref) {
return convertValueImpl<typename std::common_type<T>::type>(ref);
diff --git a/libminifi/include/utils/StringUtils.h b/libminifi/include/utils/StringUtils.h
index ca2456a..5b1902e 100644
--- a/libminifi/include/utils/StringUtils.h
+++ b/libminifi/include/utils/StringUtils.h
@@ -493,6 +493,8 @@ class StringUtils {
*/
static std::smatch getLastRegexMatch(const std::string& str, const std::regex& pattern);
+ static std::string escapeUnprintableBytes(gsl::span<const std::byte> data);
+
private:
};
diff --git a/libminifi/include/utils/crypto/ciphers/Aes256Ecb.h b/libminifi/include/utils/crypto/ciphers/Aes256Ecb.h
index 665c506..ebd201d 100644
--- a/libminifi/include/utils/crypto/ciphers/Aes256Ecb.h
+++ b/libminifi/include/utils/crypto/ciphers/Aes256Ecb.h
@@ -60,7 +60,7 @@ class Aes256EcbCipher {
private:
template<typename ...Args>
static void handleError(const char* format, Args&& ...args) {
- std::string error_msg = core::logging::format_string(-1, format, std::forward<Args>(args)...);
+ std::string error_msg = core::logging::format_string(-1, format, core::logging::conditional_stringify(std::forward<Args>(args))...);
logger_->log_error("%s", error_msg);
throw CipherError(error_msg);
}
diff --git a/libminifi/src/c2/C2Agent.cpp b/libminifi/src/c2/C2Agent.cpp
index b7cd0e4..ecfeede 100644
--- a/libminifi/src/c2/C2Agent.cpp
+++ b/libminifi/src/c2/C2Agent.cpp
@@ -243,7 +243,7 @@ void C2Agent::performHeartBeat() {
payload.addPayload(std::move(child_metric_payload));
}
}
- C2Payload && response = protocol_.load()->consumePayload(payload);
+ C2Payload response = protocol_.load()->consumePayload(payload);
enqueue_c2_server_response(std::move(response));
@@ -928,6 +928,12 @@ bool C2Agent::handleConfigurationUpdate(const C2ContentResponse &resp) {
return true;
}
+void C2Agent::enqueue_c2_server_response(C2Payload &&resp) {
+ logger_->log_trace("Server response: %s", [&] {return resp.str();});
+
+ responses.enqueue(std::move(resp));
+}
+
} // namespace c2
} // namespace minifi
} // namespace nifi
diff --git a/libminifi/src/c2/C2Payload.cpp b/libminifi/src/c2/C2Payload.cpp
index 6737e1d..a6bae27 100644
--- a/libminifi/src/c2/C2Payload.cpp
+++ b/libminifi/src/c2/C2Payload.cpp
@@ -20,6 +20,7 @@
#include <utility>
#include <vector>
#include <string>
+#include "utils/StringUtils.h"
namespace org {
namespace apache {
@@ -80,6 +81,72 @@ void C2Payload::addPayload(C2Payload &&payload) {
payloads_.push_back(std::move(payload));
}
+template<typename T>
+static std::ostream& operator<<(std::ostream& out, const std::vector<T>& items) {
+ out << "[";
+ bool first = true;
+ for (auto& item : items) {
+ if (!first) out << ", ";
+ first = false;
+ out << item;
+ }
+ out << "]";
+ return out;
+}
+
+template<typename K, typename V>
+static std::ostream& operator<<(std::ostream& out, const std::map<K, V>& items) {
+ out << "{";
+ bool first = true;
+ for (auto& item : items) {
+ if (!first) out << ", ";
+ first = false;
+ out << item.first << ": " << item.second;
+ }
+ out << "}";
+ return out;
+}
+
+std::ostream& operator<<(std::ostream& out, const C2Payload& payload) {
+ out << std::boolalpha;
+ return out << "{"
+ << "ident: \"" << payload.ident_ << "\", "
+ << "label: \"" << payload.label_ << "\", "
+ << "payloads: " << payload.payloads_ << ", "
+ << "contents: " << payload.content_ << ", "
+ << "op: " << payload.op_.toStringOr("<invalid operation>") << ", "
+ << "raw: " << payload.raw_ << ", "
+ << "data: \"" << utils::StringUtils::escapeUnprintableBytes(payload.raw_data_) << "\", "
+ << "is_container: " << payload.is_container_ << ", "
+ << "is_collapsible: " << payload.is_collapsible_
+ << "}";
+}
+
+std::ostream& operator<<(std::ostream& out, const C2ContentResponse& response) {
+ out << std::boolalpha;
+ return out << "{"
+ << "op: " << response.op.toStringOr("<invalid operation>") << ", "
+ << "required: " << response.required << ", "
+ << "ident: \"" << response.ident << "\", "
+ << "delay: " << response.delay << ", "
+ << "ttl: " << response.ttl << ", "
+ << "name: \"" << response.name << "\", "
+ << "args: " << response.operation_arguments
+ << "}";
+}
+
+std::ostream& operator<<(std::ostream& out, const AnnotatedValue& val) {
+ if (val.value_) {
+ out << '"' << val.value_->c_str() << '"';
+ } else {
+ out << "<null>";
+ }
+ if (!val.annotations.empty()) {
+ out << val.annotations;
+ }
+ return out;
+}
+
} /* namespace c2 */
} /* namespace minifi */
} /* namespace nifi */
diff --git a/libminifi/src/utils/StringUtils.cpp b/libminifi/src/utils/StringUtils.cpp
index ecb1131..a4ae085 100644
--- a/libminifi/src/utils/StringUtils.cpp
+++ b/libminifi/src/utils/StringUtils.cpp
@@ -484,4 +484,30 @@ std::smatch StringUtils::getLastRegexMatch(const std::string& str, const std::re
return last_match;
}
+std::string StringUtils::escapeUnprintableBytes(gsl::span<const std::byte> data) {
+ constexpr const char* hex_digits = "0123456789abcdef";
+ std::string result;
+ for (auto byte : data) {
+ char ch = static_cast<char>(byte);
+ if (std::isprint(static_cast<unsigned char>(ch))) {
+ result += ch;
+ } else if (ch == '\n') {
+ result += "\\n";
+ } else if (ch == '\t') {
+ result += "\\t";
+ } else if (ch == '\r') {
+ result += "\\r";
+ } else if (ch == '\v') {
+ result += "\\v";
+ } else if (ch == '\f') {
+ result += "\\f";
+ } else {
+ result += "\\x";
+ result += hex_digits[(std::to_integer<int>(byte) >> 4) & 0xf];
+ result += hex_digits[std::to_integer<int>(byte) & 0xf];
+ }
+ }
+ return result;
+}
+
} // namespace org::apache::nifi::minifi::utils
diff --git a/libminifi/test/unit/LoggerTests.cpp b/libminifi/test/unit/LoggerTests.cpp
index b53260c..73f4751 100644
--- a/libminifi/test/unit/LoggerTests.cpp
+++ b/libminifi/test/unit/LoggerTests.cpp
@@ -27,6 +27,8 @@
#include "StreamPipe.h"
#include "utils/IntegrationTestUtils.h"
+using std::chrono_literals::operator""s;
+
TEST_CASE("Test log Levels", "[ttl1]") {
LogTestController::getInstance().setTrace<logging::Logger>();
std::shared_ptr<logging::Logger> logger = logging::LoggerFactory<logging::Logger>::getLogger();
@@ -77,6 +79,43 @@ TEST_CASE("Test log Levels change", "[ttl5]") {
LogTestController::getInstance().reset();
}
+struct CStringConvertible {
+ const char* c_str() const {
+ return data.c_str();
+ }
+
+ std::string data;
+};
+
+TEST_CASE("Test log custom string formatting", "[ttl6]") {
+ LogTestController::getInstance().setTrace<logging::Logger>();
+ std::shared_ptr<logging::Logger> logger = logging::LoggerFactory<logging::Logger>::getLogger();
+ logger->log_trace("%s %s %s", "one", std::string{"two"}, CStringConvertible{"three"});
+
+ REQUIRE(LogTestController::getInstance().contains("[trace] one two three", 0s));
+ LogTestController::getInstance().reset();
+}
+
+TEST_CASE("Test log lazy string generation", "[ttl7]") {
+ LogTestController::getInstance().setDebug<logging::Logger>();
+ std::shared_ptr<logging::Logger> logger = logging::LoggerFactory<logging::Logger>::getLogger();
+ int call_count = 0;
+
+ logger->log_trace("%s", [&] {
+ ++call_count;
+ return std::string{"hello trace"};
+ });
+
+ logger->log_debug("%s", [&] {
+ ++call_count;
+ return std::string{"hello debug"};
+ });
+
+ REQUIRE(LogTestController::getInstance().contains("[debug] hello debug", 0s));
+ REQUIRE(call_count == 1);
+ LogTestController::getInstance().reset();
+}
+
namespace single {
class TestClass {
};
@@ -85,7 +124,7 @@ class TestClass {
class TestClass2 {
};
-TEST_CASE("Test ShortenNames", "[ttl6]") {
+TEST_CASE("Test ShortenNames", "[ttl8]") {
std::shared_ptr<logging::LoggerProperties> props = std::make_shared<logging::LoggerProperties>();
props->set("spdlog.shorten_names", "true");
@@ -122,7 +161,7 @@ std::string decompress(const std::shared_ptr<InputStream>& input) {
return utils::span_to<std::string>(output->getBuffer().as_span<const char>());
}
-TEST_CASE("Test Compression", "[ttl7]") {
+TEST_CASE("Test Compression", "[ttl9]") {
auto& log_config = logging::LoggerConfiguration::getConfiguration();
auto properties = std::make_shared<logging::LoggerProperties>();
std::string className;
@@ -161,7 +200,7 @@ class LoggerTestAccessor {
}
};
-TEST_CASE("Test Compression cache overflow is discarded intermittently", "[ttl8]") {
+TEST_CASE("Test Compression cache overflow is discarded intermittently", "[ttl10]") {
auto& log_config = logging::LoggerConfiguration::getConfiguration();
auto properties = std::make_shared<logging::LoggerProperties>();
properties->set(logging::internal::CompressionManager::compression_cached_log_max_size_, "10 KB");
@@ -180,7 +219,7 @@ TEST_CASE("Test Compression cache overflow is discarded intermittently", "[ttl8]
REQUIRE(cache_shrunk);
}
-TEST_CASE("Setting either properties to 0 disables in-memory compressed logs", "[ttl9]") {
+TEST_CASE("Setting either properties to 0 disables in-memory compressed logs", "[ttl11]") {
auto& log_config = logging::LoggerConfiguration::getConfiguration();
auto properties = std::make_shared<logging::LoggerProperties>();
bool is_nullptr = false;
diff --git a/libminifi/test/unit/StringUtilsTests.cpp b/libminifi/test/unit/StringUtilsTests.cpp
index 9e146af..7995401 100644
--- a/libminifi/test/unit/StringUtilsTests.cpp
+++ b/libminifi/test/unit/StringUtilsTests.cpp
@@ -543,3 +543,15 @@ TEST_CASE("StringUtils::getLastRegexMatch works correctly", "[getLastRegexMatch]
CHECK(last_match.position(0) == 21);
}
}
+
+// ignore terminating \0 character
+template<size_t N>
+gsl::span<const std::byte> from_cstring(const char (&str)[N]) {
+ return gsl::span<const char>(str, N-1).as_span<const std::byte>();
+}
+
+TEST_CASE("StringUtils::escapeUnprintableBytes", "[escapeUnprintableBytes]") {
+ REQUIRE(StringUtils::escapeUnprintableBytes(from_cstring("abcd")) == "abcd");
+ REQUIRE(StringUtils::escapeUnprintableBytes(from_cstring("ab\n\r\t\v\fde")) == "ab\\n\\r\\t\\v\\fde");
+ REQUIRE(StringUtils::escapeUnprintableBytes(from_cstring("ab\x00""c\x01""d")) == "ab\\x00c\\x01d");
+}