| Message ID | 20191223225558.19242-10-tasleson@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | Add persistent durable identifier to storage log messages | expand |
On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote: > Add persistent durable name to xfs messages so we can > correlate them with other messages for the same block > device. > > Signed-off-by: Tony Asleson <tasleson@redhat.com> > --- > fs/xfs/xfs_message.c | 17 +++++++++++++++++ > 1 file changed, 17 insertions(+) > > diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c > index 9804efe525a9..8447cdd985b4 100644 > --- a/fs/xfs/xfs_message.c > +++ b/fs/xfs/xfs_message.c > @@ -20,6 +20,23 @@ __xfs_printk( > const struct xfs_mount *mp, > struct va_format *vaf) > { > + char dict[128]; > + int dict_len = 0; > + > + if (mp && mp->m_super && mp->m_super->s_bdev && > + mp->m_super->s_bdev->bd_disk) { > + dict_len = dev_durable_name( > + disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent, > + dict, > + sizeof(dict)); > + if (dict_len) { > + printk_emit( > + 0, level[1] - '0', dict, dict_len, > + "XFS (%s): %pV\n", mp->m_fsname, vaf); > + return; > + } > + } NACK on the ground this is a gross hack. > + > if (mp && mp->m_fsname) { mp->m_fsname is the name of the device we use everywhere for log messages, it's set up at mount time so we don't have to do runtime evaulation of the device name every time we need to emit the device name in a log message. So, if you have some sooper speshial new device naming scheme, it needs to be stored into the struct xfs_mount to replace mp->m_fsname. And if you have some sooper spehsial new printk API that uses this new device name, everything XFS emits needs to use it unconditionally as we do with mp->m_fsname now. IOWs, this isn't conditional code - it either works for the entire life of the mount for every message we have to emit with a single setup call, or the API is broken and needs to be rethought. Cheers, Dave.
On 1/3/20 8:56 PM, Dave Chinner wrote: > On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote: >> Add persistent durable name to xfs messages so we can >> correlate them with other messages for the same block >> device. >> >> Signed-off-by: Tony Asleson <tasleson@redhat.com> >> --- >> fs/xfs/xfs_message.c | 17 +++++++++++++++++ >> 1 file changed, 17 insertions(+) >> >> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c >> index 9804efe525a9..8447cdd985b4 100644 >> --- a/fs/xfs/xfs_message.c >> +++ b/fs/xfs/xfs_message.c >> @@ -20,6 +20,23 @@ __xfs_printk( >> const struct xfs_mount *mp, >> struct va_format *vaf) >> { >> + char dict[128]; >> + int dict_len = 0; >> + >> + if (mp && mp->m_super && mp->m_super->s_bdev && >> + mp->m_super->s_bdev->bd_disk) { >> + dict_len = dev_durable_name( >> + disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent, >> + dict, >> + sizeof(dict)); >> + if (dict_len) { >> + printk_emit( >> + 0, level[1] - '0', dict, dict_len, >> + "XFS (%s): %pV\n", mp->m_fsname, vaf); >> + return; >> + } >> + } > > NACK on the ground this is a gross hack. James suggested I utilize dev_printk, which does make things simpler. Would something like this be acceptable? diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c index 9804efe525a9..0738c74a8d3a 100644 --- a/fs/xfs/xfs_message.c +++ b/fs/xfs/xfs_message.c @@ -20,11 +20,18 @@ __xfs_printk( const struct xfs_mount *mp, struct va_format *vaf) { + struct device *dev = NULL; + + if (mp && mp->m_super && mp->m_super->s_bdev && + mp->m_super->s_bdev->bd_disk) { + dev = disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent; + } + if (mp && mp->m_fsname) { - printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf); + dev_printk(level, dev, "XFS (%s): %pV\n", mp->m_fsname, vaf); return; } - printk("%sXFS: %pV\n", level, vaf); + dev_printk(level, dev, "XFS: %pV\n", vaf); } >> + >> if (mp && mp->m_fsname) { > > mp->m_fsname is the name of the device we use everywhere for log > messages, it's set up at mount time so we don't have to do runtime > evaulation of the device name every time we need to emit the device > name in a log message. > > So, if you have some sooper speshial new device naming scheme, it > needs to be stored into the struct xfs_mount to replace mp->m_fsname. I don't think we want to replace mp->m_fsname with the vpd 0x83 device identifier. This proposed change is adding a key/value structured data to the log message for non-ambiguous device identification over time, not to place the ID in the human readable portion of the message. The existing name is useful too, especially when it involves a partition. > And if you have some sooper spehsial new printk API that uses this > new device name, everything XFS emits needs to use it > unconditionally as we do with mp->m_fsname now. > > IOWs, this isn't conditional code - it either works for the entire > life of the mount for every message we have to emit with a single > setup call, or the API is broken and needs to be rethought. I've been wondering why the struct scsi device uses rcu data for the vpd as I would not think that it would be changing for a specific device. Perhaps James can shed some light on this? -Tony
On Sun, Jan 05, 2020 at 08:45:00PM -0600, Tony Asleson wrote: > On 1/3/20 8:56 PM, Dave Chinner wrote: > > On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote: > >> Add persistent durable name to xfs messages so we can > >> correlate them with other messages for the same block > >> device. > >> > >> Signed-off-by: Tony Asleson <tasleson@redhat.com> > >> --- > >> fs/xfs/xfs_message.c | 17 +++++++++++++++++ > >> 1 file changed, 17 insertions(+) > >> > >> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c > >> index 9804efe525a9..8447cdd985b4 100644 > >> --- a/fs/xfs/xfs_message.c > >> +++ b/fs/xfs/xfs_message.c > >> @@ -20,6 +20,23 @@ __xfs_printk( > >> const struct xfs_mount *mp, > >> struct va_format *vaf) > >> { > >> + char dict[128]; > >> + int dict_len = 0; > >> + > >> + if (mp && mp->m_super && mp->m_super->s_bdev && > >> + mp->m_super->s_bdev->bd_disk) { > >> + dict_len = dev_durable_name( > >> + disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent, > >> + dict, > >> + sizeof(dict)); > >> + if (dict_len) { > >> + printk_emit( > >> + 0, level[1] - '0', dict, dict_len, > >> + "XFS (%s): %pV\n", mp->m_fsname, vaf); > >> + return; > >> + } > >> + } > > > > NACK on the ground this is a gross hack. > > James suggested I utilize dev_printk, which does make things simpler. > Would something like this be acceptable? > > diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c > index 9804efe525a9..0738c74a8d3a 100644 > --- a/fs/xfs/xfs_message.c > +++ b/fs/xfs/xfs_message.c > @@ -20,11 +20,18 @@ __xfs_printk( > const struct xfs_mount *mp, > struct va_format *vaf) > { > + struct device *dev = NULL; > + > + if (mp && mp->m_super && mp->m_super->s_bdev && > + mp->m_super->s_bdev->bd_disk) { > + dev = disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent; > + } > + > if (mp && mp->m_fsname) { > - printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf); > + dev_printk(level, dev, "XFS (%s): %pV\n", mp->m_fsname, > vaf); > return; > } > - printk("%sXFS: %pV\n", level, vaf); > + dev_printk(level, dev, "XFS: %pV\n", vaf); No, because that's just doing the same thing involving dynamic extraction of static, unchanging information. Only now we get the output looking like: [ts] "<driver string> <dev name>: XFS (<dev name>): <message>" Or we get: [ts] "(NULL device *): XFS: <message>" Both of which don't provide any extra useful information to the person/script parsing the log message. Oh, and calling dev_printk() with a null dev pointer is likely to panic the machine in dev_driver_string(). > } > > >> + > >> if (mp && mp->m_fsname) { > > > > mp->m_fsname is the name of the device we use everywhere for log > > messages, it's set up at mount time so we don't have to do runtime > > evaulation of the device name every time we need to emit the device > > name in a log message. > > > > So, if you have some sooper speshial new device naming scheme, it > > needs to be stored into the struct xfs_mount to replace mp->m_fsname. > > I don't think we want to replace mp->m_fsname with the vpd 0x83 device > identifier. This proposed change is adding a key/value structured data > to the log message for non-ambiguous device identification over time, > not to place the ID in the human readable portion of the message. The > existing name is useful too, especially when it involves a partition. Oh, if that's all you want to do, then why is this identifier needed in every log message? It does not change over the life of the filesystem, so it the persistent identifier only needs to be emitted to the log once at filesystem mount time. i.e. instead of: [ 2.716841] XFS (dm-0): Mounting V5 Filesystem It just needs to be: [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id> If you need to do any sort of special "is this the right device" checking, it needs to be done immediately at mount time so action can be taken to shutdown the filesystem and unmount the device immediately before further damage is done.... i.e. once the filesystem is mounted, you've already got a unique and persistent identifier in the log for the life of the filesystem (the m_fsname string), so I'm struggling to understand exactly what problem you are trying to solve by adding redundant information to every log message..... > > And if you have some sooper spehsial new printk API that uses this > > new device name, everything XFS emits needs to use it > > unconditionally as we do with mp->m_fsname now. > > > > IOWs, this isn't conditional code - it either works for the entire > > life of the mount for every message we have to emit with a single > > setup call, or the API is broken and needs to be rethought. > > I've been wondering why the struct scsi device uses rcu data for the vpd > as I would not think that it would be changing for a specific device. > Perhaps James can shed some light on this? The implementation of the in-memory driver vpd data page has no relationship to the lifetime of the persistent information that the VPD stores/reports. Cheers, Dave.
> > >> + > > >> if (mp && mp->m_fsname) { > > > > > > mp->m_fsname is the name of the device we use everywhere for log > > > messages, it's set up at mount time so we don't have to do runtime > > > evaulation of the device name every time we need to emit the device > > > name in a log message. > > > > > > So, if you have some sooper speshial new device naming scheme, it > > > needs to be stored into the struct xfs_mount to replace mp->m_fsname. > > > > I don't think we want to replace mp->m_fsname with the vpd 0x83 device > > identifier. This proposed change is adding a key/value structured data > > to the log message for non-ambiguous device identification over time, > > not to place the ID in the human readable portion of the message. The > > existing name is useful too, especially when it involves a partition. > > Oh, if that's all you want to do, then why is this identifier needed > in every log message? It does not change over the life of the > filesystem, so it the persistent identifier only needs to be emitted > to the log once at filesystem mount time. i.e. instead of: > > [ 2.716841] XFS (dm-0): Mounting V5 Filesystem > > It just needs to be: > > [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id> > > If you need to do any sort of special "is this the right device" > checking, it needs to be done immediately at mount time so action > can be taken to shutdown the filesystem and unmount the device > immediately before further damage is done.... > > i.e. once the filesystem is mounted, you've already got a unique and > persistent identifier in the log for the life of the filesystem (the > m_fsname string), so I'm struggling to understand exactly what > problem you are trying to solve by adding redundant information > to every log message..... > Log rotation loses that identifier though; there are plenty of setups where a mount-time message has been rotated out of all logs by the time something goes wrong after a month or two.
On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote: > > > >> + > > > >> if (mp && mp->m_fsname) { > > > > > > > > mp->m_fsname is the name of the device we use everywhere for log > > > > messages, it's set up at mount time so we don't have to do runtime > > > > evaulation of the device name every time we need to emit the device > > > > name in a log message. > > > > > > > > So, if you have some sooper speshial new device naming scheme, it > > > > needs to be stored into the struct xfs_mount to replace mp->m_fsname. > > > > > > I don't think we want to replace mp->m_fsname with the vpd 0x83 device > > > identifier. This proposed change is adding a key/value structured data > > > to the log message for non-ambiguous device identification over time, > > > not to place the ID in the human readable portion of the message. The > > > existing name is useful too, especially when it involves a partition. > > > > Oh, if that's all you want to do, then why is this identifier needed > > in every log message? It does not change over the life of the > > filesystem, so it the persistent identifier only needs to be emitted > > to the log once at filesystem mount time. i.e. instead of: > > > > [ 2.716841] XFS (dm-0): Mounting V5 Filesystem > > > > It just needs to be: > > > > [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id> > > > > If you need to do any sort of special "is this the right device" > > checking, it needs to be done immediately at mount time so action > > can be taken to shutdown the filesystem and unmount the device > > immediately before further damage is done.... > > > > i.e. once the filesystem is mounted, you've already got a unique and > > persistent identifier in the log for the life of the filesystem (the > > m_fsname string), so I'm struggling to understand exactly what > > problem you are trying to solve by adding redundant information > > to every log message..... > > Log rotation loses that identifier though; there are plenty of setups > where a mount-time message has been rotated out of all logs by the > time something goes wrong after a month or two. At what point months after you've mounted the filesystem do you care about whether the correct device was mounted or not? And, for the log rotation case, the filesystem log output already has a unique, persistent identifier for the life of the mount - the fsname ("dm-0" in the above example). We don't need to add a new device identifier to the XFS log messages to solve that problem because *we've already got a device identifier in the log messages*. Again - the "is this the right device" information only makes sense to be checked at mount time. If it was the right device at mount time, then after months of uptime how would it suddenly become "the wrong device"? And if it's the wrong device at mount time, then you need to take action *immediately*, not after using the filesysetms on the device for months... Cheers, Dave.
On 1/6/20 7:23 PM, Dave Chinner wrote: > On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote: >>>>>> + >>>>>> if (mp && mp->m_fsname) { >>>>> >>>>> mp->m_fsname is the name of the device we use everywhere for log >>>>> messages, it's set up at mount time so we don't have to do runtime >>>>> evaulation of the device name every time we need to emit the device >>>>> name in a log message. >>>>> >>>>> So, if you have some sooper speshial new device naming scheme, it >>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname. >>>> >>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device >>>> identifier. This proposed change is adding a key/value structured data >>>> to the log message for non-ambiguous device identification over time, >>>> not to place the ID in the human readable portion of the message. The >>>> existing name is useful too, especially when it involves a partition. >>> >>> Oh, if that's all you want to do, then why is this identifier needed >>> in every log message? The value is we can filter all the messages by the id as they are all individually identifiable. The structured data id that the patch series adds is not outputted by default by journalctl. Please look at cover letter in patch series for example filter use. You can see all the data in the journal entries by using journalctl -o json-pretty. One can argue that we are adding a lot of data to each log message as the VPD data isn't trivial. This could be mitigated by hashing the VPD and storing the hash as the ID, but that makes it less user friendly. However, maybe it should be considered. >>> It does not change over the life of the >>> filesystem, so it the persistent identifier only needs to >>> be emitted to the log once at filesystem mount time. i.e. >>> instead of: >>> >>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem >>> >>> It just needs to be: >>> >>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id> >>> >>> If you need to do any sort of special "is this the right device" >>> checking, it needs to be done immediately at mount time so action >>> can be taken to shutdown the filesystem and unmount the device >>> immediately before further damage is done.... >>> >>> i.e. once the filesystem is mounted, you've already got a unique and >>> persistent identifier in the log for the life of the filesystem (the >>> m_fsname string), so I'm struggling to understand exactly what >>> problem you are trying to solve by adding redundant information >>> to every log message..... m_fsname is only valid for the life of the mount, not the life of the FS. Each and every time we reboot, remove/reattach a device the attachment point may change and thus the m_fsname changes too. Then the user or script writer has to figure out what messages go with what device. This is true for all the different storage layer messages. Some layers use sda, sata1.00 or sd 0:0:0:0 and they all refer to the same device. We have no unambiguous way today to identify which messages go with what storage device across reboots and dynamic device re-configuration across the storage stack. >> >> Log rotation loses that identifier though; there are plenty of setups >> where a mount-time message has been rotated out of all logs by the >> time something goes wrong after a month or two. > > At what point months after you've mounted the filesystem do you care > about whether the correct device was mounted or not? This isn't a question about if the correct device was mounted or not. It's the question of what actual storage hardware was associated with the message(s), an association that doesn't change across reboots or dynamic device reconfiguration or if you move the physical device to another system. The cover letter example shows filtered output of one specific device encountering errors that has an XFS FS. Without this added ID it would not be so easy to determine that these messages all belong to the same device. In this case the attachment isn't changing, it's the simple case. When it does change over time it gets even more difficult. > And, for the log rotation case, the filesystem log output already > has a unique, persistent identifier for the life of the mount - the > fsname ("dm-0" in the above example). We don't need to add a new > device identifier to the XFS log messages to solve that problem > because *we've already got a device identifier in the log messages*. It's very useful to have an ID that persists and identifies across mounts. The existing id logging scheme tells you where something is attached, not what is attached. > Again - the "is this the right device" information only makes sense > to be checked at mount time. If it was the right device at mount > time, then after months of uptime how would it suddenly become "the > wrong device"? And if it's the wrong device at mount time, then you > need to take action *immediately*, not after using the filesysetms > on the device for months... > > Cheers, > > Dave. >
On Tue, Jan 07, 2020 at 11:01:47AM -0600, Tony Asleson wrote: > On 1/6/20 7:23 PM, Dave Chinner wrote: > > On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote: > >>>>>> + > >>>>>> if (mp && mp->m_fsname) { > >>>>> > >>>>> mp->m_fsname is the name of the device we use everywhere for log > >>>>> messages, it's set up at mount time so we don't have to do runtime > >>>>> evaulation of the device name every time we need to emit the device > >>>>> name in a log message. > >>>>> > >>>>> So, if you have some sooper speshial new device naming scheme, it > >>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname. > >>>> > >>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device > >>>> identifier. This proposed change is adding a key/value structured data > >>>> to the log message for non-ambiguous device identification over time, > >>>> not to place the ID in the human readable portion of the message. The > >>>> existing name is useful too, especially when it involves a partition. > >>> > >>> Oh, if that's all you want to do, then why is this identifier needed > >>> in every log message? > > The value is we can filter all the messages by the id as they are all > individually identifiable. Then what you want is the *filesystem label* or *filesystem UUID* in the *filesystem log output* to uniquely identify the *filesystem log output* regardless of the block device identifier the kernel assigned it's underlying disk. By trying to use the block device as the source of a persistent filesytem identifier, you are creating more new problems about uniqueness than you are solving. E.g. - there can be more than one filesystem per block device, so the identifier needs to be, at minimum, a {dev_id, partition} tuple. The existing bdev name (e.g. sda2) that filesystems emit contain this information. The underlying vpd device indentifier does not. - the filesystem on a device can change (e.g. mkfs), so an unchanged vpd identifier does not mean we mounted the same filesystem - raid devices are made up of multiple physical devices, so using device information for persistent identification is problematic, especially when devices fail and are replaced with different hardware. - clone a filesystem to a new device to replace a failing disk, block device identifier changes but the filesystem doesn't. Basically, if you need a *persistent filesystem identifier* for your log messages, then you cannot rely on the underlying device to provide that. Filesystems already have unique identifiers in them that can be used for this purpose, and we have mechanisms to allow users to configure them as well. IOWs, you're trying to tackle this "filesystem identifier" at the wrong layer - use the persistent filesystem identifiers to persitently identify the filesystem across mounts, not some random block device identifier. > The structured data id that the patch series adds is not outputted by > default by journalctl. Please look at cover letter in patch series for > example filter use. You can see all the data in the journal entries by > using journalctl -o json-pretty. Yes, I understand that. But my comments about adding redundant information to the log text output were directed at your suggestiong to use dev_printk() instead of printk to achieve what you want. That changes the log text output by prepending device specific strings to the filesystem output. > One can argue that we are adding a lot of data to each log message > as the VPD data isn't trivial. This could be mitigated by hashing > the VPD and storing the hash as the ID, but that makes it less > user friendly. However, maybe it should be considered. See above, I don't think the VPD information actually solves the problem you are seeking to solve. > >>> It does not change over the life of the filesystem, so it the > >>> persistent identifier only needs to >>> be > emitted to the log once at filesystem mount time. i.e. >>> > instead of: > >>> > >>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem > >>> > >>> It just needs to be: > >>> > >>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device > >>> <persistent dev id> > >>> > >>> If you need to do any sort of special "is this the right > >>> device" checking, it needs to be done immediately at mount > >>> time so action can be taken to shutdown the filesystem and > >>> unmount the device immediately before further damage is > >>> done.... > >>> > >>> i.e. once the filesystem is mounted, you've already got a > >>> unique and persistent identifier in the log for the life of > >>> the filesystem (the m_fsname string), so I'm struggling to > >>> understand exactly what problem you are trying to solve by > >>> adding redundant information to every log message..... > > m_fsname is only valid for the life of the mount, not the life of > the FS. Each and every time we reboot, remove/reattach a device > the attachment point may change and thus the m_fsname changes too. Well, yes, that's because m_fsname is currently aimed at identifying the block device that the filesytem is currently mounted on. That's the block device we *actually care about* when trying to diagnose problems reported in the log. From that perspective, I don't want the log output to change - it contains exactly what we need to diagnose problems when things go wrong. But for structured logging, using block device identifiers for the filesystem identifier is just wrong. If you need new information, append the UUID from the filesystem to the log message and use that instead. i.e your original printk_emit() function should pass mp->m_sb.sb_uuid as the post-message binary filesystem identifier, not the block device VPD information. If you need to convert the filesystem uuid to a block device, then you can just go look up /dev/disk/by-uuid/ and follow the link the filesystem uuid points to.... > > And, for the log rotation case, the filesystem log output > > already has a unique, persistent identifier for the life of the > > mount - the fsname ("dm-0" in the above example). We don't need > > to add a new device identifier to the XFS log messages to solve > > that problem because *we've already got a device identifier in > > the log messages*. > > It's very useful to have an ID that persists and identifies across > mounts. The existing id logging scheme tells you where something > is attached, not what is attached. Yup, that's what the filesystem labels and UUIDs provide. We've been using them for this purpose for a long, long time. Cheers, Dave.
On 1/7/20 8:10 PM, Dave Chinner wrote: > On Tue, Jan 07, 2020 at 11:01:47AM -0600, Tony Asleson wrote: >> On 1/6/20 7:23 PM, Dave Chinner wrote: >>> On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote: >>>>>>>> + >>>>>>>> if (mp && mp->m_fsname) { >>>>>>> >>>>>>> mp->m_fsname is the name of the device we use everywhere for log >>>>>>> messages, it's set up at mount time so we don't have to do runtime >>>>>>> evaulation of the device name every time we need to emit the device >>>>>>> name in a log message. >>>>>>> >>>>>>> So, if you have some sooper speshial new device naming scheme, it >>>>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname. >>>>>> >>>>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device >>>>>> identifier. This proposed change is adding a key/value structured data >>>>>> to the log message for non-ambiguous device identification over time, >>>>>> not to place the ID in the human readable portion of the message. The >>>>>> existing name is useful too, especially when it involves a partition. >>>>> >>>>> Oh, if that's all you want to do, then why is this identifier needed >>>>> in every log message? >> >> The value is we can filter all the messages by the id as they are all >> individually identifiable. > > Then what you want is the *filesystem label* or *filesystem UUID* > in the *filesystem log output* to uniquely identify the *filesystem > log output* regardless of the block device identifier the kernel > assigned it's underlying disk. > > By trying to use the block device as the source of a persistent > filesytem identifier, you are creating more new problems about > uniqueness than you are solving. E.g. > > - there can be more than one filesystem per block device, so the > identifier needs to be, at minimum, a {dev_id, partition} tuple. > The existing bdev name (e.g. sda2) that filesystems emit contain > this information. The underlying vpd device indentifier does not. We are not removing any existing information, we are adding. I think all the file systems should include their FS UUID in the FS log messages too, but that is not part of the problem we are trying to solve. > - the filesystem on a device can change (e.g. mkfs), so an unchanged > vpd identifier does not mean we mounted the same filesystem > > - raid devices are made up of multiple physical devices, so using > device information for persistent identification is problematic, > especially when devices fail and are replaced with different > hardware. For the desired use cases its not problematic. With this we would have a definitive id of which messages go with which disk. We know if the disk is still present in the system or if it went away and came back or if it showed up in some other system. We also have a definitive ID of which disk to yank from the system. > - clone a filesystem to a new device to replace a failing disk, > block device identifier changes but the filesystem doesn't. Yes, and now you have log messages for two filesystems which exist on different physical hardware which you cannot distinguish, if you leverage the FS UUID in the log messages. > Basically, if you need a *persistent filesystem identifier* for > your log messages, then you cannot rely on the underlying device to > provide that. Filesystems already have unique identifiers in them > that can be used for this purpose, and we have mechanisms to allow > users to configure them as well. I'm not advocating for a persistent filesystem id. Lets outline some user stories to help illustrate. I found a few log messages from 4 months ago, device sdk was experiencing media errors. How do I view the log messages for that device in my entire log history, through the entire storage stack from device driver to FS? I have a storage device that is intermittently failing, was this disk used anywhere else in our data center? Was it experiencing issues before? Is it in the same batch of disks we bought together that has been experiencing higher failure rates? I have 2 identical external USB storage devices, I bought them at the same time. They get moved around in my home for backup and sometimes I take one with when traveling. I occasionally use dd to backup one device to the other when the data is important and I haven't backed it up anywhere else. I found log messages that shows a device is intermittently having a problem, which one is it so I can contact the vendor for warranty replacement? Trying to solve these questions can be difficult with the existing convention of logging messages that look like: blk_update_request: I/O error, dev sda, sector 89364488 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0 The user has to systematically and methodically go through the logs trying to deduce what the identifier was referring to at the time of the error. This isn't trivial and virtually impossible at times depending on circumstances. > IOWs, you're trying to tackle this "filesystem identifier" at the > wrong layer - use the persistent filesystem identifiers to > persitently identify the filesystem across mounts, not some random > block device identifier. The vpd 0x83 is not random, it's the best thing we have to identify a piece of storage hardware. One issue is it's not available for every device. We need to find suitable ID's for those devices too. We aren't trying to persistently identify the FS, we are trying to persistently identify which messages go with which device. >> The structured data id that the patch series adds is not outputted by >> default by journalctl. Please look at cover letter in patch series for >> example filter use. You can see all the data in the journal entries by >> using journalctl -o json-pretty. > > Yes, I understand that. But my comments about adding redundant > information to the log text output were directed at your suggestiong to > use dev_printk() instead of printk to achieve what you want. That > changes the log text output by prepending device specific strings to > the filesystem output. > >> One can argue that we are adding a lot of data to each log message >> as the VPD data isn't trivial. This could be mitigated by hashing >> the VPD and storing the hash as the ID, but that makes it less >> user friendly. However, maybe it should be considered. > > See above, I don't think the VPD information actually solves the > problem you are seeking to solve. > >>>>> It does not change over the life of the filesystem, so it the >>>>> persistent identifier only needs to >>> be >> emitted to the log once at filesystem mount time. i.e. >>> >> instead of: >>>>> >>>>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem >>>>> >>>>> It just needs to be: >>>>> >>>>> [ 2.716841] XFS (dm-0): Mounting V5 Filesystem on device >>>>> <persistent dev id> >>>>> >>>>> If you need to do any sort of special "is this the right >>>>> device" checking, it needs to be done immediately at mount >>>>> time so action can be taken to shutdown the filesystem and >>>>> unmount the device immediately before further damage is >>>>> done.... >>>>> >>>>> i.e. once the filesystem is mounted, you've already got a >>>>> unique and persistent identifier in the log for the life of >>>>> the filesystem (the m_fsname string), so I'm struggling to >>>>> understand exactly what problem you are trying to solve by >>>>> adding redundant information to every log message..... >> >> m_fsname is only valid for the life of the mount, not the life of >> the FS. Each and every time we reboot, remove/reattach a device >> the attachment point may change and thus the m_fsname changes too. > > Well, yes, that's because m_fsname is currently aimed at identifying > the block device that the filesytem is currently mounted on. That's > the block device we *actually care about* when trying to diagnose > problems reported in the log. From that perspective, I don't want > the log output to change - it contains exactly what we need to > diagnose problems when things go wrong. > > But for structured logging, using block device identifiers for the > filesystem identifier is just wrong. If you need new information, > append the UUID from the filesystem to the log message and use that > instead. i.e your original printk_emit() function should pass > mp->m_sb.sb_uuid as the post-message binary filesystem identifier, > not the block device VPD information. > > If you need to convert the filesystem uuid to a block device, then > you can just go look up /dev/disk/by-uuid/ and follow the link the > filesystem uuid points to.... > >>> And, for the log rotation case, the filesystem log output >>> already has a unique, persistent identifier for the life of the >>> mount - the fsname ("dm-0" in the above example). We don't need >>> to add a new device identifier to the XFS log messages to solve >>> that problem because *we've already got a device identifier in >>> the log messages*. >> >> It's very useful to have an ID that persists and identifies across >> mounts. The existing id logging scheme tells you where something >> is attached, not what is attached. > > Yup, that's what the filesystem labels and UUIDs provide. We've been > using them for this purpose for a long, long time. FS UUIDs exist on the media, they can be duplicated, destroyed or fail to be read up due to media errors. They do serve an important function, esp. mounting, but they don't address the use cases described above.
On Wed, Jan 08, 2020 at 10:53:13AM -0600, Tony Asleson wrote: > We are not removing any existing information, we are adding. A difficulty with this approach is: Where do you stop when your storage configuration is complicated and changing? Do you add the complete relevant part of the storage stack configuration to every storage message in the kernel so that it is easy to search later? Or do you catch the messages in userspace and add some of this information there before sending them on to your favourite log message database? (ref. peripety, various rsyslog extensions) > I think all the file systems should include their FS UUID in the FS log > messages too, but that is not part of the problem we are trying to solve. Each layer (subsystem) should already be tagging its messages in an easy-to-parse way so that all those relating to the same object (e.g. filesystem instance, disk) at its level of the stack can easily be matched together later. Where this doesn't already happen, we should certainly be fixing that as it's a pre-requisite for any sensible post-processing: As long as the right information got recorded, it can all be joined together on demand later by some userspace software. > The user has to systematically and methodically go through the logs > trying to deduce what the identifier was referring to at the time of the > error. This isn't trivial and virtually impossible at times depending > on circumstances. So how about logging what these identifiers reference at different times in a way that is easy to query later? Come to think of it, we already get uevents when the references change, and udev rules even already now create neat "by-*" links for us. Maybe we just need to log better what udev is actually already doing? Then we could reproduce what the storage configuration looked like at any particular time in the past to provide the missing context for the identifiers in the log messages. --------------------- Which seems like an appropriate time to introduce storage-logger. https://github.com/lvmteam/storage-logger Fedora rawhide packages: https://copr.fedorainfracloud.org/coprs/agk/storage-logger/ The goal of this particular project is to maintain a record of the storage configuration as it changes over time. It should provide a quick way to check the state of a system at a specified time in the past. The initial logging implementation is triggered by storage uevents and consists of two components: 1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after all the other rules have run and invokes: 2. A script, udev_storage_logger.sh, that captures relevant information about devices that changed and stores it in the system journal. The effect is to log the data from relevant uevents plus some supplementary information (including device-mapper tables, for example). It does not yet handle filesystem-related events. Two methods to query the data are offered: 1. journalctl Data is tagged with the identifier UDEVLOG and retrievable as key-value pairs. journalctl -t UDEVLOG --output verbose journalctl -t UDEVLOG --output json --since 'YYYY-MM-DD HH:MM:SS' --until 'YYYY-MM-DD HH:MM:SS' journalctl -t UDEVLOG --output verbose --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0 2. lsblkj [appended j for journal] This lsblk wrapper reprocesses the logged uevents to reconstruct a dummy system environment that "looks like" the system did at a specified earlier time and then runs lsblk against it. Yes, I'm looking for feedback to help to decide whether or not it's worth developing this any further. Alasdair
On Thu, Jan 09, 2020 at 01:41:17AM +0000, Alasdair G Kergon wrote: > On Wed, Jan 08, 2020 at 10:53:13AM -0600, Tony Asleson wrote: > > We are not removing any existing information, we are adding. > > A difficulty with this approach is: Where do you stop when your storage > configuration is complicated and changing? Do you add the complete > relevant part of the storage stack configuration to every storage > message in the kernel so that it is easy to search later? > > Or do you catch the messages in userspace and add some of this > information there before sending them on to your favourite log message > database? (ref. peripety, various rsyslog extensions) > > > I think all the file systems should include their FS UUID in the FS log > > messages too, but that is not part of the problem we are trying to solve. > > Each layer (subsystem) should already be tagging its messages in an > easy-to-parse way so that all those relating to the same object (e.g. > filesystem instance, disk) at its level of the stack can easily be > matched together later. Where this doesn't already happen, we should > certainly be fixing that as it's a pre-requisite for any sensible > post-processing: As long as the right information got recorded, it can > all be joined together on demand later by some userspace software. *nod* That was the essence of my suggestion that the filesystem mount log notification emits it's persistent identifier. If you need it to be logged, that's where the verbose identifier output should be.... > > The user has to systematically and methodically go through the logs > > trying to deduce what the identifier was referring to at the time of the > > error. This isn't trivial and virtually impossible at times depending > > on circumstances. > > So how about logging what these identifiers reference at different times > in a way that is easy to query later? > > Come to think of it, we already get uevents when the references change, > and udev rules even already now create neat "by-*" links for us. Maybe > we just need to log better what udev is actually already doing? Right, this is essentially what I've been trying to point out - I even used the by-uuid links as an example of how the filesystem is persistently identified by existing system boot infrastructure. :) > Then we could reproduce what the storage configuration looked like at > any particular time in the past to provide the missing context for > the identifiers in the log messages. > > --------------------- > > Which seems like an appropriate time to introduce storage-logger. > > https://github.com/lvmteam/storage-logger > > Fedora rawhide packages: > https://copr.fedorainfracloud.org/coprs/agk/storage-logger/ > > The goal of this particular project is to maintain a record of the > storage configuration as it changes over time. It should provide a > quick way to check the state of a system at a specified time in the > past. > > The initial logging implementation is triggered by storage uevents and > consists of two components: > > 1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after > all the other rules have run and invokes: > > 2. A script, udev_storage_logger.sh, that captures relevant > information about devices that changed and stores it in the system > journal. > > The effect is to log the data from relevant uevents plus some > supplementary information (including device-mapper tables, for example). > It does not yet handle filesystem-related events. There are very few filesystem uevents issued that you could log, anyway. Certainly nothing standardised across filesystems.... > Two methods to query the data are offered: > > 1. journalctl > Data is tagged with the identifier UDEVLOG and retrievable as > key-value pairs. > journalctl -t UDEVLOG --output verbose > journalctl -t UDEVLOG --output json > --since 'YYYY-MM-DD HH:MM:SS' > --until 'YYYY-MM-DD HH:MM:SS' > journalctl -t UDEVLOG --output verbose > --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR > PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0 > > 2. lsblkj [appended j for journal] > This lsblk wrapper reprocesses the logged uevents to reconstruct a > dummy system environment that "looks like" the system did at a > specified earlier time and then runs lsblk against it. Yeah, and if you add the equivalent of 'lsblk -f' then you also get the fs UUID to identify the filesystem on the block device at a given time.... > Yes, I'm looking for feedback to help to decide whether or not it's > worth developing this any further. This seems like a more flexible approach to me - it allows for text-based system loggers a hook to capture this device information, too, and hence implement their own post-processing scripts to provide the same lifetime information. Cheers, Dave.
On Fri, Jan 10, 2020 at 10:22:44AM +1100, Dave Chinner wrote: > Yeah, and if you add the equivalent of 'lsblk -f' then you also get > the fs UUID to identify the filesystem on the block device at a > given time.... The UUID usually already gets recorded and displayed: # lsblkj -f --until "2020-01-09 22:00:00" NAME FSTYPE FSVER LABEL UUID FSAVAIL FSUSE% MOUNTPOINT sda ├─sda1 xfs 78524ad6-6445-4bb6-840b-194871231274 ... (It's also capturing something simple for mountpoint when it can, but so far that's only visible with journalctl.) Alasdair
On 1/8/20 7:41 PM, Alasdair G Kergon wrote: > The goal of this particular project is to maintain a record of the > storage configuration as it changes over time. It should provide a > quick way to check the state of a system at a specified time in the > past. This helps with one aspect of the problem, it leaves a bread crumb which states that at this point in time /dev/sda was the attachment point for some device, eg. wwn-0x5002538844580000. > The initial logging implementation is triggered by storage uevents and > consists of two components: > > 1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after > all the other rules have run and invokes: > > 2. A script, udev_storage_logger.sh, that captures relevant > information about devices that changed and stores it in the system > journal. > > The effect is to log the data from relevant uevents plus some > supplementary information (including device-mapper tables, for example). > It does not yet handle filesystem-related events. > > Two methods to query the data are offered: > > 1. journalctl > Data is tagged with the identifier UDEVLOG and retrievable as > key-value pairs. > journalctl -t UDEVLOG --output verbose > journalctl -t UDEVLOG --output json > --since 'YYYY-MM-DD HH:MM:SS' > --until 'YYYY-MM-DD HH:MM:SS' > journalctl -t UDEVLOG --output verbose > --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR > PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0 > > 2. lsblkj [appended j for journal] > This lsblk wrapper reprocesses the logged uevents to reconstruct a > dummy system environment that "looks like" the system did at a > specified earlier time and then runs lsblk against it. You've outlined how to view and filter on the added data and how to figure out what the configuration looked like a some point in the past, that adds one more piece of the puzzle. However, how would a user simply show all the log messages for a specific device over time? It looks like journalctl would need to have logic added to make this a seamless user experience, yes? Perhaps I'm missing something that makes the outlined use case above work?
diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c index 9804efe525a9..8447cdd985b4 100644 --- a/fs/xfs/xfs_message.c +++ b/fs/xfs/xfs_message.c @@ -20,6 +20,23 @@ __xfs_printk( const struct xfs_mount *mp, struct va_format *vaf) { + char dict[128]; + int dict_len = 0; + + if (mp && mp->m_super && mp->m_super->s_bdev && + mp->m_super->s_bdev->bd_disk) { + dict_len = dev_durable_name( + disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent, + dict, + sizeof(dict)); + if (dict_len) { + printk_emit( + 0, level[1] - '0', dict, dict_len, + "XFS (%s): %pV\n", mp->m_fsname, vaf); + return; + } + } + if (mp && mp->m_fsname) { printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf); return;
Add persistent durable name to xfs messages so we can correlate them with other messages for the same block device. Signed-off-by: Tony Asleson <tasleson@redhat.com> --- fs/xfs/xfs_message.c | 17 +++++++++++++++++ 1 file changed, 17 insertions(+)