iSCSI device reporting lots of iscsi sessions logging in and out

I just finished up reviewing a customer problem and I thought I would post some information about it to save others some time. In conclusion the problem was due to improperly removing iSCSI devices from the system. When removing an iSCSI device for good from a Solaris system. Its a good idea to issue devfsadm -C to clean up the old /dev paths and also update the MPxIO device cache (/etc/devices/mdi_scsi_vhci_cache).

The customer reported that in their iSCSI device log they were seeing frequent repeating iSCSI sessions logging in and out for no known reason. The Solaris messages log showed no iscsi related information to explain these device messages.

First, We quickly confirmed that the iSCSI initiator was causing sessions to login and out of the device with dtrace. To do this I used the below script.

#!/usr/sbin/dtrace -s
sdt:iscsi:iscsi_conn_state_machine:event
{
  printf("%p %s %s", arg0, (string)arg1, (string)arg2);
}

This script logs connection state changes within the iscsi initiator. If you want to better understand the initiators connection state machine you can either refer to the opensolaris code or the iSCSI RFC. The Solaris iSCSI initiator's connection state machine matches the iSCSI RFCs suggested connection state machine.

The output from the script looked as follows.

CPU     ID                    FUNCTION:NAME
  2   2303   iscsi_conn_state_machine:event 300246927c0 free T1
  2   2303   iscsi_conn_state_machine:event 300246927c0 in_login T5
  0   2303   iscsi_conn_state_machine:event 300246927c0 logged_in T9
  0   2303   iscsi_conn_state_machine:event 300246927c0 in_logout T17
  0   2303   iscsi_conn_state_machine:event 3002467f000 free T1
...

Since we could see activity in the trace this confirms the Solaris initiator is logging in and out of the target iSCSI device. Next, We needed to determine the reason for the login requests. The Solaris iSCSI initiator logs into devices under two conditions. The user wants to do IO to a device or the Solaris iSCSI initiator is trying to determine what devices are accessible to it. The later case can again occur under two conditions; The user has changed discovery information or the Solaris kernel is requesting the iSCSI initiator to update its discovery information, via a HBA tran_bus_config() request. Since the user was not performing management operations and their were already running IO something likely is kicking tran_bus_config(). To isolate the problem I ran the following dtrace.

#!/usr/sbin/dtrace -s
fbt:iscsi:iscsid_poke_discovery:entry
{
        stack();
}

The iSCSI initiators tran_bus_config() entry point is iscsi_tran_bus_config(). It then quickly branches out into two types of config requests. CONFIG_ALL in which Solaris wants the initiator to discover and login to all discovered devices. A CONFIG_ALL occurs when you issue devfsadm. The second type is CONFIG_ONE in which the kernel is requesting a specific device be discovered and logged in. When a CONFIG_ONE occurs the iSCSI initiator looks at all its current iSCSI sessions to see if the requested session is already discovered and logged in. If not discovered then it calls iscsid_poke_discovery(). This cause the initiator to query all enabled discovery methods. In this case SendTargets discovery is enabled to poke discovery would cause a iSCSI login/out along with a SendTargets query of the device. This seems to match the login pattern reported by the device.

The output from the script is show below...

...
  2  33609      iscsid_poke_discovery:entry poke
              iscsi`iscsid_config_one+0x70
              iscsi`iscsi_tran_bus_config+0x144
              genunix`ndi_devi_config_one+0x9c
              genunix`bus_config_one_phci_child+0x38
              genunix`config_client_paths+0xbcI wease
              genunix`mdi_vhci_bus_config+0x114
              scsi_vhci`vhci_scsi_bus_config+0x40
              genunix`ndi_devi_config_one+0x9c
              genunix`resolve_pathname+0x158
              genunix`e_ddi_hold_devi_by_path+0x10
              genunix`e_devid_cache_to_devt_list+0x2a8
              genunix`ddi_lyr_devid_to_devlist+0x10
              md`md_resolve_bydevid+0xe4
              md_raid`raid_check_cols+0x68
              md_raid`raid_iosetup+0x12c
              md_raid`md_raid_strategy+0x208
              md`mdstrategy+0xd4
              ufs`lufs_write_strategy+0x11c
              ufs`ufs_putapage+0x308
              ufs`ufs_putpages+0x2a4
...

Since a stack is reported this confirms that a tran_bus_config() is occuring. We can also see the request was for a CONFIG_ONE and continues on to iscsid_poke_discovery(). This means the kernel has requested iSCSI to discover and login to a specific device. Although that device is not found so we have to update our discovery leading to a iSCSI login/out on the target.

This still leaves the question why the kernel is requesting discovery of a device we don't know about. Looking at the rest of the stack we can see the MPxIO code (vhci_scsi_bus_config()) is involved so maybe this is an old device path still in its cache.

If we add the below trace clip to our last script we can now collect the device name that is not found.

fbt:iscsi:iscsid_config_one:entry
{
        printf("%s %d", (string)arg1, arg2);
}

Once that device name is collected we can run strings on the MPxIO device cache (/etc/devices/mdi_scsi_vhci_cache) to see if this device is in the cache. Which it was explaining why the kernel was asking us about it.

To resolve the problem the customer needed to run devfsadm -C to cleanup the cache of old stale cache data. After that was done the repeating iSCSI login/out messages stopped appearing in the iSCSI target device's logs.

In conclusion its recommended that upon removing iSCSI logical units form a host that the user also issue devfsadm -C to clean up addition Solaris cache information.

Posted at 02:24PM Jun 27, 2006 by dweibel in General  |