[PATCH v1] Add XFS messages to printk index

[PATCH v1] Add XFS messages to printk index

[Jonathan Lassoff]

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.

[PATCH v1] -- De-duplicate kernel logging levels and tidy whitespace.
---
 fs/xfs/xfs_message.c | 68 +++++++++++++++++++-----------------
 fs/xfs/xfs_message.h | 82 ++++++++++++++++++++++++++++++++------------
 2 files changed, 97 insertions(+), 53 deletions(-)

diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
index bc66d95c8d4c..8f29d8e86482 100644
--- a/fs/xfs/xfs_message.c
+++ b/fs/xfs/xfs_message.c
@@ -21,46 +21,50 @@ __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)		\
-void func(const struct xfs_mount *mp, const char *fmt, ...)	\
-{								\
-	struct va_format	vaf;				\
-	va_list			args;				\
-	int			level;				\
-								\
-	va_start(args, fmt);					\
-								\
-	vaf.fmt = fmt;						\
-	vaf.va = &args;						\
-								\
-	__xfs_printk(kern_level, mp, &vaf);			\
-	va_end(args);						\
-								\
-	if (!kstrtoint(kern_level, 0, &level) &&		\
-	    level <= LOGLEVEL_ERR &&				\
-	    xfs_error_level >= XFS_ERRLEVEL_HIGH)		\
-		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 define_xfs_printk_level(func)			\
+void func(						\
+	const char *kern_level,				\
+	const struct xfs_mount *mp,			\
+	const char *fmt,				\
+	...)						\
+{							\
+	struct va_format	vaf;			\
+	va_list			args;			\
+	int			level;			\
+							\
+	va_start(args, fmt);				\
+							\
+	vaf.fmt = fmt;					\
+	vaf.va = &args;					\
+							\
+	__xfs_printk(kern_level, mp, &vaf);		\
+	va_end(args);					\
+							\
+	if (!kstrtoint(kern_level, 0, &level) &&	\
+	    level <= LOGLEVEL_ERR &&			\
+	    xfs_error_level >= XFS_ERRLEVEL_HIGH)	\
+		xfs_stack_trace();			\
+}							\
+
+define_xfs_printk_level(_xfs_emerg);
+define_xfs_printk_level(_xfs_alert);
+define_xfs_printk_level(_xfs_crit);
+define_xfs_printk_level(_xfs_err);
+define_xfs_printk_level(_xfs_warn);
+define_xfs_printk_level(_xfs_notice);
+define_xfs_printk_level(_xfs_info);
 #ifdef DEBUG
-define_xfs_printk_level(xfs_debug, KERN_DEBUG);
+define_xfs_printk_level(_xfs_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..6f9d4a3553de 100644
--- a/fs/xfs/xfs_message.h
+++ b/fs/xfs/xfs_message.h
@@ -6,31 +6,71 @@
 
 struct xfs_mount;
 
-extern __printf(2, 3)
-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, ...);
+#define xfs_printk_index_wrap(_p_func, kern_level, mp, fmt, ...)		\
+({										\
+	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt, ##__VA_ARGS__);	\
+	_p_func(kern_level, 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(3, 4)
+void _xfs_emerg(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_alert(
+	const char *kern_level, 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, ...);
-extern __printf(2, 3)
-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, ...);
-extern __printf(2, 3)
-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, ...);
-extern __printf(2, 3)
-void xfs_info(const struct xfs_mount *mp, const char *fmt, ...);
+void _xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_crit(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_err(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_warn(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_notice(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
+extern __printf(3, 4)
+void _xfs_info(
+	const char *kern_level, 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, ...);
+extern __printf(3, 4)
+void _xfs_debug(
+	const char *kern_level, 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, ...)
-{
-}
+extern __printf(3, 4)
+void _xfs_debug(
+	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...)
+{}
 #endif
 
 #define xfs_printk_ratelimited(func, dev, fmt, ...)			\
-- 
2.30.2

Re: [PATCH v1] Add XFS messages to printk index

[Dave Chinner]

On Mon, Mar 21, 2022 at 11:11:23PM +0000, 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.

Hmmmm.  This is still missing a description of what "semi-stable"
implies in terms of kernel/userspace ABI guarantees/constraints for
the XFS codebase and developers.

I've cc'd the printk maintainers so they can be berated directly for
failing to provide any useful documentation for what appears to be a
shiny new userspace ABI.  Then they can answer our questions about
the implications of exposing source code directly to userspace have
for us kernel developers....

> So that detailed XFS messages are captures by this printk index, this
> patch wraps the xfs_<level> and xfs_alert_tag functions.
> 
> [PATCH v1] -- De-duplicate kernel logging levels and tidy whitespace.

Good!

But this is only the first step - there's a heap of improvements
that lead directly from lifting this definition.

However, change logs should not be part of the commit message - they
go either in the cover message or below the "---" line as we don't
record them in the git history when the code is merged.

Most importantly, the patch is missing a Signed-off-by line.

> ---
>  fs/xfs/xfs_message.c | 68 +++++++++++++++++++-----------------
>  fs/xfs/xfs_message.h | 82 ++++++++++++++++++++++++++++++++------------
>  2 files changed, 97 insertions(+), 53 deletions(-)
> 
> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
> index bc66d95c8d4c..8f29d8e86482 100644
> --- a/fs/xfs/xfs_message.c
> +++ b/fs/xfs/xfs_message.c
> @@ -21,46 +21,50 @@ __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)		\
> -void func(const struct xfs_mount *mp, const char *fmt, ...)	\
> -{								\
> -	struct va_format	vaf;				\
> -	va_list			args;				\
> -	int			level;				\
> -								\
> -	va_start(args, fmt);					\
> -								\
> -	vaf.fmt = fmt;						\
> -	vaf.va = &args;						\
> -								\
> -	__xfs_printk(kern_level, mp, &vaf);			\
> -	va_end(args);						\
> -								\
> -	if (!kstrtoint(kern_level, 0, &level) &&		\
> -	    level <= LOGLEVEL_ERR &&				\
> -	    xfs_error_level >= XFS_ERRLEVEL_HIGH)		\
> -		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 define_xfs_printk_level(func)			\
> +void func(						\
> +	const char *kern_level,				\
> +	const struct xfs_mount *mp,			\
> +	const char *fmt,				\
> +	...)						\
> +{							\
> +	struct va_format	vaf;			\
> +	va_list			args;			\
> +	int			level;			\
> +							\
> +	va_start(args, fmt);				\
> +							\
> +	vaf.fmt = fmt;					\
> +	vaf.va = &args;					\
> +							\
> +	__xfs_printk(kern_level, mp, &vaf);		\
> +	va_end(args);					\
> +							\
> +	if (!kstrtoint(kern_level, 0, &level) &&	\
> +	    level <= LOGLEVEL_ERR &&			\
> +	    xfs_error_level >= XFS_ERRLEVEL_HIGH)	\
> +		xfs_stack_trace();			\
> +}							\
> +
> +define_xfs_printk_level(_xfs_emerg);
> +define_xfs_printk_level(_xfs_alert);
> +define_xfs_printk_level(_xfs_crit);
> +define_xfs_printk_level(_xfs_err);
> +define_xfs_printk_level(_xfs_warn);
> +define_xfs_printk_level(_xfs_notice);
> +define_xfs_printk_level(_xfs_info);
>  #ifdef DEBUG
> -define_xfs_printk_level(xfs_debug, KERN_DEBUG);
> +define_xfs_printk_level(_xfs_debug);
>  #endif

Now the kern_level comes from the high level macros, we don't need
these constructors any more. This just results in identical functions
that differ only by name. i.e. this constructor macro and the
functions it builds can be replaced with a single function such as:

void
xfs_printk_level(
	const char		*kern_level,
	const struct xfs_mount	*mp,
	const char		*fmt,
	...)
{
	struct va_format	vaf;
	va_list			args;
	int			level;

	va_start(args, fmt);

	vaf.fmt = fmt;
	vaf.va = &args;

	__xfs_printk(kern_level, mp, &vaf);
	va_end(args);

	if (!kstrtoint(kern_level, 0, &level) &&
	    level <= LOGLEVEL_ERR &&
	    xfs_error_level >= XFS_ERRLEVEL_HIGH)
		xfs_stack_trace();
}

>  
>  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..6f9d4a3553de 100644
> --- a/fs/xfs/xfs_message.h
> +++ b/fs/xfs/xfs_message.h
> @@ -6,31 +6,71 @@
>  
>  struct xfs_mount;
>  
> -extern __printf(2, 3)
> -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, ...);
> +#define xfs_printk_index_wrap(_p_func, kern_level, mp, fmt, ...)		\
> +({										\
> +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt, ##__VA_ARGS__);	\
> +	_p_func(kern_level, mp, fmt, ##__VA_ARGS__);				\
> +})

Over 80 columns wide.

> +#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, ...)\
                                ^^^^   whitespace needed.

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

So with xfs_printk_level() now present, all these macros now simply
call xfs_printk_level() and pass the level to it. e.g.

#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
({								\
	printk_index_subsys_emit("%sXFS%s: ",			\
			kern_level, fmt, ##__VA_ARGS__);	\
	xfs_printk_level(kern_level, mp, fmt, ##__VA_ARGS__);	\
})

#define xfs_emerg(mp, fmt, ...)	\
	xfs_printk_index_wrap(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
.....

And then all this mass of grotty printf prototype cruft can go away:

> +
> +
> +extern __printf(3, 4)
> +void _xfs_emerg(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_alert(
> +	const char *kern_level, 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, ...);
> -extern __printf(2, 3)
> -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, ...);
> -extern __printf(2, 3)
> -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, ...);
> -extern __printf(2, 3)
> -void xfs_info(const struct xfs_mount *mp, const char *fmt, ...);
> +void _xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_crit(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_err(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_warn(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_notice(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...);
> +extern __printf(3, 4)
> +void _xfs_info(
> +	const char *kern_level, 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, ...);
> +extern __printf(3, 4)
> +void _xfs_debug(
> +	const char *kern_level, 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, ...)
> -{
> -}
> +extern __printf(3, 4)
> +void _xfs_debug(
> +	const char *kern_level, const struct xfs_mount *mp, const char *fmt, ...)
> +{}
>  #endif

And be replaced with a single declaration:

extern __printf(3, 4)
void xfs_printk_level(const char *kern_level, const struct xfs_mount *mp,
		const char *fmt, ...);

And in doing this, we gain the new functionality, clean up a bunch
of messy code, reduce the number of lines of code to implement the
XFS printk wrappers, and we reduce the code size of the XFS printk
module, too.  That's wins all around.

And then if you split this patch into two - the first patch
reorganises the printf code, the second introduces the new printk
functionality (i.e xfs_printk_index_wrap() macro) - then we can
review and merge the cleanup patch independently of the fate of the
second patch that may introduce ABI contraints....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v1] Add XFS messages to printk index

[Jonathan Lassoff]

On Thu, 24 Mar 2022 at 18:17, Dave Chinner <david@fromorbit.com> wrote:
> Hmmmm.  This is still missing a description of what "semi-stable"
> implies in terms of kernel/userspace ABI guarantees/constraints for
> the XFS codebase and developers.

I'll reword this in a followup patch.
The printk index just captures and exposes these strings from the
sources. Its design was chosen specifically because it places no new
constraints on kernel developers.
This functionality enables kernel developers to change format strings
at will, and when captured by the printk index, enables end users to
detect changes from release to release (and presumably trigger them to
update any relevant regexes on their end).

> However, change logs should not be part of the commit message - they
> go either in the cover message or below the "---" line as we don't
> record them in the git history when the code is merged.
>
> Most importantly, the patch is missing a Signed-off-by line.

I've got these fixed up now in my format-patch configuration and use
of notes. Sorry for the noise in this regard, I don't usually email
patches around.

> Now the kern_level comes from the high level macros, we don't need
> these constructors any more. This just results in identical functions
> that differ only by name. i.e. this constructor macro and the
> functions it builds can be replaced with a single function

This is a good suggestion for simplifying the existing functionality
and making the logical change to switch in printk indexing much
smaller.

> And then if you split this patch into two - the first patch
> reorganises the printf code, the second introduces the new printk
> functionality (i.e xfs_printk_index_wrap() macro) - then we can
> review and merge the cleanup patch independently of the fate of the
> second patch that may introduce ABI contraints....

Seems reasonable. I'll follow up with a PATCH v2 incorporating these
suggestions.

-- jof