feat(agent): Implements log decorating (#733)

Adds linking metadata to the Monolog LogRecord by using the 'extra' array element to store a string containing the log decorating linking metadata. --------- Co-authored-by: bduranleau-nr <[email protected]>
newrelic · Sep 27, 2023 · 3023054 · 3023054
1 parent 84d9cc1
commit 3023054
Show file tree

Hide file tree

Showing 498 changed files with 4,299 additions and 1,871 deletions.
diff --git a/agent/lib_monolog.c b/agent/lib_monolog.c
@@ -19,6 +19,14 @@
 #include "util_strings.h"
 #include "util_sleep.h"
 
+/*
+ * Define name of log decorating processor function
+ */
+#define LOG_DECORATE_NAMESPACE "Newrelic\\Monolog"
+#define LOG_DECORATE_NAMESPACE_LC "newrelic\\monolog"
+#define LOG_DECORATE_PROC_FUNC_NAME \
+  "newrelic_phpagent_monolog_decorating_processor"
+
 // clang-format off
 /*
  * This macro affects how instrumentation $context argument of
@@ -400,7 +408,7 @@ NR_PHP_WRAPPER(nr_monolog_logger_addrecord) {
     timestamp
         = nr_monolog_get_timestamp(api, argc, NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
   }
-  
+
   /* Record the log event */
   nr_txn_record_log_event(NRPRG(txn), level_name, message, timestamp,
                           NRPRG(app));
@@ -415,6 +423,54 @@ NR_PHP_WRAPPER(nr_monolog_logger_addrecord) {
 }
 NR_PHP_WRAPPER_END
 
+/*
+ * Create processor function used for log decorating as needed
+ */
+static int nr_monolog_create_decorate_processor_function(TSRMLS_D) {
+  int retval = SUCCESS;
+  zend_function* processor_func = NULL;
+
+  /* see if processor function exists and if not create */
+  processor_func = nr_php_find_function(LOG_DECORATE_NAMESPACE_LC "\\" LOG_DECORATE_PROC_FUNC_NAME);
+  if (NULL == processor_func) {
+    nrl_verbosedebug(NRL_INSTRUMENT,
+                     "Creating Monolog decorating processor func");
+
+    /* this function will add NR-LINKING data to the 'extra' array
+     * entry in the log record.  It is careful to confirm all the
+     * expected linking metadata is present as well as escaping
+     * special chars in the entity.name */
+    retval = zend_eval_string(
+        "namespace " LOG_DECORATE_NAMESPACE
+        ";"
+        "function " LOG_DECORATE_PROC_FUNC_NAME
+        "($record) {"
+        "    $linkmeta = newrelic_get_linking_metadata();"
+        "    $guid = $linkmeta['entity.guid'] ?? '';"
+        "    $hostname = $linkmeta['hostname'] ?? '';"
+        "    $traceid = $linkmeta['trace.id'] ?? '';"
+        "    $spanid = $linkmeta['span.id'] ?? '';"
+        "    $name = $linkmeta['entity.name'] ?? '';"
+        "    $name = urlencode($name);"
+        "    $data = 'NR-LINKING|' . $guid . '|' . $hostname . '|' ."
+        "             $traceid . '|' . $spanid . '|' . $name . '|';"
+        "    $record['extra']['NR-LINKING'] = $data;"
+        "    return $record;"
+        "}",
+        NULL, "newrelic/Monolog/" LOG_DECORATE_PROC_FUNC_NAME TSRMLS_CC);
+
+    if (SUCCESS != retval) {
+      nrl_warning(NRL_FRAMEWORK,
+                  "%s: error creating Monolog decorating processor function!",
+                  __func__);
+    }
+  } else {
+    nrl_verbosedebug(NRL_INSTRUMENT, "Using existing Monolog decorating processor func");
+  }
+
+  return retval;
+}
+
 NR_PHP_WRAPPER(nr_monolog_logger_pushhandler) {
   (void)wraprec;
 
@@ -424,6 +480,11 @@ NR_PHP_WRAPPER(nr_monolog_logger_pushhandler) {
     goto end;
   }
 
+  nrl_verbosedebug(
+      NRL_INSTRUMENT, "%s : Monolog handler = %*s", __func__,
+      NRSAFELEN(nr_php_class_entry_name_length(Z_OBJCE_P(handler))),
+      nr_php_class_entry_name(Z_OBJCE_P(handler)));
+
   if (nr_txn_log_forwarding_enabled(NRPRG(txn))
       && nr_php_object_instanceof_class(
           handler, "NewRelic\\Monolog\\Enricher\\Handler" TSRMLS_CC)) {
@@ -432,6 +493,47 @@ NR_PHP_WRAPPER(nr_monolog_logger_pushhandler) {
                 "application may be sending logs to New Relic twice.");
   }
 
+  if (nr_txn_log_decorating_enabled(NRPRG(txn))) {
+    zval* callback_name = NULL;
+    zval* ph_retval = NULL;
+
+    /* Verify the handler implements pushProcessor () */
+    if (!nr_php_object_has_method(handler, "pushProcessor" TSRMLS_CC)) {
+      nrl_warning(
+          NRL_INSTRUMENT,
+          "Monolog handler %*s does not implement the pushProcessor() "
+          "method so log decoration will not occur!",
+          NRSAFELEN(nr_php_class_entry_name_length(Z_OBJCE_P(handler))),
+          nr_php_class_entry_name(Z_OBJCE_P(handler)));
+
+      goto end;
+    }
+
+    /* Create function used to decorate Monolog log records */
+    nr_monolog_create_decorate_processor_function();
+
+    /*
+     * Actually call pushProcessor
+     */
+    callback_name = nr_php_zval_alloc();
+    nr_php_zval_str(callback_name,
+                    LOG_DECORATE_NAMESPACE "\\" LOG_DECORATE_PROC_FUNC_NAME);
+
+    ph_retval = nr_php_call(handler, "pushProcessor", callback_name TSRMLS_CC);
+    if (!nr_php_is_zval_true(ph_retval)) {
+      nrl_warning(
+          NRL_FRAMEWORK,
+          "%s: error registering Monolog decorating processor function!",
+          __func__);
+    } else {
+      nrl_verbosedebug(NRL_INSTRUMENT,
+                       "Monolog log decorating processor registered");
+    }
+
+    nr_php_zval_free(&ph_retval);
+    nr_php_zval_free(&callback_name);
+  }
+
 end:
   NR_PHP_WRAPPER_CALL
   nr_php_arg_release(&handler);

diff --git a/agent/php_minit.c b/agent/php_minit.c
@@ -263,16 +263,16 @@ static void nr_php_check_CAT_DT_config(TSRMLS_D) {
                 "the 'newrelic.cross_application_tracer.enabled' INI setting "
                 "in your INI file and enabling DT via the "
                 "'newrelic.distributed_tracing_enabled' INI setting.");
-    
+
     // set CAT INI value to disabled (just to be safe)
     NRINI(cross_process_enabled) = 0;
   }
 }
 
 /*
- * @brief Check the INI values for 'logging_enabled' and
- *        'log_forwarding_enabled' and log a warning on
- *        invalid configuration state.
+ * @brief Check the INI values for 'logging_enabled',
+ *        'log_forwarding_enabled', and 'log_decorating_enabled' and log a
+ *        warning on invalid configuration state.
  *
  */
 static void nr_php_check_logging_config(TSRMLS_D) {
@@ -283,6 +283,24 @@ static void nr_php_check_logging_config(TSRMLS_D) {
                 "'newrelic.application_logging.logging.enabled' in the agent "
                 "configuration.");
   }
