[Bug 1569925] Re: Shutdown hang on 16.04 with iscsi targets

Sat Feb 3 13:20:43 UTC 2018

Commit has been merged upstream:

commit d754941225a7dbc61f6dd2173fa9498049f9a7ee
Author: Rafael David Tinoco <rafael.tinoco at canonical.com>
Date:   Thu Dec 7 19:59:13 2017 -0200

    scsi: libiscsi: Allow sd_shutdown on bad transport

    If, for any reason, userland shuts down iscsi transport interfaces
    before proper logouts - like when logging in to LUNs manually, without
    logging out on server shutdown, or when automated scripts can't
    umount/logout from logged LUNs - kernel will hang forever on its
    sd_sync_cache() logic, after issuing the SYNCHRONIZE_CACHE cmd to all
    still existent paths.

    PID: 1 TASK: ffff8801a69b8000 CPU: 1 COMMAND: "systemd-shutdow"
     #0 [ffff8801a69c3a30] __schedule at ffffffff8183e9ee
     #1 [ffff8801a69c3a80] schedule at ffffffff8183f0d5
     #2 [ffff8801a69c3a98] schedule_timeout at ffffffff81842199
     #3 [ffff8801a69c3b40] io_schedule_timeout at ffffffff8183e604
     #4 [ffff8801a69c3b70] wait_for_completion_io_timeout at ffffffff8183fc6c
     #5 [ffff8801a69c3bd0] blk_execute_rq at ffffffff813cfe10
     #6 [ffff8801a69c3c88] scsi_execute at ffffffff815c3fc7
     #7 [ffff8801a69c3cc8] scsi_execute_req_flags at ffffffff815c60fe
     #8 [ffff8801a69c3d30] sd_sync_cache at ffffffff815d37d7
     #9 [ffff8801a69c3da8] sd_shutdown at ffffffff815d3c3c

    This happens because iscsi_eh_cmd_timed_out(), the transport layer
    timeout helper, would tell the queue timeout function (scsi_times_out)
    to reset the request timer over and over, until the session state is
    back to logged in state. Unfortunately, during server shutdown, this
    might never happen again.

    Other option would be "not to handle" the issue in the transport
    layer. That would trigger the error handler logic, which would also need
    the session state to be logged in again.

    Best option, for such case, is to tell upper layers that the command was
    handled during the transport layer error handler helper, marking it as
    DID_NO_CONNECT, which will allow completion and inform about the
    problem.

    After the session was marked as ISCSI_STATE_FAILED, due to the first
    timeout during the server shutdown phase, all subsequent cmds will fail
    to be queued, allowing upper logic to fail faster.

    Signed-off-by: Rafael David Tinoco <rafael.tinoco at canonical.com>
    Reviewed-by: Lee Duncan <lduncan at suse.com>
    Signed-off-by: Martin K. Petersen <martin.petersen at oracle.com>

Applied in Bionic:

https://lists.ubuntu.com/archives/kernel-team/2018-January/089509.html

And Fix Committed.

Ack-ed for Trusty, Xenial, Artful:

https://lists.ubuntu.com/archives/kernel-team/2018-January/089774.html
https://lists.ubuntu.com/archives/kernel-team/2018-February/089809.html

Waiting to be Fix Committed there. A soon as it is released to -proposed
I'll verify it and provide feedback so it can be Fix Released.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to open-iscsi in Ubuntu.
https://bugs.launchpad.net/bugs/1569925

Title:
  Shutdown hang on 16.04 with iscsi targets

Status in linux package in Ubuntu:
  Fix Committed
Status in open-iscsi package in Ubuntu:
  Opinion
Status in linux source package in Trusty:
  In Progress
Status in open-iscsi source package in Trusty:
  Opinion
Status in linux source package in Xenial:
  In Progress
Status in open-iscsi source package in Xenial:
  Opinion
Status in linux source package in Artful:
  In Progress
Status in open-iscsi source package in Artful:
  Opinion
Status in linux source package in Bionic:
  Fix Committed
Status in open-iscsi source package in Bionic:
  Opinion

Bug description:
  [Impact]

   * open-iscsi users might face hangs during OS shutdown.
   * hangs can be caused by manual iscsi configuration/setup.
   * hangs can also be caused by bad systemd unit ordering.
   * if transport layer interface vanishes before lun is
     disconnected, then the hang will happen.
   * check comment #89 for the fix decision.

  [Test Case]

   * a simple way of reproducing the kernel hang is to disable
     the open-iscsi logouts. this simulates a situation when
     a service has shutdown the network interface, used by
     the transport layer, before proper iscsi logout was done.

     $ log into all iscsi luns

     $ systemctl edit --full open-iscsi.service
     ...
     #ExecStop=/lib/open-iscsi/logout-all.sh
     ...

     $ sudo reboot # this will make server to hang forever
                   # on shutdown

  [Regression Potential]

   * the regression is low because the change acts on the iscsi
     transport layer code ONLY when the server is in shutdown 
     state.

   * any error in logic would only appear during shutdown and
     would not cause any harm to data.

  [Other Info]

   * ORIGINAL BUG DESCRIPTION

  I have 4 servers running the latest 16.04 updates from the development
  branch (as of right now).

  Each server is connected to NetApp storage using iscsi software
  initiator.  There are a total of 56 volumes spread across two NetApp
  arrays.  Each volume has 4 paths available to it which are being
  managed by device mapper.

  While logged into the iscsi sessions all I have to do is reboot the
  server and I get a hang.

  I see a message that says:

    "Reached target Shutdown"

  followed by

    "systemd-shutdown[1]: Failed to finalize DM devices, ignoring"

  and then I see 8 lines that say:

    "connection1:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection2:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection3:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection4:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection5:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection6:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection7:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    "connection8:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4311815***, last ping 43118164**, now 4311817***"
    NOTE: the actual values of the *'s differ for each line above.

  This seems like a bug somewhere but I am unaware of any additional
  logging that I could turn on to pinpoint the problem.

  Note I also have similar setups that are not doing iscsi and they
  don't have this problem.

  Here is a screenshot of what I see on the shell when I try to reboot:

  (https://launchpadlibrarian.net/291303059/Screenshot.jpg)

  This is being tracked in NetApp bug tracker CQ number 860251.

  If I log out of all iscsi sessions before rebooting then I do not
  experience the hang:

  iscsiadm -m node -U all

  We are wondering if this could be some kind of shutdown ordering
  problem.  Like the network devices have already disappeared and then
  iscsi tries to perform some operation (hence the ping timeouts).

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