From 205041a826fc9343641f87f53bc0e797a7e3b8bf Mon Sep 17 00:00:00 2001 From: Vladimir Kozhukalov Date: Tue, 14 Oct 2014 14:51:59 +0400 Subject: [PATCH] Added some additional log messages in fuel_agent Change-Id: I585b0e805364433d4d3f877e9ee29f0b74f1fed9 Implements: blueprint image-based-provisioning --- fuel_agent/drivers/nailgun.py | 64 ++++++++++++++++++++++++++++++ fuel_agent/manager.py | 32 ++++++++++----- fuel_agent/utils/artifact_utils.py | 11 +++++ 3 files changed, 97 insertions(+), 10 deletions(-) diff --git a/fuel_agent/drivers/nailgun.py b/fuel_agent/drivers/nailgun.py index 7db8b7d..fc0dcf8 100644 --- a/fuel_agent/drivers/nailgun.py +++ b/fuel_agent/drivers/nailgun.py @@ -118,6 +118,7 @@ class Nailgun(object): return self._get_partition_count('ceph') def partition_scheme(self): + LOG.debug('--- Preparing partition scheme ---') data = self.partition_data() ks_spaces_validator.validate(data) partition_scheme = objects.PartitionScheme() @@ -126,21 +127,38 @@ class Nailgun(object): journals_left = ceph_osds ceph_journals = self._num_ceph_journals() + LOG.debug('Looping over all disks in provision data') for disk in self.ks_disks: + LOG.debug('Processing disk %s' % disk['name']) + LOG.debug('Adding gpt table on disk %s' % disk['name']) parted = partition_scheme.add_parted( name=self._disk_dev(disk), label='gpt') # we install bootloader on every disk + LOG.debug('Adding bootloader stage0 on disk %s' % disk['name']) parted.install_bootloader = True # legacy boot partition + LOG.debug('Adding bios_grub partition on disk %s: size=24' % + disk['name']) parted.add_partition(size=24, flags=['bios_grub']) # uefi partition (for future use) + LOG.debug('Adding UEFI partition on disk %s: size=200' % + disk['name']) parted.add_partition(size=200) + LOG.debug('Looping over all volumes on disk %s' % disk['name']) for volume in disk['volumes']: + LOG.debug('Processing volume: ' + 'name=%s type=%s size=%s mount=%s vg=%s' % + (volume.get('name'), volume.get('type'), + volume.get('size'), volume.get('mount'), + volume.get('vg'))) if volume['size'] <= 0: + LOG.debug('Volume size is zero. Skipping.') continue if volume.get('name') == 'cephjournal': + LOG.debug('Volume seems to be a CEPH journal volume. ' + 'Special procedure is supposed to be applied.') # We need to allocate a journal partition for each ceph OSD # Determine the number of journal partitions we need on # each device @@ -164,25 +182,42 @@ class Nailgun(object): for i in range(0, end): journals_left -= 1 if volume['type'] == 'partition': + LOG.debug('Adding CEPH journal partition on ' + 'disk %s: size=%s' % + (disk['name'], size)) prt = parted.add_partition(size=size) + LOG.debug('Partition name: %s' % prt.name) if 'partition_guid' in volume: + LOG.debug('Setting partition GUID: %s' % + volume['partition_guid']) prt.set_guid(volume['partition_guid']) continue if volume['type'] in ('partition', 'pv', 'raid'): + LOG.debug('Adding partition on disk %s: size=%s' % + (disk['name'], volume['size'])) prt = parted.add_partition(size=volume['size']) + LOG.debug('Partition name: %s' % prt.name) if volume['type'] == 'partition': if 'partition_guid' in volume: + LOG.debug('Setting partition GUID: %s' % + volume['partition_guid']) prt.set_guid(volume['partition_guid']) if 'mount' in volume and volume['mount'] != 'none': + LOG.debug('Adding file system on partition: ' + 'mount=%s type=%s' % + (volume['mount'], + volume.get('file_system', 'xfs'))) partition_scheme.add_fs( device=prt.name, mount=volume['mount'], fs_type=volume.get('file_system', 'xfs'), fs_label=self._getlabel(volume.get('disk_label'))) if volume['type'] == 'pv': + LOG.debug('Creating pv on partition: pv=%s vg=%s' % + (prt.name, volume['vg'])) lvm_meta_size = volume.get('lvm_meta_size', 64) # The reason for that is to make sure that # there will be enough space for creating logical volumes. @@ -209,6 +244,8 @@ class Nailgun(object): if volume['type'] == 'raid': if 'mount' in volume and volume['mount'] != 'none': + LOG.debug('Attaching partition to RAID ' + 'by its mount point %s' % volume['mount']) partition_scheme.md_attach_by_mount( device=prt.name, mount=volume['mount'], fs_type=volume.get('file_system', 'xfs'), @@ -216,32 +253,49 @@ class Nailgun(object): # this partition will be used to put there configdrive image if partition_scheme.configdrive_device() is None: + LOG.debug('Adding configdrive partition on disk %s: size=20' % + disk['name']) parted.add_partition(size=20, configdrive=True) + LOG.debug('Looping over all volume groups in provision data') for vg in self.ks_vgs: + LOG.debug('Processing vg %s' % vg['id']) + LOG.debug('Looping over all logical volumes in vg %s' % vg['id']) for volume in vg['volumes']: + LOG.debug('Processing lv %s' % volume['name']) if volume['size'] <= 0: + LOG.debug('Lv size is zero. Skipping.') continue if volume['type'] == 'lv': + LOG.debug('Adding lv to vg %s: name=%s, size=%s' % + (vg['id'], volume['name'], volume['size'])) lv = partition_scheme.add_lv(name=volume['name'], vgname=vg['id'], size=volume['size']) if 'mount' in volume and volume['mount'] != 'none': + LOG.debug('Adding file system on lv: ' + 'mount=%s type=%s' % + (volume['mount'], + volume.get('file_system', 'xfs'))) partition_scheme.add_fs( device=lv.device_name, mount=volume['mount'], fs_type=volume.get('file_system', 'xfs'), fs_label=self._getlabel(volume.get('disk_label'))) + LOG.debug('Appending kernel parameters: %s' % + self.data['ks_meta']['pm_data']['kernel_params']) partition_scheme.append_kernel_params( self.data['ks_meta']['pm_data']['kernel_params']) return partition_scheme def configdrive_scheme(self): + LOG.debug('--- Preparing configdrive scheme ---') data = self.data configdrive_scheme = objects.ConfigDriveScheme() + LOG.debug('Adding common parameters') admin_interface = filter( lambda x: (x['mac_address'] == data['kernel_options']['netcfg/choose_interface']), @@ -263,10 +317,12 @@ class Nailgun(object): timezone=data['ks_meta']['timezone'], ) + LOG.debug('Adding puppet parameters') configdrive_scheme.set_puppet( master=data['ks_meta']['puppet_master'] ) + LOG.debug('Adding mcollective parameters') configdrive_scheme.set_mcollective( pskey=data['ks_meta']['mco_pskey'], vhost=data['ks_meta']['mco_vhost'], @@ -276,10 +332,12 @@ class Nailgun(object): connector=data['ks_meta']['mco_connector'] ) + LOG.debug('Setting configdrive profile %s' % data['profile']) configdrive_scheme.set_profile(profile=data['profile']) return configdrive_scheme def image_scheme(self, partition_scheme): + LOG.debug('--- Preparing image scheme ---') data = self.data image_scheme = objects.ImageScheme() # We assume for every file system user may provide a separate @@ -287,10 +345,16 @@ class Nailgun(object): # /, /boot, /var/lib file systems then we will try to get images # for all those mount points. Images data are to be defined # at provision.json -> ['ks_meta']['image_data'] + LOG.debug('Looping over all file systems in partition scheme') for fs in partition_scheme.fss: + LOG.debug('Processing fs %s' % fs.mount) if fs.mount not in data['ks_meta']['image_data']: + LOG.debug('There is no image for fs %s. Skipping.' % fs.mount) continue image_data = data['ks_meta']['image_data'][fs.mount] + LOG.debug('Adding image for fs %s: uri=%s format=%s container=%s' % + (fs.mount, image_data['uri'], + image_data['format'], image_data['container'])) image_scheme.add_image( uri=image_data['uri'], target_device=fs.device, diff --git a/fuel_agent/manager.py b/fuel_agent/manager.py index 95acdd2..fd19923 100644 --- a/fuel_agent/manager.py +++ b/fuel_agent/manager.py @@ -64,11 +64,13 @@ class Manager(object): self.image_scheme = None def do_parsing(self): + LOG.debug('--- Parsing data (do_parsing) ---') self.partition_scheme = self.driver.partition_scheme() self.configdrive_scheme = self.driver.configdrive_scheme() self.image_scheme = self.driver.image_scheme(self.partition_scheme) def do_partitioning(self): + LOG.debug('--- Partitioning disks (do_partitioning) ---') # If disks are not wiped out at all, it is likely they contain lvm # and md metadata which will prevent re-creating a partition table # with 'device is busy' error. @@ -138,6 +140,7 @@ class Manager(object): fu.make_fs(fs.type, fs.options, fs.label, fs.device) def do_configdrive(self): + LOG.debug('--- Creating configdrive (do_configdrive) ---') cc_output_path = os.path.join(CONF.tmp_path, 'cloud_config.txt') bh_output_path = os.path.join(CONF.tmp_path, 'boothook.txt') # NOTE:file should be strictly named as 'user-data' @@ -179,31 +182,33 @@ class Manager(object): ) def do_copyimage(self): + LOG.debug('--- Copying images (do_copyimage) ---') for image in self.image_scheme.images: + LOG.debug('Processing image: %s' % image.uri) processing = au.Chain() + + LOG.debug('Appending uri processor: %s' % image.uri) processing.append(image.uri) if image.uri.startswith('http://'): + LOG.debug('Appending HTTP processor') processing.append(au.HttpUrl) elif image.uri.startswith('file://'): + LOG.debug('Appending FILE processor') processing.append(au.LocalFile) if image.container == 'gzip': + LOG.debug('Appending GZIP processor') processing.append(au.GunzipStream) + LOG.debug('Appending TARGET processor: %s' % image.target_device) processing.append(image.target_device) - # For every file system in partitioning scheme we call - # make_fs utility. That means we do not care whether fs image - # is available for a particular file system or not. - # If image is not available we assume user wants to - # leave this file system un-touched. - try: - processing.process() - except Exception as e: - LOG.warn('Exception while processing image: uri=%s exc=%s' % - (image.uri, e.message)) + + LOG.debug('Launching image processing chain') + processing.process() def mount_target(self, chroot): + LOG.debug('Mounting target file systems') # Here we are going to mount all file systems in partition scheme. # Shorter paths earlier. We sort all mount points by their depth. # ['/', '/boot', '/var', '/var/lib/mysql'] @@ -220,6 +225,7 @@ class Manager(object): fu.mount_bind(chroot, '/proc') def umount_target(self, chroot): + LOG.debug('Umounting target file systems') key = lambda x: len(x.mount.rstrip('/').split('/')) for fs in sorted(self.partition_scheme.fss, key=key, reverse=True): fu.umount_fs(fs.device) @@ -228,6 +234,7 @@ class Manager(object): fu.umount_fs(chroot + '/sys') def do_bootloader(self): + LOG.debug('--- Installing bootloader (do_bootloader) ---') chroot = '/tmp/target' self.mount_target(chroot) @@ -246,7 +253,12 @@ class Manager(object): self.umount_target(chroot) + def do_reboot(self): + LOG.debug('--- Rebooting node (do_reboot) ---') + utils.execute('reboot') + def do_provisioning(self): + LOG.debug('--- Provisioning (do_provisioning) ---') self.do_parsing() self.do_partitioning() self.do_configdrive() diff --git a/fuel_agent/utils/artifact_utils.py b/fuel_agent/utils/artifact_utils.py index d17d98b..f3e539f 100644 --- a/fuel_agent/utils/artifact_utils.py +++ b/fuel_agent/utils/artifact_utils.py @@ -18,6 +18,10 @@ import tarfile import tempfile import zlib +from fuel_agent.openstack.common import log as logging + +LOG = logging.getLogger(__name__) + class Target(object): __metaclass__ = abc.ABCMeta @@ -29,10 +33,16 @@ class Target(object): raise StopIteration() def target(self, filename='/dev/null'): + LOG.debug('Opening file: %s for write' % filename) with open(filename, 'wb') as f: + count = 0 for chunk in self: + LOG.debug('Next chunk: %s' % count) f.write(chunk) + count += 1 + LOG.debug('Flushing file: %s' % filename) f.flush() + LOG.debug('File is written: %s' % filename) class LocalFile(Target): @@ -166,6 +176,7 @@ class Chain(object): # if next_proc is just a string we assume it is a filename # and we save stream into a file if isinstance(next_proc, (str, unicode)): + LOG.debug('Processor target: %s' % next_proc) proc.target(next_proc) return LocalFile(next_proc) # if next_proc is not a string we return new instance