openstack/kolla
Code Issues Proposed changes

Merge "Stop using a global logger for all the things"

Browse Source
This commit is contained in:
Jenkins 2016-06-27 06:48:07 +00:00 committed by Gerrit Code Review
commit 01d183da27
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

@ -145,6 +145,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

@ -53,9 +53,29 @@ from kolla.common import task
from kolla.template import filters as jinja_filters from kolla.template import filters as jinja_filters
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):
@ -92,33 +112,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:
@ -140,7 +133,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
@ -148,11 +142,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)") % (
@ -186,6 +193,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):
@ -193,38 +201,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):
@ -238,6 +243,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):
@ -268,23 +274,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
@ -292,16 +298,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
@ -311,7 +316,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:
@ -321,8 +326,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
@ -349,19 +353,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)
@ -384,10 +388,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
@ -398,7 +402,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,
@ -410,23 +413,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):
@ -453,10 +454,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()
@ -469,7 +470,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:
@ -707,7 +708,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:
@ -720,26 +721,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():
@ -768,7 +769,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']
@ -786,7 +787,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
@ -878,7 +880,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
@ -910,7 +912,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]