From 929d84b143e723735817c88efc5df8d6239c6991 Mon Sep 17 00:00:00 2001 From: Joshua Harlow Date: Wed, 8 Jun 2016 17:46:16 -0700 Subject: [PATCH] Stop using a global logger for all the things 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 --- kolla/common/config.py | 1 + kolla/image/build.py | 184 +++++++++++++++++++------------------- kolla/tests/test_build.py | 6 +- 3 files changed, 96 insertions(+), 95 deletions(-) diff --git a/kolla/common/config.py b/kolla/common/config.py index b1f2fdea16..ea2b9b97b9 100644 --- a/kolla/common/config.py +++ b/kolla/common/config.py @@ -144,6 +144,7 @@ _CLI_OPTS = [ help='Time in seconds after which any operation times out'), cfg.StrOpt('template-override', help='Path to template override file'), + cfg.StrOpt('logs-dir', help='Path to logs directory'), ] _BASE_OPTS = [ diff --git a/kolla/image/build.py b/kolla/image/build.py index 301dea0d1c..8558792aed 100755 --- a/kolla/image/build.py +++ b/kolla/image/build.py @@ -51,9 +51,29 @@ from kolla.common import config as common_config from kolla.common import task from kolla import version -logging.basicConfig() -LOG = logging.getLogger(__name__) -LOG.setLevel(logging.INFO) + +def make_a_logger(conf=None, image_name=None): + 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): @@ -90,33 +110,6 @@ STATUS_ERRORS = (STATUS_CONNECTION_ERROR, STATUS_PUSH_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 def join_many(threads): try: @@ -138,7 +131,8 @@ def docker_client(): class Image(object): 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.canonical_name = canonical_name self.path = path @@ -146,11 +140,24 @@ class Image(object): self.parent = parent self.source = source self.parent_name = parent_name - self.logs = Recorder() - self.push_logs = Recorder() + if logger is None: + logger = make_a_logger(image_name=name) + self.logger = logger self.children = [] 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): return ("Image(%s, %s, %s, parent_name=%s," " status=%s, parent=%s, source=%s)") % ( @@ -184,6 +191,7 @@ class PushTask(task.Task): self.dc = docker_client() self.conf = conf self.image = image + self.logger = image.logger @property def name(self): @@ -191,38 +199,35 @@ class PushTask(task.Task): def run(self): image = self.image + self.logger.info('Trying to push the image') try: - LOG.debug('%s:Try to push the image', image.name) self.push_image(image) except requests_exc.ConnectionError: - LOG.exception('%s:Make sure Docker is running and that you' - ' have the correct privileges to run Docker' - ' (root)', image.name) + self.logger.exception('Make sure Docker is running and that you' + ' have the correct privileges to run Docker' + ' (root)') image.status = STATUS_CONNECTION_ERROR except Exception: - LOG.exception('%s:Unknown error when pushing', image.name) + self.logger.exception('Unknown error when pushing') image.status = STATUS_PUSH_ERROR finally: if (image.status not in STATUS_ERRORS and image.status != STATUS_UNPROCESSED): - LOG.info('%s:Pushed successfully', image.name) + self.logger.info('Pushed successfully') self.success = True else: self.success = False def push_image(self, image): - image.push_logs.clear() for response in self.dc.push(image.canonical_name, stream=True, insecure_registry=True): stream = json.loads(response) if 'stream' in stream: - image.push_logs.write(image.logs) - image.push_logs.write(stream['stream']) - LOG.info('%s', stream['stream']) + self.logger.info(stream['stream']) elif 'errorDetail' in stream: image.status = STATUS_ERROR - LOG.error(stream['errorDetail']['message']) + self.logger.error(stream['errorDetail']['message']) class BuildTask(task.Task): @@ -236,6 +241,7 @@ class BuildTask(task.Task): self.push_queue = push_queue self.nocache = not conf.cache or conf.no_cache self.forcerm = not conf.keep + self.logger = image.logger @property def name(self): @@ -266,23 +272,23 @@ class BuildTask(task.Task): dest_archive = os.path.join(image.path, source['name'] + '-archive') if source.get('type') == 'url': - LOG.debug("%s:Getting archive from %s", image.name, - source['source']) + self.logger.debug("Getting archive from %s", source['source']) try: r = requests.get(source['source'], timeout=self.conf.timeout) except requests_exc.Timeout: - LOG.exception('Request timed out while getting archive' - ' from %s', source['source']) + self.logger.exception( + 'Request timed out while getting archive from %s', + source['source']) image.status = STATUS_ERROR - image.logs.clear() return if r.status_code == 200: with open(dest_archive, 'wb') as f: f.write(r.content) else: - LOG.error('%s:Failed to download archive: status_code %s', - image.name, r.status_code) + self.logger.error( + 'Failed to download archive: status_code %s', + r.status_code) image.status = STATUS_ERROR return @@ -290,16 +296,15 @@ class BuildTask(task.Task): clone_dir = '{}-{}'.format(dest_archive, source['reference'].replace('/', '-')) try: - LOG.debug("%s:Cloning from %s", image.name, - source['source']) + self.logger.debug("Cloning from %s", source['source']) git.Git().clone(source['source'], clone_dir) git.Git(clone_dir).checkout(source['reference']) reference_sha = git.Git(clone_dir).rev_parse('HEAD') - LOG.debug("%s:Git checkout by reference %s (%s)", - image.name, source['reference'], reference_sha) + self.logger.debug("Git checkout by reference %s (%s)", + source['reference'], reference_sha) except Exception as e: - LOG.error("%s:Failed to get source from git", image.name) - LOG.error("%s:Error:%s", image.name, str(e)) + self.logger.error("Failed to get source from git", image.name) + self.logger.error("Error: %s", e) # clean-up clone folder to retry shutil.rmtree(clone_dir) image.status = STATUS_ERROR @@ -309,8 +314,8 @@ class BuildTask(task.Task): tar.add(clone_dir, arcname=os.path.basename(clone_dir)) elif source.get('type') == 'local': - LOG.debug("%s:Getting local archive from %s", image.name, - source['source']) + self.logger.debug("Getting local archive from %s", + source['source']) if os.path.isdir(source['source']): with tarfile.open(dest_archive, 'w') as tar: tar.add(source['source'], @@ -319,8 +324,7 @@ class BuildTask(task.Task): shutil.copyfile(source['source'], dest_archive) else: - LOG.error("%s:Wrong source type '%s'", image.name, - source.get('type')) + self.logger.error("Wrong source type '%s'", source.get('type')) image.status = STATUS_ERROR return @@ -347,19 +351,19 @@ class BuildTask(task.Task): return buildargs def builder(self, image): - LOG.debug('%s:Processing', image.name) + self.logger.debug('Processing') if image.status == STATUS_UNMATCHED: return if (image.parent is not None and image.parent.status in STATUS_ERRORS): - LOG.error('%s:Parent image error\'d with message "%s"', - image.name, image.parent.status) + self.logger.error('Parent image error\'d with message "%s"', + image.parent.status) image.status = STATUS_PARENT_ERROR return image.status = STATUS_BUILDING - LOG.info('%s:Building', image.name) + self.logger.info('Building') if image.source and 'source' in image.source: self.process_source(image, image.source) @@ -382,11 +386,11 @@ class BuildTask(task.Task): os.mkdir(plugins_path) except OSError as e: if e.errno == errno.EEXIST: - LOG.info('Directory %s already exist. Skipping.', - plugins_path) + self.logger.info('Directory %s already exist. Skipping.', + plugins_path) else: - LOG.error('Failed to create directory %s: %s', - plugins_path, e) + self.logger.error('Failed to create directory %s: %s', + plugins_path, e) image.status = STATUS_CONNECTION_ERROR return with tarfile.open(os.path.join(image.path, 'plugins-archive'), @@ -396,7 +400,6 @@ class BuildTask(task.Task): # Pull the latest image for the base distro only pull = True if image.parent is None else False - image.logs.clear() buildargs = self.update_buildargs() for response in self.dc.build(path=image.path, tag=image.canonical_name, @@ -408,23 +411,21 @@ class BuildTask(task.Task): stream = json.loads(response.decode('utf-8')) if 'stream' in stream: - image.logs.write(stream['stream']) for line in stream['stream'].split('\n'): if line: - LOG.info('%s:%s', image.name, line) + self.logger.info('%s', line) if 'errorDetail' in stream: image.status = STATUS_ERROR - LOG.error('%s:Error\'d with the following message', - image.name) + self.logger.error('Error\'d with the following message') for line in stream['errorDetail']['message'].split('\n'): if line: - LOG.error('%s:%s', image.name, line) + self.logger.error('%s', line) return image.status = STATUS_BUILT - LOG.info('%s:Built', image.name) + self.logger.info('Built') class WorkerThread(threading.Thread): @@ -451,11 +452,11 @@ class WorkerThread(threading.Thread): if self.should_stop: break if attempt > 0: - LOG.debug("Attempting to run task %s for the %s time", - task.name, attempt + 1) + LOG.info("Attempting to run task %s for the %s time", + task.name, attempt + 1) else: - LOG.debug("Attempting to run task %s for the first" - " time", task.name) + LOG.info("Attempting to run task %s for the first" + " time", task.name) try: task.run() if task.success: @@ -467,8 +468,8 @@ class WorkerThread(threading.Thread): task.reset() if task.success and not self.should_stop: for next_task in task.followups: - LOG.debug('Added next task %s to queue', - next_task.name) + LOG.info('Added next task %s to queue', + next_task.name) self.queue.put(next_task) finally: self.queue.task_done() @@ -691,7 +692,7 @@ class KollaWorker(object): image.parent.status != STATUS_MATCHED): image = image.parent image.status = STATUS_MATCHED - LOG.debug('%s:Matched regex', image.name) + LOG.debug('Image %s matched regex', image.name) else: image.status = STATUS_UNMATCHED else: @@ -704,26 +705,26 @@ class KollaWorker(object): # help us debug and it will be extra helpful in the gate. for image in self.images: if image.status in STATUS_ERRORS: - LOG.debug("%s:Failed with the following logs", image.name) - for line in image.logs: - if line: - LOG.debug("%s:%s", image.name, line) + LOG.debug("Image %s failed", image.name) self.get_image_statuses() if self.image_statuses_good: + LOG.info("=========================") LOG.info("Successfully built images") LOG.info("=========================") for name in self.image_statuses_good.keys(): LOG.info(name) if self.image_statuses_bad: + LOG.info("===========================") LOG.info("Images that failed to build") LOG.info("===========================") for name, status in self.image_statuses_bad.items(): LOG.error('%s Failed with status: %s', name, status) if self.image_statuses_unmatched: + LOG.debug("=====================================") LOG.debug("Images not matched for build by regex") LOG.debug("=====================================") for name in self.image_statuses_unmatched.keys(): @@ -752,7 +753,7 @@ class KollaWorker(object): installation = dict() # NOTE(jeffrey4l): source is not needed when the type 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: installation['type'] = self.conf[section]['type'] installation['source'] = self.conf[section]['location'] @@ -770,7 +771,8 @@ class KollaWorker(object): canonical_name = (self.namespace + '/' + self.image_prefix + image_name + ':' + self.tag) 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': # NOTE(jeffrey4l): register the opts if the section didn't @@ -862,7 +864,7 @@ class KollaWorker(object): for image in self.images: if image.parent is None: 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 @@ -894,7 +896,7 @@ def run_build(): if 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) return if conf.list_images: diff --git a/kolla/tests/test_build.py b/kolla/tests/test_build.py index 98ffebf998..92962913a4 100644 --- a/kolla/tests/test_build.py +++ b/kolla/tests/test_build.py @@ -10,7 +10,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import copy import fixtures import itertools import mock @@ -31,7 +30,7 @@ class TasksTest(base.TestCase): def setUp(self): super(TasksTest, self).setUp() - self.image = copy.deepcopy(FAKE_IMAGE) + self.image = FAKE_IMAGE.copy() # NOTE(jeffrey4l): use a real, temporary dir self.image.path = self.useFixture(fixtures.TempDir()).path @@ -129,7 +128,6 @@ class TasksTest(base.TestCase): self.assertIsNone(get_result) 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'], timeout=120) @@ -142,7 +140,7 @@ class KollaWorkerTest(base.TestCase): def setUp(self): super(KollaWorkerTest, self).setUp() - image = copy.deepcopy(FAKE_IMAGE) + image = FAKE_IMAGE.copy() image.status = None self.images = [image]