Hi Greg, I looked at your logs and also reviewed the PLOGI handling in Trunk-SCST.15. We found a issue with PLOGI/PRLI cleanup handling that I¹m addressing. Whatever fixes will get pushed upstream with the qla2xxx and scst-qla2xxx.git. ‹duane On 12/3/14, 12:46 PM, "Dr. Greg Wettstein" <greg@xxxxxxxxxxxxxxxxx> wrote: >On Nov 30, 4:00pm, Duane Grigsby wrote: >} Subject: Re: [Scst-devel] New qla2x00tgt Driver Question > >Hi, Ihope the week is going well for everyone. > >I've significantly cut information out of this in order to simplify >the mail. > >Duane, I had forwarded logs from previous testing to you on Monday and >hadn't received any response, I wanted to make sure you had received >that mail. > >Secondly, Vlad, we have been running additional testing for the last >two days and we have logs from the SCST core which I am including >below which suggests that the SCST core target code excessively stalls >or mishandles an ABORT while processing a NEXUS_LOSS_SESS TMF. >Regardless of your feelings about the target driver code in the kernel >we need to make sure there is not some subtle regression in the core >SCST code paths during TMF processing. > >To NAB and company, regardless of your feelings about the SCST target >core if there are issues with the in-kernel Qlogic target driver we >are running your code so if there are issues it affects your stack as >well. > >> Yes, it may be related. It has to do with receiving a PLOGI from an >> initiator with the same port_id, but a different WWPN. Can you send me >> your complete driver log? >> >> Hi Greg, Yes, I think there may be a issue there, but let me look at >> your logs. > >Since we need to get to the bottom of this we've spent the week >putting the testing harnesses back in place so we can feed >reproducible data back to the lists and to Qlogic. We just completed >the first run of tests which we have thoroughly documented so that we >know exactly what went into producing these issues. > >These tests are run in a multi-datacenter/multi-hop Cisco Nexus FCOE >fabric. Some of this may be related to that environment and if that >is the case we will figure out how to engage further on that front but >we need to fully understand if the behavior we are seeing out of the >Qlogic target driver is anomalous. > >All testing is being done against a 3.10.57 Linux kernel with a >handful of patches backported to the Qlogic target driver from later >kernels. The target server is running SCST 3.0.x with a Qlogic >QLE-8362 CNA. The backing storage is a 30 gigabyte RAM based block >device using our HPD driver. We will post a complete kernel diff to >our FTP server so the kernel can be reproduced. The target server is >attached to a Nexus 7009 storage VDC. > >The first round of testing was from a Linux 3.10.55 initiator using a >QLE-2462 HBA. That initiator is attached to a Nexus 5596 which is >upstreamed into a Nexus 7010 storage VDC. That storage VDC has a 20 >GBPS dual-interface ISL to the Nexus 7009 VDC in the second >data-center. > >The Qlogic driver was loaded as a module, along with the target >interface driver, into the kernel which had SCST statically built into >it. The Qlogic driver command line which was used is as follows: > >ql2xextended_error_logging=0x00003000 > >The driver was loaded and the SCST storage stack was configured with >the virtual fibre-channel interface to the target disabled. After the >storage stack was completely configured and target mode enabled on the >interface the switch interface to the target was enabled. > >The following is the output from the Qlogic target driver as it >processed the fabric events which were generated by its entry into the >fabric: > >-------------------------------------------------------------------------- >- >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83b:9: >qla_target(0): Async LOOP_UP occurred (m[0]=8011, m[1]=13, m[2]=44ef, >m[3]=0) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-505f:9: >Link is operational (10 Gbps). >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=ffff, m[2]=6, m[3]=0) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=ffff, m[2]=6, m[3]=0)<4>qla2xxx >[0000:02:00.3]-f826:9: qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x03 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x03 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x03 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x20 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x20 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x20 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x21 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x21 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x21 >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:53 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f806:9: >Adding sess ffff88081a962d80 to tgt ffff880819f53c00 via >->check_initiator_node_acl() >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f84b:9: >qla_target(0): session for wwn 21:01:00:e0:8b:a6:d1:9f (loop_id 3, s_id >45:2:0, confirmed completion not supported) added >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f806:9: >Adding sess ffff88081a962180 to tgt ffff880819f53c00 via >->check_initiator_node_acl() >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f84b:9: >qla_target(0): session for wwn 21:00:00:0e:1e:31:83:5f (loop_id 4, s_id >e:0:0, confirmed completion not supported) added >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x03 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=600) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x20 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=4, m[3]=a00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x21 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=1, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x71:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=2, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x45:fc:ff ELS opcode: 0x05 >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=0, m[2]=7, m[3]=b00) >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83f:9: >Async MB 2: Port Logged Out >Dec 2 03:13:54 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x0e:fc:ff ELS opcode: 0x05 >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c61a8) status 0x0 state 0x1 >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x20 >Dec 2 03:13:56 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c61a8) status 0x0 state 0x1 >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:00:0e ELS opcode: 0x03 >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c61a8) status 0x0 state 0x1 >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=4, m[2]=4, m[3]=600) >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=4, m[2]=4, m[3]=600) >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:00:0e ELS opcode: 0x20 >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c61a8) status 0x0 state 0x1 >Dec 2 03:13:57 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x52 >-------------------------------------------------------------------------- >- > >While this is the raw data the the important thing to highlight is the >following extract from this log: > >-------------------------------------------------------------------------- >- >0x0e:fc:ff ELS opcode: 0x03 >0x71:fc:ff ELS opcode: 0x03 >0x45:fc:ff ELS opcode: 0x03 >0x0e:fc:ff ELS opcode: 0x20 >0x71:fc:ff ELS opcode: 0x20 >0x45:fc:ff ELS opcode: 0x20 >0x0e:fc:ff ELS opcode: 0x21 >0x71:fc:ff ELS opcode: 0x21 >0x45:fc:ff ELS opcode: 0x21 >0x0e:fc:ff ELS opcode: 0x05 >0x71:fc:ff ELS opcode: 0x05 >0x0e:fc:ff ELS opcode: 0x03 >0x71:fc:ff ELS opcode: 0x03 >0x71:fc:ff ELS opcode: 0x20 >0x45:fc:ff ELS opcode: 0x05 >0x0e:fc:ff ELS opcode: 0x20 >0x45:fc:ff ELS opcode: 0x03 >0x71:fc:ff ELS opcode: 0x21 >0x0e:fc:ff ELS opcode: 0x21 >0x45:fc:ff ELS opcode: 0x20 >0x71:fc:ff ELS opcode: 0x05 >0x45:fc:ff ELS opcode: 0x21 >0x0e:fc:ff ELS opcode: 0x05 >0x45:fc:ff ELS opcode: 0x05 >0x71:fc:ff ELS opcode: 0x03 >0x45:fc:ff ELS opcode: 0x03 >0x0e:fc:ff ELS opcode: 0x03 >0x71:fc:ff ELS opcode: 0x20 >0x45:fc:ff ELS opcode: 0x20 >0x0e:fc:ff ELS opcode: 0x20 >0x71:fc:ff ELS opcode: 0x21 >0x45:fc:ff ELS opcode: 0x21 >0x0e:fc:ff ELS opcode: 0x21 >0x71:fc:ff ELS opcode: 0x05 >0x45:fc:ff ELS opcode: 0x05 >0x0e:fc:ff ELS opcode: 0x05 >-------------------------------------------------------------------------- >- > >Which are the domain/switch specific fibre-channel name servers (FCNS) >which engaged the target with extended link service requests. There >are a total of three distinct FCNS instances which issued these and >they are the three Nexus 55xx switches in the fabric. > >It is currently unclear to us why these independent FCNS directory >servers are engaging with the target. Our understanding of >fibre-channel is that an endpoint is responsible for negotiating a >port login (PLOGI) with the nameserver running on the switch which has >been elected the principal of the fabric (PS) at the 'well-known' >FCID/address of 0xff:ff:fc. > >Also of note from the the logs was the following: > >Dec 2 03:13:54 fc-rp1-targ10-s kernel: [1982]: >sqa_qla2xxx_check_initiator_node_acl:626:sqatgt(9/0): Registering >initiator: pwwn=21:01:00:e0:8b:a6:d1:9f, fcid=0x450200, loop=0x0003 > >Which was the initiator registering with the target. As we have noted >previously it is our belief that the card is maintaing loop id's of 0, >1 and 2 for the three FCNS nameservers. > >If this is expected behavior it us unclear to us why the storage VDC's >on the Nexus 7009 and 7010 are not issueing asynchronous transactions >against the target port since they are independent domains on the >fabric as well. > >We had previously noted that during subsequent NEXUS_LOSS_SESS events >that these FCNS instances would issue asynchronous events against the >target. Marc's logs confirmed this as well. > >Since there is the issue that this may be secondary to the target port >having initial visibility as an initiator on the fabric before >transitioning to an FCP class of target we had strictly controlled the >visibility of the target. We used the sg_reset command to issue an >adapater reset against the block device which was presented to the >initiator to see if we could reproduce this behavior. The initiator >adapater request was logged as follows: > >-------------------------------------------------------------------------- >- >Dec 2 03:35:40 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-8018:3: >ADAPTER RESET ISSUED nexus=3:3:0. >Dec 2 03:35:40 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-00af:3: >Performing ISP error recovery - ha=ffff880255184000. >Dec 2 03:35:41 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-505f:3: >Link is operational (4 Gbps). >Dec 2 03:35:42 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-8017:3: >ADAPTER RESET SUCCEEDED nexus=3:3:0. >-------------------------------------------------------------------------- >- > >Which presented to the target as follows: > >-------------------------------------------------------------------------- >- >Dec 2 03:35:40 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83c:9: >qla_target(0): Async event 0x8015 occurred (m[0]=8015, m[1]=45, m[2]=200, >m[3]=0) >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f808:9: >qla_tgt_fc_port_deleted ffff88081a962d80<4>qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x20 >Dec 2 03:35:42 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x52 >Dec 2 03:35:52 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f822:9: >qla_target(0): Unable to find wwn login (s_id 45:2:0), trying to create >it manually >Dec 2 03:35:52 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f841:9: >loop_id 3 >Dec 2 03:36:10 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f805:9: >Double sess ffff88081a962d80 found (s_id 45:0:2, loop_id 3), updating to >d_id 45:0:2, loop_id 3 rport-9:0-0: blocked FC remote port time out: >removing rport >-------------------------------------------------------------------------- >- > >Of interest in the log above is the apparent indication by the target >driver that it cannot locate the login for the initiator which had >generated the TMF. > >We then ran our standard I/O interruption test in which we use an FIO >script to generate four separate classes of I/O which are run >sequentially against the block device. This test loops continously >until stopped. > >While that I/O test was running we run a script which randomly selects >either a device, lun, bus or adapter reset and issues it against the >block device which the test is being run against. > >This test, on a fibre-channel initiator, typically runs a small number >of cycles and then experiences an error during the process of an >adapter reset sequence. The log from the initiator seed is as >follows: > >-------------------------------------------------------------------------- >- >Dec 2 14:06:02 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-8018:3: >ADAPTER RESET ISSUED nexus=3:3:0. >Dec 2 14:06:02 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-00af:3: >Performing ISP error recovery - ha=ffff880255184000. >Dec 2 14:06:04 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-505f:3: >Link is operational (4 Gbps). >Dec 2 14:06:05 fc-iacc1-prox2-s kernel: qla2xxx [0000:0d:00.1]-8017:3: >ADAPTER RESET SUCCEEDED nexus=3:3:0. >Dec 2 14:06:32 fc-iacc1-prox2-s kernel: rport-3:0-13: blocked FC remote >port time out: removing target and saving binding >Dec 2 14:06:32 fc-iacc1-prox2-s kernel: rport-3:0-13: blocked FC remote >port time out: removing target and saving binding >Dec 2 14:06:32 fc-iacc1-prox2-s kernel: sd 3:0:3:0: rejecting I/O to >offline device >-------------------------------------------------------------------------- >- > >Which is documented on the target as follows: > >-------------------------------------------------------------------------- >- >MESSAGES: >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [0]: >sqa_qla2xxx_handle_tmr:497:sqatgt(9/0): NEXUS_LOSS_SESS received. >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [0]: scst: >scst_rx_mgmt_fn:6701:TM fn 6 (mcmd ffff88081b39e070, initiator >21:01:00:e0:8b:a6:d1:9f, target 21:00:00:0e:1e:15:19:f1) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [0]: >scst_rx_mgmt_fn:6713:sess=ffff880899878000, tag_set 0, tag 0, lun_set 1, >lun=0, cmd_sn_set 0, cmd_sn 0, priv ffff88101a6c6590 >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [0]: >scst_post_rx_mgmt_cmd:6629:Adding mgmt cmd ffff88081b39e070 to active >mgmt cmd list >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: >scst_tm_thread:6514:Deleting mgmt cmd ffff88081b39e070 from active cmd >list >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: >scst_abort_all_nexus_loss_sess:6023:Nexus loss or UNREG SESS for sess >ffff880899878000 (mcmd ffff88081b39e070) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5266:Aborting cmd ffff880899830780 (tag 1222816, op >WRITE(10)) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5379:cmd ffff880899830780 (tag 1222816, sn 4294967276) >being executed/xmitted (state 118, op WRITE(10), proc time 3 sec., >timeout 60 sec.), deferring ABORT (cmd_done_wait_count 0, >cmd_finish_wait_count 1, internal 0, mcmd fn 6 (mcmd ffff88081b39e070)) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [0]: scst: >scst_alloc_set_UA:7963:Queuing new UA ffff88101aa2ecc0 (6:29:7, d_sense >0) to tgt_dev ffff88101a668000 (dev r10:prox2, initiator >21:01:00:e0:8b:a6:d1:9f) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5221:Calling dev handler vdisk_blockio >task_mgmt_fn_done(fn=6) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5224:Dev handler vdisk_blockio >task_mgmt_fn_done() returned >Dec 2 14:06:06 fc-rp1-targ10-s kernel: [1669]: scst: >scst_set_mcmd_next_state:5434:cmd_finish_wait_count(1) not 0, preparing >to wait >Dec 2 14:06:12 fc-rp1-targ10-s kernel: [2043]: >__scst_check_local_events:2785:ABORTED set, aborting cmd ffff880899830780 >Dec 2 14:06:12 fc-rp1-targ10-s kernel: [2043]: >scst_xmit_process_aborted_cmd:8743:Aborted cmd ffff880899830780 done >(cmd_ref 2) >Dec 2 14:06:12 fc-rp1-targ10-s kernel: [2043]: >scst_done_cmd_mgmt:5009:cmd ffff880899830780 done (tag 1222816) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [0]: >sqa_qla2xxx_handle_tmr:497:sqatgt(9/0): NEXUS_LOSS_SESS received. >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [0]: scst: >scst_rx_mgmt_fn:6701:TM fn 6 (mcmd ffff880898543000, initiator >21:01:00:e0:8b:a6:d1:9f, target 21:00:00:0e:1e:15:19:f1) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [0]: >scst_rx_mgmt_fn:6713:sess=ffff880899878000, tag_set 0, tag 0, lun_set 1, >lun=0, cmd_sn_set 0, cmd_sn 0, priv ffff88101a6c6978 >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [0]: >scst_post_rx_mgmt_cmd:6629:Adding mgmt cmd ffff880898543000 to active >mgmt cmd list >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: >scst_tm_thread:6514:Deleting mgmt cmd ffff880898543000 from active cmd >list >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: >scst_abort_all_nexus_loss_sess:6023:Nexus loss or UNREG SESS for sess >ffff880899878000 (mcmd ffff880898543000) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5266:Aborting cmd ffff880899830780 (tag 1222816, op >WRITE(10)) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5379:cmd ffff880899830780 (tag 1222816, sn 4294967276) >being executed/xmitted (state 123, op WRITE(10), proc time 24 sec., >timeout 60 sec.), deferring ABORT (cmd_done_wait_count 0, >cmd_finish_wait_count 1, internal 0, mcmd fn 6 (mcmd ffff880898543000)) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5221:Calling dev handler vdisk_blockio >task_mgmt_fn_done(fn=6) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5224:Dev handler vdisk_blockio >task_mgmt_fn_done() returned >Dec 2 14:06:27 fc-rp1-targ10-s kernel: [1669]: scst: >scst_set_mcmd_next_state:5434:cmd_finish_wait_count(1) not 0, preparing >to wait >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [0]: >sqa_qla2xxx_handle_tmr:497:sqatgt(9/0): NEXUS_LOSS_SESS received. >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [0]: scst: >scst_rx_mgmt_fn:6701:TM fn 6 (mcmd ffff880898543070, initiator >21:01:00:e0:8b:a6:d1:9f, target 21:00:00:0e:1e:15:19:f1) >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [0]: >scst_rx_mgmt_fn:6713:sess=ffff880899878000, tag_set 0, tag 0, lun_set 1, >lun=0, cmd_sn_set 0, cmd_sn 0, priv ffff88101a6c6d60 >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [0]: >scst_post_rx_mgmt_cmd:6629:Adding mgmt cmd ffff880898543070 to active >mgmt cmd list >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: >scst_tm_thread:6514:Deleting mgmt cmd ffff880898543070 from active cmd >list >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: >scst_abort_all_nexus_loss_sess:6023:Nexus loss or UNREG SESS for sess >ffff880899878000 (mcmd ffff880898543070) >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5266:Aborting cmd ffff880899830780 (tag 1222816, op >WRITE(10)) >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: scst: >scst_abort_cmd:5379:cmd ffff880899830780 (tag 1222816, sn 4294967276) >being executed/xmitted (state 123, op WRITE(10), proc time 31 sec., >timeout 60 sec.), deferring ABORT (cmd_done_wait_count 0, >cmd_finish_wait_count 1, internal 0, mcmd fn 6 (mcmd ffff880898543070)) >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5221:Calling dev handler vdisk_blockio >task_mgmt_fn_done(fn=6) >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: >scst_call_dev_task_mgmt_fn_done:5224:Dev handler vdisk_blockio >task_mgmt_fn_done() returned >Dec 2 14:06:34 fc-rp1-targ10-s kernel: [1669]: scst: >scst_set_mcmd_next_state:5434:cmd_finish_wait_count(1) not 0, preparing >to wait > > >SYSLOG: >Dec 2 14:06:06 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83c:9: >qla_target(0): Async event 0x8015 occurred (m[0]=8015, m[1]=45, m[2]=200, >m[3]=0) >Dec 2 14:06:06 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 14:06:06 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 14:06:12 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f858:9: >qla_target(0): CTIO with status 0xb received, state 1, se_cmd >ffff880899899820, (LIP_RESET=e, ABORTED=2, TARGET_RESET=17, TIMEOUT=b, >INVALID_RX_ID=8) >Dec 2 14:06:27 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 14:06:27 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 14:06:34 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 14:06:34 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 14:06:55 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x03 >Dec 2 14:06:55 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 14:07:14 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f814:9: >qla_target(0): terminating exchange for aborted cmd=ffff880899899810 >(se_cmd=ffff880899899820, tag=1222816) >Dec 2 14:07:14 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c6590) status 0x0 state 0x1 >Dec 2 14:07:14 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c6978) status 0x0 state 0x1 >Dec 2 14:07:14 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c6d60) status 0x0 state 0x1 >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c7148) status 0x0 state 0x1 >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83d:9: >qla_target(0): Port update async event 0x8014 occurred: updating the >ports database (m[0]=8014, m[1]=3, m[2]=4, m[3]=600) >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f83e:9: >Async MB 2: Got PLOGI Complete >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x20 >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-10807:9: >qla_target(0): Doing NEXUS_LOSS_SESS >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f813:9: TM >response mcmd (ffff88101a6c7530) status 0x0 state 0x1 >Dec 2 14:07:15 fc-rp1-targ10-s kernel: qla2xxx [0000:02:00.3]-f826:9: >qla_target(0): Port ID: 0x00:02:45 ELS opcode: 0x52 >-------------------------------------------------------------------------- >- > >The logs on the target are separated into two groups since the syslog >group gets priority *.warn and above while messages are .info and >.notice. > >As can be noted in the 'messages' log the SCST core is processing the >NEXUS_LOSS_SESS event which was triggered by the sg_reset. While >doing that it defers the abort of a WRITE operation, presumably >covered by the management command, since it believes it hasn't >completed. As I have noted previously all of this testing is being >done with RAM based block devices so there should be no issue with >backstorage delay unless something is happening in the I/O stack >downward from the BLOCKIO device to the actual backing device. > >Also to be noted is that the target was hit with multiple >NEXUS_LOSS_SESS events while all of this was going on (14:06:27, >14:06:34, 14:06:55) which are not attributable to the initiator since >its next I/O interruption injection was not scheduled until 14:07:46. >We find it interesting that the number of events is equal to the >number of sessions which we believe are attributable to the switch >FCNS servers. > >By now everyone has run out of patience so I will leave the group to >cogitate on all of the above. We have anecdotal evidence that this >error which gets thrown during TMF process occurs ONLY when the >initiator is a native fibre-channel initiator. We will be running the >same test with an FCOE initiator to verify this. > >Hopefully the above information is helpful. We will post the target >driver patch later. > >Have a good evening. > >Greg > >}-- End of excerpt from Duane Grigsby > >As always, >Dr. G.W. Wettstein, Ph.D. Enjellic Systems Development, LLC. >4206 N. 19th Ave. Specializing in information infra-structure >Fargo, ND 58102 development. >PH: 701-281-1686 >FAX: 701-281-3949 EMAIL: greg@xxxxxxxxxxxx >-------------------------------------------------------------------------- >---- >"As a software development model, Anarchy does not scale well." > -- Dave Welch
<<attachment: winmail.dat>>
