SCSI target logs

SCSI target logs

[Konstantin Shelekhin]

Hi,

For the last couple of days I've been thinking how to improve the target
logs. My pain points:

  1. There is no common prefix for the subsystem
  2. It's kinda hard to determine which I-T-L nexus was affected

For example:

  [Thu May 11 00:00:00 2023] Waiting for running cmds to complete.

Or something even more sinister:

  [Thu May 11 00:00:00 2023] bio error: 0xfffffffff, err 10

Only someone familiar with the kernel code can tell that this is
actually target_core_iblock discovering an I/O error.

While all of this is not a blocker per se, because a skilled enough
developer can connect all the dots, such analysis requires a lot of time
and patience on large systems with hundreds of ACLs and several TPGs.

Okay, so what the others do? PCI and USB subsystems clearly enjoy having
a unique ID:

  [Thu May 11 00:00:00 2023] iwlwifi 0000:00:14.3: WFPM_UMAC_PD_NOTIFICATION: 0x1f
  [Thu May 11 00:00:00 2023] usb 3-7: reset high-speed USB device number 2 using xhci_hcd

Quick look at the lspci/lsusb output is all it takes to understand which
device was affected.

Network interfaces enjoy having a user-friendly name:

  [Thu May 11 00:00:00 2023] wlan0: authenticate with cc:2d:e0:10:8d:b9

Same goes for file systems and block devices.

NVMe target uses pr_info(), benefiting from having neatly chosen module
names:

  [Thu May 11 00:00:00 2023] nvmet: Foo happened (NVMe core)
  [Thu May 11 00:00:00 2023] nvmet_fc: Bar happened (NVMe over FC)
  [Thu May 11 00:00:00 2023] nvmet_tcp: Foo happened (NVMe overTCP)

However, we don't get to known which NVMe Host was affected unless the
log line already contains the necessary info.

Back to the target. The simplest solution that at least gives the user
some context is to put this in each C file:

  #define pr_fmt(fmt) KBUILD_MODENAME  ": " fmt

But since target modules all named differently, one can't just

  $ dmesg | grep target_

like with NVMe target. You'll have to do this:

  $ dmesg | grep -E '_target_|tcm_|isert|cxgbit'

That's because we have target_core_mod, isert, cxgbit, iscsi_target_mod,
tcm_qla2xxx and so on. Yikes, but this is still an improvement. However,
it does not give us any clue about the affected I-T-L nexus.

So, my proposal. We should give all modules similar names:

  tcm
  tcm_iscsi
  tcm_iser
  tcm_qla2xxx
  tcm_iblock
  tcm_loop
  tcm_cxgb

I would prefer scsit_ instead of tcm_, but I guess this ship has sailed.

