On Thu, 2020-09-10 at 12:36 -0400, Laurence Oberman wrote: > Hello > > I was testing lpfc on 5.9 and noticed a lot more logging on modprobe. > Even when lpfc_log_verbose = 0 > > root@segstorage3 ~]# cat /sys/class/scsi_host/host*/lpfc_log_verbose > 0x0 > 0x0 > 0x0 > 0x0 > > Wondered if its been there for a while and its just because I now > started testing. > > [ 143.398194] scsi host3: Emulex LPe12000 PCIe Fibre Channel Adapter > on PCI bus 0e device 00 irq 213 > [ 145.598711] scsi host4: Emulex LPe12000 PCIe Fibre Channel Adapter > on PCI bus 0e device 01 irq 216 > [ 147.877559] lpfc 0000:0b:00.0: 2:6101 Disabling NVME support: Not > supported by firmware (0 0) x3 > [ 147.929264] lpfc 0000:0b:00.0: 2:2574 IO channels: hdwQ 64 IRQ 64 > MRQ: 0 > [ 147.974727] scsi host5: Emulex LPe16000 16Gb PCIe Fibre Channel > Adapter on PCI bus 0b device 00 irq 219 PCI resettable > [ 149.156406] lpfc 0000:0b:00.0: 2:3176 Port Name 0 Physical Link is > functional > [ 149.284537] lpfc 0000:0b:00.1: 3:6101 Disabling NVME support: Not > supported by firmware (0 0) x3 > [ 149.336809] lpfc 0000:0b:00.1: 3:2574 IO channels: hdwQ 64 IRQ 64 > MRQ: 0 > [ 149.388033] scsi host6: Emulex LPe16000 16Gb PCIe Fibre Channel > Adapter on PCI bus 0b device 01 irq 284 PCI resettable > [ 150.848392] lpfc 0000:0b:00.1: 3:3176 Port Name 1 Physical Link is > functional > [ 151.477690] lpfc 0000:0b:00.0: 2:1303 Link Up Event x1 received > Data: x1 x0 x20 x0 x0 x0 0 > [ 151.526732] lpfc 0000:0b:00.0: start 183 end 182 cnt 256 > [ 151.559193] lpfc 0000:0b:00.0: 183: [ 148.759023] 2:2593 WQ > setup: > wq[35]-id=35 assoc=35, cq[35]-id=35 > [ 151.617510] lpfc 0000:0b:00.0: 184: [ 148.763089] 2:(0):0356 > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4 > x24 xb8000000 x24 x1000 CQ: x0 x0 x0 x90000000 > [ 151.715751] lpfc 0000:0b:00.0: 185: [ 148.763090] 2:6087 CQ > setup: > cq[36]-id=36, parent eq[36]-id=36 > [ 151.772034] lpfc 0000:0b:00.0: 186: [ 148.767155] 2:(0):0356 > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4 > x240024 x4008504 x0 xcf400000 CQ: x0 x0 x0 x90000000 > [ 151.872722] lpfc 0000:0b:00.0: 187: [ 148.767156] 2:2593 WQ > setup: > wq[36]-id=36 assoc=36, cq[36]-id=36 > [ 151.929396] lpfc 0000:0b:00.0: 188: [ 148.771220] 2:(0):0356 > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4 > x25 xb8000000 x25 x1000 CQ: x0 x0 x0 x90000000 > [ 152.030050] lpfc 0000:0b:00.0: 189: [ 148.771221] 2:6087 CQ > setup: > cq[37]-id=37, parent eq[37]-id=37 > [ 152.085622] lpfc 0000:0b:00.0: 190: [ 148.775285] 2:(0):0356 > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4 > x250025 x4008504 x0 xbc7e0000 CQ: x0 x0 x0 x90000000 > [ 152.185681] lpfc 0000:0b:00.0: 191: [ 148.775287] 2:2593 WQ > setup: > wq[37]-id=37 assoc=37, cq[37]-id=37 > [ 152.243645] lpfc 0000:0b:00.0: 192: [ 148.779351] 2:(0):0356 > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4 > x26 xb8000000 x26 x1000 CQ: x0 x0 x0 x90000000 > [ 152.341442] lpfc 0000:0b:00.0: 193: [ 148.779352] 2:6087 CQ > setup: > cq[38]-id=38, parent eq[38]-id=38 > [ 152.399734] lpfc 0000:0b:00.0: 194: [ 148.783416] 2:(0):0356 > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4 > x260026 x4008504 x0 x5ef40000 CQ: x0 x0 x0 x90000000 > [ 152.501390] lpfc 0000:0b:00.0: 195: [ 148.783417] 2:2593 WQ > setup: > wq[38]-id=38 assoc=38, cq[38]-id=38 > [ 152.557531] lpfc 0000:0b:00.0: 196: [ 148.787481] 2:(0):0356 > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4 > x27 xb8000000 x27 x1000 CQ: x0 x0 x0 x90000000 > .. > .. > [ 190.872503] lpfc 0000:0b:00.0: start 109 end 115 cnt 6 > [ 190.872506] lpfc 0000:0b:00.0: 109: [ 190.871058] 2:(0):0117 Xmit > ELS response x1 to remote NPORT x20300 I/O tag: xb92, size: x8 > port_state x20 rpi x10 fc_flag x800110 > [ 190.872507] lpfc 0000:0b:00.0: 110: [ 190.871060] 2:(0):0129 Xmit > ELS RJT xb00 response tag xb92 xri xffff, did x20300, nlp_flag > x80000000, nlp_state x7, rpi x10 > [ 190.872509] lpfc 0000:0b:00.0: 111: [ 190.871085] 2:(0):0110 ELS > response tag xb92 completes Data: x0 x0 x0 x20300 x80000000 x7 x10 > [ 190.872511] lpfc 0000:0b:00.0: 112: [ 190.872497] 2:2538 Received > frame rctl:x22, type:x1, frame Data:220a0300 00010600 01290000 > 00000000 > 0048ffff 00000000 00000000 > [ 190.872512] lpfc 0000:0b:00.0: 113: [ 190.872500] 2:(0):0929 FIND > node DID Data: xffff896e4faf2c00 x10600 x80000000 x7001801 xc > xffff896e4faf1200 > [ 190.872514] lpfc 0000:0b:00.0: 114: [ 190.872501] 2:(0):0112 ELS > command x14001023 received from NPORT x10600 Data: x20 x800110 xa0300 > xa0300 > [ 190.872515] lpfc 0000:0b:00.0: 2:(0):0115 Unknown ELS command > x14001023 received from NPORT x10600 > [ 190.873239] lpfc 0000:0b:00.0: start 115 end 121 cnt 6 > [ 190.873241] lpfc 0000:0b:00.0: 115: [ 190.872517] 2:(0):0117 Xmit > ELS response x1 to remote NPORT x10600 I/O tag: xb8f, size: x8 > port_state x20 rpi xc fc_flag x800110 > [ 190.873243] lpfc 0000:0b:00.0: 116: [ 190.872519] 2:(0):0129 Xmit > ELS RJT xb00 response tag xb8f xri xffff, did x10600, nlp_flag > x80000000, nlp_state x7, rpi xc > [ 190.873244] lpfc 0000:0b:00.0: 117: [ 190.872545] 2:(0):0110 ELS > response tag xb8f completes Data: x0 x0 x0 x10600 x80000000 x7 xc > [ 190.873246] lpfc 0000:0b:00.0: 118: [ 190.873234] 2:2538 Received > frame rctl:x22, type:x1, frame Data:220a0300 00010700 01290000 > 00000000 > 008cffff 00000000 00000000 > [ 190.873249] lpfc 0000:0b:00.0: 119: [ 190.873236] 2:(0):0929 FIND > node DID Data: xffff896e4faf0600 x10700 x80000000 x7001801 xd > xffff896e4faf3600 > > I have not investogated the masking changes yet, decided to first > ask. > > Thanks > Laurence Hi Dick I dont see this when booting 5.5, which was when I last tested, and before I start the long arduous code review and maybe bisect I would rather have you look at it. Can you look at this please and let me know. Its not happeniong on latest RHEL8 but could happen if we take latest code in. Regards Laurence
