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:

quoted

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)

quoted

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....

quoted

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.
-- 
Dave Chinner
david@fromorbit.com