[Bug 1987663] Re: cinder-volume: "Failed to re-export volume, setting to ERROR" with "tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected" on service startup

Wed Oct 18 16:49:50 UTC 2023

** Summary changed:

- "Failed to re-export volume, setting to ERROR" with "tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected" on cinder-volume service start
+ cinder-volume: "Failed to re-export volume, setting to ERROR" with "tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected" on service startup

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to cinder in Ubuntu.
https://bugs.launchpad.net/bugs/1987663

Title:
  cinder-volume: "Failed to re-export volume, setting to ERROR" with
  "tgtadm: failed to send request hdr to tgt daemon, Transport endpoint
  is not connected" on service startup

Status in cinder package in Ubuntu:
  In Progress
Status in cinder package in Debian:
  Fix Released

Bug description:
  Debian bug #1018084 [1]
  Debian MR on Salsa: [2]

  [1] https://bugs.debian.org/1018084
  [2] https://salsa.debian.org/openstack-team/services/cinder/-/merge_requests/2

  Problem:

  The cinder-volume.service unit is _not_ ordered after the tgt.service unit,
  and thus might fail to run 'tgtadm' commands because tgtd is not yet ready,
  on service start up / boot:

   INFO cinder.service [-] Starting cinder-volume node (version 12.0.9)
   ...
   ERROR cinder.volume.manager [req-UUID - - - - -] Failed to re-export volume, setting to ERROR.: ProcessExecutionError: Unexpected error while running command.
   Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgtadm --lld iscsi --op show --mode target
   Exit code: 107
   Stdout: u''
   Stderr: u'tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected\n'

  Approach:

  It should be OK to order `cinder-volume.service` (generated from `cinder-volume.init.in` template) with `After=tgt.service`,
  as the `cinder-volume` package has a `Depends: tgt` dependency, and actually restarts `tgt` on its install/remove scripts,
  thus it is already strongly bound to `tgt` at the packaging level, even if its runtime usage is optional (eg, other drivers).

  # dpkg -s cinder-volume | grep Depends:
  Depends: ..., tgt, ...

  Real-world example:

  1) Unit `ovs-vswitchd.service` took 2 minutes to start up.
  2) That delayed `network.target` (`ovs-vswitchd.service` has `Before=network.target`).
  3) That delayed `tgt.service` too (it has `After=network.target`).

  4) BUT that did _not_ delay `cinder-volume.service` (it does _not_ have `After=tgt.service`)
  5) So it failed to talk to tgtd with tgtadm, and volume re-export failed.

   $ cat sos_commands/logs/journalctl_--no-pager_--catalog_--boot \
     | grep -E -B1 'Subject: Unit (cinder-volume.service|tgt.service|ovs-vswitchd.service|network.target)'

   Aug 10 06:23:15 <HOST> systemd[1]: Started OpenStack Cinder Volume.
   -- Subject: Unit cinder-volume.service has finished start-up
   --
   <<< ERROR in cinder-volume.log >>>

   Aug 10 06:23:16 <HOST> systemd[1]: Starting Open vSwitch Forwarding Unit...
   -- Subject: Unit ovs-vswitchd.service has begun start-up
   --
   <<< DELAY of 2 minutes >>>

   Aug 10 06:25:17 <HOST> systemd[1]: Started Open vSwitch Forwarding Unit.
   -- Subject: Unit ovs-vswitchd.service has finished start-up
   --
   Aug 10 06:25:17 <HOST> systemd[1]: Reached target Network.
   -- Subject: Unit network.target has finished start-up
   --
   Aug 10 06:25:17 <HOST> systemd[1]: Starting (i)SCSI target daemon...
   -- Subject: Unit tgt.service has begun start-up
   --
   Aug 10 06:25:19 <HOST> systemd[1]: Started (i)SCSI target daemon.
   -- Subject: Unit tgt.service has finished start-up

   <<< NOW tgtd is running >>>

  @ var/log/cinder/cinder-volume.log

    9901 2022-08-10 06:23:21.515 3939 INFO cinder.service [-] Starting cinder-volume node (version 12.0.9)
   ...
    9932 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager [req-e67a852a-6cce-4073-a2de-d3487c85d586 - - - - -] Failed to re-export volume, setting to ERROR.: ProcessExecutionError: Unexpected error while running command.
    9933 Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgtadm --lld iscsi --op show --mode target
    9934 Exit code: 107
    9935 Stdout: u''
    9936 Stderr: u'tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected\n'
    9937 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager Traceback (most recent call last):
    9938 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 486, in init_host
    9939 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     self.driver.ensure_export(ctxt, volume)
    9940 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/lvm.py", line 826, in ensure_export
    9941 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     self.target_driver.ensure_export(context, volume, volume_path)
    9942 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/volume/targets/iscsi.py", line 261, in ensure_export
    9943 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     old_name=None, **portals_config)
    9944 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/utils.py", line 818, in _wrapper
    9945 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     return r.call(f, *args, **kwargs)
    9946 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/retrying.py", line 206, in call
    9947 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     return attempt.get(self._wrap_exception)
    9948 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/retrying.py", line 247, in get
    9949 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     six.reraise(self.value[0], self.value[1], self.value[2])
    9950 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/retrying.py", line 200, in call
    9951 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
    9952 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/volume/targets/tgt.py", line 141, in create_iscsi_target
    9953 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     run_as_root=True)
    9954 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/cinder/utils.py", line 126, in execute
    9955 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     return processutils.execute(*cmd, **kwargs)
    9956 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager   File "/usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py", line 424, in execute
    9957 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager     cmd=sanitized_cmd)
    9958 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager ProcessExecutionError: Unexpected error while running command.
    9959 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgtadm --lld iscsi --op show --mode target
    9960 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager Exit code: 107
    9961 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager Stdout: u''
    9962 2022-08-10 06:23:23.398 3932 ERROR cinder.volume.manager Stderr: u'tgtadm: failed to send request hdr to tgt daemon, Transport endpoint is not connected\n'

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/cinder/+bug/1987663/+subscriptions