Fix Deckhand logging

The following deployment logic should be included to get logging
to work correctly:

1) tox -egenconfig
   - Store the output in /etc/deckhand/deckhand.conf for example
2) Copy logging.conf.sample in etc folder to /etc/deckhand/logging.conf
3) Set the following options in under [DEFAULT] in
   /etc/deckhand/deckhand.conf:

   - log_config_append = /etc/deckhand/logging.conf
   - log_file = deckhand.log
   - log_dir = <path/to/deckhand/dir>
   - debug = true (optionally)

Change-Id: I8e8ebd041e801a5eef0f10b1bbc76ce95aecbf55

deckhand/control/api.py

@@ -18,7 +18,6 @@ import falcon
 from oslo_config import cfg
 from oslo_log import log as logging
 
-from deckhand.conf import config
 from deckhand.control import base
 from deckhand.control import buckets
 from deckhand.control import middleware
@@ -28,35 +27,17 @@ from deckhand.control import revisions
 from deckhand.db.sqlalchemy import api as db_api
 
 CONF = cfg.CONF
-LOG = None
+logging.register_options(CONF)
+
+# TODO(fmontei): Include deckhand-paste.ini later.
+CONFIG_FILES = ['deckhand.conf']
 
 
-def __setup_logging():
+def _get_config_files(env=None):
-    global LOG
+    if env is None:
-
+        env = os.environ
-    logging.register_options(CONF)
+    dirname = env.get('OS_DECKHAND_CONFIG_DIR', '/etc/deckhand').strip()
-    config.parse_args()
+    return [os.path.join(dirname, config_file) for config_file in CONFIG_FILES]
-
-    current_path = os.path.dirname(os.path.realpath(__file__))
-    root_path = os.path.abspath(os.path.join(current_path, os.pardir,
-                                             os.pardir))
-    logging_cfg_path = "%s/etc/deckhand/logging.conf" % root_path
-
-    # If logging conf is in place we need to set log_config_append. Only do so
-    # if the log path already exists.
-    if ((not hasattr(CONF, 'log_config_append') or
-        CONF.log_config_append is None) and
-        os.path.isfile(logging_cfg_path)):
-        CONF.log_config_append = logging_cfg_path
-
-    logging.setup(CONF, 'deckhand')
-    LOG = logging.getLogger(__name__, 'deckhand')
-    LOG.debug('Initiated Deckhand logging.')
-
-
-def __setup_db():
-    db_api.drop_db()
-    db_api.setup_db()
 
 
 def _get_routing_map():
