openstack/kolla-ansible
Code Issues Proposed changes

Stop using a global logger for all the things

Browse Source 
Instead of using the same logger for all the things
which makes it incredibly hard to figure out what the images
and there builds are doing; instead have it so that each
image gets its own logger which is then used by tasks that
process that image.

Each images logs now will (optionally) go to a logs directory
that can be more easily read and looked over and leaves
the main logger for informational/task kind of
output only.

Closes-Bug: #1586478

Change-Id: I939e073a2bc5ed8b5a1e969888fc743d80f468c9
This commit is contained in:
Joshua Harlow 2016-06-08 17:46:16 -07:00
parent 2cb0f445bb
commit 929d84b143
3 changed files with 96 additions and 95 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
kolla/common/config.py
View File

@ -144,6 +144,7 @@ _CLI_OPTS = [
help='Time in seconds after which any operation times out'), help='Time in seconds after which any operation times out'),
cfg.StrOpt('template-override', cfg.StrOpt('template-override',
help='Path to template override file'), help='Path to template override file'),
cfg.StrOpt('logs-dir', help='Path to logs directory'),
] ]
_BASE_OPTS = [ _BASE_OPTS = [

170
kolla/image/build.py
View File

@ -51,9 +51,29 @@ from kolla.common import config as common_config
from kolla.common import task from kolla.common import task
from kolla import version from kolla import version
logging.basicConfig()
LOG = logging.getLogger(__name__) def make_a_logger(conf=None, image_name=None):
LOG.setLevel(logging.INFO) if image_name:
log = logging.getLogger(".".join([__name__, image_name]))
else:
log = logging.getLogger(__name__)
if not log.handlers:
if conf is None or not conf.logs_dir or not image_name:
handler = logging.StreamHandler(sys.stdout)
else:
filename = os.path.join(conf.logs_dir, "%s.log" % image_name)
handler = logging.FileHandler(filename, delay=True)
handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT))
log.addHandler(handler)
if conf is not None and conf.debug:
log.setLevel(logging.DEBUG)
else:
log.setLevel(logging.INFO)
log.propagate = False
return log
LOG = make_a_logger()
class KollaDirNotFoundException(Exception): class KollaDirNotFoundException(Exception):
@ -90,33 +110,6 @@ STATUS_ERRORS = (STATUS_CONNECTION_ERROR, STATUS_PUSH_ERROR,
STATUS_ERROR, STATUS_PARENT_ERROR) STATUS_ERROR, STATUS_PARENT_ERROR)
class Recorder(object):
"""Recorder/buffer of (unicode) log lines for eventual display."""
def __init__(self):
self._lines = []
def write(self, text=""):
if isinstance(text, six.text_type):
self._lines.append(text)
elif isinstance(text, six.binary_type):
self._lines.append(text.decode('utf8'))
elif isinstance(text, Recorder):
self._lines.extend(text._lines)
else:
self.write(text=str(text))
def clear(self):
self._lines = []
def __iter__(self):
for line in self._lines:
yield line
def __str__(self):
return u"\n".join(self._lines)
@contextlib.contextmanager @contextlib.contextmanager
def join_many(threads): def join_many(threads):
try: try:
@ -138,7 +131,8 @@ def docker_client():
class Image(object): class Image(object):
def __init__(self, name, canonical_name, path, parent_name='', def __init__(self, name, canonical_name, path, parent_name='',
status=STATUS_UNPROCESSED, parent=None, source=None): status=STATUS_UNPROCESSED, parent=None,
source=None, logger=None):
self.name = name self.name = name
self.canonical_name = canonical_name self.canonical_name = canonical_name
self.path = path self.path = path
@ -146,11 +140,24 @@ class Image(object):
self.parent = parent self.parent = parent
self.source = source self.source = source
self.parent_name = parent_name self.parent_name = parent_name
self.logs = Recorder() if logger is None:
self.push_logs = Recorder() logger = make_a_logger(image_name=name)
self.logger = logger
self.children = [] self.children = []
self.plugins = [] self.plugins = []
def copy(self):
c = Image(self.name, self.canonical_name, self.path,
logger=self.logger, parent_name=self.parent_name,
status=self.status, parent=self.parent)
if self.source:
c.source = self.source.copy()
if self.children:
c.children = list(self.children)
if self.plugins:
c.plugins = list(self.plugins)
return c
def __repr__(self): def __repr__(self):
return ("Image(%s, %s, %s, parent_name=%s," return ("Image(%s, %s, %s, parent_name=%s,"
" status=%s, parent=%s, source=%s)") % ( " status=%s, parent=%s, source=%s)") % (
@ -184,6 +191,7 @@ class PushTask(task.Task):
self.dc = docker_client() self.dc = docker_client()
self.conf = conf self.conf = conf
self.image = image self.image = image
self.logger = image.logger
@property @property
def name(self): def name(self):
@ -191,38 +199,35 @@ class PushTask(task.Task):
def run(self): def run(self):
image = self.image image = self.image
self.logger.info('Trying to push the image')
try: try:
LOG.debug('%s:Try to push the image', image.name)
self.push_image(image) self.push_image(image)
except requests_exc.ConnectionError: except requests_exc.ConnectionError:
LOG.exception('%s:Make sure Docker is running and that you' self.logger.exception('Make sure Docker is running and that you'
' have the correct privileges to run Docker' ' have the correct privileges to run Docker'
' (root)', image.name) ' (root)')
image.status = STATUS_CONNECTION_ERROR image.status = STATUS_CONNECTION_ERROR
except Exception: except Exception:
LOG.exception('%s:Unknown error when pushing', image.name) self.logger.exception('Unknown error when pushing')
image.status = STATUS_PUSH_ERROR image.status = STATUS_PUSH_ERROR
finally: finally:
if (image.status not in STATUS_ERRORS if (image.status not in STATUS_ERRORS
and image.status != STATUS_UNPROCESSED): and image.status != STATUS_UNPROCESSED):
LOG.info('%s:Pushed successfully', image.name) self.logger.info('Pushed successfully')
self.success = True self.success = True
else: else:
self.success = False self.success = False
def push_image(self, image): def push_image(self, image):
image.push_logs.clear()
for response in self.dc.push(image.canonical_name, for response in self.dc.push(image.canonical_name,
stream=True, stream=True,
insecure_registry=True): insecure_registry=True):
stream = json.loads(response) stream = json.loads(response)
if 'stream' in stream: if 'stream' in stream:
image.push_logs.write(image.logs) self.logger.info(stream['stream'])
image.push_logs.write(stream['stream'])
LOG.info('%s', stream['stream'])
elif 'errorDetail' in stream: elif 'errorDetail' in stream:
image.status = STATUS_ERROR image.status = STATUS_ERROR
LOG.error(stream['errorDetail']['message']) self.logger.error(stream['errorDetail']['message'])
class BuildTask(task.Task): class BuildTask(task.Task):
@ -236,6 +241,7 @@ class BuildTask(task.Task):
self.push_queue = push_queue self.push_queue = push_queue
self.nocache = not conf.cache or conf.no_cache self.nocache = not conf.cache or conf.no_cache
self.forcerm = not conf.keep self.forcerm = not conf.keep
self.logger = image.logger
@property @property
def name(self): def name(self):
@ -266,23 +272,23 @@ class BuildTask(task.Task):
dest_archive = os.path.join(image.path, source['name'] + '-archive') dest_archive = os.path.join(image.path, source['name'] + '-archive')
if source.get('type') == 'url': if source.get('type') == 'url':
LOG.debug("%s:Getting archive from %s", image.name, self.logger.debug("Getting archive from %s", source['source'])
source['source'])
try: try:
r = requests.get(source['source'], timeout=self.conf.timeout) r = requests.get(source['source'], timeout=self.conf.timeout)
except requests_exc.Timeout: except requests_exc.Timeout:
LOG.exception('Request timed out while getting archive' self.logger.exception(
' from %s', source['source']) 'Request timed out while getting archive from %s',
source['source'])
image.status = STATUS_ERROR image.status = STATUS_ERROR
image.logs.clear()
return return
if r.status_code == 200: if r.status_code == 200:
with open(dest_archive, 'wb') as f: with open(dest_archive, 'wb') as f:
f.write(r.content) f.write(r.content)
else: else:
LOG.error('%s:Failed to download archive: status_code %s', self.logger.error(
image.name, r.status_code) 'Failed to download archive: status_code %s',
r.status_code)
image.status = STATUS_ERROR image.status = STATUS_ERROR
return return
@ -290,16 +296,15 @@ class BuildTask(task.Task):
clone_dir = '{}-{}'.format(dest_archive, clone_dir = '{}-{}'.format(dest_archive,
source['reference'].replace('/', '-')) source['reference'].replace('/', '-'))
try: try:
LOG.debug("%s:Cloning from %s", image.name, self.logger.debug("Cloning from %s", source['source'])
source['source'])
git.Git().clone(source['source'], clone_dir) git.Git().clone(source['source'], clone_dir)
git.Git(clone_dir).checkout(source['reference']) git.Git(clone_dir).checkout(source['reference'])
reference_sha = git.Git(clone_dir).rev_parse('HEAD') reference_sha = git.Git(clone_dir).rev_parse('HEAD')
LOG.debug("%s:Git checkout by reference %s (%s)", self.logger.debug("Git checkout by reference %s (%s)",
image.name, source['reference'], reference_sha) source['reference'], reference_sha)
except Exception as e: except Exception as e:
LOG.error("%s:Failed to get source from git", image.name) self.logger.error("Failed to get source from git", image.name)
LOG.error("%s:Error:%s", image.name, str(e)) self.logger.error("Error: %s", e)
# clean-up clone folder to retry # clean-up clone folder to retry
shutil.rmtree(clone_dir) shutil.rmtree(clone_dir)
image.status = STATUS_ERROR image.status = STATUS_ERROR
@ -309,7 +314,7 @@ class BuildTask(task.Task):
tar.add(clone_dir, arcname=os.path.basename(clone_dir)) tar.add(clone_dir, arcname=os.path.basename(clone_dir))
elif source.get('type') == 'local': elif source.get('type') == 'local':
LOG.debug("%s:Getting local archive from %s", image.name, self.logger.debug("Getting local archive from %s",
source['source']) source['source'])
if os.path.isdir(source['source']): if os.path.isdir(source['source']):
with tarfile.open(dest_archive, 'w') as tar: with tarfile.open(dest_archive, 'w') as tar:
@ -319,8 +324,7 @@ class BuildTask(task.Task):
shutil.copyfile(source['source'], dest_archive) shutil.copyfile(source['source'], dest_archive)
else: else:
LOG.error("%s:Wrong source type '%s'", image.name, self.logger.error("Wrong source type '%s'", source.get('type'))
source.get('type'))
image.status = STATUS_ERROR image.status = STATUS_ERROR
return return
@ -347,19 +351,19 @@ class BuildTask(task.Task):
return buildargs return buildargs
def builder(self, image): def builder(self, image):
LOG.debug('%s:Processing', image.name) self.logger.debug('Processing')
if image.status == STATUS_UNMATCHED: if image.status == STATUS_UNMATCHED:
return return
if (image.parent is not None and if (image.parent is not None and
image.parent.status in STATUS_ERRORS): image.parent.status in STATUS_ERRORS):
LOG.error('%s:Parent image error\'d with message "%s"', self.logger.error('Parent image error\'d with message "%s"',
image.name, image.parent.status) image.parent.status)
image.status = STATUS_PARENT_ERROR image.status = STATUS_PARENT_ERROR
return return
image.status = STATUS_BUILDING image.status = STATUS_BUILDING
LOG.info('%s:Building', image.name) self.logger.info('Building')
if image.source and 'source' in image.source: if image.source and 'source' in image.source:
self.process_source(image, image.source) self.process_source(image, image.source)
@ -382,10 +386,10 @@ class BuildTask(task.Task):
os.mkdir(plugins_path) os.mkdir(plugins_path)
except OSError as e: except OSError as e:
if e.errno == errno.EEXIST: if e.errno == errno.EEXIST:
LOG.info('Directory %s already exist. Skipping.', self.logger.info('Directory %s already exist. Skipping.',
plugins_path) plugins_path)
else: else:
LOG.error('Failed to create directory %s: %s', self.logger.error('Failed to create directory %s: %s',
plugins_path, e) plugins_path, e)
image.status = STATUS_CONNECTION_ERROR image.status = STATUS_CONNECTION_ERROR
return return
@ -396,7 +400,6 @@ class BuildTask(task.Task):
# Pull the latest image for the base distro only # Pull the latest image for the base distro only
pull = True if image.parent is None else False pull = True if image.parent is None else False
image.logs.clear()
buildargs = self.update_buildargs() buildargs = self.update_buildargs()
for response in self.dc.build(path=image.path, for response in self.dc.build(path=image.path,
tag=image.canonical_name, tag=image.canonical_name,
@ -408,23 +411,21 @@ class BuildTask(task.Task):
stream = json.loads(response.decode('utf-8')) stream = json.loads(response.decode('utf-8'))
if 'stream' in stream: if 'stream' in stream:
image.logs.write(stream['stream'])
for line in stream['stream'].split('\n'): for line in stream['stream'].split('\n'):
if line: if line:
LOG.info('%s:%s', image.name, line) self.logger.info('%s', line)
if 'errorDetail' in stream: if 'errorDetail' in stream:
image.status = STATUS_ERROR image.status = STATUS_ERROR
LOG.error('%s:Error\'d with the following message', self.logger.error('Error\'d with the following message')
image.name)
for line in stream['errorDetail']['message'].split('\n'): for line in stream['errorDetail']['message'].split('\n'):
if line: if line:
LOG.error('%s:%s', image.name, line) self.logger.error('%s', line)
return return
image.status = STATUS_BUILT image.status = STATUS_BUILT
LOG.info('%s:Built', image.name) self.logger.info('Built')
class WorkerThread(threading.Thread): class WorkerThread(threading.Thread):
@ -451,10 +452,10 @@ class WorkerThread(threading.Thread):
if self.should_stop: if self.should_stop:
break break
if attempt > 0: if attempt > 0:
LOG.debug("Attempting to run task %s for the %s time", LOG.info("Attempting to run task %s for the %s time",
task.name, attempt + 1) task.name, attempt + 1)
else: else:
LOG.debug("Attempting to run task %s for the first" LOG.info("Attempting to run task %s for the first"
" time", task.name) " time", task.name)
try: try:
task.run() task.run()
@ -467,7 +468,7 @@ class WorkerThread(threading.Thread):
task.reset() task.reset()
if task.success and not self.should_stop: if task.success and not self.should_stop:
for next_task in task.followups: for next_task in task.followups:
LOG.debug('Added next task %s to queue', LOG.info('Added next task %s to queue',
next_task.name) next_task.name)
self.queue.put(next_task) self.queue.put(next_task)
finally: finally:
@ -691,7 +692,7 @@ class KollaWorker(object):
image.parent.status != STATUS_MATCHED): image.parent.status != STATUS_MATCHED):
image = image.parent image = image.parent
image.status = STATUS_MATCHED image.status = STATUS_MATCHED
LOG.debug('%s:Matched regex', image.name) LOG.debug('Image %s matched regex', image.name)
else: else:
image.status = STATUS_UNMATCHED image.status = STATUS_UNMATCHED
else: else:
@ -704,26 +705,26 @@ class KollaWorker(object):
# help us debug and it will be extra helpful in the gate. # help us debug and it will be extra helpful in the gate.
for image in self.images: for image in self.images:
if image.status in STATUS_ERRORS: if image.status in STATUS_ERRORS:
LOG.debug("%s:Failed with the following logs", image.name) LOG.debug("Image %s failed", image.name)
for line in image.logs:
if line:
LOG.debug("%s:%s", image.name, line)
self.get_image_statuses() self.get_image_statuses()
if self.image_statuses_good: if self.image_statuses_good:
LOG.info("=========================")
LOG.info("Successfully built images") LOG.info("Successfully built images")
LOG.info("=========================") LOG.info("=========================")
for name in self.image_statuses_good.keys(): for name in self.image_statuses_good.keys():
LOG.info(name) LOG.info(name)
if self.image_statuses_bad: if self.image_statuses_bad:
LOG.info("===========================")
LOG.info("Images that failed to build") LOG.info("Images that failed to build")
LOG.info("===========================") LOG.info("===========================")
for name, status in self.image_statuses_bad.items(): for name, status in self.image_statuses_bad.items():
LOG.error('%s Failed with status: %s', name, status) LOG.error('%s Failed with status: %s', name, status)
if self.image_statuses_unmatched: if self.image_statuses_unmatched:
LOG.debug("=====================================")
LOG.debug("Images not matched for build by regex") LOG.debug("Images not matched for build by regex")
LOG.debug("=====================================") LOG.debug("=====================================")
for name in self.image_statuses_unmatched.keys(): for name in self.image_statuses_unmatched.keys():
@ -752,7 +753,7 @@ class KollaWorker(object):
installation = dict() installation = dict()
# NOTE(jeffrey4l): source is not needed when the type is None # NOTE(jeffrey4l): source is not needed when the type is None
if self.conf._get('type', self.conf._get_group(section)) is None: if self.conf._get('type', self.conf._get_group(section)) is None:
LOG.debug('%s:No source location found', section) LOG.debug('No source location found in section %s', section)
else: else:
installation['type'] = self.conf[section]['type'] installation['type'] = self.conf[section]['type']
installation['source'] = self.conf[section]['location'] installation['source'] = self.conf[section]['location']
@ -770,7 +771,8 @@ class KollaWorker(object):
canonical_name = (self.namespace + '/' + self.image_prefix + canonical_name = (self.namespace + '/' + self.image_prefix +
image_name + ':' + self.tag) image_name + ':' + self.tag)
image = Image(image_name, canonical_name, path, image = Image(image_name, canonical_name, path,
parent_name=content.split(' ')[1].split('\n')[0]) parent_name=content.split(' ')[1].split('\n')[0],
logger=make_a_logger(self.conf, image_name))
if self.install_type == 'source': if self.install_type == 'source':
# NOTE(jeffrey4l): register the opts if the section didn't # NOTE(jeffrey4l): register the opts if the section didn't
@ -862,7 +864,7 @@ class KollaWorker(object):
for image in self.images: for image in self.images:
if image.parent is None: if image.parent is None:
queue.put(BuildTask(self.conf, image, push_queue)) queue.put(BuildTask(self.conf, image, push_queue))
LOG.debug('%s:Added image to queue', image.name) LOG.info('Added image %s to queue', image.name)
return queue return queue
@ -894,7 +896,7 @@ def run_build():
if conf.save_dependency: if conf.save_dependency:
kolla.save_dependency(conf.save_dependency) kolla.save_dependency(conf.save_dependency)
LOG.info('Docker images dependency is saved in %s', LOG.info('Docker images dependency are saved in %s',
conf.save_dependency) conf.save_dependency)
return return
if conf.list_images: if conf.list_images:

6
kolla/tests/test_build.py
View File

@ -10,7 +10,6 @@
# See the License for the specific language governing permissions and # See the License for the specific language governing permissions and
# limitations under the License. # limitations under the License.
import copy
import fixtures import fixtures
import itertools import itertools
import mock import mock
@ -31,7 +30,7 @@ class TasksTest(base.TestCase):
def setUp(self): def setUp(self):
super(TasksTest, self).setUp() super(TasksTest, self).setUp()
self.image = copy.deepcopy(FAKE_IMAGE) self.image = FAKE_IMAGE.copy()
# NOTE(jeffrey4l): use a real, temporary dir # NOTE(jeffrey4l): use a real, temporary dir
self.image.path = self.useFixture(fixtures.TempDir()).path self.image.path = self.useFixture(fixtures.TempDir()).path
@ -129,7 +128,6 @@ class TasksTest(base.TestCase):
self.assertIsNone(get_result) self.assertIsNone(get_result)
self.assertEqual(self.image.status, build.STATUS_ERROR) self.assertEqual(self.image.status, build.STATUS_ERROR)
self.assertEqual(str(self.image.logs), str())
mock_get.assert_called_once_with(self.image.source['source'], mock_get.assert_called_once_with(self.image.source['source'],
timeout=120) timeout=120)
@ -142,7 +140,7 @@ class KollaWorkerTest(base.TestCase):
def setUp(self): def setUp(self):
super(KollaWorkerTest, self).setUp() super(KollaWorkerTest, self).setUp()
image = copy.deepcopy(FAKE_IMAGE) image = FAKE_IMAGE.copy()
image.status = None image.status = None
self.images = [image] self.images = [image]