VNX SPA再起動時のVMware IO停止時間について(FC接続)

Ryo.Tさん

背景のご説明をありがとうございます。

私はケーブルの抜線とSPの再起動でファイルオーバーの動作は同じだと勝手に思っていたのですが、どうも違うみたいですね。。

調べてみた限り、フェイルオーバーに掛かる時間の情報を見つけることは出来なかったのですが、VMware社のKBで以下のものを見つけることが出来ました。

ESX サーバで別のパスへの LUN が失敗する原因となり得る SCSI イベント (2080967)

これを見ると、抜線の時には恐らく1.の「0/1 0x0 0x0 0x0 - DID_NO_CONNECT」が返ってきてESXiはフェイルオーバーをかけていそうですが、SPの再起動の時には3.2/0 0x2 0x4 0xa - NOT_READY - LUN IS NOT READY AND TARGET PORT IS IN TRANSITIONか何かが最初に返ってきているのかもしれません。

そう考えると抜線時と再起動時でESXiの動作が異なることは十分に考えられます。

本当はこちらのラボで確認出来たらよいのですが、複数人数が共用で利用しているために再起動が出来なかったり、本体が日本になかったりするので抜線ができなかったりとちょっと難しい状況です。。

Ryo.Tさんが確認をしたESXiの/var/log/vmkernel（ラボマシンだとvmkernel.logになってました）に、どのSCSIイベントコードが記録されていたかを教えて頂くことは可能でしょうか。

Uehara Y.さん

ご回答頂きありがとうございました。

私もケーブル抜線と同じだと思っておりました。
そのため現状の動作が仕様なのか、不具合なのか、設定ミスなのかが判断がつかず、一般的な挙動を知りたいと思っております。

検証用のVNXのバージョンが05.33.000.5.051と古いことも良くないのかもしれませんが。

grep -vコマンドで少しフィルターしておりますが、/var/log/vmkernelとテスト時の動画を載せておきます。

/var/log/vmkernelの情報を提供頂きありがとうございました。大変参考になりました。

2016-12-22T08:19:52.958Z cpu1:33077)ScsiScan: 836: Path vmhba2:C0:T1:L0 supports REPORT LUNS 0x11

2016-12-22T08:19:52.958Z cpu4:490545)ScsiScan: 836: Path vmhba1:C0:T1:L0 supports REPORT LUNS 0x11

2016-12-22T08:23:13.720Z cpu8:87016)NMP: nmp_ThrottleLogForDevice:3298: Cmd 0x28 (0x439dcf5ec9c0, 87015) to dev "naa.6006016031f03500f325c616d5c5e611" on path "vmhba2:C0:T1:L0" Failed: H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x2a 0x6. Act:FAILOVER

2016-12-22T08:23:13.720Z cpu8:87016)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2016-12-22T08:23:13.958Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dcf5ec9c0

2016-12-22T08:23:14.328Z cpu28:86981)WARNING: NMP: nmp_DeviceStartLoop:725: NMP Device "naa.6006016031f03500f325c616d5c5e611" is blocked. Not starting I/O from device.

2016-12-22T08:23:15.280Z cpu8:33162)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

2016-12-22T08:23:32.310Z cpu26:86984)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2016-12-22T08:23:41.596Z cpu30:32845)ScsiDeviceIO: 2651: Cmd(0x43a5cee45c40) 0xfe, CmdSN 0x10697 from world 32806 to dev "naa.6006016031f03500f325c616d5c5e611" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x24 0x0.

2016-12-22T08:23:42.593Z cpu21:32858)ScsiDeviceIO: 2595: Cmd(0x43a5ce11df80) 0x2a, CmdSN 0x800e0010 from world 86981 to dev "naa.6006016031f03500f325c616d5c5e611" failed H:0x8 D:0x0 P:0x0

2016-12-22T08:23:42.593Z cpu21:32858)WARNING: NMP: nmp_DeviceStartLoop:725: NMP Device "naa.6006016031f03500f325c616d5c5e611" is blocked. Not starting I/O from device.

2016-12-22T08:23:42.593Z cpu21:32836)ScsiDeviceIO: 2595: Cmd(0x439dc0e90cc0) 0x2a, CmdSN 0x8000000a from world 87015 to dev "naa.6006016031f03500f325c616d5c5e611" failed H:0x8 D:0x0 P:0x0