@@ -86,8 +67,15 @@ def start_api(state_manager=None):
 
     Create routes for the v1.0 API and sets up logging.
     """
-    __setup_logging()
+    config_files = _get_config_files()
-    __setup_db()
+    CONF([], project='deckhand', default_config_files=config_files)
+    logging.setup(CONF, "deckhand")
+
+    LOG = logging.getLogger(__name__)
+    LOG.info('Initiated Deckhand logging.')
+
+    db_api.drop_db()
+    db_api.setup_db()
 
     control_api = falcon.API(
         request_type=base.DeckhandRequest,

deckhand/tests/unit/control/test_api.py

@@ -36,10 +36,11 @@ class TestApi(test_base.DeckhandTestCase):
             setattr(self, '%s_resource' % resource_name, resource_obj)
 
     @mock.patch.object(api, 'db_api', autospec=True)
-    @mock.patch.object(api, 'config', autospec=True)
+    @mock.patch.object(api, 'logging', autospec=True)
+    @mock.patch.object(api, 'CONF', autospec=True)
     @mock.patch.object(api, 'falcon', autospec=True)
-    def test_start_api(self, mock_falcon,
+    def test_start_api(self, mock_falcon, mock_config, mock_logging,
-                       mock_config, mock_db_api):
+                       mock_db_api):
         mock_falcon_api = mock_falcon.API.return_value
 
         result = api.start_api()
@@ -60,5 +61,6 @@ class TestApi(test_base.DeckhandTestCase):
             mock.call('/api/v1.0/revisions/{revision_id}/tags/{tag}',
                       self.revision_tags_resource())
         ])
-        mock_config.parse_args.assert_called_once_with()
+
+        mock_db_api.drop_db.assert_called_once_with()
         mock_db_api.setup_db.assert_called_once_with()

etc/deckhand/deckhand.conf.sample

@@ -247,11 +247,15 @@
 # (boolean value)
 #mysql_enable_ndb = false
 
-# Timeout before idle SQL connections are reaped. (integer value)
+# Connections which have been present in the connection pool longer than this
+# number of seconds will be replaced with a new one the next time they are
+# checked out from the pool. (integer value)
+# Deprecated group/name - [DATABASE]/idle_timeout
+# Deprecated group/name - [database]/idle_timeout
 # Deprecated group/name - [DEFAULT]/sql_idle_timeout
 # Deprecated group/name - [DATABASE]/sql_idle_timeout
 # Deprecated group/name - [sql]/idle_timeout
-#idle_timeout = 3600
+#connection_recycle_time = 3600
 
 # Minimum number of SQL connections to keep open in a pool. (integer value)
 # Deprecated group/name - [DEFAULT]/sql_min_pool_size

etc/deckhand/logging.conf

@@ -1,35 +0,0 @@
-[loggers]
-keys=root
-
-[handlers]
-keys=file,devel,syslog
-
-[formatters]
-keys=simple,tests
-
-[logger_root]
-level=DEBUG
-handlers=file
-
-[handler_file]
-class=FileHandler
-level=DEBUG
-args=('deckhand.log', 'w+')
-formatter=tests
-
-[handler_syslog]
-class=handlers.SysLogHandler
-level=ERROR
-args = ('/dev/log', handlers.SysLogHandler.LOG_USER)
-
-[handler_devel]
-class=StreamHandler
-level=DEBUG
-args=(sys.stdout,)
-formatter=simple
-
-[formatter_tests]
-class = oslo_log.formatters.ContextFormatter
-
-[formatter_simple]
-format=%(asctime)s.%(msecs)03d %(process)d %(levelname)s: %(message)s

etc/deckhand/logging.conf.sample

@@ -1,34 +1,38 @@
 [loggers]
-keys=root
+keys = root, deckhand
 
 [handlers]
-keys=file,devel,syslog
+keys = file, null, syslog
 
 [formatters]
-keys=simple,tests
+keys = simple, context
+
+[logger_deckhand]
+level = DEBUG
+handlers = file
+qualname = deckhand
 
 [logger_root]
-level=DEBUG
+level = WARNING
-handlers=file
+handlers = null
 
 [handler_file]
-class=FileHandler
+class = FileHandler
-level=DEBUG
+level = DEBUG
-args=('deckhand.log', 'w+')
+args = ('deckhand.log', 'w+')
-formatter=tests
+formatter = context
+
+[handler_null]
+class = logging.NullHandler
+formatter = context
+args = ()
 
 [handler_syslog]
-class=handlers.SysLogHandler
+class = handlers.SysLogHandler
-level=ERROR
+level = ERROR
 args = ('/dev/log', handlers.SysLogHandler.LOG_USER)
 
-[handler_devel]
+[formatter_context]
-class=StreamHandler
-level=DEBUG
-args=(sys.stdout,)
-formatter=simple
-
-[formatter_tests]
 class = oslo_log.formatters.ContextFormatter
 
 [formatter_simple]

tools/functional-tests.sh

@@ -40,26 +40,31 @@ POSTGRES_PORT=$(
             $POSTGRES_ID
 )
 
+log_section Creating config file
+CONF_DIR=$(mktemp -d)
 
 export DECKHAND_TEST_URL=http://localhost:9000
 export DATABASE_URL=postgres://deckhand:password@$POSTGRES_IP:$POSTGRES_PORT/deckhand
+# Used by Deckhand's initialization script to search for config files.
+export OS_DECKHAND_CONFIG_DIR=$CONF_DIR
 
-log_section Creating config file
+cp etc/deckhand/logging.conf.sample $CONF_DIR/logging.conf
-CONF_DIR=$(mktemp -d)
 
 cat <<EOCONF > $CONF_DIR/deckhand.conf
 [DEFAULT]
 debug = true
+log_config_append = $CONF_DIR/logging.conf
+log_file = deckhand.log
+log_dir = .
 use_stderr = true
-[barbican]
 
+[barbican]
 
 [database]
 # XXX For now, connection to postgres is not setup.
 #connection = $DATABASE_URL
 connection = sqlite://
 
-
 [keystone_authtoken]
 EOCONF