+
+  if (!NRINI(logging_enabled) && NRINI(log_decorating_enabled)) {
+    nrl_warning(NRL_INIT,
+                "Log Decorating will be DISABLED because logging is disabled. "
+                "Log Decorating requires Logging to be enabled. Please check "
+                "'newrelic.application_logging.logging.enabled' in the agent "
+                "configuration.");
+  }
+
+  if (NRINI(logging_enabled) && NRINI(log_forwarding_enabled)
+      && NRINI(log_decorating_enabled)) {
+    nrl_warning(NRL_INIT,
+                "Log Forwarding and Log Decorating have been enabled! "
+                "This could lead to duplicated ingest of log messages! "
+                "Check newrelic.application_logging.forwarding.enabled and "
+                "newrelic.application_logging.local_decorating.enabled in the "
+                "agent configuration.");
+  }
 }
 
 /*
@@ -618,7 +636,7 @@ PHP_MINIT_FUNCTION(newrelic) {
     nr_agent_close_daemon_connection();
   }
 
-  /* Do some sanity checking of configuration settings and handle accordingly */
+  /* Do some checking of configuration settings and handle accordingly */
 
   /* If infinite tracing (8T) is enabled but distributed tracing (DT) is
    * disabled this is an unworkable combination because span IDs cannot be

diff --git a/agent/php_newrelic.h b/agent/php_newrelic.h
@@ -474,6 +474,9 @@ nrinitime_t
  */
 
 nrinibool_t logging_enabled; /* newrelic.application_logging.enabled */