Next, let's introduce some macros: tcm_LEVEL(), tcm_sess_LEVEL() and
tcm_lun_LEVEL():

  tcm_err("This module blew up\n")
  [Thu May 11 00:00:00 2023] tcm_iser: This module blew up
                             ^^^^^^^^
                             |
                             Module name

  tcm_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
  [Thu May 11 00:00:00 2023] tcm_iscsi [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.
                             ^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^
                             |          |                                    |
                             |          |                                    RTPI
                             |          Initiator port
                             Module name

  tcm_lun_err(&se_lun, "bio error %p, err: %d\n", bio, bio_status)
  [Thu May 11 00:00:00 2023] tcm_iblock [iqn.2023-01.com.example:blah-blah -> 10/5]: bio error: 0xfffffffff, err 10
                             ^^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^ ^
                             |           |                                    |  |
                             |           |                                    |  MAPPED LUN
                             |           |                                    RTPI
                             |           Initiator port
                             Module name

Sorry for the long email, just needed to swap out all this. Thoughts?

Re: SCSI target logs

[Mike Christie]

On 5/11/23 10:40 AM, Konstantin Shelekhin wrote:
> Hi,
> 
> For the last couple of days I've been thinking how to improve the target
> logs. My pain points:
> 
>   1. There is no common prefix for the subsystem
>   2. It's kinda hard to determine which I-T-L nexus was affected
> 
> For example:
> 
>   [Thu May 11 00:00:00 2023] Waiting for running cmds to complete.
> 
> Or something even more sinister:
> 
>   [Thu May 11 00:00:00 2023] bio error: 0xfffffffff, err 10
> 
> Only someone familiar with the kernel code can tell that this is
> actually target_core_iblock discovering an I/O error.
> 
> While all of this is not a blocker per se, because a skilled enough
> developer can connect all the dots, such analysis requires a lot of time
> and patience on large systems with hundreds of ACLs and several TPGs.
> 
> Okay, so what the others do? PCI and USB subsystems clearly enjoy having
> a unique ID:
> 
>   [Thu May 11 00:00:00 2023] iwlwifi 0000:00:14.3: WFPM_UMAC_PD_NOTIFICATION: 0x1f
>   [Thu May 11 00:00:00 2023] usb 3-7: reset high-speed USB device number 2 using xhci_hcd
> 
> Quick look at the lspci/lsusb output is all it takes to understand which
> device was affected.
> 
> Network interfaces enjoy having a user-friendly name:
> 
>   [Thu May 11 00:00:00 2023] wlan0: authenticate with cc:2d:e0:10:8d:b9
> 
> Same goes for file systems and block devices.
> 
> NVMe target uses pr_info(), benefiting from having neatly chosen module
> names:
> 
>   [Thu May 11 00:00:00 2023] nvmet: Foo happened (NVMe core)
>   [Thu May 11 00:00:00 2023] nvmet_fc: Bar happened (NVMe over FC)
>   [Thu May 11 00:00:00 2023] nvmet_tcp: Foo happened (NVMe overTCP)
> 
> However, we don't get to known which NVMe Host was affected unless the
> log line already contains the necessary info.
> 
> Back to the target. The simplest solution that at least gives the user
> some context is to put this in each C file:
> 
>   #define pr_fmt(fmt) KBUILD_MODENAME  ": " fmt
> 
> But since target modules all named differently, one can't just
> 
>   $ dmesg | grep target_
> 
> like with NVMe target. You'll have to do this:
> 
>   $ dmesg | grep -E '_target_|tcm_|isert|cxgbit'
> 
> That's because we have target_core_mod, isert, cxgbit, iscsi_target_mod,
> tcm_qla2xxx and so on. Yikes, but this is still an improvement. However,
> it does not give us any clue about the affected I-T-L nexus.
> 
> So, my proposal. We should give all modules similar names:
> 
>   tcm
>   tcm_iscsi
>   tcm_iser
>   tcm_qla2xxx
>   tcm_iblock
>   tcm_loop
>   tcm_cxgb

Do you mean you will rename the actual modules, or just have each module
have some define with a name like "tcm_$WHATEVER" that's used in the log
message?

I don't think we can change the actual name because scripts might do

modprobe isert

Unless there's a way to do some sort of automatic/magic alias then it
would be ok.


> 
> I would prefer scsit_ instead of tcm_, but I guess this ship has sailed.
> 
> Next, let's introduce some macros: tcm_LEVEL(), tcm_sess_LEVEL() and


We've been switching new code to the "target_" prefix.


> tcm_lun_LEVEL():
> 
>   tcm_err("This module blew up\n")
>   [Thu May 11 00:00:00 2023] tcm_iser: This module blew up
>                              ^^^^^^^^
>                              |
>                              Module name
> 
>   tcm_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
>   [Thu May 11 00:00:00 2023] tcm_iscsi [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.
>                              ^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^
>                              |          |                                    |
>                              |          |                                    RTPI
>                              |          Initiator port
>                              Module name
> 
>   tcm_lun_err(&se_lun, "bio error %p, err: %d\n", bio, bio_status)
>   [Thu May 11 00:00:00 2023] tcm_iblock [iqn.2023-01.com.example:blah-blah -> 10/5]: bio error: 0xfffffffff, err 10
>                              ^^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^ ^
>                              |           |                                    |  |
>                              |           |                                    |  MAPPED LUN
>                              |           |                                    RTPI
>                              |           Initiator port
>                              Module name


Nice.

Re: SCSI target logs

[Konstantin Shelekhin]

On Sat, May 20, 2023 at 12:56:29PM -0500, Mike Christie wrote:
> On 5/11/23 10:40 AM, Konstantin Shelekhin wrote:
> > So, my proposal. We should give all modules similar names:
> >
> >   tcm
> >   tcm_iscsi
> >   tcm_iser
> >   tcm_qla2xxx
> >   tcm_iblock
> >   tcm_loop
> >   tcm_cxgb
> 
> Do you mean you will rename the actual modules, or just have each module
> have some define with a name like "tcm_$WHATEVER" that's used in the log
> message?
> 
> I don't think we can change the actual name because scripts might do
> modprobe isert
> 
> Unless there's a way to do some sort of automatic/magic alias then it
> would be ok.

We have MODULE_ALIAS(), so it's possible to do something similar to
drivers/md/raid5.c:

  # lsmod | grep -c '^raid456'
  0
  # modprobe raid5
  # lsmod | grep '^raid456'
  raid456               204800  0
  # doas rmmod raid456
  # lsmod | grep -c '^raid456'
  0
  # doas modprobe raid6
  # lsmod | grep '^raid456'
  raid456               204800  0 
 
> > I would prefer scsit_ instead of tcm_, but I guess this ship has sailed.
> >
> > Next, let's introduce some macros: tcm_LEVEL(), tcm_sess_LEVEL() and
> 
> We've been switching new code to the "target_" prefix.

Yeah, forgot about that. target_LEVEL() and target_sess_LEVEL() then.
 
> > tcm_lun_LEVEL():
> >
> >   tcm_err("This module blew up\n")
> >   [Thu May 11 00:00:00 2023] tcm_iser: This module blew up
> >                              ^^^^^^^^
> >                              |
> >                              Module name
> >
> >   tcm_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
> >   [Thu May 11 00:00:00 2023] tcm_iscsi [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.
> >                              ^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^
> >                              |          |                                    |
> >                              |          |                                    RTPI
> >                              |          Initiator port
> >                              Module name
> >
> >   tcm_lun_err(&se_lun, "bio error %p, err: %d\n", bio, bio_status)
> >   [Thu May 11 00:00:00 2023] tcm_iblock [iqn.2023-01.com.example:blah-blah -> 10/5]: bio error: 0xfffffffff, err 10
> >                              ^^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^    ^^ ^
> >                              |           |                                    |  |
> >                              |           |                                    |  MAPPED LUN
> >                              |           |                                    RTPI
> >                              |           Initiator port
> >                              Module name
> 
> Nice.

Sweet! If you approve the general idea, we'll start working on the RFC
patch series.

Re: SCSI target logs

[Mike Christie]

On 5/21/23 4:36 AM, Konstantin Shelekhin wrote:
> On Sat, May 20, 2023 at 12:56:29PM -0500, Mike Christie wrote:
>> On 5/11/23 10:40 AM, Konstantin Shelekhin wrote:
>>> So, my proposal. We should give all modules similar names:
>>>
>>>   tcm
>>>   tcm_iscsi
>>>   tcm_iser
>>>   tcm_qla2xxx
>>>   tcm_iblock
>>>   tcm_loop
>>>   tcm_cxgb
>> Do you mean you will rename the actual modules, or just have each module
>> have some define with a name like "tcm_$WHATEVER" that's used in the log
>> message?
>>
>> I don't think we can change the actual name because scripts might do
>> modprobe isert
>>
>> Unless there's a way to do some sort of automatic/magic alias then it
>> would be ok.
> We have MODULE_ALIAS(), so it's possible to do something similar to
> drivers/md/raid5.c:

Ah ok, nice.

What is the target_core_fabric_ops->fabric_name going to be?

I think that can't change or it will break userspace tools like rtslib/targetlci
right? It would change the /sys/kernel/config/target/$fabric_name path?

Do you want the module level error message to match to the fabric_name
or the module name? I think the fabric_name is nicer, because it's what
the users normally use to interact with the tools/kernel.

Other than that, I think it's ok.

Re: SCSI target logs

[Konstantin Shelekhin]

On Tue, May 23, 2023 at 10:40:25AM -0500, Mike Christie wrote:
> > We have MODULE_ALIAS(), so it's possible to do something similar to
> > drivers/md/raid5.c:
> 
> Ah ok, nice.
> 
> What is the target_core_fabric_ops->fabric_name going to be?
> 
> I think that can't change or it will break userspace tools like rtslib/targetlci
> right? It would change the /sys/kernel/config/target/$fabric_name path?

Yeah, we surely can't do that.
 
> Do you want the module level error message to match to the fabric_name
> or the module name? I think the fabric_name is nicer, because it's what
> the users normally use to interact with the tools/kernel.
> 
> Other than that, I think it's ok.

Actually the whole module renaming idea came to me after studying the
NVMe target code, because of how neatly the module names reflect the
code units. As for the SCSI target, maybe instead of using module names
we can do something similar to what device mapper does with DM_PREFIX
and get away with simply stating this in core modules:

  TARGET_PREFIX core

This in fabric modules:

  TARGET_PREFIX <fabric-name>

And this in backstore modules:

  TARGET_PREFIX <bs-name>

So the resulting messages would be something like this:

  target_err("This module blew up\n")
  [Thu May 11 00:00:00 2023] target iser: This module blew up

  target_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
  [Thu May 11 00:00:00 2023] target iscsi [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.

We can do the very same thing with this:

  pr_fmt(fmt) "target <fabric-name>": fmt

but then we will have one extra ":" here:

  target_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
  [Thu May 11 00:00:00 2023] target iscsi: [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.

Dunno how much of an OCD issue this is :D

Re: SCSI target logs

[Konstantin Shelekhin]

On Wed, May 24, 2023 at 11:54:45AM +0300, Konstantin Shelekhin wrote:
> We can do the very same thing with this:
> 
>   pr_fmt(fmt) "target <fabric-name>": fmt
> 
> but then we will have one extra ":" here:
> 
>   target_sess_err(&se_sess, "Waiting for running cmds to complete.\n")
>   [Thu May 11 00:00:00 2023] target iscsi: [iqn.2023-01.com.example:blah-blah -> 10]: Waiting for running cmds to complete.
> 
> Dunno how much of an OCD issue this is :D

Disregard this, we can't do this with pr_fmt() because theree is no way
to hook in between "target <fabric-name" and fmt.