Add log_level config (#946)

* Remove unused arg from conf.setup_logging

* Add ValidValuesValidator

* Add tests for ValidValuesValidator

* Add support for callbacks_on_default

Also refactored one of the `call_callbacks` methods to
`call_all_callbacks` for clarity.

* Add log_level config with stubbed callback

* Don't run callbacks on copy operations

* Move callbacks to the end of any update() operation

This allows for callbacks to be config aware, and makes the full
config available to callback functions.

* Add log_file/size and implement logging setup callback

* Fix docs link

* Add changelog

* Audit logger calls

* Don't mess with global logging library

* Add tests

* Fix missing arg for ConfigurationError

* Import logging.handlers

* Implement review suggestions

* Fix windows tests

* Don't set log_level by default

* Better handling for callbacks if default is None

* With new default handling, don't need to check for new_value

* Allow `warn` in addition to `warning` for log_level

Author: basepi

CHANGELOG.asciidoc

@@ -40,6 +40,7 @@ endif::[]
  * Implement "sample_rate" property for transactions and spans, and propagate through tracestate {pull}891[#891]
  * Add support for callbacks on config changes {pull}912[#912]
  * Override `sys.excepthook` to catch all exceptions {pull}943[#943]
+ * Implement `log_level` config (supports central config) {pull}946[#946]
 
 [float]
 ===== Bug fixes

docs/configuration.asciidoc

@@ -157,6 +157,73 @@ but the agent will continue to poll the server for configuration changes.
 
 The transport class to use when sending events to the APM Server.
 
+[float]
+[[logging-options]]
+=== Logging Options
+
+[float]
+[[config-log_level]]
+==== `log_level`
+
+<<dynamic-configuration, image:./images/dynamic-config.svg[] >>
+
+[options="header"]
+|============
+| Environment             | Django/Flask | Default
+| `ELASTIC_APM_LOG_LEVEL` | `LOG_LEVEL`  |
+|============
+
+The `logging.logLevel` at which the `elasticapm` logger will log. Available
+options are:
+
+* `"off"` (sets `logging.logLevel` to 1000)
+* `"critical"`
+* `"error"`
+* `"warning"`
+* `"info"`
+* `"debug"`
+* `"trace"` (sets `logging.log_level` to 5)
+
+Options are case-insensitive.
+
+Note that this option doesn't do anything with logging handlers. In order
+for any logs to be visible, you must either configure a handler
+(https://docs.python.org/3/library/logging.html#logging.basicConfig[`logging.basicConfig`]
+will do this for you) or set <<config-log_file>>. This will also override
+any log level your app has set for the `elasticapm` logger.
+
+[float]
+[[config-log_file]]
+==== `log_file`
+
+[options="header"]
+|============
+| Environment             | Django/Flask | Default | Example
+| `ELASTIC_APM_LOG_FILE` | `LOG_FILE`    | `""`    | `"/var/log/elasticapm/log.txt"`
+|============
+
+Enables the agent to log to a file. Disabled by default. The agent will log
+at the `logging.logLevel` configured with <<config-log_level>>. Use
+<<config-log_file_size>> to configure the max size of the log file. This log
+file will automatically rotate.
+
+Note that setting <<config-log_level>> is required for this setting to do
+anything.
+
+[float]
+[[config-log_file_size]]
+==== `log_file_size`
+
+[options="header"]
+|============
+| Environment                 | Django/Flask    | Default     | Example
+| `ELASTIC_APM_LOG_FILE_SIZE` | `LOG_FILE_SIZE` | `"50mb"`    | `"100mb"`
+|============
+
+The size of the log file, if <<config-log_file>> is set.
+
+The agent always keeps one backup file when rotating, so the max space that
+the log files will consume is twice the value of this setting.
 
 [float]
 [[other-options]]

elasticapm/base.py

@@ -539,7 +539,7 @@ def _filter_exception_type(self, data):
                     exc_name = "%s.%s" % (exc_module, exc_type)
                 else:
                     exc_name = exc_type
-                self.logger.info("Ignored %s exception due to exception type filter", exc_name)
+                self.logger.debug("Ignored %s exception due to exception type filter", exc_name)
                 return True
         return False
 

elasticapm/conf/__init__.py

@@ -30,6 +30,7 @@
 
 
 import logging
+import logging.handlers
 import math
 import os
 import re
@@ -46,6 +47,18 @@
 
 logger = get_logger("elasticapm.conf")
 
+log_levels_map = {
+    "trace": 5,
+    "debug": logging.DEBUG,
+    "info": logging.INFO,
+    "warning": logging.WARNING,
+    "warn": logging.WARNING,
+    "error": logging.ERROR,
+    "critical": logging.CRITICAL,
+    "off": 1000,
+}
+logfile_set_up = False
+
 
 class ConfigurationError(ValueError):
     def __init__(self, msg, field_name):
@@ -71,7 +84,19 @@ class _ConfigValue(object):
         fails.
     callbacks
         List of functions which will be called when the config value is updated.
-        The callbacks must match this signature: callback(dict_key, old_value, new_value)
+        The callbacks must match this signature:
+            callback(dict_key, old_value, new_value, config_instance)
+
+        Note that callbacks wait until the end of any given `update()` operation
+        and are called at this point. This, coupled with the fact that callbacks
+        receive the config instance, means that callbacks can utilize multiple
+        configuration values (such as is the case for logging). This is
+        complicated if more than one of the involved config values are
+        dynamic, as both would need callbacks and the callback would need to
+        be idempotent.
+    callbacks_on_default
+        Whether the callback should be called on config initialization if the
+        default value is used. Default: True
     default
         The default for this config value if not user-configured.
     required
@@ -92,6 +117,7 @@ def __init__(
         type=compat.text_type,
         validators=None,
         callbacks=None,
+        callbacks_on_default=True,
         default=None,
         required=False,
     ):
@@ -104,6 +130,7 @@ def __init__(
         if env_key is None:
             env_key = "ELASTIC_APM_" + dict_key
         self.env_key = env_key
+        self.callbacks_on_default = callbacks_on_default
 
     def __get__(self, instance, owner):
         if instance:
@@ -139,19 +166,20 @@ def _callback_if_changed(self, instance, new_value):
         """
         old_value = instance._values.get(self.dict_key, self.default)
         if old_value != new_value:
-            self.call_callbacks(old_value, new_value)
+            instance.callbacks_queue.append((self.dict_key, old_value, new_value))
 
-    def call_callbacks(self, old_value, new_value):
+    def call_callbacks(self, old_value, new_value, config_instance):
         if not self.callbacks:
             return
         for callback in self.callbacks:
             try:
-                callback(self.dict_key, old_value, new_value)
+                callback(self.dict_key, old_value, new_value, config_instance)
             except Exception as e:
                 raise ConfigurationError(
                     "Callback {} raised an exception when setting {} to {}: {}".format(
                         callback, self.dict_key, new_value, e
-                    )
+                    ),
+                    self.dict_key,
                 )
 
 
@@ -297,20 +325,83 @@ def __call__(self, value, field_name):
         return value
 
 
+class EnumerationValidator(object):
+    """
+    Validator which ensures that a given config value is chosen from a list
+    of valid string options.
+    """
+
+    def __init__(self, valid_values, case_sensitive=False):
+        """
+        valid_values
+            List of valid string values for the config value
+        case_sensitive
+            Whether to compare case when comparing a value to the valid list.
+            Defaults to False (case-insensitive)
+        """
+        self.case_sensitive = case_sensitive
+        if case_sensitive:
+            self.valid_values = {s: s for s in valid_values}
+        else:
+            self.valid_values = {s.lower(): s for s in valid_values}
+
+    def __call__(self, value, field_name):
+        if self.case_sensitive:
+            ret = self.valid_values.get(value)
+        else:
+            ret = self.valid_values.get(value.lower())
+        if ret is None:
+            raise ConfigurationError(
+                "{} is not in the list of valid values: {}".format(value, list(self.valid_values.values())), field_name
+            )
+        return ret
+
+
+def _log_level_callback(dict_key, old_value, new_value, config_instance):
+    elasticapm_logger = logging.getLogger("elasticapm")
+    elasticapm_logger.setLevel(log_levels_map.get(new_value, 100))
+
+    global logfile_set_up
+    if not logfile_set_up and config_instance.log_file:
+        logfile_set_up = True
+        filehandler = logging.handlers.RotatingFileHandler(
+            config_instance.log_file, maxBytes=config_instance.log_file_size, backupCount=1
+        )
+        elasticapm_logger.addHandler(filehandler)
+
+
 class _ConfigBase(object):
     _NO_VALUE = object()  # sentinel object
 
-    def __init__(self, config_dict=None, env_dict=None, inline_dict=None):
+    def __init__(self, config_dict=None, env_dict=None, inline_dict=None, copy=False):
+        """
+        config_dict
+            Configuration dict as is common for frameworks such as flask and django.
+            Keys match the _ConfigValue.dict_key (usually all caps)
+        env_dict
+            Environment variables dict. Keys match the _ConfigValue.env_key
+            (usually "ELASTIC_APM_" + dict_key)
+        inline_dict
+            Any config passed in as kwargs to the Client object. Typically
+            the keys match the names of the _ConfigValue variables in the Config
+            object.
+        copy
+            Whether this object is being created to copy an existing Config
+            object. If True, don't run the initial `update` (which would call
+            callbacks if present)
+        """
         self._values = {}
         self._errors = {}
         self._dict_key_lookup = {}
+        self.callbacks_queue = []
         for config_value in self.__class__.__dict__.values():
             if not isinstance(config_value, _ConfigValue):
                 continue
             self._dict_key_lookup[config_value.dict_key] = config_value
-        self.update(config_dict, env_dict, inline_dict)
+        if not copy:
+            self.update(config_dict, env_dict, inline_dict, initial=True)
 
-    def update(self, config_dict=None, env_dict=None, inline_dict=None):
+    def update(self, config_dict=None, env_dict=None, inline_dict=None, initial=False):
         if config_dict is None:
             config_dict = {}
         if env_dict is None:
@@ -336,20 +427,30 @@ def update(self, config_dict=None, env_dict=None, inline_dict=None):
                     setattr(self, field, new_value)
                 except ConfigurationError as e:
                     self._errors[e.field_name] = str(e)
+            # handle initial callbacks
+            if (
+                initial
+                and config_value.callbacks_on_default
+                and getattr(self, field) is not None
+                and getattr(self, field) == config_value.default
+            ):
+                self.callbacks_queue.append((config_value.dict_key, self._NO_VALUE, config_value.default))
             # if a field has not been provided by any config source, we have to check separately if it is required
             if config_value.required and getattr(self, field) is None:
                 self._errors[config_value.dict_key] = "Configuration error: value for {} is required.".format(
                     config_value.dict_key
                 )
+        self.call_pending_callbacks()
 
-    def call_callbacks(self, callbacks):
+    def call_pending_callbacks(self):
         """
         Call callbacks for config options matching list of tuples:
 
         (dict_key, old_value, new_value)
         """
-        for dict_key, old_value, new_value in callbacks:
-            self._dict_key_lookup[dict_key].call_callbacks(old_value, new_value)
+        for dict_key, old_value, new_value in self.callbacks_queue:
+            self._dict_key_lookup[dict_key].call_callbacks(old_value, new_value, self)
+        self.callbacks_queue = []
 
     @property
     def values(self):
@@ -364,21 +465,21 @@ def errors(self):
         return self._errors
 
     def copy(self):
-        c = self.__class__()
+        c = self.__class__(copy=True)
         c._errors = {}
         c.values = self.values.copy()
         return c
 
 
 class Config(_ConfigBase):
     service_name = _ConfigValue("SERVICE_NAME", validators=[RegexValidator("^[a-zA-Z0-9 _-]+$")], required=True)
-    service_node_name = _ConfigValue("SERVICE_NODE_NAME", default=None)
-    environment = _ConfigValue("ENVIRONMENT", default=None)
+    service_node_name = _ConfigValue("SERVICE_NODE_NAME")
+    environment = _ConfigValue("ENVIRONMENT")
     secret_token = _ConfigValue("SECRET_TOKEN")
     api_key = _ConfigValue("API_KEY")
     debug = _BoolConfigValue("DEBUG", default=False)
     server_url = _ConfigValue("SERVER_URL", default="http://localhost:8200", required=True)
-    server_cert = _ConfigValue("SERVER_CERT", default=None, validators=[FileIsReadableValidator()])
+    server_cert = _ConfigValue("SERVER_CERT", validators=[FileIsReadableValidator()])
     verify_server_cert = _BoolConfigValue("VERIFY_SERVER_CERT", default=True)
     include_paths = _ListConfigValue("INCLUDE_PATHS")
     exclude_paths = _ListConfigValue("EXCLUDE_PATHS", default=compat.get_default_library_patters())
@@ -456,9 +557,9 @@ class Config(_ConfigBase):
     autoinsert_django_middleware = _BoolConfigValue("AUTOINSERT_DJANGO_MIDDLEWARE", default=True)
     transactions_ignore_patterns = _ListConfigValue("TRANSACTIONS_IGNORE_PATTERNS", default=[])
     service_version = _ConfigValue("SERVICE_VERSION")
-    framework_name = _ConfigValue("FRAMEWORK_NAME", default=None)
-    framework_version = _ConfigValue("FRAMEWORK_VERSION", default=None)
-    global_labels = _DictConfigValue("GLOBAL_LABELS", default=None)
+    framework_name = _ConfigValue("FRAMEWORK_NAME")
+    framework_version = _ConfigValue("FRAMEWORK_VERSION")
+    global_labels = _DictConfigValue("GLOBAL_LABELS")
     disable_send = _BoolConfigValue("DISABLE_SEND", default=False)
     enabled = _BoolConfigValue("ENABLED", default=True)
     recording = _BoolConfigValue("RECORDING", default=True)
@@ -470,6 +571,13 @@ class Config(_ConfigBase):
     use_elastic_traceparent_header = _BoolConfigValue("USE_ELASTIC_TRACEPARENT_HEADER", default=True)
     use_elastic_excepthook = _BoolConfigValue("USE_ELASTIC_EXCEPTHOOK", default=False)
     cloud_provider = _ConfigValue("CLOUD_PROVIDER", default=True)
+    log_level = _ConfigValue(
+        "LOG_LEVEL",
+        validators=[EnumerationValidator(["trace", "debug", "info", "warning", "warn", "error", "critical", "off"])],
+        callbacks=[_log_level_callback],
+    )
+    log_file = _ConfigValue("LOG_FILE", default="")
+    log_file_size = _ConfigValue("LOG_FILE_SIZE", validators=[size_validator], type=int, default=50 * 1024 * 1024)
 
     @property
     def is_recording(self):
@@ -544,7 +652,8 @@ def reset(self):
             self._version = self._first_version
             self._config = self._first_config
 
-        self._config.call_callbacks(callbacks)
+        self._config.callbacks_queue.extend(callbacks)
+        self._config.call_pending_callbacks()
 
     @property
     def changed(self):
@@ -578,7 +687,7 @@ def update_config(self):
                 logger.error("Error applying new configuration: %s", repr(errors))
             else:
                 logger.info(
-                    "Applied new configuration: %s",
+                    "Applied new remote configuration: %s",
                     "; ".join(
                         "%s=%s" % (compat.text_type(k), compat.text_type(v)) for k, v in compat.iteritems(new_config)
                     ),
@@ -604,12 +713,10 @@ def stop_thread(self):
             self._update_thread = None
 
 
-def setup_logging(handler, exclude=("gunicorn", "south", "elasticapm.errors")):
+def setup_logging(handler):
     """
     Configures logging to pipe to Elastic APM.
 
-    - ``exclude`` is a list of loggers that shouldn't go to ElasticAPM.
-
     For a typical Python install:
 
     >>> from elasticapm.handlers.logging import LoggingHandler
@@ -623,6 +730,9 @@ def setup_logging(handler, exclude=("gunicorn", "south", "elasticapm.errors")):
 
     Returns a boolean based on if logging was configured or not.
     """
+    # TODO We should probably revisit this. Does it make more sense as
+    # a method within the Client class? The Client object could easily
+    # pass itself into LoggingHandler and we could eliminate args altogether.
     logger = logging.getLogger()
     if handler.__class__ in map(type, logger.handlers):
         return False