+nrinibool_t
+    log_decorating_enabled; /* newrelic.application_logging.local_decorating.enabled
+                             */
 nrinibool_t
     log_forwarding_enabled; /* newrelic.application_logging.forwarding.enabled
                              */

diff --git a/agent/php_nrini.c b/agent/php_nrini.c
@@ -2943,6 +2943,14 @@ STD_PHP_INI_ENTRY_EX("newrelic.application_logging.enabled",
                      zend_newrelic_globals,
                      newrelic_globals,
                      nr_enabled_disabled_dh)
+STD_PHP_INI_ENTRY_EX("newrelic.application_logging.local_decorating.enabled",
+                     "0",
+                     NR_PHP_REQUEST,
+                     nr_boolean_mh,
+                     log_decorating_enabled,
+                     zend_newrelic_globals,
+                     newrelic_globals,
+                     nr_enabled_disabled_dh)
 STD_PHP_INI_ENTRY_EX("newrelic.application_logging.forwarding.enabled",
                      "1",
                      NR_PHP_REQUEST,

diff --git a/agent/php_txn.c b/agent/php_txn.c
@@ -637,6 +637,11 @@ static void nr_php_txn_send_metrics_once(nrtxn_t* txn TSRMLS_DC) {
 
 #define FMT_BOOL(v) (v) ? "enabled" : "disabled"
 
+  metname = nr_formatf("Supportability/Logging/LocalDecorating/PHP/%s",
+                       FMT_BOOL(nr_txn_log_decorating_enabled(txn)));
+  nrm_force_add(NRTXN(unscoped_metrics), metname, 0);
+  nr_free(metname);
+
   metname = nr_formatf("Supportability/Logging/Forwarding/PHP/%s",
                        FMT_BOOL(nr_txn_log_forwarding_enabled(txn)));
   nrm_force_add(NRTXN(unscoped_metrics), metname, 0);
@@ -740,6 +745,7 @@ nr_status_t nr_php_txn_begin(const char* appnames,
   opts.span_queue_batch_size = NRINI(agent_span_queue_size);
   opts.span_queue_batch_timeout = NRINI(agent_span_queue_timeout);
   opts.logging_enabled = NRINI(logging_enabled);
+  opts.log_decorating_enabled = NRINI(log_decorating_enabled);
   opts.log_forwarding_enabled = NRINI(log_forwarding_enabled);
   opts.log_forwarding_log_level = NRINI(log_forwarding_log_level);
   opts.log_events_max_samples_stored = NRINI(log_events_max_samples_stored);

diff --git a/axiom/nr_txn.c b/axiom/nr_txn.c
@@ -3316,12 +3316,11 @@ bool nr_txn_log_decorating_enabled(nrtxn_t* txn) {
     return false;
   }
 
-  if (!txn->options
-           .logging_enabled /* || !txn->options.log_decorating_enabled */) {
+  if (!txn->options.logging_enabled || !txn->options.log_decorating_enabled) {
     return false;
   }
 
-  return false;
+  return true;
 }
 
 #define ENSURE_LOG_LEVEL_NAME(level_name) \

diff --git a/axiom/nr_txn.h b/axiom/nr_txn.h
@@ -120,6 +120,7 @@ typedef struct _nrtxnopt_t {
   nrtime_t span_queue_batch_timeout; /* Span queue batch timeout in us. */
   bool logging_enabled; /* An overall configuration for enabling/disabling all
                            application logging features */
+  bool log_decorating_enabled;  /* Whether log decorating is enabled */
   bool log_forwarding_enabled;  /* Whether log forwarding is enabled */
   int log_forwarding_log_level; /* minimum log level to forward to the collector
                                  */

diff --git a/axiom/tests/test_txn.c b/axiom/tests/test_txn.c
@@ -8102,6 +8102,7 @@ static nrtxn_t* new_txn_for_record_log_event_test(char* entity_name) {
   opts.logging_enabled = true;
   opts.log_forwarding_enabled = true;
   opts.log_forwarding_log_level = LOG_LEVEL_WARNING;
+  opts.log_decorating_enabled = false;
   opts.log_events_max_samples_stored = 10;
   opts.log_metrics_enabled = true;
 
@@ -8398,6 +8399,7 @@ static void test_txn_log_configuration(void) {
   txn->options.logging_enabled = false;
   txn->high_security = false;
 
+  txn->options.log_decorating_enabled = false;
   txn->options.log_forwarding_enabled = false;
   txn->options.log_events_max_samples_stored = 0;
   txn->options.log_metrics_enabled = false;
@@ -8419,10 +8421,20 @@ static void test_txn_log_configuration(void) {
   txn->options.log_events_max_samples_stored = 1;
   tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=0, high_security=0, forwarding=1, samples=1 -> off");
 
+  txn->options.log_forwarding_enabled = false;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_false(__func__, nr_txn_log_decorating_enabled(txn), "global=0, high_security=0, decorating=1 -> off");
+
+  txn->options.log_forwarding_enabled = true;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=0, high_security=0, forwarding=1, samples=1, decorating=1 -> forwarding off");
+  tlib_pass_if_false(__func__, nr_txn_log_decorating_enabled(txn), "global=0, high_security=0, forwarding=1, samples=1, decorating=1 -> decorating off");
+
   /* log features globally enabled, high security disabled */
   txn->options.logging_enabled = true;
   txn->high_security = false;
 
+  txn->options.log_decorating_enabled = false;
   txn->options.log_forwarding_enabled = false;
   txn->options.log_events_max_samples_stored = 0;
   txn->options.log_metrics_enabled = false;
@@ -8444,8 +8456,18 @@ static void test_txn_log_configuration(void) {
   txn->options.log_events_max_samples_stored = 1;
   tlib_pass_if_true(__func__, nr_txn_log_forwarding_enabled(txn), "global=1, high_security=0, forwarding=1, samples=1 -> on");
 
+  txn->options.log_forwarding_enabled = false;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_true(__func__, nr_txn_log_decorating_enabled(txn), "global=1, high_security=0, decorating=1 -> on");
+
+  txn->options.log_forwarding_enabled = true;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_true(__func__, nr_txn_log_forwarding_enabled(txn), "global=1, high_security=0, forwarding=1, samples=1, decorating=1 -> forwarding on");
+  tlib_pass_if_true(__func__, nr_txn_log_decorating_enabled(txn), "global=1, high_security=0, forwarding=1, samples=1, decorating=1 -> decorating on");
+
   /* log features globally disabled, high security enabled */
   txn->options.logging_enabled = false;
+  txn->options.log_decorating_enabled = false;
   txn->high_security = true;
 
   txn->options.log_forwarding_enabled = false;
@@ -8469,10 +8491,20 @@ static void test_txn_log_configuration(void) {
   txn->options.log_events_max_samples_stored = 1;
   tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=0, high_security=1, forwarding=1, samples=1 -> off");
 
+  txn->options.log_forwarding_enabled = false;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_false(__func__, nr_txn_log_decorating_enabled(txn), "global=0, high_security=1, decorating=1 -> off");
+
+  txn->options.log_forwarding_enabled = true;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=0, high_security=1, forwarding=1, samples=1, decorating=1 -> forwarding off");
+  tlib_pass_if_false(__func__, nr_txn_log_decorating_enabled(txn), "global=0, high_security=1, forwarding=1, samples=1, decorating=1 -> decorating off");
+
   /* log features globally enabled, high security enabled */
   txn->options.logging_enabled = true;
   txn->high_security = true;
 
+  txn->options.log_decorating_enabled = false;
   txn->options.log_forwarding_enabled = false;
   txn->options.log_events_max_samples_stored = 0;
   txn->options.log_metrics_enabled = false;
@@ -8493,6 +8525,15 @@ static void test_txn_log_configuration(void) {
   txn->options.log_forwarding_enabled = true;
   txn->options.log_events_max_samples_stored = 1;
   tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=1, high_security=1, forwarding=1, samples=1 -> off");
+
+  txn->options.log_forwarding_enabled = false;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_true(__func__, nr_txn_log_decorating_enabled(txn), "global=1, high_security=1, decorating=1 -> on");
+
+  txn->options.log_forwarding_enabled = true;
+  txn->options.log_decorating_enabled = true;
+  tlib_pass_if_false(__func__, nr_txn_log_forwarding_enabled(txn), "global=1, high_security=1, forwarding=1, samples=1, decorating=1 -> forwarding off");
+  tlib_pass_if_true(__func__, nr_txn_log_decorating_enabled(txn), "global=1, high_security=1, forwarding=1, samples=1, decorating=1 -> decorating on");
   // clang-format on
 }
 

diff --git a/tests/integration/api/add_custom_span_parameter/test_span_event_parameter_disabled.php b/tests/integration/api/add_custom_span_parameter/test_span_event_parameter_disabled.php
@@ -88,12 +88,14 @@
     [{"name":"Supportability/api/add_custom_tracer"},               [1, 0, 0, 0, 0, 0]],
     [{"name":"Supportability/api/add_custom_span_parameter"},       [4, 0, 0, 0, 0, 0]],
     [{"name":"Supportability/Logging/Forwarding/PHP/enabled"},      [1, "??", "??", "??", "??", "??"]],
-    [{"name":"Supportability/Logging/Metrics/PHP/enabled"},         [1, "??", "??", "??", "??", "??"]]
+    [{"name":"Supportability/Logging/Metrics/PHP/enabled"},         [1, "??", "??", "??", "??", "??"]],
+    [{"name":"Supportability/Logging/LocalDecorating/PHP/disabled"},[1, "??", "??", "??", "??", "??"]]
   ]
 ]
 */
 
 
+
 require_once(realpath(dirname(__FILE__)) . '/../../../include/tap.php');
 
 newrelic_add_custom_tracer("a");

diff --git a/tests/integration/api/add_custom_span_parameter/test_span_event_parameter_duplicate.php b/tests/integration/api/add_custom_span_parameter/test_span_event_parameter_duplicate.php
@@ -114,7 +114,7 @@
         "string": "span str"
       },
       {
-        "code.lineno": 155,
+        "code.lineno": 157,
         "code.filepath": "__FILE__",
         "code.function": "a"
       }
@@ -142,12 +142,14 @@
     [{"name":"Supportability/api/add_custom_span_parameter"},       [3, 0, 0, 0, 0, 0]],
     [{"name":"Supportability/api/add_custom_parameter"},            [5, 0, 0, 0, 0, 0]],
     [{"name":"Supportability/Logging/Forwarding/PHP/enabled"},      [1, "??", "??", "??", "??", "??"]],
-    [{"name":"Supportability/Logging/Metrics/PHP/enabled"},         [1, "??", "??", "??", "??", "??"]]
+    [{"name":"Supportability/Logging/Metrics/PHP/enabled"},         [1, "??", "??", "??", "??", "??"]],
+    [{"name":"Supportability/Logging/LocalDecorating/PHP/disabled"},[1, "??", "??", "??", "??", "??"]]
   ]
 ]
 */
 
 
+
 require_once(realpath(dirname(__FILE__)) . '/../../../include/tap.php');
 
 newrelic_add_custom_tracer("a");