From 33fa818c45b8435bcab844a01cc0657da702f404 Mon Sep 17 00:00:00 2001 From: Pawel Filipczak Date: Mon, 3 Feb 2025 19:28:09 +0100 Subject: [PATCH] Improved Otel->Elatic log writer (#151) (#154) * added [EDOT] prefix to each log line --- .../native/extension/code/ModuleFunctions.cpp | 8 ++++-- prod/native/libcommon/code/LogFeature.cpp | 4 +++ prod/native/libcommon/code/LogFeature.h.in | 1 + prod/native/libcommon/code/Logger.cpp | 7 ++--- prod/native/libcommon/code/LoggerInterface.h | 3 +- prod/native/libcommon/code/RequestScope.h | 6 ++-- prod/native/libcommon/test/LoggerTest.cpp | 2 +- prod/php/ElasticOTel/Log/ElasticLogWriter.php | 28 ++++++++++++++----- 8 files changed, 40 insertions(+), 19 deletions(-) diff --git a/prod/native/extension/code/ModuleFunctions.cpp b/prod/native/extension/code/ModuleFunctions.cpp index 865785f..a6d6245 100644 --- a/prod/native/extension/code/ModuleFunctions.cpp +++ b/prod/native/extension/code/ModuleFunctions.cpp @@ -21,6 +21,7 @@ #include "ModuleFunctions.h" #include "ConfigurationStorage.h" #include "LoggerInterface.h" +#include "LogFeature.h" #include "RequestScope.h" #include "ModuleGlobals.h" #include "ModuleFunctionsImpl.h" @@ -100,7 +101,7 @@ PHP_FUNCTION(elastic_otel_log) { Z_PARAM_STRING(message, messageLength) ZEND_PARSE_PARAMETERS_END(); - ELASTICAPM_G(globals)->logger_->printf(static_cast(level), PRsv " " PRsv " %d " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); + ELASTICAPM_G(globals)->logger_->printf(static_cast(level), "[" PRsv "] [" PRsv ":%d] [" PRsv "] " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); } /* }}} */ @@ -154,9 +155,10 @@ PHP_FUNCTION(elastic_otel_log_feature) { if (isForced || ELASTICAPM_G(globals)->logger_->doesFeatureMeetsLevelCondition(static_cast(level), static_cast(feature))) { if (lineNull) { - ELASTICAPM_G(globals)->logger_->printf(static_cast(level), PRsv " " PRsv " " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); + ELASTICAPM_G(globals)->logger_->printf(static_cast(level), "[" PRsv "] [" PRsv "] [" PRsv "] [" PRsv "] " PRsv, PRsvArg(elasticapm::php::getLogFeatureName(static_cast(feature))), PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); + return; } - ELASTICAPM_G(globals)->logger_->printf(static_cast(level), PRsv " " PRsv " %d " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); + ELASTICAPM_G(globals)->logger_->printf(static_cast(level), "[" PRsv "] [" PRsv "] [" PRsv ":%d] [" PRsv "] " PRsv, PRsvArg(elasticapm::php::getLogFeatureName(static_cast(feature))), PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength)); } } /* }}} */ diff --git a/prod/native/libcommon/code/LogFeature.cpp b/prod/native/libcommon/code/LogFeature.cpp index 2e93399..91c3644 100644 --- a/prod/native/libcommon/code/LogFeature.cpp +++ b/prod/native/libcommon/code/LogFeature.cpp @@ -34,4 +34,8 @@ namespace elasticapm::php { return feature.value(); } +[[nodiscard]] std::string_view getLogFeatureName(LogFeature feature) { + return magic_enum::enum_name(feature); +} + } // namespace elasticapm::php diff --git a/prod/native/libcommon/code/LogFeature.h.in b/prod/native/libcommon/code/LogFeature.h.in index 963e98d..8156d39 100644 --- a/prod/native/libcommon/code/LogFeature.h.in +++ b/prod/native/libcommon/code/LogFeature.h.in @@ -37,5 +37,6 @@ enum LogFeature { // clang-format on [[nodiscard]] LogFeature parseLogFeature(std::string_view featureName); +[[nodiscard]] std::string_view getLogFeatureName(LogFeature feature); } // namespace elasticapm::php \ No newline at end of file diff --git a/prod/native/libcommon/code/Logger.cpp b/prod/native/libcommon/code/Logger.cpp index a2a7b2c..f71aa55 100644 --- a/prod/native/libcommon/code/Logger.cpp +++ b/prod/native/libcommon/code/Logger.cpp @@ -27,6 +27,8 @@ namespace elasticapm::php { +using namespace std::string_literals; + void Logger::setLogFeatures(std::unordered_map features) { features_ = std::move(features); } @@ -78,8 +80,7 @@ void Logger::printf(LogLevel level, const char *format, ...) const { auto msg = elasticapm::utils::stringVPrintf(format, args); va_end(args); - - std::string output; + std::string output = "[EDOT] "s; output.append(getFormattedTime()); output.append(" "); @@ -112,8 +113,6 @@ void Logger::printf(LogLevel level, const char *format, ...) const { } } - - std::string Logger::getFormattedTime() const { const auto now = std::chrono::system_clock::now(); const std::time_t nowTime = std::chrono::system_clock::to_time_t(now); diff --git a/prod/native/libcommon/code/LoggerInterface.h b/prod/native/libcommon/code/LoggerInterface.h index d0677c8..048daad 100644 --- a/prod/native/libcommon/code/LoggerInterface.h +++ b/prod/native/libcommon/code/LoggerInterface.h @@ -21,6 +21,7 @@ #include "LogLevel.h" #include "LogFeature.h" +#include "basic_macros.h" #include #include @@ -46,7 +47,7 @@ class LoggerInterface { // clang-format off -#define ELOGF(logger, level, feature, format, ...) do { if (!logger || !logger->doesFeatureMeetsLevelCondition(level, elasticapm::php::LogFeature::feature)) break; logger->printf(level, format, ##__VA_ARGS__); } while(false); +#define ELOGF(logger, level, feature, format, ...) do { if (!logger || !logger->doesFeatureMeetsLevelCondition(level, elasticapm::php::LogFeature::feature)) break; logger->printf(level, "[" EL_STRINGIFY(feature) "] " format, ##__VA_ARGS__); } while(false); #define ELOG(logger, level, format, ...) ELOGF(logger, level, ALL, format, ##__VA_ARGS__) #define ELOGF_CRITICAL(logger, feature, format, ...) ELOGF(logger, LogLevel::logLevel_critical, feature, format, ##__VA_ARGS__) diff --git a/prod/native/libcommon/code/RequestScope.h b/prod/native/libcommon/code/RequestScope.h index c7a53fc..79473cf 100644 --- a/prod/native/libcommon/code/RequestScope.h +++ b/prod/native/libcommon/code/RequestScope.h @@ -43,7 +43,7 @@ class RequestScope { } void onRequestInit() { - ELOGF_DEBUG(log_, REQUEST, __FUNCTION__); + ELOGF_DEBUG(log_, REQUEST, "%s", __FUNCTION__); resetRequest(); @@ -109,7 +109,7 @@ class RequestScope { } void onRequestShutdown() { - ELOGF_DEBUG(log_, REQUEST, __FUNCTION__); + ELOGF_DEBUG(log_, REQUEST, "%s", __FUNCTION__); if (preloadDetected_) { ELOGF_DEBUG(log_, REQUEST, "opcache.preload request detected on shutdown"); @@ -132,7 +132,7 @@ class RequestScope { } void onRequestPostDeactivate() { - ELOGF_DEBUG(log_, REQUEST, __FUNCTION__); + ELOGF_DEBUG(log_, REQUEST, "%s", __FUNCTION__); resetRequest(); diff --git a/prod/native/libcommon/test/LoggerTest.cpp b/prod/native/libcommon/test/LoggerTest.cpp index a07fb1c..558777a 100644 --- a/prod/native/libcommon/test/LoggerTest.cpp +++ b/prod/native/libcommon/test/LoggerTest.cpp @@ -83,7 +83,7 @@ TEST_F(LoggerTest, Formatting) { ASSERT_NE(str.find("["s + std::to_string(getpid()) + "/"s), std::string::npos); }; auto testFormattedTime = [](std::string_view str) { - ASSERT_EQ(str.length(), 32u); + ASSERT_EQ(str.length(), 39u); ASSERT_TRUE(str.ends_with(" UTC]"sv)); }; diff --git a/prod/php/ElasticOTel/Log/ElasticLogWriter.php b/prod/php/ElasticOTel/Log/ElasticLogWriter.php index c5abf4b..be2b7bb 100644 --- a/prod/php/ElasticOTel/Log/ElasticLogWriter.php +++ b/prod/php/ElasticOTel/Log/ElasticLogWriter.php @@ -23,17 +23,31 @@ namespace Elastic\OTel\Log; -use OpenTelemetry\API\Behavior\Internal\LogWriter\LogWriterInterface; use OpenTelemetry\API\Behavior\Internal\Logging; +use OpenTelemetry\SDK\Common\Configuration\Configuration; +use OpenTelemetry\API\Behavior\Internal\LogWriter\LogWriterInterface; class ElasticLogWriter implements LogWriterInterface { + private bool $attachLogContext; + + public function __construct() + { + $this->attachLogContext = Configuration::getBoolean('ELASTIC_OTEL_LOG_OTEL_WITH_CONTEXT', true); + } + /** * @param array $context */ public function write(mixed $level, string $message, array $context): void { $edotLevel = is_string($level) ? Level::getFromPsrLevel($level) : Level::OFF; + + $caller = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 4)[3]; + + $func = ($caller['class'] ?? '') . ($caller['type'] ?? '') . $caller['function']; + $logContext = $this->attachLogContext ? (' context: ' . var_export($context, true)) : ''; + /** * elastic_otel_* functions are provided by the extension * @@ -42,12 +56,12 @@ public function write(mixed $level, string $message, array $context): void \elastic_otel_log_feature( // @phpstan-ignore function.notFound 0 /* isForced */, $edotLevel, - LogFeature::OTEL /* feature */, - '' /* category */, - '' /* file */, - 0 /* line */, - $context['source'] ?? '' /* func */, - $message . ' context: ' . var_export($context, true) /* message */ + LogFeature::OTEL, + 'OpenTelemetry', + $caller['file'] ?? '', + $caller['line'] ?? '', + $func, + $message . $logContext ); }