2016-12-22T08:23:42.593Z cpu21:32836)ScsiDeviceIO: 2595: Cmd(0x43a5c0eab680) 0xfe, CmdSN 0x10698 from world 32806 to dev "naa.6006016031f03500f325c616d5c5e611" failed H:0x8 D:0x0 P:0x0

2016-12-22T08:23:42.957Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 3

2016-12-22T08:23:44.952Z cpu15:33137)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_TIMEOUT

2016-12-22T08:23:44.952Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:44.952Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:44.952Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:46.954Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:46.957Z cpu15:32875)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:46.957Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:46.957Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:46.957Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:48.959Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:48.962Z cpu15:33137)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:48.962Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:48.962Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:48.962Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:50.964Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:50.967Z cpu15:32875)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:50.967Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:50.967Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:50.967Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:52.957Z cpu12:33361)NMP: nmp_ResetDeviceLogThrottling:3349: last error status from device naa.6006016031f03500f325c616d5c5e611 repeated 1 times

2016-12-22T08:23:52.969Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:52.973Z cpu15:32875)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:52.973Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:52.973Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:52.973Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:54.975Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:54.978Z cpu15:33137)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:54.978Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:54.978Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:54.978Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:56.980Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:56.983Z cpu15:32935)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:56.983Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:56.983Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:56.983Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:23:58.985Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:23:58.988Z cpu15:32935)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:23:58.988Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:23:58.988Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:23:58.988Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:24:00.990Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:24:00.994Z cpu15:32935)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:24:00.994Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:24:00.994Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:24:00.994Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:24:02.996Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:24:02.999Z cpu15:32935)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_ABORTED

2016-12-22T08:24:02.999Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 FAILED

2016-12-22T08:24:02.999Z cpu23:33188)WARNING: LinScsi: SCSILinuxAbortCommands:1891: Failed, Driver fnic, for vmhba1

2016-12-22T08:24:02.999Z cpu23:33188)WARNING: ScsiPath: 7154: Set retry timeout for failed TaskMgmt abort for CmdSN  0x0, status Failure, path vmhba1:C0:T1:L0

2016-12-22T08:24:05.001Z cpu23:33188)<7>fnic : 2 :: Abort Cmd called FCID 0x3100ef, LUN 0x0 TAG 46 flags 273

2016-12-22T08:24:05.001Z cpu15:32935)<7>fnic : 2 :: abts cmpl recd. id 70 status FCPIO_IO_NOT_FOUND

2016-12-22T08:24:05.001Z cpu23:33188)<7>fnic : 2 :: Returning from abort cmd type 2 SUCCESS

2016-12-22T08:24:06.163Z cpu26:86983)HBX: 2802: 'VNX5800-LUN01': HB at offset 4009984 - Waiting for timed out HB:

2016-12-22T08:24:06.163Z cpu26:86983)  [HB state abcdef02 offset 4009984 gen 27 stampUS 185017651676 uuid 5858bae2-0bf257a0-3a2f-0025b522771b jrnl drv 14.61 lockImpl 4]

2016-12-22T08:24:09.746Z cpu12:33328)<7>fnic : 1 :: fnic_rport_exch_reset called portid 0xec00ef

2016-12-22T08:24:09.746Z cpu12:33328)<7>fnic : 1 :: fnic_rport_reset_exch: Issuing abts

2016-12-22T08:24:09.746Z cpu2:33301)<7>fnic : 2 :: fnic_rport_exch_reset called portid 0x3100ef

2016-12-22T08:24:09.749Z cpu24:33236)<7>fnic : 1 :: abts cmpl recd. id 181 status FCPIO_SUCCESS

2016-12-22T08:24:09.749Z cpu24:33236)<7>fnic : 1 :: abts cmpl, completing IO

2016-12-22T08:24:09.749Z cpu9:531852)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:09.749Z cpu9:531852)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:19.747Z cpu11:33331)<3> rport-2:0-3: blocked FC remote port time out: saving binding

2016-12-22T08:24:19.747Z cpu2:33301)<3> rport-1:0-3: blocked FC remote port time out: saving binding

2016-12-22T08:24:19.747Z cpu11:33331)<7>fnic : 2 :: fnic_terminate_rport_io called wwpn 0x5006016108600b53, wwnn0xffffffffffffffff, rport 0x0x4306ec760ee0, portid 0xffffffff

2016-12-22T08:24:19.747Z cpu7:33325)<7>fnic : 1 :: fnic_terminate_rport_io called wwpn 0x5006016008600b53, wwnn0xffffffffffffffff, rport 0x0x4306ec75f490, portid 0xffffffff

