Cinder

test_volume_backup_create_get_detailed_list_restore_delete failed with "iscsiadm: Could not execute operation on all records: encountered iSCSI database failure" in c-bak log

Bug #1635643 reported by Ihar Hrachyshka
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Cinder
New
Undecided
Unassigned

Bug Description

http://logs.openstack.org/49/384949/5/gate/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/38c7208/logs/testr_results.html.gz

  File "tempest/api/volume/test_volumes_backup.py", line 50, in test_volume_backup_create_get_detailed_list_restore_delete
    backup['id'], 'available')
  File "tempest/common/waiters.py", line 224, in wait_for_backup_status
    raise lib_exc.VolumeBackupException(backup_id=backup_id)
tempest.lib.exceptions.VolumeBackupException: Volume backup 495518d9-e768-402f-b509-872d3ec9ffb2 failed and is in ERROR status

At the time of failure, we see the following in c-bak:

http://logs.openstack.org/49/384949/5/gate/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/38c7208/logs/screen-c-bak.txt.gz#_2016-10-21_13_19_57_328

2016-10-21 13:19:57.328 ERROR oslo_messaging.rpc.server [req-2f486c13-eade-459e-bea5-dd741f8c692b tempest-VolumesBackupsV2Test-2126147785] Exception during message handling
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 225, in dispatch
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 195, in _do_dispatch
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 404, in create_backup
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server self._update_backup_error(backup, six.text_type(err))
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server self.force_reraise()
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 398, in create_backup
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server self._run_backup(context, backup, volume)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 434, in _run_backup
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server properties, is_snapshot)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 904, in _attach_device
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return self._attach_volume(context, backup_device, properties)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 931, in _attach_volume
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server {'volume_id', volume.id})
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server self.force_reraise()
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 920, in _attach_volume
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return self._connect_device(conn)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/opt/stack/new/cinder/cinder/backup/manager.py", line 943, in _connect_device
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server vol_handle = connector.connect_volume(conn['data'])
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/utils.py", line 145, in trace_logging_wrapper
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py", line 396, in connect_volume
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server connection_properties)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py", line 216, in _get_potential_volume_paths
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server if self._connect_to_iscsi_portal(props):
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py", line 742, in _connect_to_iscsi_portal
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server "automatic")
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py", line 602, in _iscsiadm_update
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server **kwargs)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py", line 589, in _run_iscsiadm
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server delay_on_retry=delay_on_retry)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/os_brick/privileged/rootwrap.py", line 57, in execute
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return execute_root(*cmd, **kwargs)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/priv_context.py", line 205, in _wrap
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server return self.channel.remote_call(name, args, kwargs)
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 187, in remote_call
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server raise exc_type(*result[2])
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server ProcessExecutionError: Unexpected error while running command.
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server Command: iscsiadm -m node -T iqn.2010-10.org.openstack:volume-6d9a4621-7233-4e28-921e-50ffe10bd719 -p 10.3.41.163:3260 --op update -n node.startup -v automatic
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server Exit code: 6
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server Stdout: u''
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server Stderr: u'iscsiadm: Could not execute operation on all records: encountered iSCSI database failure\n'
2016-10-21 13:19:57.328 4171 ERROR oslo_messaging.rpc.server

In syslog around that time, we see:

Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: scsi 32:0:0:0: RAID IET Controller 0001 PQ: 0 ANSI: 5
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: scsi 32:0:0:0: Attached scsi generic sg3 type 12
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: scsi 32:0:0:1: Direct-Access IET VIRTUAL-DISK 0001 PQ: 0 ANSI: 5
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: Attached scsi generic sg4 type 0
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: [sdb] Write Protect is off
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: [sdb] Mode Sense: 69 00 10 08
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: [sdb] Write cache: enabled, read cache: enabled, supports DPO and FUA
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 kernel: sd 32:0:0:1: [sdb] Attached SCSI disk
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 iscsid[644]: Connection31:0 to [target: iqn.2010-10.org.openstack:volume-6d9a4621-7233-4e28-921e-50ffe10bd719, portal: 10.3.41.163,3260] through [iface: default] is operational now
Oct 21 13:19:57 ubuntu-xenial-osic-cloud1-s3500-5049162 iscsid[644]: Connection30:0 to [target: iqn.2010-10.org.openstack:volume-a76c3f40-9687-4702-a35b-4e4644b450cc, portal: 10.3.41.163,3260] through [iface: default] is shutdown.

Not sure if the last message is an indication of an issue.

Tags: gate-failure
Revision history for this message
Ihar Hrachyshka (ihar-hrachyshka) wrote :

Logstash: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Could%20not%20execute%20operation%20on%20all%20records%3A%20encountered%20iSCSI%20database%5C%22

9 hits in last 7 days.

tags: added: gate-failure
Revision history for this message
Matt Riedemann (mriedem) wrote :

Still seeing this, 2 hits in 7 days:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Could%20not%20execute%20operation%20on%20all%20records%3A%20encountered%20iSCSI%20database%20failure%5C%22%20AND%20tags%3A%5C%22screen-c-bak.txt%5C%22&from=7d

Revision history for this message
Matt Riedemann (mriedem) wrote :

I've also seen this in n-api logs when attaching a volume:

http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-cells-ubuntu-xenial/af9d60d/logs/screen-n-cpu.txt.gz?level=TRACE#_2017-02-17_00_11_17_422

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.