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 72bee11abb7cd878befaa8504ed568ad0436a9cb..8ceff1f139fabd6db1466d76d6186d74ee176276 100644 (file)
--- 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 79173840f385fa9c2086a25527fb3fa0123abb67..0976ecb0a9ece31de82068a24cfc353de9d10099 100644 (file)
--- 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 02ff1d385061ba0fca8fe287af69021c3447f9b2..2d156f490a8d03cf5bf17e2c2b5556beb9a58629 100644 (file)
--- 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: