feat(agent): add log level config option (newrelic#525)

* feat(agent, axiom): add log level config option

* fix(axiom): add NULL check for pointer arg

* fix(axiom): include stdbool for boolean type use in nr_log_level.c

* fix(axiom): do not execute level compare block if err == true

* fix(axiom): remove parenthesis from Log Level string macro defines

* feat(agent,axiom): add log_forwarding_log_level to txn opts

* feat(axiom): verify valid log level based on config setting for txns

* feat(axiom/tests): update log test framework to use new Log Level macros

* chore(agent): Add test_log_level test to gitignore

* chore(agent): Rework nr_log_levels

* No longer return allocated string from nr_log_level_rfc_to_psr().
* Cleanup API doc.

* chore(agent): Reword log level init message

* fix(agent): Updates log level filtering

* Ensures filtered events included in "Dropped" log forwarding metric
* Remove redundant filtering then already occurs in
  nr_txn_log_forwarding_enabled().

* test(agent): Enhance log level filtering tests

* Added test_log_level.c to exercise API.
* Extended transaction tests to include examples where
  log level filtering would reject some messages.

* test(agent): Integration test for log level filtering

* fix(agent): Fix rebase issue

After the rebase it is no longer necessary to destroy
the event passed to nr_log_events_add_event().

* test(agent): Update test case after rebase

Fixed "log.level" to "level" and move "timestamp"
field to proper location in JSON output after
rebase with dev.

* fix(agent): Fix spelling of log level filtering INI value

* fix(agent): If unknown log level filter given use default

* test(agent): Fix logging integration tests

With the addition of log level filtering is was necessary
to update all the monolog integration tests to include
this option.  Tests for log level filtering were also added.

* test(agent): Set log level filter for integration tests

* test(agent): Include logging metrics in expected

Co-authored-by: Brian Duranleau <[email protected]>

Author: mfulb

agent/php_newrelic.h

@@ -465,14 +465,19 @@ nrinitime_t
  * configuration options for handling application logging
  */
 
-nrinibool_t logging_enabled;        /* newrelic.application_logging.enabled */
-nrinibool_t log_forwarding_enabled; /* newrelic.application_logging.forwarding.enabled
-                                     */
-nriniuint_t log_events_max_samples_stored; /* newrelic.application_logging.forwarding.max_samples_stored
-                                            */
+nrinibool_t logging_enabled; /* newrelic.application_logging.enabled */
+nrinibool_t
+    log_forwarding_enabled; /* newrelic.application_logging.forwarding.enabled
+                             */
+nriniuint_t
+    log_events_max_samples_stored; /* newrelic.application_logging.forwarding.max_samples_stored
+                                    */
 nrinibool_t
     log_metrics_enabled; /* newrelic.application_logging.metrics.enabled */
 
+nriniuint_t log_forwarding_log_level; /* newrelic.application_logging.forwarding.log_level
+                                       */
+
 /*
  * pid and user_function_wrappers are used to store user function wrappers.
  * Storing this on a request level (as opposed to storing it on transaction

agent/php_nrini.c

@@ -13,6 +13,7 @@
 #include "nr_configstrings.h"
 #include "nr_limits.h"
 #include "nr_version.h"
+#include "nr_log_level.h"
 #include "util_buffer.h"
 #include "util_json.h"
 #include "util_logging.h"
@@ -1802,6 +1803,44 @@ static PHP_INI_MH(nr_log_events_max_samples_stored_mh) {
   return SUCCESS;
 }
 
+static PHP_INI_MH(nr_log_forwarding_log_level_mh) {
+  nriniuint_t* p;
+  int log_level = LOG_LEVEL_DEFAULT;
+
+#ifndef ZTS
+  char* base = (char*)mh_arg2;
+#else
+  char* base = (char*)ts_resource(*((int*)mh_arg2));
+#endif
+
+  p = (nriniuint_t*)(base + (size_t)mh_arg1);
+
+  (void)entry;
+  (void)mh_arg3;
+  NR_UNUSED_TSRMLS;
+
+  p->where = 0;
+
+  if (NEW_VALUE_LEN > 0) {
+    nrl_debug(NRL_INIT, "Log Level (PSR-3): %s", NEW_VALUE);
+
+    log_level = nr_log_level_str_to_int(NEW_VALUE);
+    if (LOG_LEVEL_UNKNOWN ==  log_level) {
+      log_level = LOG_LEVEL_DEFAULT;
+      nrl_warning(NRL_INIT, "Unknown log forwarding level %s, using %s instead.",
+      NEW_VALUE, nr_log_level_rfc_to_psr(log_level));
+    }
+    p->value = log_level;
+    p->where = stage;
+
+    nrl_debug(NRL_INIT, "Log Forwarding Log Level (RFC5424) set to: %d (%s)",
+              p->value, nr_log_level_rfc_to_psr(p->value));
+    return SUCCESS;
+  }
+
+  return FAILURE;
+}
+
 /*
  * Now for the actual INI entry table. Please note there are two types of INI
  * entry specification used.
@@ -2851,6 +2890,14 @@ STD_PHP_INI_ENTRY_EX(
     zend_newrelic_globals,
     newrelic_globals,
     0)
+STD_PHP_INI_ENTRY_EX("newrelic.application_logging.forwarding.log_level",
+                     "WARNING",
+                     NR_PHP_REQUEST,
+                     nr_log_forwarding_log_level_mh,
+                     log_forwarding_log_level,
+                     zend_newrelic_globals,
+                     newrelic_globals,
+                     0)
 STD_PHP_INI_ENTRY_EX("newrelic.application_logging.metrics.enabled",
                      "1",
                      NR_PHP_REQUEST,

agent/php_txn.c

@@ -737,6 +737,7 @@ nr_status_t nr_php_txn_begin(const char* appnames,
   opts.span_queue_batch_timeout = NRINI(agent_span_queue_timeout);
   opts.logging_enabled = NRINI(logging_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);
   opts.log_metrics_enabled = NRINI(log_metrics_enabled);
 

agent/scripts/newrelic.ini.template

@@ -1174,6 +1174,29 @@ newrelic.daemon.logfile = "/var/log/newrelic/newrelic-daemon.log"
 ;
 ;newrelic.application_logging.forwarding.max_samples_stored = 10000
 
+; Setting: newrelic.application_logging.forwarding.log_level
+; Type   : string
+; Scope  : per-directory
+; Default: "WARNING"
+; Info   : Sets the minimum log level to be collected when log forwarding
+;          is enabled. 
+;
+;          Based on
+;           https://www.php-fig.org/psr/psr-3/#5-psrlogloglevel
+;           https://datatracker.ietf.org/doc/html/rfc5424
+;
+;          Valid settings (ordered highest to lowest):
+;           "EMERGENCY"
+;           "ALERT"
+;           "CRITICAL"
+;           "ERROR"
+;           "WARNING"
+;           "NOTICE"
+;           "INFO"
+;           "DEBUG"
+;          
+;newrelic.application_logging.forwarding.log_level = "WARNING"
+
 ; Setting: newrelic.application_logging.metrics.enabled
 ; Type   : boolean
 ; Scope  : per-directory

axiom/Makefile

@@ -104,6 +104,7 @@ OBJS := \
 	nr_header.o \
 	nr_log_event.o \
 	nr_log_events.o \
+	nr_log_level.o \
 	nr_mysqli_metadata.o \
 	nr_postgres.o \
 	nr_rules.o \

axiom/nr_log_level.c

@@ -0,0 +1,94 @@
+/*
+ * Copyright 2022 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#include "nr_axiom.h"
+
+#include <stddef.h>
+
+#include "nr_log_level.h"
+#include "util_strings.h"
+#include "util_logging.h"
+#include "util_memory.h"
+
+int nr_log_level_str_to_int(const char* str) {
+  int level;
+  bool err = false;
+
+  if (NULL == str) {
+    err = true;
+  }
+
+#define LEVELCMP(x) (0 == nr_stricmp(str, x))
+
+  if (!err) {
+    if (LEVELCMP(LL_EMER_STR)) {
+      level = LOG_LEVEL_EMERGENCY;
+    } else if (LEVELCMP(LL_ALER_STR)) {
+      level = LOG_LEVEL_ALERT;
+    } else if (LEVELCMP(LL_CRIT_STR)) {
+      level = LOG_LEVEL_CRITICAL;
+    } else if (LEVELCMP(LL_ERRO_STR)) {
+      level = LOG_LEVEL_ERROR;
+    } else if (LEVELCMP(LL_WARN_STR)) {
+      level = LOG_LEVEL_WARNING;
+    } else if (LEVELCMP(LL_NOTI_STR)) {
+      level = LOG_LEVEL_NOTICE;
+    } else if (LEVELCMP(LL_INFO_STR)) {
+      level = LOG_LEVEL_INFO;
+    } else if (LEVELCMP(LL_DEBU_STR)) {
+      level = LOG_LEVEL_DEBUG;
+    } else {
+      err = true;
+    }
+  }
+
+#undef LEVELCMP
+
+  if (err) {
+    nrl_warning(
+        NRL_INIT,
+        "Unknown Log Forwarding Log Level Specified; Defaulting to \"%s\"",
+        nr_log_level_rfc_to_psr(LOG_LEVEL_UNKNOWN));
+    level = LOG_LEVEL_UNKNOWN;
+  }
+
+  return level;
+}
+
+const char* nr_log_level_rfc_to_psr(int level) {
+  const char* psr = NULL;
+
+  switch (level) {
+    case LOG_LEVEL_EMERGENCY:
+      psr = LL_EMER_STR;
+      break;
+    case LOG_LEVEL_ALERT:
+      psr = LL_ALER_STR;
+      break;
+    case LOG_LEVEL_CRITICAL:
+      psr = LL_CRIT_STR;
+      break;
+    case LOG_LEVEL_ERROR:
+      psr = LL_ERRO_STR;
+      break;
+    case LOG_LEVEL_WARNING:
+      psr = LL_WARN_STR;
+      break;
+    case LOG_LEVEL_NOTICE:
+      psr = LL_NOTI_STR;
+      break;
+    case LOG_LEVEL_INFO:
+      psr = LL_INFO_STR;
+      break;
+    case LOG_LEVEL_DEBUG:
+      psr = LL_DEBU_STR;
+      break;
+    default:
+      psr = LL_UNKN_STR;
+      break;
+  }
+
+  return psr;
+}

axiom/nr_log_level.h

@@ -0,0 +1,57 @@
+/*
+ * Copyright 2022 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef NR_LOG_LEVEL_HDR
+#define NR_LOG_LEVEL_HDR
+
+#include <stdbool.h>
+
+/*
+ *  Implementation Based on:
+ *      https://www.php-fig.org/psr/psr-3/#5-psrlogloglevel
+ *      https://datatracker.ietf.org/doc/html/rfc5424#section-6.2.1
+ */
+
+#define LOG_LEVEL_EMERGENCY (0)  // system is unusable
+#define LOG_LEVEL_ALERT (1)      // action must be taken immediately
+#define LOG_LEVEL_CRITICAL (2)   // critical conditions
+#define LOG_LEVEL_ERROR (3)      // error conditions
+#define LOG_LEVEL_WARNING (4)    // warning conditions
+#define LOG_LEVEL_NOTICE (5)     // normal but significant conditions
+#define LOG_LEVEL_INFO (6)       // informational messages
+#define LOG_LEVEL_DEBUG (7)      // debug-level messages
+#define LOG_LEVEL_UNKNOWN (8)    // NON PSR- Unknown/Undefined log level
+#define LOG_LEVEL_DEFAULT (LOG_LEVEL_WARNING)
+
+#define LL_EMER_STR "EMERGENCY"
+#define LL_ALER_STR "ALERT"
+#define LL_CRIT_STR "CRITICAL"
+#define LL_ERRO_STR "ERROR"
+#define LL_WARN_STR "WARNING"
+#define LL_NOTI_STR "NOTICE"
+#define LL_INFO_STR "INFO"
+#define LL_DEBU_STR "DEBUG"
+#define LL_UNKN_STR "UNKNOWN"
+
+/*
+ * Purpose : Convert PSR-3 string log level to RFC5424 represenation.
+ *
+ * Params  : 1.  str     String Log Level
+ *
+ * Returns : Integer RFC5424 Log Level numerical code
+ */
+extern int nr_log_level_str_to_int(const char* str);
+
+/*
+ * Purpose : Convert RFC5424 log level to PSR-3 string represenation.
+ *
+ * Params  : 1. level   RFC5424 Log Level
+ *
+ * Returns : PSR-3 String Log Level as a const char *
+ *
+ */
+extern const char* nr_log_level_rfc_to_psr(int level);
+
+#endif /* NR_LOG_LEVEL_HDR */

axiom/nr_txn.c

@@ -18,6 +18,7 @@
 #include "nr_header.h"
 #include "nr_limits.h"
 #include "nr_log_events.h"
+#include "nr_log_level.h"
 #include "nr_segment.h"
 #include "nr_segment_private.h"
 #include "nr_segment_traces.h"
@@ -3269,6 +3270,29 @@ bool nr_txn_log_forwarding_enabled(nrtxn_t* txn) {
   return true;
 }
 
+bool nr_txn_log_forwarding_log_level_verify(nrtxn_t* txn,
+                                            const char* log_level_name) {
+  int log_level;
+
+  if (NULL == txn) { /* more like an assert */
+    return false;
+  }
+
+  log_level = nr_log_level_str_to_int(log_level_name);
+
+  // pass through UNKNOWN by default
+  if (LOG_LEVEL_UNKNOWN == log_level) {
+    return true;
+  }
+
+  // log levels are organized 0 -> 7 in decreasing severity
+  if (log_level > txn->options.log_forwarding_log_level) {
+    return false;
+  }
+
+  return true;
+}
+
 bool nr_txn_log_metrics_enabled(nrtxn_t* txn) {
   if (NULL == txn) { /* more like an assert */
     return false;
@@ -3377,12 +3401,18 @@ static void nr_txn_add_log_event(nrtxn_t* txn,
     return;
   }
 
-  e = log_event_create(log_level_name, log_message, timestamp, txn, app);
-  if (NULL == e) {
-    nrl_debug(NRL_TXN, "%s: failed to create log event", __func__);
+  /* log events filtered out by log level will go into the Dropped metric */
+  if (!nr_txn_log_forwarding_log_level_verify(txn, log_level_name)) {
     event_dropped = true;
   } else {
-    event_dropped = nr_log_events_add_event(txn->log_events, e);
+    /* event passed log level filter so add it */
+    e = log_event_create(log_level_name, log_message, timestamp, txn, app);
+    if (NULL == e) {
+      nrl_debug(NRL_TXN, "%s: failed to create log event", __func__);
+      event_dropped = true;
+    } else {
+      event_dropped = nr_log_events_add_event(txn->log_events, e);
+    }
   }
 
   if (event_dropped) {

axiom/nr_txn.h

@@ -23,6 +23,7 @@
 #include "nr_errors.h"
 #include "nr_file_naming.h"
 #include "nr_log_events.h"
+#include "nr_log_level.h"
 #include "nr_segment.h"
 #include "nr_slowsqls.h"
 #include "nr_span_queue.h"
@@ -117,7 +118,9 @@ 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_forwarding_enabled;          /* Whether log forwarding is enabled */
+  bool log_forwarding_enabled;  /* Whether log forwarding is enabled */
+  int log_forwarding_log_level; /* minimum log level to forward to the collector
+                                 */
   size_t log_events_max_samples_stored; /* The maximum number of log events per
                                            transaction */
   bool log_metrics_enabled;             /* Whether log metrics are enabled */
@@ -617,6 +620,12 @@ extern void nr_txn_record_custom_event(nrtxn_t* txn,
  */
 extern bool nr_txn_log_forwarding_enabled(nrtxn_t* txn);
 
+/*
+ * Purpose : Check log forwarding log level configuration
+ */
+extern bool nr_txn_log_forwarding_log_level_verify(nrtxn_t* txn,
+                                                   const char* log_level_name);
+
 /*
  * Purpose : Check logging metrics configuration
  */

axiom/tests/.gitignore

@@ -68,6 +68,7 @@ test_json
 test_labels
 test_log_event
 test_log_events
+test_log_level
 test_logging
 test_logging_parallel
 test_math