Make log levels configurable

Allows logging levels to be specified in the shipyard.conf so that
specific logger levels can be set by logger name.

The default option specified for keystoneauth prevents repetitive
logging of information that is generally not useful and is polluting
the logs with extraneous info.

Removes or reduces the logging level of some information, including
database queries and response messages. Response messages are now
only logged at debug in the case of an error response.

Change-Id: I895439e78c6ba71b4b7d6bd7dd26b768221e0489

shipyard_airflow/conf/config.py

@@ -75,6 +75,15 @@ SECTIONS = [
                 help=('The default logging level for the root logger. '
                       'ERROR=40, WARNING=30, INFO=20, DEBUG=10')
             ),
+            cfg.DictOpt(
+                'named_log_levels',
+                default={"keystoneauth": logging.INFO},
+                help=('The logging levels for named loggers. '
+                      'Use standard representations for logging levels: '
+                      'ERROR. WARN, INFO, DEBUG. Configuration file format: '
+                      'named_log_levels = keystoneauth:INFO,othlgr:WARN'
+                      )
+            ),
         ]
     ),
     ConfigSection(

shipyard_airflow/control/middleware/logging_mw.py

@@ -42,7 +42,12 @@ class LoggingMiddleware(object):
         ctx = req.context
         resp.append_header('X-Shipyard-Req', ctx.request_id)
         LOG.info('%s %s - %s', req.method, req.uri, resp.status)
-        LOG.debug('Response body:%s', resp.body)
+        # TODO(bryan-strassner) since response bodies can contain sensitive
+        #     information, only logging error response bodies here. When we
+        #     have response scrubbing or way to categorize responses in the
+        #     future, this may be an appropriate place to utilize it.
+        if self._get_resp_code(resp) >= 400:
+            LOG.debug('Errored Response body: %s', resp.body)
 
     def _log_headers(self, headers):
         """ Log request headers, while scrubbing sensitive values
@@ -50,3 +55,13 @@ class LoggingMiddleware(object):
         for header, header_value in headers.items():
             if not LoggingMiddleware.hdr_exclude.match(header):
                 LOG.debug("Header %s: %s", header, header_value)
+
+    def _get_resp_code(self, resp):
+        # Falcon response object doesn't have a raw status code.
+        # Splits by the first space
+        try:
+            return int(resp.status.split(" ", 1)[0])
+        except ValueError:
+            # if for some reason this Falcon response doesn't have a valid
+            # status, return a high value sentinel
+            return 9999

shipyard_airflow/control/start_shipyard.py

@@ -16,6 +16,8 @@
 Sets up the global configurations for the Shipyard service. Hands off
 to the api startup to handle the Falcon specific setup.
 """
+import logging
+
 from oslo_config import cfg
 
 from shipyard_airflow.conf import config
@@ -31,6 +33,7 @@ def start_shipyard(default_config_files=None):
     config.parse_args(args=[], default_config_files=default_config_files)
 
     ucp_logging.setup_logging(CONF.logging.log_level)
+    setup_log_levels()
 
     # Setup the RBAC policy enforcer
     policy.policy_engine = policy.ShipyardPolicy()
@@ -38,3 +41,17 @@ def start_shipyard(default_config_files=None):
 
     # Start the API
     return api.start_api()
+
+
+def setup_log_levels():
+    """Sets up the logger levels for named loggers
+
+    Uses the named_logger_levels dict to set each of the specified
+    logging levels.
+    """
+    level_dict = CONF.logging.named_log_levels or {}
+    for logger_name, level in level_dict.items():
+        logger = logging.getLogger(logger_name)
+        logger.setLevel(level)
+        tp_logger = logging.getLogger(__name__)
+        tp_logger.info("Set %s to use logging level %s", logger_name, level)

shipyard_airflow/db/common_db.py

@@ -87,7 +87,7 @@ class DbAccess:
         executes the supplied query and returns the array of dictionaries of
         the row results
         """
-        LOG.info('Query: %s', query)
+        LOG.debug('Query: %s', query)
         result_dict_list = []
         if query is not None:
             with self.get_engine().connect() as connection:
@@ -95,7 +95,7 @@ class DbAccess:
                 result_dict_list = [dict(row) for row in result_set]
         LOG.info('Result has %s rows', len(result_dict_list))
         for dict_row in result_dict_list:
-            LOG.info('Result: %s', dict_row)
+            LOG.debug('Result: %s', dict_row)
         return result_dict_list
 
     def perform_insert(self, query, **kwargs):

tests/unit/control/test.conf

@@ -44,4 +44,6 @@ validation_connect_timeout=5
 validation_read_timeout=300
 [shipyard]
 service_type = shipyard
+[logging]
+named_log_levels = keystoneauth:ERROR,cheese:WARN,pumpkins:INFO
 

tests/unit/control/test_start_shipyard.py

@@ -0,0 +1,31 @@
+# Copyright 2017 AT&T Intellectual Property.  All other rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+import logging
+import os
+
+from shipyard_airflow.control.start_shipyard import start_shipyard
+
+
+class TestStartShipyard():
+    def test_start_shipyard_logging_levels(self):
+        cur_dir = os.path.dirname(__file__)
+        filename = os.path.join(cur_dir, 'test.conf')
+
+        api = start_shipyard(default_config_files=[filename])
+        cheese_logger = logging.getLogger("cheese")
+        ksauth_logger = logging.getLogger("keystoneauth")
+        pumpkin_logger = logging.getLogger("pumpkins")
+        assert ksauth_logger.level == logging.ERROR
+        assert cheese_logger.level == logging.WARN
+        assert pumpkin_logger.level == logging.INFO