switch structlog out for oslo.log

requirements.txt

@@ -5,7 +5,6 @@ wsgiref>=0.1.2
 pecan>=0.4.5
 WSME>=0.6
 six>=1.5.2
-structlog==0.4.1
 oslo.config==1.2.1
 Babel==1.3
 iso8601==0.1.10

teeth_agent/agent.py

@@ -21,7 +21,6 @@ import time
 
 import pkg_resources
 from stevedore import driver
-import structlog
 from wsgiref import simple_server
 
 from teeth_agent.api import app
@@ -29,9 +28,15 @@ from teeth_agent import base
 from teeth_agent import encoding
 from teeth_agent import errors
 from teeth_agent import hardware
+from teeth_agent.openstack.common import log
 from teeth_agent import overlord_agent_api
 
 
+def _time():
+    """Wraps time.time() for simpler testing."""
+    return time.time()
+
+
 class TeethAgentStatus(encoding.Serializable):
     def __init__(self, mode, started_at, version):
         self.mode = mode
@@ -66,7 +71,7 @@ class TeethAgentHeartbeater(threading.Thread):
         self.agent = agent
         self.hardware = hardware.get_manager()
         self.api = overlord_agent_api.APIClient(agent.api_url)
-        self.log = structlog.get_logger(api_url=agent.api_url)
+        self.log = log.getLogger(__name__)
         self.stop_event = threading.Event()
         self.error_delay = self.initial_delay
 
@@ -79,8 +84,9 @@ class TeethAgentHeartbeater(threading.Thread):
             next_heartbeat_by = self.do_heartbeat()
             interval_multiplier = random.uniform(self.min_jitter_multiplier,
                                                  self.max_jitter_multiplier)
-            interval = (next_heartbeat_by - time.time()) * interval_multiplier
+            interval = (next_heartbeat_by - _time()) * interval_multiplier
-            self.log.info('sleeping before next heartbeat', interval=interval)
+            log_msg = 'sleeping before next heartbeat, interval: {0}'
+            self.log.info(log_msg.format(interval))
 
     def do_heartbeat(self):
         try:
@@ -91,8 +97,9 @@ class TeethAgentHeartbeater(threading.Thread):
             self.error_delay = self.initial_delay
             self.log.info('heartbeat successful')
         except Exception as e:
-            self.log.error('error sending heartbeat', exception=e)
+            self.log.error('error sending heartbeat')
-            deadline = time.time() + self.error_delay
+            self.log.exception(e)
+            deadline = _time() + self.error_delay
             self.error_delay = min(self.error_delay * self.backoff_factor,
                                    self.max_delay)
             pass
@@ -117,7 +124,7 @@ class TeethAgent(object):
         self.heartbeater = TeethAgentHeartbeater(self)
         self.hardware = hardware.get_manager()
         self.command_lock = threading.Lock()
-        self.log = structlog.get_logger()
+        self.log = log.getLogger(__name__)
         self.started_at = None
 
     def get_mode_name(self):
@@ -197,7 +204,7 @@ class TeethAgent(object):
 
     def run(self):
         """Run the Teeth Agent."""
-        self.started_at = time.time()
+        self.started_at = _time()
         self.heartbeater.start()
         wsgi = simple_server.make_server(
             self.listen_address[0],
@@ -208,7 +215,8 @@ class TeethAgent(object):
         try:
             wsgi.serve_forever()
         except BaseException as e:
-            self.log.error('shutting down', exception=e)
+            self.log.error('shutting down')
+            self.log.exception(e)
 
         self.heartbeater.stop()
 

teeth_agent/base.py

@@ -17,10 +17,10 @@ limitations under the License.
 import threading
 import uuid
 
-import structlog
 
 from teeth_agent import encoding
 from teeth_agent import errors
+from teeth_agent.openstack.common import log
 
 
 class AgentCommandStatus(object):
@@ -117,7 +117,7 @@ class AsyncCommandResult(BaseCommandResult):
 class BaseAgentMode(object):
     def __init__(self, name):
         super(BaseAgentMode, self).__init__()
-        self.log = structlog.get_logger(agent_mode=name)
+        self.log = log.getLogger(__name__)
         self.name = name
         self.command_map = {}
 

teeth_agent/cmd/agent.py

@@ -17,7 +17,6 @@ limitations under the License.
 import argparse
 
 from teeth_agent import agent
-from teeth_agent import logging
 
 
 def run():
@@ -44,7 +43,6 @@ def run():
                         help='The external IP address to advertise to ironic')
 
     args = parser.parse_args()
