Bug 234654 - bad iSCSI/ctld interaction after network failures (timeouts)
Summary: bad iSCSI/ctld interaction after network failures (timeouts)
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 12.0-RELEASE
Hardware: Any Any
: --- Affects Only Me
Assignee: freebsd-scsi mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-01-06 07:25 UTC by Martin Birgmeier
Modified: 2019-01-08 16:29 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Birgmeier 2019-01-06 07:25:55 UTC
Scenario:
- Machine A ("hal")
  . runs FreeBSD 12.0
  . runs as VirtualBox host
  . exports virtual disks via iSCSI (ctld)
  . Because of sometimes poor network connectivity (overload on a 1 Gbps network), sysctl kern.cam.ctl.iscsi.ping_timeout=30 has been set (from previous experience with 11.2)

- Machine V ("v903")
  . runs 12.0
  . runs as VirtualBox client on A
  . mounts a UFS filesystem from a virtual disk exported by A
  . has the default kern.iscsi.ping_timeout: 5 set

- Due to network overload, machine V runs into the ping timeout (5 seconds)

Result:
- V cannot access the disk exported from A anymore, with the following messages appearing in the respective syslogs as shown below.

Likely cause:
- The likely cause seems to be a poor handling of reconnects initiated from V while A thinks that the old connection is still valid.

Syslog output:
- On machine V:

Jan  5 22:35:09 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:35:09 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 8a 40 00 01 00 00 
Jan  5 22:35:09 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:35:09 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:35:09 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:35:09 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:35:15 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:35:15 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 8a 40 00 01 00 00 
Jan  5 22:35:15 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:35:15 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:35:15 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:35:15 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:35:22 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:35:22 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 8a 40 00 01 00 00 
Jan  5 22:35:22 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:35:22 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:35:22 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:35:22 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:35:29 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:35:29 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 8a 40 00 01 00 00 
Jan  5 22:35:29 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:35:29 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:35:29 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:35:29 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:35:35 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:35:35 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 8a 40 00 01 00 00 
Jan  5 22:35:35 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:35:35 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:35:35 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:35:35 v903 kernel: (da0:iscsi1:0:0:0): Error 5, Retries exhausted
Jan  5 22:35:35 v903 kernel: g_vfs_done():diskid/DISK-HAL_00925s2a[WRITE(offset=4697849856, length=131072)]error = 5
Jan  5 22:36:46 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 7b 00 00 00 c0 00 
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:39:25 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 7b 00 00 00 c0 00 
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:39:25 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 7b 00 00 00 c0 00 
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:39:25 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 7b 00 00 00 c0 00 
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): Retrying command (per sense data)
Jan  5 22:39:25 v903 kernel: WARNING: hal.xyzzy (iqn.1995-06.xyzzy.hal:disk925): no ping reply (NOP-In) after 5 seconds; reconnecting
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): WRITE(10). CDB: 2a 00 00 8c 7b 00 00 00 c0 00 
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): CAM status: SCSI Status Error
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI status: Check Condition
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): SCSI sense: UNIT ATTENTION asc:29,7 (I_T nexus loss occurred)
Jan  5 22:39:25 v903 kernel: (da0:iscsi1:0:0:0): Error 5, Retries exhausted
Jan  5 22:39:25 v903 kernel: g_vfs_done():diskid/DISK-HAL_00925s2a[WRITE(offset=4619042816, length=12288)]error = 5
Jan  5 22:39:25 v903 kernel: g_vfs_done():diskid/DISK-HAL_00925s2a[WRITE(offset=4669407232, length=32768)]error = 5
Jan  5 22:39:25 v903 kernel: g_vfs_done():diskid/DISK-HAL_00925s2a[WRITE(offset=4734410752, length=8192)]error = 5
...
repeating ad infinitum

- On machine A:

Jan  5 22:35:10 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 9 tasks
Jan  5 22:35:10 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:35:16 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 10 tasks
Jan  5 22:35:16 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:35:23 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 10 tasks
Jan  5 22:35:23 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:35:30 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 8 tasks
Jan  5 22:35:30 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:35:36 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 7 tasks
Jan  5 22:35:36 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:36:47 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 23 tasks
Jan  5 22:36:47 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:36:53 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 20 tasks
Jan  5 22:36:53 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:02 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:37:02 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:10 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:37:10 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:16 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 20 tasks
Jan  5 22:37:16 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:22 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 21 tasks
Jan  5 22:37:22 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:31 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 19 tasks
Jan  5 22:37:31 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:38 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 19 tasks
Jan  5 22:37:38 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:44 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:37:44 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:37:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:37:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:00 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:38:00 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:09 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 22 tasks
Jan  5 22:38:09 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:18 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 20 tasks
Jan  5 22:38:18 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:25 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 20 tasks
Jan  5 22:38:25 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:30 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 18 tasks
Jan  5 22:38:30 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:38 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 25 tasks
Jan  5 22:38:38 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:45 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 19 tasks
Jan  5 22:38:45 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 20 tasks
Jan  5 22:38:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:38:57 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 26 tasks
Jan  5 22:38:57 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:39:04 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 30 tasks
Jan  5 22:39:04 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:39:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 41 tasks
Jan  5 22:39:51 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:39:58 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 26 tasks
Jan  5 22:39:58 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:40:05 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 28 tasks
Jan  5 22:40:05 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:40:12 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 29 tasks
Jan  5 22:40:12 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): tasks terminated
Jan  5 22:40:20 hal kernel: WARNING: 192.168.1.195 (iqn.1995-06.xyzzy.hal:v903): waiting for CTL to terminate 26 tasks
...
likewise repeating forever
Comment 1 Martin Birgmeier 2019-01-06 15:29:51 UTC
Correction: The VM client V runs HEAD at r341726.