feat: Implements APM Log Context Attributes (newrelic#758)

This PR adds the log context attribute feature for APM Log Forwarding.

---------

Co-authored-by: bduranleau-nr <[email protected]>
Co-authored-by: Amber Sistla <[email protected]>
Co-authored-by: Michal Nowacki <[email protected]>
Co-authored-by: Hitesh Ahuja <[email protected]>

Author: 5 people

agent/Makefile.frag

@@ -89,6 +89,7 @@ TEST_BINARIES = \
 	tests/test_internal_instrument \
 	tests/test_hash \
 	tests/test_mongodb \
+	tests/test_monolog \
 	tests/test_mysql \
 	tests/test_mysqli \
 	tests/test_output \

agent/lib_monolog.c

@@ -12,9 +12,12 @@
 #include "php_wrapper.h"
 #include "fw_hooks.h"
 #include "fw_support.h"
+#include "lib_monolog_private.h"
 #include "nr_datastore_instance.h"
 #include "nr_segment_datastore.h"
+#include "nr_txn.h"
 #include "util_logging.h"
+#include "util_object.h"
 #include "util_memory.h"
 #include "util_strings.h"
 #include "util_sleep.h"
@@ -27,19 +30,6 @@
 #define LOG_DECORATE_PROC_FUNC_NAME \
   "newrelic_phpagent_monolog_decorating_processor"
 
-// clang-format off
-/*
- * This macro affects how instrumentation $context argument of
- * Monolog\Logger::addRecord works:
- *
- * 0 - $context argument will not be instrumented: its existance and value
- *     are ignored 
- * 1 - the message of the log record forwarded by the agent will have the value
- *     of $context appended to the value of $message.
- */
-// clang-format on
-#define HAVE_CONTEXT_IN_MESSAGE 0
-
 /*
  * Purpose : Convert Monolog\Logger::API to integer
  *
@@ -155,123 +145,78 @@ static char* nr_monolog_get_message(NR_EXECUTE_PROTO TSRMLS_DC) {
   return message;
 }
 
-#if HAVE_CONTEXT_IN_MESSAGE
 /*
- * Purpose : Format key of $context array's element as string
+ * Purpose : Convert a zval value from context data to a nrobj_t
  *
- * Params  : zend_hash_key
- * *
- * Returns : A new string representing zval; caller must free
- *
- */
-static char* nr_monolog_fmt_context_key(const zend_hash_key* hash_key) {
-  char* key_str = NULL;
-  zval* key = nr_php_zval_alloc();
-  if (nr_php_zend_hash_key_is_string(hash_key)) {
-    nr_php_zval_str(key, nr_php_zend_hash_key_string_value(hash_key));
-    key_str = nr_formatf("%s", Z_STRVAL_P(key));
-  } else if (nr_php_zend_hash_key_is_numeric(hash_key)) {
-    ZVAL_LONG(key, (zend_long)nr_php_zend_hash_key_integer(hash_key));
-    key_str = nr_formatf("%ld", (long)Z_LVAL_P(key));
-  } else {
-    /*
-     * This is a warning because this really, really shouldn't ever happen.
-     */
-    nrl_warning(NRL_INSTRUMENT, "%s: unexpected key type", __func__);
-    key_str = nr_formatf("unsupported-key-type");
-  }
-  nr_php_zval_free(&key);
-  return key_str;
-}
-
-/*
- * Purpose : Format value of $context array's  element as string
+ * Params  : zval
  *
- * Params  : zval value
- * *
- * Returns : A new string representing zval; caller must free
+ * Returns : nrobj_t* holding converted value
+ *           NULL otherwise
  *
+ * Notes   : Only scalar and string types are supported.
+ *           Nested arrays are not converted and are ignored.
+ *           Other zval types are also ignored.
  */
-static char* nr_monolog_fmt_context_value(zval* zv) {
-  char* val_str = NULL;
-  zval* zv_str = NULL;
+nrobj_t* nr_monolog_context_data_zval_to_attribute_obj(
+    const zval* z TSRMLS_DC) {
+  nrobj_t* retobj = NULL;
 
-  if (NULL == zv) {
-    return nr_strdup("");
+  if (NULL == z) {
+    return NULL;
   }
 
-  zv_str = nr_php_zval_alloc();
-  if (NULL == zv_str) {
-    return nr_strdup("");
-  }
+  nr_php_zval_unwrap(z);
 
-  ZVAL_DUP(zv_str, zv);
-  convert_to_string(zv_str);
-  val_str = nr_strdup(Z_STRVAL_P(zv_str));
-  nr_php_zval_free(&zv_str);
+  switch (Z_TYPE_P(z)) {
+    case IS_NULL:
+      retobj = NULL;
+      break;
 
-  return val_str;
-}
+    case IS_LONG:
+      retobj = nro_new_long((long)Z_LVAL_P(z));
+      break;
 
-/*
- * Purpose : Format an element of $context array as "key => value" string
- *
- * Params  : zval value, pointer to string buffer to store formatted output
- * and hash key
- *
- * Side effect : string buffer is reallocated with each call.
- *
- * Returns : ZEND_HASH_APPLY_KEEP to keep iteration
- *
- */
-static int nr_monolog_fmt_context_item(zval* value,
-                                       char** strbuf,
-                                       zend_hash_key* hash_key TSRMLS_DC) {
-  NR_UNUSED_TSRMLS;
-  char* key = nr_monolog_fmt_context_key(hash_key);
-  char* val = nr_monolog_fmt_context_value(value);
-
-  char* kv_str = nr_formatf("%s => %s", key, val);
-  nr_free(key);
-  nr_free(val);
-
-  char* sep = nr_strlen(*strbuf) > 1 ? ", " : "";
-  *strbuf = nr_str_append(*strbuf, kv_str, sep);
-  nr_free(kv_str);
-
-  return ZEND_HASH_APPLY_KEEP;
-}
+    case IS_DOUBLE:
+      retobj = nro_new_double(Z_DVAL_P(z));
+      break;
 
-/*
- * Purpose : Iterate over $context array and format each element
- *
- * Params  : string buffer to store formatted output and
- * Monolog\Logger::addRecord argument list
- *
- * Returns : A new string with Monolog's log context
- */
-static char* nr_monolog_fmt_context(char* strbuf,
-                                    HashTable* context TSRMLS_DC) {
-  strbuf = nr_str_append(strbuf, "[", "");
+    case IS_TRUE:
+      retobj = nro_new_boolean(true);
+      break;
+
+    case IS_FALSE:
+      retobj = nro_new_boolean(false);
+      break;
 
-  nr_php_zend_hash_zval_apply(context,
-                              (nr_php_zval_apply_t)nr_monolog_fmt_context_item,
-                              (void*)&strbuf TSRMLS_CC);
+    case IS_STRING:
+      if (!nr_php_is_zval_valid_string(z)) {
+        retobj = NULL;
+      } else {
+        retobj = nro_new_string(Z_STRVAL_P(z));
+      }
+      break;
+
+    default:
+      /* any other type conversion to attribute not supported */
+      retobj = NULL;
+      break;
+  }
 
-  return nr_str_append(strbuf, "]", "");
+  return retobj;
 }
 
 /*
- * Purpose : Convert $context argument of Monolog\Logger::addRecord to a string
+ * Purpose : Get $context argument of Monolog\Logger::addRecord as `zval *`.
  *
  * Params  : # of Monolog\Logger::addRecord arguments, and
  * Monolog\Logger::addRecord argument list
  *
- * Returns : A new string with Monolog's log context
+ * Returns : zval* for context array on success (must be freed by caller)
+ *           NULL otherwise
+ *
  */
-static char* nr_monolog_get_context(const size_t argc,
-                                    NR_EXECUTE_PROTO TSRMLS_DC) {
-  char* context = nr_strdup("");
+static zval* nr_monolog_extract_context_data(const size_t argc,
+                                             NR_EXECUTE_PROTO TSRMLS_DC) {
   zval* context_arg = NULL;
 
   if (3 > argc) {
@@ -298,45 +243,57 @@ static char* nr_monolog_get_context(const size_t argc,
     goto return_context;
   }
 
-  context = nr_monolog_fmt_context(context, Z_ARRVAL_P(context_arg) TSRMLS_CC);
-
 return_context:
-  nr_php_arg_release(&context_arg);
-  return context;
+  return context_arg;
 }
-#endif
 
 /*
- * Purpose : Combine $message and $context arguments of
- * Monolog\Logger::addRecord into a single string to be used as a message
- * property of the log event.
+ * Purpose : Convert $context array of Monolog\Logger::addRecord to
+ * attributes
  *
- * Params  : # of Monolog\Logger::addRecord arguments, and
- * Monolog\Logger::addRecord argument list
+ * Params  : zval* for context array from Monolog
+ *
+ * Returns : nr_attributes representation of $context on success
+ *           NULL otherwise
  *
- * Returns : A new string with a log record message; caller must free
  */
-static char* nr_monolog_build_message(const size_t argc,
-                                      NR_EXECUTE_PROTO TSRMLS_DC) {
-#if !HAVE_CONTEXT_IN_MESSAGE
-  /* Make the compiler happy - argc is not used when $context is ignored */
-  (void)argc;
-#endif
-  char* message_and_context = nr_strdup("");
-
-  char* message = nr_monolog_get_message(NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
-  message_and_context = nr_str_append(message_and_context, message, "");
-  nr_free(message);
+nr_attributes_t* nr_monolog_convert_context_data_to_attributes(
+    zval* context_data TSRMLS_DC) {
+  zend_string* key;
+  zval* val;
 
-#if HAVE_CONTEXT_IN_MESSAGE
-  char* context = nr_monolog_get_context(argc, NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
-  if (!nr_strempty(context)) {
-    message_and_context = nr_str_append(message_and_context, context, " ");
+  nr_attributes_t* attributes = NULL;
+
+  if (NULL == context_data || !nr_php_is_zval_valid_array(context_data)) {
+    return NULL;
+  }
+
+  attributes = nr_attributes_create(NRPRG(txn)->attribute_config);
+  if (NULL == attributes) {
+    return NULL;
+  }
+
+  ZEND_HASH_FOREACH_STR_KEY_VAL(Z_ARR_P(context_data), key, val) {
+    if (NULL == key) {
+      continue;
+    }
+
+    nrobj_t* obj = nr_monolog_context_data_zval_to_attribute_obj(val);
+
+    if (NULL != obj) {
+      nr_attributes_user_add(attributes, NR_ATTRIBUTE_DESTINATION_LOG,
+                                  ZSTR_VAL(key), obj);
+      nro_delete(obj);
+    } else {
+      nrl_verbosedebug(NRL_INSTRUMENT,
+                       "%s: log context attribute '%s' dropped due to value "
+                       "being of unsupported type %d",
+                       __func__, ZSTR_VAL(key), Z_TYPE_P(val));
+    }
   }
-  nr_free(context);
-#endif
+  ZEND_HASH_FOREACH_END();
 
-  return message_and_context;
+  return attributes;
 }
 
 /*
@@ -397,21 +354,30 @@ NR_PHP_WRAPPER(nr_monolog_logger_addrecord) {
   int api = 0;
   size_t argc = 0;
   char* message = NULL;
+  nr_attributes_t* context_attributes = NULL;
   nrtime_t timestamp = nr_get_time();
 
   /* Values of $message and $timestamp arguments are needed only if log
    * forwarding is enabled so agent will get them conditionally */
   if (nr_txn_log_forwarding_enabled(NRPRG(txn))) {
     argc = nr_php_get_user_func_arg_count(NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
-    message = nr_monolog_build_message(argc, NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
+    message = nr_monolog_get_message(NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
+
+    if (nr_txn_log_forwarding_context_data_enabled(NRPRG(txn))) {
+      zval* context_data = nr_monolog_extract_context_data(
+          argc, NR_EXECUTE_ORIG_ARGS TSRMLS_CC);
+      context_attributes
+          = nr_monolog_convert_context_data_to_attributes(context_data);
+      nr_php_arg_release(&context_data);
+    }
     api = nr_monolog_version(this_var TSRMLS_CC);
     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));
+                          context_attributes, NRPRG(app));
 
   nr_free(level_name);
   nr_free(message);

agent/lib_monolog_private.h

@@ -0,0 +1,29 @@
+/*
+ * Copyright 2020 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef LIB_MONOLOG_PRIVATE_HDR
+#define LIB_MONOLOG_PRIVATE_HDR
+
+/*
+ * Purpose : ONLY for testing to verify that the appropriate behavior of
+ *           the conversion of zvals to attribute via nro.
+ *
+ * Returns : Pointer to nr_object_t representation of zval or
+ *           NULL if zval is not a supported type for conversion
+ *           to an attribute
+ */
+extern nrobj_t* nr_monolog_context_data_zval_to_attribute_obj(
+    const zval* z TSRMLS_DC);
+
+/*
+ * Purpose : ONLY for testing to verify that the appropriate behavior of
+ *           the conversion of a Monolog context array to attributes.
+ *
+ * Returns : Caller takes ownership of attributes struct
+ *
+ */
+extern nr_attributes_t* nr_monolog_convert_context_data_to_attributes(
+    zval* context_data TSRMLS_DC);
+#endif /* LIB_MONOLOG_PRIVATE_HDR */

agent/php_newrelic.h

@@ -308,6 +308,9 @@ nr_php_ini_attribute_config_t
 nr_php_ini_attribute_config_t
     browser_monitoring_attributes; /* newrelic.browser_monitoring.attributes.*
                                     */
+nr_php_ini_attribute_config_t
+    log_context_data_attributes; /* newrelic.application_logging.forwarding.context_data.*
+                                  */
 
 nrinibool_t custom_events_enabled; /* newrelic.custom_insights_events.enabled */
 nriniuint_t custom_events_max_samples_stored; /* newrelic.custom_events.max_samples_stored