-    logging.configure()
     agent.build_agent(args.api_url,
                       args.listen_host,
                       args.listen_port,

teeth_agent/hardware.py

@@ -20,9 +20,9 @@ import os
 import subprocess
 
 import stevedore
-import structlog
 
 from teeth_agent import encoding
+from teeth_agent.openstack.common import log
 
 _global_manager = None
 
@@ -162,7 +162,7 @@ def get_manager():
     global _global_manager
 
     if not _global_manager:
-        log = structlog.get_logger()
+        LOG = log.getLogger()
         extension_manager = stevedore.ExtensionManager(
             namespace='teeth_agent.hardware_managers',
             invoke_on_load=True)
@@ -175,8 +175,8 @@ def get_manager():
         if preferred_manager.evaluate_hardware_support() <= 0:
             raise RuntimeError('No suitable HardwareManager could be found')
 
-        log.info('selected hardware manager',
+        LOG.info('selected hardware manager {0}'.format(
-                 manager_name=preferred_extension.entry_point_target)
+                 preferred_extension.entry_point_target))
 
         _global_manager = preferred_manager
 

teeth_agent/logging.py

@@ -1,72 +0,0 @@
-"""
-Copyright 2013 Rackspace, Inc.
-
-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 string
-
-import structlog
-
-import traceback
-
-EXCEPTION_LOG_METHODS = ['error']
-
-
-def _capture_stack_trace(logger, method, event):
-    if method in EXCEPTION_LOG_METHODS:
-        event['exception'] = traceback.format_exc()
-
-    return event
-
-
-def _format_event(logger, method, event):
-    """Formats the log message using keyword args.
-    log('hello {keyword}', keyword='world') should log: "hello world"
-    Removes the keywords used for formatting from the logged message.
-    Throws a KeyError if the log message requires formatting but doesn't
-    have enough keys to format.
-    """
-    if 'event' not in event:
-        # nothing to format
-        return event
-    # Get a list of fields that need to be filled.
-    formatter = string.Formatter()
-    try:
-        formatted = formatter.format(event['event'], **event)
-    except KeyError:
-        keys = formatter.parse(event['event'])
-        # index 1 is the key name
-        keys = [item[1] for item in keys]
-        missing_keys = list(set(keys) - set(event))
-        raise KeyError("Log formatter missing keys: {}, cannot format."
-                       .format(missing_keys))
-    event['event'] = formatted
-    return event
-
-
-def configure(pretty=False):
-    processors = [
-        _capture_stack_trace,
-        _format_event,
-    ]
-
-    if pretty:
-        processors.append(structlog.processors.ExceptionPrettyPrinter())
-        processors.append(structlog.processors.KeyValueRenderer())
-    else:
-        processors.append(structlog.processors.JSONRenderer())
-
-    structlog.configure(
-        processors=processors
-    )

teeth_agent/standby.py

@@ -17,7 +17,6 @@ limitations under the License.
 import hashlib
 import os
 import requests
-import structlog
 import subprocess
 import time
 
@@ -26,8 +25,9 @@ from teeth_agent import configdrive
 from teeth_agent import decorators
 from teeth_agent import errors
 from teeth_agent import hardware
+from teeth_agent.openstack.common import log
 
-log = structlog.get_logger()
+LOG = log.getLogger(__name__)
 
 
 def _configdrive_location():
@@ -49,29 +49,31 @@ def _write_image(image_info, device):
 
     script = _path_to_script('shell/write_image.sh')
     command = ['/bin/bash', script, image, device]
-    log.info('Writing image', command=' '.join(command))
+    LOG.info('Writing image with command: {0}'.format(' '.join(command)))
     exit_code = subprocess.call(command)
     if exit_code != 0:
         raise errors.ImageWriteError(exit_code, device)
     totaltime = time.time() - starttime
-    log.info('Image written', device=device, seconds=totaltime, image=image)
+    LOG.info('Image {0} written to device {1} in {2} seconds'.format(
+             image, device, totaltime))
 
 
 def _copy_configdrive_to_disk(configdrive_dir, device):
     starttime = time.time()
     script = _path_to_script('shell/copy_configdrive_to_disk.sh')
     command = ['/bin/bash', script, configdrive_dir, device]
-    log.info('copying configdrive to disk', command=' '.join(command))
+    LOG.info('copying configdrive to disk with command {0}'.format(
+             ' '.join(command)))
     exit_code = subprocess.call(command)
 
     if exit_code != 0:
         raise errors.ConfigDriveWriteError(exit_code, device)
 
     totaltime = time.time() - starttime
-    log.info('configdrive copied',
+    LOG.info('configdrive copied from {0} to {1} in {2} seconds'.format(
-             from_directory=configdrive_dir,
+             configdrive_dir,
-             device=device,
+             device,
-             seconds=totaltime)
+             totaltime))
 
 
 def _request_url(image_info, url):
@@ -86,11 +88,12 @@ def _download_image(image_info):
     resp = None
     for url in image_info['urls']:
         try:
-            log.info("Attempting to download image", url=url)
+            LOG.info("Attempting to download image from {0}".format(url))
             resp = _request_url(image_info, url)
         except errors.ImageDownloadError:
             failtime = time.time() - starttime
-            log.warning("Image download failed", url=url, seconds=failtime)
+            log_msg = "Image download failed. URL: {0}; time: {1} seconds"
+            LOG.warning(log_msg.format(url, failtime))
             continue
         else:
             break
@@ -106,7 +109,8 @@ def _download_image(image_info):
             raise errors.ImageDownloadError(image_info['id'])
 
     totaltime = time.time() - starttime
-    log.info("Image downloaded", image=image_location, seconds=totaltime)
+    LOG.info("Image downloaded from {0} in {1} seconds".format(image_location,
+                                                               totaltime))
 
     if not _verify_image(image_info, image_location):
         raise errors.ImageChecksumError(image_info['id'])
@@ -118,19 +122,16 @@ def _verify_image(image_info, image_location):
         algo = getattr(hashlib, k, None)
         if algo is None:
             continue
-        log.debug('Verifying image',
+        log_msg = 'Verifying image at {0} with algorithm {1} against hash {2}'
-                  image=image_location,
+        LOG.debug(log_msg.format(image_location, k, v))
-                  algo=k,
-                  passed_hash=v)
         hash_ = algo(open(image_location).read()).hexdigest()
         if hash_ == v:
             return True
         else:
-            log.warning('Image verification failed',
+            log_msg = ('Image verification failed. Location: {0};'
-                        image=image_location,
+                       'algorithm: {1}; image hash: {2};'
-                        algo=k,
+                       'verification hash: {3}')
-                        imagehash=hash_,
+            LOG.warning(log_msg.format(image_location, k, hash_, v))
-                        passed_hash=v)
     return False
 
 
@@ -185,14 +186,14 @@ class StandbyMode(base.BaseAgentMode):
             _write_image(image_info, device)
             self.cached_image_id = image_info['id']
 
-        log.debug('Writing configdrive', location=location)
+        LOG.debug('Writing configdrive to {0}'.format(location))
         configdrive.write_configdrive(location, metadata, files)
         _copy_configdrive_to_disk(location, device)
 
     @decorators.async_command()
     def run_image(self, command_name):
         script = _path_to_script('shell/reboot.sh')
-        log.info('Rebooting system')
+        LOG.info('Rebooting system')
         command = ['/bin/bash', script]
         # this should never return if successful
         exit_code = subprocess.call(command)

teeth_agent/tests/agent.py

@@ -53,7 +53,7 @@ class TestHeartbeater(unittest.TestCase):
             hardware.HardwareManager)
         self.heartbeater.stop_event = mock.Mock()
 
-    @mock.patch('time.time')
+    @mock.patch('teeth_agent.agent._time')
     @mock.patch('random.uniform')
     def test_heartbeat(self, mocked_uniform, mocked_time):
         time_responses = []

teeth_agent/tests/logging.py

@@ -1,44 +0,0 @@
-"""
-Copyright 2013 Rackspace, Inc.
-
-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 structlog
-import unittest
-
-import teeth_agent.logging
-
-
-def _return_event_processor(logger, method, event):
-    return event['event']
-
-
-class EventLogger(unittest.TestCase):
-    def test_format_event_basic(self):
-        processors = [teeth_agent.logging._format_event,
-                      _return_event_processor]
-        structlog.configure(processors=processors)
-        log = structlog.wrap_logger(structlog.ReturnLogger())
-        logged_msg = log.msg("hello {word}", word='world')
-        self.assertEqual(logged_msg, "hello world")
-
-    def test_no_format_keys(self):
-        """Check that we get an exception if you don't provide enough keys to
-        format a log message requiring format
-        """
-        processors = [teeth_agent.logging._format_event,
-                      _return_event_processor]
-        structlog.configure(processors=processors)
-        log = structlog.wrap_logger(structlog.ReturnLogger())
-        self.assertRaises(KeyError, log.msg, "hello {word}")

tox.ini

@@ -16,3 +16,6 @@ commands =
 [testenv:devenv]
 envdir = devenv
 usedevelop = True
+
+[flake8]
+exclude=*openstack/common*