| Message ID | 0bc6a322d6f9b812b1444b588b5036263f377455.1647495044.git.jof@thejof.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v0,1/2] Add XFS messages to printk index | expand |
On Wed, Mar 16, 2022 at 10:32:07PM -0700, Jonathan Lassoff wrote: > In order for end users to quickly react to new issues that come up in > production, it is proving useful to leverage the printk indexing system. > This printk index enables kernel developers to use calls to printk() > with changable ad-hoc format strings, while still enabling end users to > detect changes and develop a semi-stable interface for detecting and > parsing these messages. > > So that detailed XFS messages are captures by this printk index, this > patch wraps the xfs_<level> and xfs_alert_tag functions. > > Signed-off-by: Jonathan Lassoff <jof@thejof.com> > --- > fs/xfs/xfs_message.c | 22 +++++++++---------- > fs/xfs/xfs_message.h | 52 +++++++++++++++++++++++++++++++++++--------- > 2 files changed, 53 insertions(+), 21 deletions(-) > > diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c > index bc66d95c8d4c..cf86d5dd7ba8 100644 > --- a/fs/xfs/xfs_message.c > +++ b/fs/xfs/xfs_message.c > @@ -21,10 +21,10 @@ __xfs_printk( > struct va_format *vaf) > { > if (mp && mp->m_super) { > - printk("%sXFS (%s): %pV\n", level, mp->m_super->s_id, vaf); > + _printk("%sXFS (%s): %pV\n", level, mp->m_super->s_id, vaf); > return; > } > - printk("%sXFS: %pV\n", level, vaf); > + _printk("%sXFS: %pV\n", level, vaf); > } > > #define define_xfs_printk_level(func, kern_level) \ > @@ -48,19 +48,19 @@ void func(const struct xfs_mount *mp, const char *fmt, ...) \ > xfs_stack_trace(); \ > } \ > > -define_xfs_printk_level(xfs_emerg, KERN_EMERG); > -define_xfs_printk_level(xfs_alert, KERN_ALERT); > -define_xfs_printk_level(xfs_crit, KERN_CRIT); > -define_xfs_printk_level(xfs_err, KERN_ERR); > -define_xfs_printk_level(xfs_warn, KERN_WARNING); > -define_xfs_printk_level(xfs_notice, KERN_NOTICE); > -define_xfs_printk_level(xfs_info, KERN_INFO); > +define_xfs_printk_level(_xfs_emerg, KERN_EMERG); > +define_xfs_printk_level(_xfs_alert, KERN_ALERT); > +define_xfs_printk_level(_xfs_crit, KERN_CRIT); > +define_xfs_printk_level(_xfs_err, KERN_ERR); > +define_xfs_printk_level(_xfs_warn, KERN_WARNING); > +define_xfs_printk_level(_xfs_notice, KERN_NOTICE); > +define_xfs_printk_level(_xfs_info, KERN_INFO); > #ifdef DEBUG > -define_xfs_printk_level(xfs_debug, KERN_DEBUG); > +define_xfs_printk_level(_xfs_debug, KERN_DEBUG); > #endif > > void > -xfs_alert_tag( > +_xfs_alert_tag( > const struct xfs_mount *mp, > int panic_tag, > const char *fmt, ...) > diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h > index bb9860ec9a93..2d90daf96946 100644 > --- a/fs/xfs/xfs_message.h > +++ b/fs/xfs/xfs_message.h > @@ -6,29 +6,61 @@ > > struct xfs_mount; > > +#define xfs_printk_index_wrap(_p_func, kern_level, mp, fmt, ...) \ > +({\ > + printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt, ##__VA_ARGS__);\ > + _p_func(mp, fmt, ##__VA_ARGS__);\ > +}) > +#define xfs_alert_tag(mp, tag, fmt, ...) \ > +({\ > + printk_index_subsys_emit("%sXFS%s: ", KERN_ALERT, fmt, ##__VA_ARGS__);\ > + _xfs_alert_tag(mp, tag, fmt, ##__VA_ARGS__);\ > +}) > +#define xfs_emerg(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_emerg, KERN_EMERG, mp, fmt, ##__VA_ARGS__) > +#define xfs_alert(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_alert, KERN_ALERT, mp, fmt, ##__VA_ARGS__) > +#define xfs_crit(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_crit, KERN_CRIT, mp, fmt, ##__VA_ARGS__) > +#define xfs_err(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_err, KERN_ERR, mp, fmt, ##__VA_ARGS__) > +#define xfs_warn(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_warn, KERN_WARNING, mp, fmt, ##__VA_ARGS__) > +#define xfs_notice(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_notice, KERN_NOTICE, mp, fmt, ##__VA_ARGS__) > +#define xfs_info(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_info, KERN_INFO, mp, fmt, ##__VA_ARGS__) > +#ifdef DEBUG > +#define xfs_debug(mp, fmt, ...)\ > + xfs_printk_index_wrap(_xfs_debug, KERN_DEBUG, mp, fmt, ##__VA_ARGS__) > +#else > +#define xfs_debug(mp, fmt, ...) do {} while (0) > +#endif That's a nasty mess. To begin with, we most definitely do not want to have to define log level translations in multiple places so this needs to be reworked so the front end macros define everything and pass things down to the lower level functions. And, anyway, why can't you just drop printk_index_subsys_emit() into the define_xfs_printk_level() macro? The kern_level, the fmt string and the varargs are all available there... Anyway, there's more important high level stuff that needs explaining first. This is competely undocumented functionality and it's the first I've ever heard about it. There's nothing I can easily find to learn how this information being exposed to userspace is supposed to be used. The commit message is pretty much information free, but this is a new userspace ABI. What ABI constraints are we now subject to by exporting XFS log message formats to userspace places? i.e. Where's the documentation defining the contract this new userspace ABI forms between the kernel log messages and userspace? How do users know what we guarantee won't or will break, and how do we kernel developers know what we're allowed to do once these very specific internal subsystem implementation details are exposed to userspace? Hell, how did this stuff even get merged without any supporting documentation? -Dave.
On Thu, 17 Mar 2022 at 16:16, Dave Chinner <david@fromorbit.com> wrote: > That's a nasty mess. To begin with, we most definitely do not want > to have to define log level translations in multiple places so this > needs to be reworked so the front end macros define everything and > pass things down to the lower level functions. I can follow up with a PATCH v1 to do this kernel level deduplication. I focused my initial attempt at changing as little as possible. > And, anyway, why can't you just drop printk_index_subsys_emit() into > the define_xfs_printk_level() macro? The kern_level, the fmt string > and the varargs are all available there... The short answer is that the format strings need to be known at compile time, as this printk index is added into a section of the resultant ELF binary. > Anyway, there's more important high level stuff that needs > explaining first. > > This is competely undocumented functionality and it's the first I've > ever heard about it. There's nothing I can easily find to learn how > this information being exposed to userspace is supposed to be used. > The commit message is pretty much information free, but this is a > new userspace ABI. What ABI constraints are we now subject to by > exporting XFS log message formats to userspace places? > > i.e. Where's the documentation defining the contract this new > userspace ABI forms between the kernel log messages and userspace? > How do users know what we guarantee won't or will break, and how do > we kernel developers know what we're allowed to do once these very > specific internal subsystem implementation details are exposed to > userspace? > > Hell, how did this stuff even get merged without any supporting > documentation? I can't really comment as to the commit history of the printk indexing, though I think it's a fair criticism that there doesn't currently seem to be any in-tree Documentation file about the functionality yet. The best references I could point to are commit 337015573718b161891a3473d25f59273f2e626b and this LWN article: https://lwn.net/Articles/857148/ Your concern about ABI commitments is totally valid, and is (to me) rather ironic in this context. This printk indexing effort was started so that end user-operators can more reliably capture critical event data *without* asking developers to commit to anything. The hope here is that developers can change format strings and parameters at will, and that from release-to-release end user-operators can compare the printk index to see if there are any changes in printk index entries that they care about for their environment. It is my genuine hope that by merging a change like what I'm proposing here, that end users can more reliably detect and react to XFS events without XFS developers needing to know about this or commit to anything. The only reason this change is needed is because XFS wraps printk() for its own formatting.
diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c index bc66d95c8d4c..cf86d5dd7ba8 100644 --- a/fs/xfs/xfs_message.c +++ b/fs/xfs/xfs_message.c @@ -21,10 +21,10 @@ __xfs_printk( struct va_format *vaf) { if (mp && mp->m_super) { - printk("%sXFS (%s): %pV\n", level, mp->m_super->s_id, vaf); + _printk("%sXFS (%s): %pV\n", level, mp->m_super->s_id, vaf); return; } - printk("%sXFS: %pV\n", level, vaf); + _printk("%sXFS: %pV\n", level, vaf); } #define define_xfs_printk_level(func, kern_level) \ @@ -48,19 +48,19 @@ void func(const struct xfs_mount *mp, const char *fmt, ...) \ xfs_stack_trace(); \ } \ -define_xfs_printk_level(xfs_emerg, KERN_EMERG); -define_xfs_printk_level(xfs_alert, KERN_ALERT); -define_xfs_printk_level(xfs_crit, KERN_CRIT); -define_xfs_printk_level(xfs_err, KERN_ERR); -define_xfs_printk_level(xfs_warn, KERN_WARNING); -define_xfs_printk_level(xfs_notice, KERN_NOTICE); -define_xfs_printk_level(xfs_info, KERN_INFO); +define_xfs_printk_level(_xfs_emerg, KERN_EMERG); +define_xfs_printk_level(_xfs_alert, KERN_ALERT); +define_xfs_printk_level(_xfs_crit, KERN_CRIT); +define_xfs_printk_level(_xfs_err, KERN_ERR); +define_xfs_printk_level(_xfs_warn, KERN_WARNING); +define_xfs_printk_level(_xfs_notice, KERN_NOTICE); +define_xfs_printk_level(_xfs_info, KERN_INFO); #ifdef DEBUG -define_xfs_printk_level(xfs_debug, KERN_DEBUG); +define_xfs_printk_level(_xfs_debug, KERN_DEBUG); #endif void -xfs_alert_tag( +_xfs_alert_tag( const struct xfs_mount *mp, int panic_tag, const char *fmt, ...) diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h index bb9860ec9a93..2d90daf96946 100644 --- a/fs/xfs/xfs_message.h +++ b/fs/xfs/xfs_message.h @@ -6,29 +6,61 @@ struct xfs_mount; +#define xfs_printk_index_wrap(_p_func, kern_level, mp, fmt, ...) \ +({\ + printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt, ##__VA_ARGS__);\ + _p_func(mp, fmt, ##__VA_ARGS__);\ +}) +#define xfs_alert_tag(mp, tag, fmt, ...) \ +({\ + printk_index_subsys_emit("%sXFS%s: ", KERN_ALERT, fmt, ##__VA_ARGS__);\ + _xfs_alert_tag(mp, tag, fmt, ##__VA_ARGS__);\ +}) +#define xfs_emerg(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_emerg, KERN_EMERG, mp, fmt, ##__VA_ARGS__) +#define xfs_alert(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_alert, KERN_ALERT, mp, fmt, ##__VA_ARGS__) +#define xfs_crit(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_crit, KERN_CRIT, mp, fmt, ##__VA_ARGS__) +#define xfs_err(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_err, KERN_ERR, mp, fmt, ##__VA_ARGS__) +#define xfs_warn(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_warn, KERN_WARNING, mp, fmt, ##__VA_ARGS__) +#define xfs_notice(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_notice, KERN_NOTICE, mp, fmt, ##__VA_ARGS__) +#define xfs_info(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_info, KERN_INFO, mp, fmt, ##__VA_ARGS__) +#ifdef DEBUG +#define xfs_debug(mp, fmt, ...)\ + xfs_printk_index_wrap(_xfs_debug, KERN_DEBUG, mp, fmt, ##__VA_ARGS__) +#else +#define xfs_debug(mp, fmt, ...) do {} while (0) +#endif + + extern __printf(2, 3) -void xfs_emerg(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_emerg(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(2, 3) -void xfs_alert(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_alert(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(3, 4) -void xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...); +void _xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...); extern __printf(2, 3) -void xfs_crit(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_crit(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(2, 3) -void xfs_err(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_err(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(2, 3) -void xfs_warn(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_warn(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(2, 3) -void xfs_notice(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_notice(const struct xfs_mount *mp, const char *fmt, ...); extern __printf(2, 3) -void xfs_info(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_info(const struct xfs_mount *mp, const char *fmt, ...); #ifdef DEBUG extern __printf(2, 3) -void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...); +void _xfs_debug(const struct xfs_mount *mp, const char *fmt, ...); #else static inline __printf(2, 3) -void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...) +void _xfs_debug(const struct xfs_mount *mp, const char *fmt, ...) { } #endif
In order for end users to quickly react to new issues that come up in production, it is proving useful to leverage the printk indexing system. This printk index enables kernel developers to use calls to printk() with changable ad-hoc format strings, while still enabling end users to detect changes and develop a semi-stable interface for detecting and parsing these messages. So that detailed XFS messages are captures by this printk index, this patch wraps the xfs_<level> and xfs_alert_tag functions. Signed-off-by: Jonathan Lassoff <jof@thejof.com> --- fs/xfs/xfs_message.c | 22 +++++++++---------- fs/xfs/xfs_message.h | 52 +++++++++++++++++++++++++++++++++++--------- 2 files changed, 53 insertions(+), 21 deletions(-)