2016-12-22T08:24:19.752Z cpu9:531852)VMW_SATP_ALUA: satp_alua_issueCommandOnPath:656: Path "vmhba1:C0:T1:L0" (UP) command 0xa3 failed with status Timeout. H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

2016-12-22T08:24:19.752Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:566: Retry world restore device "naa.6006016031f03500f325c616d5c5e611" - no more commands to retry

2016-12-22T08:24:19.753Z cpu21:32858)HBX: 276: 'VNX5800-LUN01': HB at offset 4009984 - Reclaimed heartbeat [Timeout]:

2016-12-22T08:24:19.753Z cpu21:32858)  [HB state abcdef02 offset 4009984 gen 27 stampUS 185066810832 uuid 5858bae2-0bf257a0-3a2f-0025b522771b jrnl drv 14.61 lockImpl 4]

2016-12-22T08:24:21.749Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:21.749Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:21.770Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:21.770Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:52.957Z cpu17:33085)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:52.957Z cpu17:33085)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-22T08:24:52.957Z cpu14:33077)ScsiScan: 836: Path vmhba2:C0:T0:L0 supports REPORT LUNS 0x11

2016-12-22T08:24:52.957Z cpu14:531853)ScsiScan: 836: Path vmhba1:C0:T0:L0 supports REPORT LUNS 0x11 Video Link : 135857

00:15 頃

  SPA Reboot実行（左上のRDP）

00:17 頃

  Working Pathが変わる(右下のPutty画面、ESXiのコマンド)

00:36 頃

  Iometer停止（左上のRDP、ESXi上のWindowsの仮想マシン）

  コピー＆削除Script停止（右上のPutty、ESXi上のCentOSの仮想マシン）

01:13 頃

  RCSN検知（下から2つ目のPutty、Cisco Nexus）

01:21 頃

  Iometer復活（左上のRDP、Windowsの仮想マシン）

  コピー＆削除Script復活（右上のPutty、ESXi上のCentOSの仮想マシン）

  トレスパス確認（下から3つ目のPutty、VNX5800）

  Reboot成功メッセージが表示される（左上のRDP、VNX5800）

Uehara Y.さん

VNXを最新のバージョン（05.33.009.5.184）にして同じ検証を実施したところ、IO停止時間はほぼ一瞬（1秒かかったかかからないか）でした。

私としてはこちらの動作が正しいような気がしております。

何かしらVNXの不具合だったのかと推測しております。

ただ、一般的な挙動は知っておきたいですので、情報がありましたら教えて頂けると幸いです。

参考までに/var/log/vmkernelを記載しておきます。※不要と思われるログはgrep -vコマンドでフィルターしています。

"Act:FAILOVER"のメッセージが出て、"Peer SP is hung"のメッセージが出るまでの時間が、古いバージョンに比べてかなり短くなっていました。

2016-12-26T07:47:35.218Z cpu2:33299)NMP: nmp_ThrottleLogForDevice:3298: Cmd 0x2a (0x439dcf5d8200, 87015) to dev "naa.6006016031f03500f325c616d5c5e611" on path "vmhba1:C0:T1:L0" Failed: H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x2a 0x6. Act:FAILOVER

2016-12-26T07:47:35.218Z cpu2:33299)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2016-12-26T07:47:35.986Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dcf5d8200

2016-12-26T07:47:35.988Z cpu2:838289)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

2016-12-26T07:47:40.170Z cpu3:32813)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2016-12-26T07:47:40.985Z cpu20:844501)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-26T07:47:40.985Z cpu20:844501)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-26T07:47:40.986Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dced940c0

2016-12-26T07:47:40.995Z cpu3:32813)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

2016-12-26T07:48:08.842Z cpu13:33318)<7>fnic : 2 :: fnic_rport_exch_reset called portid 0x3100ef

2016-12-26T07:48:08.848Z cpu4:33301)<7>fnic : 1 :: fnic_rport_exch_reset called portid 0xec00ef

2016-12-26T07:48:18.844Z cpu12:33314)<3> rport-2:0-3: blocked FC remote port time out: saving binding

2016-12-26T07:48:18.844Z cpu4:33301)<7>fnic : 2 :: fnic_terminate_rport_io called wwpn 0x5006016108600b53, wwnn0xffffffffffffffff, rport 0x0x4306ec760ee0, portid 0xffffffff

2016-12-26T07:48:18.850Z cpu6:33323)<3> rport-1:0-3: blocked FC remote port time out: saving binding

