From: John Griffith Date: Fri, 9 Jan 2015 00:42:05 +0000 (-0700) Subject: Add debug messaging for tgt already exists X-Git-Url: https://review.fuel-infra.org/gitweb?a=commitdiff_plain;h=1e49234db32d2b4ba000e676ab36602a313b6784;p=openstack-build%2Fcinder-build.git Add debug messaging for tgt already exists We have a race condition where the call to create an iscsi target seems to be issued twice. This patch adds some debug logging to try and get some more info around where things are going wrong. First, we add a log message to the intialize_connection call in the cinder.volume.api and include the connector info. Second, we add a target show output prior to the update/create command in the target driver. In addition, we also had the update and show commands in the same try/except block which led us to believe the show was failing, but that's NOT the case at all. So this patch also moves that existing show (debug purposes as well) out of the main try block. Note that there are some old bugs logged against TgtAdm for issues with it "loosing count" of target id's it's issued, and in turn reissuing the same ID multiple times. This patch is intended to give us enough info to determine if that's what's going on or not. Other possibility is that the initialize call is being issued more than once. Change-Id: If17acff6c0b697261ae0e7a40fc26962cbee6c7b Related-Bug: #1398078 --- diff --git a/cinder/tests/targets/test_tgt_driver.py b/cinder/tests/targets/test_tgt_driver.py index 72bee11ab..8ceff1f13 100644 --- a/cinder/tests/targets/test_tgt_driver.py +++ b/cinder/tests/targets/test_tgt_driver.py @@ -200,11 +200,14 @@ class TestTgtAdmDriver(test.TestCase): def test_create_iscsi_target_already_exists(self): def _fake_execute(*args, **kwargs): - raise putils.ProcessExecutionError( - exit_code=1, - stdout='', - stderr='target already exists', - cmd='tgtad --lld iscsi --op show --mode target') + if 'update' in args: + raise putils.ProcessExecutionError( + exit_code=1, + stdout='', + stderr='target already exists', + cmd='tgtad --lld iscsi --op show --mode target') + else: + return 'fake out', 'fake err' self.stubs.Set(utils, 'execute', diff --git a/cinder/volume/api.py b/cinder/volume/api.py index 79173840f..0976ecb0a 100644 --- a/cinder/volume/api.py +++ b/cinder/volume/api.py @@ -437,8 +437,8 @@ class API(base.Base): @wrap_check_policy def reserve_volume(self, context, volume): - #NOTE(jdg): check for Race condition bug 1096983 - #explicitly get updated ref and check + # NOTE(jdg): check for Race condition bug 1096983 + # explicitly get updated ref and check volume = self.db.volume_get(context, volume['id']) if volume['status'] == 'available': self.update(context, volume, {"status": "attaching"}) @@ -505,6 +505,9 @@ class API(base.Base): @wrap_check_policy def initialize_connection(self, context, volume, connector): + LOG.debug('initialize connection for volume-id: %{volid}s, and ' + 'connector: %{connector}s', {'volid': volume['id'], + 'connector': connector}) return self.volume_rpcapi.initialize_connection(context, volume, connector) diff --git a/cinder/volume/targets/tgt.py b/cinder/volume/targets/tgt.py index 02ff1d385..2d156f490 100644 --- a/cinder/volume/targets/tgt.py +++ b/cinder/volume/targets/tgt.py @@ -181,8 +181,22 @@ class TgtAdm(iscsi.ISCSITarget): def create_iscsi_target(self, name, tid, lun, path, chap_auth=None, **kwargs): + # Note(jdg) tid and lun aren't used by TgtAdm but remain for # compatibility + + # NOTE(jdg): Remove this when we get to the bottom of bug: #1398078 + # for now, since we intermittently hit target already exists we're + # adding some debug info to try and pinpoint what's going on + (out, err) = utils.execute('tgtadm', + '--lld', + 'iscsi', + '--op', + 'show', + '--mode', + 'target', + run_as_root=True) + LOG.debug("Targets prior to update: %s" % out) fileutils.ensure_tree(self.volumes_dir) vol_id = name.split(':')[1] @@ -194,24 +208,30 @@ class TgtAdm(iscsi.ISCSITarget): volume_conf = self.VOLUME_CONF_WITH_CHAP_AUTH % (name, path, chap_str, write_cache) - LOG.info(_LI('Creating iscsi_target for: %s') % vol_id) + LOG.debug('Creating iscsi_target for: %s', vol_id) volumes_dir = self.volumes_dir volume_path = os.path.join(volumes_dir, vol_id) + if os.path.exists(volume_path): + LOG.warning(_LW('Persistence file already exists for volume, ' + 'found file at: %s'), volume_path) f = open(volume_path, 'w+') f.write(volume_conf) f.close() LOG.debug(('Created volume path %(vp)s,\n' - 'content: %(vc)s') - % {'vp': volume_path, 'vc': volume_conf}) + 'content: %(vc)s'), + {'vp': volume_path, 'vc': volume_conf}) old_persist_file = None old_name = kwargs.get('old_name', None) if old_name is not None: + LOG.debug('Detected old persistence file for volume ' + '%{vol}s at %{old_name}s', + {'vol': vol_id, 'old_name': old_name}) old_persist_file = os.path.join(volumes_dir, old_name) try: - # with the persistent tgts we create them + # With the persistent tgts we create them # by creating the entry in the persist file # and then doing an update to get the target # created. @@ -219,40 +239,36 @@ class TgtAdm(iscsi.ISCSITarget): run_as_root=True) LOG.debug("StdOut from tgt-admin --update: %s", out) LOG.debug("StdErr from tgt-admin --update: %s", err) - - # Grab targets list for debug - # Consider adding a check for lun 0 and 1 for tgtadm - # before considering this as valid - (out, err) = utils.execute('tgtadm', - '--lld', - 'iscsi', - '--op', - 'show', - '--mode', - 'target', - run_as_root=True) - LOG.debug("Targets after update: %s" % out) except putils.ProcessExecutionError as e: if "target already exists" in e.stderr: + # Adding the additional Warning message below for a clear + # ER marker (Ref bug: #1398078). LOG.warning(_LW('Could not create target because ' 'it already exists for volume: %s'), vol_id) - # NOTE(jdg): We've run into issues where the command being sent - # was not correct. This may be related to using the executor - # directly? Even though the above call specified is a show - # we see a new being called instead... - - # Adding the additional Warning message above for a clear - # ER marker (Ref bug: #1398078). + LOG.debug('Exception was: %s', e) pass else: - LOG.warning(_LW("Failed to create iscsi target for volume " - "id:%(vol_id)s: %(e)s") - % {'vol_id': vol_id, 'e': e}) + LOG.error(_LE("Failed to create iscsi target for volume " + "id:%(vol_id)s: %(e)s"), + {'vol_id': vol_id, 'e': e}) # Don't forget to remove the persistent file we created os.unlink(volume_path) raise exception.ISCSITargetCreateFailed(volume_id=vol_id) + # Grab targets list for debug + # Consider adding a check for lun 0 and 1 for tgtadm + # before considering this as valid + (out, err) = utils.execute('tgtadm', + '--lld', + 'iscsi', + '--op', + 'show', + '--mode', + 'target', + run_as_root=True) + LOG.debug("Targets after update: %s" % out) + iqn = '%s%s' % (self.iscsi_target_prefix, vol_id) tid = self._get_target(iqn) if tid is None: