Improved Otel->Elatic log writer (#151)

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<LogLevel>(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<LogLevel>(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<LogLevel>(level), static_cast<elasticapm::php::LogFeature>(feature))) {
         if (lineNull) {
-            ELASTICAPM_G(globals)->logger_->printf(static_cast<LogLevel>(level), PRsv " " PRsv " " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), PRcsvArg(func, funcLength), PRcsvArg(message, messageLength));
+            ELASTICAPM_G(globals)->logger_->printf(static_cast<LogLevel>(level), "[" PRsv "] [" PRsv "] [" PRsv "] [" PRsv "] " PRsv, PRsvArg(elasticapm::php::getLogFeatureName(static_cast<elasticapm::php::LogFeature>(feature))), PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), PRcsvArg(func, funcLength), PRcsvArg(message, messageLength));
+            return;
         }
-        ELASTICAPM_G(globals)->logger_->printf(static_cast<LogLevel>(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<LogLevel>(level), "[" PRsv "] [" PRsv "] [" PRsv ":%d] [" PRsv "] " PRsv, PRsvArg(elasticapm::php::getLogFeatureName(static_cast<elasticapm::php::LogFeature>(feature))), PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength));
     }
 }
 /* }}} */

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

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

prod/native/libcommon/code/Logger.cpp

@@ -27,6 +27,8 @@
 
 namespace elasticapm::php {
 
+using namespace std::string_literals;
+
 void Logger::setLogFeatures(std::unordered_map<elasticapm::php::LogFeature, LogLevel> 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);

prod/native/libcommon/code/LoggerInterface.h

@@ -21,6 +21,7 @@
 
 #include "LogLevel.h"
 #include "LogFeature.h"
+#include "basic_macros.h"
 
 #include <unordered_map>
 #include <stdarg.h>
@@ -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__)

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();
 

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));
     };
 

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<array-key, mixed> $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
         );
     }