2016-12-26T07:48:18.850Z cpu6:33323)<7>fnic : 1 :: fnic_terminate_rport_io called wwpn 0x5006016008600b53, wwnn0xffffffffffffffff, rport 0x0x4306ec75f490, portid 0xffffffff

2016-12-26T07:48:18.860Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-26T07:48:18.860Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-26T07:48:18.866Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba1:C0:T0:L0" Peer SP is hung.

2016-12-26T07:48:18.866Z cpu1:32867)WARNING: VMW_SATP_LIB_CX: satp_lib_cx_otherSPIsHung:338: Path "vmhba2:C0:T0:L0" Peer SP is hung.

2016-12-26T07:48:22.985Z cpu25:33361)NMP: nmp_ResetDeviceLogThrottling:3349: last error status from device naa.6006016031f03500f325c616d5c5e611 repeated 1 times

Ryo.Tさん

詳細な確認結果をありがとうございます！

VMware ESX/ESXi のネイティブ マルチパスにおけるストレージ パスのフェイルオーバー シーケンスについて (2077136)

というKBを見つけたので、ESXiのシーケンスを追ってみたのですが、簡単に書くと

① ストレージへのパス異常を検知

② 本当に異常が発生しているのかのTEST_UNIT_READYコマンドをパスに対して送信して本当にダウンしていることを確認

③ パスの変更（切り替え）を実施

④ フェイルオーバーが成功して新しいパスが利用できることを確認

という流れになっています。

これを出力ログに当てはめると

① Valid sense data: 0x6 0x2a 0x6. Act:FAILOVER #SCSIイベントからASYMMETRIC ACCESS ATATE CHANGEDでありALUAのPrefered Pathが変わったことをESXiが認識

② awaiting fast path state update for failover with I/O blocked.No prior reservation exists on the device.

③ Retry world failover device

④ Retry world recovered device

となります。

更にこれを載せて頂いたログにあてはめると、最新バージョンのコードではこの①～④の流れが

①2016-12-26T07:47:35.218Z cpu2:33299)NMP: nmp_ThrottleLogForDevice:3298: Cmd 0x2a (0x439dcf5d8200, 87015) to dev "naa.6006016031f03500f325c616d5c5e611" on path "vmhba1:C0:T1:L0" Failed: H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x2a 0x6. Act:FAILOVER

②2016-12-26T07:47:35.218Z cpu2:33299)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

③2016-12-26T07:47:35.986Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dcf5d8200

④2016-12-26T07:47:35.988Z cpu2:838289)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

②2016-12-26T07:47:40.170Z cpu3:32813)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

③2016-12-26T07:47:40.986Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dced940c0

④2016-12-26T07:47:40.995Z cpu3:32813)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

と綺麗に2回出ています（2回出るのは恐らく片SPに対して2つずつパスを張っているせいかと）。

それに対して問題がある方のコードは以下の通りです。

①2016-12-22T08:23:13.720Z cpu8:87016)NMP: nmp_ThrottleLogForDevice:3298: Cmd 0x28 (0x439dcf5ec9c0, 87015) to dev "naa.6006016031f03500f325c616d5c5e611" on path "vmhba2:C0:T1:L0" Failed: H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x2a 0x6. Act:FAILOVER

②2016-12-22T08:23:13.720Z cpu8:87016)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

③2016-12-22T08:23:13.958Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world failover device "naa.6006016031f03500f325c616d5c5e611" - issuing command 0x439dcf5ec9c0

④2016-12-22T08:23:15.280Z cpu8:33162)NMP: nmpCompleteRetryForPath:325: Retry world recovered device "naa.6006016031f03500f325c616d5c5e611"

②2016-12-22T08:23:32.310Z cpu26:86984)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6006016031f03500f325c616d5c5e611": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

③ログ無し

④2016-12-22T08:24:19.752Z cpu0:33362)WARNING: NMP: nmpDeviceAttemptFailover:566: Retry world restore device "naa.6006016031f03500f325c616d5c5e611" - no more commands to retry

1回目の④から2回目の②が始まるまでの時間が長い上に、2回目の③の記録はなく、④の最後にも「no more commands to retry」という文言がついています。。。

とここまで書いておきながら何故この問題が発生しているのかまでは分かりません。。

なんとなく②の後の処理が上手くいっていないことに問題がありそうなのですが、これ以上の詳細は判断できないです。

（これを見て「あそこが悪いんじゃね？」とかわかる有識者の方がいらっしゃったら是非教えていただきたいです）