[PATCH v3 1/2] Simplify XFS logging methods.

[PATCH v3 1/2] Simplify XFS logging methods.

[Jonathan Lassoff]

Rather than have a constructor to define many nearly-identical
functions, use preprocessor macros to pass down a kernel logging level
to a common function.

Signed-off-by: Jonathan Lassoff <jof@thejof.com>
---

Notes:
    [PATCH v1]
      * De-duplicate kernel logging levels and tidy whitespace.
    [PATCH v2]
      * Split changes into two patches:
         - function and prototype de-duplication.
         - Adding printk indexing
    [PATCH v3]
      * Fix some whitespace and semicolon. *facepalm*

 fs/xfs/xfs_message.c | 53 ++++++++++++++++++--------------------------
 fs/xfs/xfs_message.h | 47 +++++++++++++++++++++------------------
 2 files changed, 47 insertions(+), 53 deletions(-)

diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
index bc66d95c8d4c..ede8a4f2f676 100644
--- a/fs/xfs/xfs_message.c
+++ b/fs/xfs/xfs_message.c
@@ -27,37 +27,28 @@ __xfs_printk(
 	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);
-#ifdef DEBUG
-define_xfs_printk_level(xfs_debug, KERN_DEBUG);
-#endif
+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(
diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
index bb9860ec9a93..2f609800e806 100644
--- a/fs/xfs/xfs_message.h
+++ b/fs/xfs/xfs_message.h
@@ -6,33 +6,36 @@
 
 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, ...);
 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_printk_level(
+	const char *kern_level,
+	const struct xfs_mount *mp,
+	const char *fmt, ...);
+#define xfs_emerg(mp, fmt, ...) \
+	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
+#define xfs_alert(mp, fmt, ...) \
+	xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
+#define xfs_crit(mp, fmt, ...) \
+	xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
+#define xfs_err(mp, fmt, ...) \
+	xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
+#define xfs_warn(mp, fmt, ...) \
+	xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
+#define xfs_notice(mp, fmt, ...) \
+	xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
+#define xfs_info(mp, fmt, ...) \
+	xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
 #ifdef DEBUG
-extern __printf(2, 3)
-void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...);
+#define xfs_debug(mp, fmt, ...) \
+	xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
 #else
-static inline __printf(2, 3)
-void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...)
-{
-}
+#define xfs_debug(mp, fmt, ...) do {} while (0)
 #endif
 
+extern __printf(3, 4)
+void xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);
+
+
 #define xfs_printk_ratelimited(func, dev, fmt, ...)			\
 do {									\
 	static DEFINE_RATELIMIT_STATE(_rs,				\

base-commit: 34af78c4e616c359ed428d79fe4758a35d2c5473
-- 
2.35.1

[PATCH v3 2/2] 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 changeable ad-hoc format strings, while still enabling end users
to detect changes from release to release.

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

Notes:
    [PATCH v1]
      * De-duplicate kernel logging levels and tidy whitespace.
    [PATCH v2]
      * Split changes into two patches:
         - function and prototype de-duplication.
         - Adding printk indexing
    [PATCH v3]
      * Fix some whitespace and semicolon. *facepalm*

 fs/xfs/xfs_message.c |  2 +-
 fs/xfs/xfs_message.h | 29 ++++++++++++++++++++---------
 2 files changed, 21 insertions(+), 10 deletions(-)

diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
index ede8a4f2f676..f01efad20420 100644
--- a/fs/xfs/xfs_message.c
+++ b/fs/xfs/xfs_message.c
@@ -51,7 +51,7 @@ void xfs_printk_level(
 }
 
 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 2f609800e806..6f9a1b67c4d7 100644
--- a/fs/xfs/xfs_message.h
+++ b/fs/xfs/xfs_message.h
@@ -6,34 +6,45 @@
 
 struct xfs_mount;
 
+#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
+({								\
+	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
+	xfs_printk_level(kern_level, mp, fmt, ##__VA_ARGS__);	\
+})
 extern __printf(3, 4)
 void xfs_printk_level(
 	const char *kern_level,
 	const struct xfs_mount *mp,
 	const char *fmt, ...);
 #define xfs_emerg(mp, fmt, ...) \
-	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
 #define xfs_alert(mp, fmt, ...) \
-	xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
 #define xfs_crit(mp, fmt, ...) \
-	xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
 #define xfs_err(mp, fmt, ...) \
-	xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_ERR, mp, fmt, ##__VA_ARGS__)
 #define xfs_warn(mp, fmt, ...) \
-	xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
 #define xfs_notice(mp, fmt, ...) \
-	xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
 #define xfs_info(mp, fmt, ...) \
-	xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_INFO, mp, fmt, ##__VA_ARGS__)
 #ifdef DEBUG
 #define xfs_debug(mp, fmt, ...) \
-	xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
+	xfs_printk_index_wrap(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
 #else
 #define xfs_debug(mp, fmt, ...) do {} while (0)
 #endif
 
+#define xfs_alert_tag(mp, tag, fmt, ...)			\
+({								\
+	printk_index_subsys_emit("%sXFS%s: ", KERN_ALERT, fmt);	\
+	_xfs_alert_tag(mp, tag, fmt, ##__VA_ARGS__);		\
+})
+
 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, ...);
 
 
 #define xfs_printk_ratelimited(func, dev, fmt, ...)			\
-- 
2.35.1

Re: [PATCH v3 1/2] Simplify XFS logging methods.

[Petr Mladek]

On Fri 2022-03-25 10:19:45, Jonathan Lassoff wrote:
> Rather than have a constructor to define many nearly-identical
> functions, use preprocessor macros to pass down a kernel logging level
> to a common function.
> 
> diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
> index bb9860ec9a93..2f609800e806 100644
> --- a/fs/xfs/xfs_message.h
> +++ b/fs/xfs/xfs_message.h
> @@ -6,33 +6,36 @@
> -void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...)
> -{
> -}
> +#define xfs_debug(mp, fmt, ...) do {} while (0)
>  #endif
>  
> +extern __printf(3, 4)
> +void xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);

The trend is to avoid "extern" because it just creates noise. Well, I
am not sure what are the preferences in the XFS code.

Otherwise the changes look fine to me. Feel free to use:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Petr Mladek]

On Fri 2022-03-25 10:19:46, 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 changeable ad-hoc format strings, while still enabling end users
> to detect changes from release to release.
> 
> 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>

> --- a/fs/xfs/xfs_message.h
> +++ b/fs/xfs/xfs_message.h
> @@ -6,34 +6,45 @@
>  
>  struct xfs_mount;
>  
> +#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
> +({								\
> +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\

I would probably use "%sXFS: " for the first parameter as
a compromise here.

It affects how the printk formats are shown in debugfs. With the
current patch I see in /sys/kernel/debug/printk/index/vmlinux:

<4> fs/xfs/libxfs/xfs_ag.c:877 xfs_ag_shrink_space "%sXFS%s: Error %d reserving per-AG metadata reserve pool."
<1> fs/xfs/libxfs/xfs_ag.c:151 xfs_initialize_perag_data "%sXFS%s: AGF corruption. Please run xfs_repair."
<4> fs/xfs/libxfs/xfs_alloc.c:2429 xfs_agfl_reset "%sXFS%s: WARNING: Reset corrupted AGFL on AG %u. %d blocks leaked. Please unmount and run xfs_repair."
<4> fs/xfs/libxfs/xfs_alloc.c:262 xfs_alloc_get_rec "%sXFS%s: start block 0x%x block count 0x%x"
<4> fs/xfs/libxfs/xfs_alloc.c:260 xfs_alloc_get_rec "%sXFS%s: %s Freespace BTree record corruption in AG %d detected!"
<1> fs/xfs/libxfs/xfs_attr_remote.c:304 xfs_attr_rmtval_copyout "%sXFS%s: remote attribute header mismatch bno/off/len/owner (0x%llx/0x%x/Ox%x/0x%llx)"
<4> fs/xfs/libxfs/xfs_bmap.c:1129 xfs_iread_bmbt_block "%sXFS%s: corrupt dinode %llu, (btree extents)."

In reality, the prefix is chosen in __xfs_printk() at runtime:

	+ "%sXFS (%s): "	when mp->m_super is defined
	+ "%sXFS: "		otherwise

It means that "%sXFS: " is not perfect but it looks closer to reality
than "%sXFS%s: ".


Otherwise, the patch looks good to me. Feel free to use:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCH v3 1/2] Simplify XFS logging methods.

[Dave Chinner]

On Fri, Mar 25, 2022 at 10:19:45AM -0700, Jonathan Lassoff wrote:
> Rather than have a constructor to define many nearly-identical
> functions, use preprocessor macros to pass down a kernel logging level
> to a common function.
> 
> Signed-off-by: Jonathan Lassoff <jof@thejof.com>

Mostly looks good, mainly just whitespace/formatting consistency
issues now.

....
> -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);
> -#endif
> +void xfs_printk_level(
> +	const char *kern_level,
> +	const struct xfs_mount *mp,
> +	const char *fmt, ...)

Use the same format as __xfs_printk() and xfs_alert_tag():

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(
> diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
> index bb9860ec9a93..2f609800e806 100644
> --- a/fs/xfs/xfs_message.h
> +++ b/fs/xfs/xfs_message.h
> @@ -6,33 +6,36 @@
>  
>  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, ...);
>  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_printk_level(
> +	const char *kern_level,
> +	const struct xfs_mount *mp,
> +	const char *fmt, ...);

This still needs the __printf() attribute because we still want the
compiler to check the printf format string for issues. Also the
format for function prototypes should follow the ones that got
removed:

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

There also needs to be an empty line between the prototype and the
following defines - the empty line provides demarcation between
prototype and the macro definitions that then use it.

> +#define xfs_emerg(mp, fmt, ...) \
> +	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
> +#define xfs_alert(mp, fmt, ...) \
> +	xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
> +#define xfs_crit(mp, fmt, ...) \
> +	xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
> +#define xfs_err(mp, fmt, ...) \
> +	xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
> +#define xfs_warn(mp, fmt, ...) \
> +	xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
> +#define xfs_notice(mp, fmt, ...) \
> +	xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
> +#define xfs_info(mp, fmt, ...) \
> +	xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
>  #ifdef DEBUG
> -extern __printf(2, 3)
> -void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...);
> +#define xfs_debug(mp, fmt, ...) \
> +	xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
>  #else
> -static inline __printf(2, 3)
> -void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...)
> -{
> -}
> +#define xfs_debug(mp, fmt, ...) do {} while (0)
>  #endif
>  
> +extern __printf(3, 4)
> +void xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);
> +
> +

And one to many extra blank lines here :)

CHeers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Dave Chinner]

On Fri, Mar 25, 2022 at 10:19:46AM -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 changeable ad-hoc format strings, while still enabling end users
> to detect changes from release to release.
> 
> 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>

Looks good. Minor whitespace/ordering nit below....

Reviewed-by: Dave Chinner <dchinner@redhat.com>

> diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
> index 2f609800e806..6f9a1b67c4d7 100644
> --- a/fs/xfs/xfs_message.h
> +++ b/fs/xfs/xfs_message.h
> @@ -6,34 +6,45 @@
>  
>  struct xfs_mount;
>  
> +#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
> +({								\
> +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
> +	xfs_printk_level(kern_level, mp, fmt, ##__VA_ARGS__);	\
> +})
>  extern __printf(3, 4)
>  void xfs_printk_level(
>  	const char *kern_level,
>  	const struct xfs_mount *mp,
>  	const char *fmt, ...);
>  #define xfs_emerg(mp, fmt, ...) \
> -	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
> +	xfs_printk_index_wrap(KERN_EMERG, mp, fmt, ##__VA_ARGS__)

Empty lines, again. Also, put the xfs_printk_index_wrap() after
the function prototype so it groups with the macros that use it.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Dave Chinner]

Hi Petr,

On Tue, Mar 29, 2022 at 03:34:00PM +0200, Petr Mladek wrote:
> On Fri 2022-03-25 10:19:46, 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 changeable ad-hoc format strings, while still enabling end users
> > to detect changes from release to release.
> > 
> > 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>
> 
> > --- a/fs/xfs/xfs_message.h
> > +++ b/fs/xfs/xfs_message.h
> > @@ -6,34 +6,45 @@
> >  
> >  struct xfs_mount;
> >  
> > +#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
> > +({								\
> > +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
> 
> I would probably use "%sXFS: " for the first parameter as
> a compromise here.

If you really want to be pedantic, the correct format string would
be "%sXFS (%s):" because of the reasons you state below -  mp &&
mp->m_super is almost -always- present, so almost all messages are
going to be emitted in the the (%s) form....

But that makes me wonder - if the format string doesn't apparently
need to be an exact match to what is actually output by the kernel,
then how is this information supposed to be used?

And so....

> It affects how the printk formats are shown in debugfs. With the
> current patch I see in /sys/kernel/debug/printk/index/vmlinux:
> 
> <4> fs/xfs/libxfs/xfs_ag.c:877 xfs_ag_shrink_space "%sXFS%s: Error %d reserving per-AG metadata reserve pool."
> <1> fs/xfs/libxfs/xfs_ag.c:151 xfs_initialize_perag_data "%sXFS%s: AGF corruption. Please run xfs_repair."
> <4> fs/xfs/libxfs/xfs_alloc.c:2429 xfs_agfl_reset "%sXFS%s: WARNING: Reset corrupted AGFL on AG %u. %d blocks leaked. Please unmount and run xfs_repair."
> <4> fs/xfs/libxfs/xfs_alloc.c:262 xfs_alloc_get_rec "%sXFS%s: start block 0x%x block count 0x%x"
> <4> fs/xfs/libxfs/xfs_alloc.c:260 xfs_alloc_get_rec "%sXFS%s: %s Freespace BTree record corruption in AG %d detected!"
> <1> fs/xfs/libxfs/xfs_attr_remote.c:304 xfs_attr_rmtval_copyout "%sXFS%s: remote attribute header mismatch bno/off/len/owner (0x%llx/0x%x/Ox%x/0x%llx)"
> <4> fs/xfs/libxfs/xfs_bmap.c:1129 xfs_iread_bmbt_block "%sXFS%s: corrupt dinode %llu, (btree extents)."

... onto the implications of explicitly exposing source code
directly to userspace via a kernel ABI.

I ask, because user/kernel ABIs are usually fixed and we are not
allowed to change them in a way that might break userspace. What
happens when one of these format messages gets moved? What if the
file, function and line of code all change, but the format string
stays the same? What about duplicate format strings in different
files/functions?

Exactly how is this supposed to be used by userspace? Given that you
are exposing both the file and the line of the file that the format
string belongs to, does this mean we can no longer actually move
this format string to any other location in the source code?

IOWs, I cannot find anything that documents the implications of
directly exposing the *raw source code* to userspace though a sysfs
file on either developers or userspace applications.  Exposing
anything through a sysfs file usually comes with constraints and
guarantees and just because it is in /sys/kernel/debug means we can
waive ABI constraints: I'll refer you to the canonical example of
tracepoints vs powertop.

With tracepoints in mind, XFS has an explicit policy that
tracepoints do not form part of the user ABI because they expose the
internal implementation directly to userspace. Hence if you use XFS
tracepoints for any purpose, you get to keep all the broken bits
when we change/add/remove tracepoints as part of our normal
development.

However, for information we explicitly expose via files in proc and
sysfs (and via ioctls, for that matter), we have to provide explicit
ABI guarantees, and that means we cannot remove or change the format
or content of those files in ways that would cause userspace parsers
and applications to break. If we are removing a proc/sysfs file, we
have an explicit deprecation process that takes years to run so that
userspace has time to notice that removal will be occurring and be
updated not to depend on it by the time we remove it.

I see no statement anywhere about what this printk index ABI
requires in terms of code stablility, format string maintenance and
modification, etc. I've seen it referred to as "semi-stable" but
there is no clear, easily accessible definition as to what that
means for either kernel developers or userspace app developers that
might want to use this information. There's zero information
available about how userspace will use this information, too, so at
this point I can't even guess what the policy for this new ABI
actually is.

If this was discussed and a policy was created, then great. But it
*hasn't been documented* for the rest of the world to be able to
read and understand so they know how to deal safely with the
information this ABI now provides. So, can you please explain what
the rules are, and then please write some documentation for the
kernel admin guide defining the user ABI for application writers and
what guarantees the kernel provides them with about the contents of
this ABI.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Darrick J. Wong]

On Wed, Mar 30, 2022 at 11:34:57AM +1100, Dave Chinner wrote:
> Hi Petr,
> 
> On Tue, Mar 29, 2022 at 03:34:00PM +0200, Petr Mladek wrote:
> > On Fri 2022-03-25 10:19:46, 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 changeable ad-hoc format strings, while still enabling end users
> > > to detect changes from release to release.
> > > 
> > > 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>
> > 
> > > --- a/fs/xfs/xfs_message.h
> > > +++ b/fs/xfs/xfs_message.h
> > > @@ -6,34 +6,45 @@
> > >  
> > >  struct xfs_mount;
> > >  
> > > +#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
> > > +({								\
> > > +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
> > 
> > I would probably use "%sXFS: " for the first parameter as
> > a compromise here.
> 
> If you really want to be pedantic, the correct format string would
> be "%sXFS (%s):" because of the reasons you state below -  mp &&
> mp->m_super is almost -always- present, so almost all messages are
> going to be emitted in the the (%s) form....
> 
> But that makes me wonder - if the format string doesn't apparently
> need to be an exact match to what is actually output by the kernel,
> then how is this information supposed to be used?
> 
> And so....
> 
> > It affects how the printk formats are shown in debugfs. With the
> > current patch I see in /sys/kernel/debug/printk/index/vmlinux:
> > 
> > <4> fs/xfs/libxfs/xfs_ag.c:877 xfs_ag_shrink_space "%sXFS%s: Error %d reserving per-AG metadata reserve pool."
> > <1> fs/xfs/libxfs/xfs_ag.c:151 xfs_initialize_perag_data "%sXFS%s: AGF corruption. Please run xfs_repair."
> > <4> fs/xfs/libxfs/xfs_alloc.c:2429 xfs_agfl_reset "%sXFS%s: WARNING: Reset corrupted AGFL on AG %u. %d blocks leaked. Please unmount and run xfs_repair."
> > <4> fs/xfs/libxfs/xfs_alloc.c:262 xfs_alloc_get_rec "%sXFS%s: start block 0x%x block count 0x%x"
> > <4> fs/xfs/libxfs/xfs_alloc.c:260 xfs_alloc_get_rec "%sXFS%s: %s Freespace BTree record corruption in AG %d detected!"
> > <1> fs/xfs/libxfs/xfs_attr_remote.c:304 xfs_attr_rmtval_copyout "%sXFS%s: remote attribute header mismatch bno/off/len/owner (0x%llx/0x%x/Ox%x/0x%llx)"
> > <4> fs/xfs/libxfs/xfs_bmap.c:1129 xfs_iread_bmbt_block "%sXFS%s: corrupt dinode %llu, (btree extents)."
> 
> ... onto the implications of explicitly exposing source code
> directly to userspace via a kernel ABI.
> 
> I ask, because user/kernel ABIs are usually fixed and we are not
> allowed to change them in a way that might break userspace. What
> happens when one of these format messages gets moved? What if the
> file, function and line of code all change, but the format string
> stays the same? What about duplicate format strings in different
> files/functions?
> 
> Exactly how is this supposed to be used by userspace? Given that you
> are exposing both the file and the line of the file that the format
> string belongs to, does this mean we can no longer actually move
> this format string to any other location in the source code?
> 
> IOWs, I cannot find anything that documents the implications of
> directly exposing the *raw source code* to userspace though a sysfs
> file on either developers or userspace applications.  Exposing
> anything through a sysfs file usually comes with constraints and
> guarantees and just because it is in /sys/kernel/debug means we can
> waive ABI constraints: I'll refer you to the canonical example of
> tracepoints vs powertop.
> 
> With tracepoints in mind, XFS has an explicit policy that
> tracepoints do not form part of the user ABI because they expose the
> internal implementation directly to userspace. Hence if you use XFS
> tracepoints for any purpose, you get to keep all the broken bits
> when we change/add/remove tracepoints as part of our normal
> development.
> 
> However, for information we explicitly expose via files in proc and
> sysfs (and via ioctls, for that matter), we have to provide explicit
> ABI guarantees, and that means we cannot remove or change the format
> or content of those files in ways that would cause userspace parsers
> and applications to break. If we are removing a proc/sysfs file, we
> have an explicit deprecation process that takes years to run so that
> userspace has time to notice that removal will be occurring and be
> updated not to depend on it by the time we remove it.
> 
> I see no statement anywhere about what this printk index ABI
> requires in terms of code stablility, format string maintenance and
> modification, etc. I've seen it referred to as "semi-stable" but
> there is no clear, easily accessible definition as to what that
> means for either kernel developers or userspace app developers that
> might want to use this information. There's zero information
> available about how userspace will use this information, too, so at
> this point I can't even guess what the policy for this new ABI
> actually is.
> 
> If this was discussed and a policy was created, then great. But it
> *hasn't been documented* for the rest of the world to be able to
> read and understand so they know how to deal safely with the
> information this ABI now provides. So, can you please explain what
> the rules are, and then please write some documentation for the
> kernel admin guide defining the user ABI for application writers and
> what guarantees the kernel provides them with about the contents of
> this ABI.

FWIW if you /did/ accept this for 5.19, I would suggest adding:

printk_index_subsys_emit("XFS log messages shall not be considered a stable kernel ABI as they can change at any time");

I base that largely on the evidence -- there's nothing saying that
catalogued strings are or are not a stable ABI.  That means it's up to
the subsystem or the maintainers or whoever to make a decision, and I
would decide that while some people somewhere might benefit from having
the message catalogue over not having it (e.g. i18n), someone would have
to show a /very/ strong case for letting XFS get powertop'd.

Granted I won't be the maintainer after Sunday and this isn't 5.18
material, so I suppose the ball is in your court. ;)

--D

> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Dave Chinner]

On Tue, Mar 29, 2022 at 05:46:49PM -0700, Darrick J. Wong wrote:
> On Wed, Mar 30, 2022 at 11:34:57AM +1100, Dave Chinner wrote:
> > I see no statement anywhere about what this printk index ABI
> > requires in terms of code stablility, format string maintenance and
> > modification, etc. I've seen it referred to as "semi-stable" but
> > there is no clear, easily accessible definition as to what that
> > means for either kernel developers or userspace app developers that
> > might want to use this information. There's zero information
> > available about how userspace will use this information, too, so at
> > this point I can't even guess what the policy for this new ABI
> > actually is.
> > 
> > If this was discussed and a policy was created, then great. But it
> > *hasn't been documented* for the rest of the world to be able to
> > read and understand so they know how to deal safely with the
> > information this ABI now provides. So, can you please explain what
> > the rules are, and then please write some documentation for the
> > kernel admin guide defining the user ABI for application writers and
> > what guarantees the kernel provides them with about the contents of
> > this ABI.
> 
> FWIW if you /did/ accept this for 5.19, I would suggest adding:
> 
> printk_index_subsys_emit("XFS log messages shall not be considered a stable kernel ABI as they can change at any time");
> 
> I base that largely on the evidence -- there's nothing saying that
> catalogued strings are or are not a stable ABI.  That means it's up to
> the subsystem or the maintainers or whoever to make a decision, and I

Yup, that's largely what I want clarified before we make a
decision one way or another. There must have been some discussion
and decisions on what the policy is before it was merged, but it's
not easily findable.

And, IMO, instead of every single subsystem having to go through the
same question and answer process as we are currently doing, I want
that policy to be documented such that a simple "git grep
printk_index_subsys_emit" search returns the file in the
Documentation/ directory that explains all this. That makes
everyone's lives a whole lot easier.

> would decide that while some people somewhere might benefit from having
> the message catalogue over not having it (e.g. i18n), someone would have
> to show a /very/ strong case for letting XFS get powertop'd.

Yeah, I'd push back very hard against that, too, but in the absence
of any documentation defining the contract to either the kernel or
userspace application developers, it's impossible to know where we
stand to begin with. I much prefer to be able to quote letter and
verse of the documentation than to have to repeatedly justify why
we consider the (un)documented policy to be broken....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 1/2] Simplify XFS logging methods.

[Petr Mladek]

On Wed 2022-03-30 10:54:41, Dave Chinner wrote:
> On Fri, Mar 25, 2022 at 10:19:45AM -0700, Jonathan Lassoff wrote:
> > Rather than have a constructor to define many nearly-identical
> > functions, use preprocessor macros to pass down a kernel logging level
> > to a common function.
> > 
> > Signed-off-by: Jonathan Lassoff <jof@thejof.com>
> 
> Mostly looks good, mainly just whitespace/formatting consistency
> issues now.
> 
> ....
> > -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);
> > -#endif
> > +void xfs_printk_level(
> > +	const char *kern_level,
> > +	const struct xfs_mount *mp,
> > +	const char *fmt, ...)
> 
> Use the same format as __xfs_printk() and xfs_alert_tag():
> 
> 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(
> > diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
> > index bb9860ec9a93..2f609800e806 100644
> > --- a/fs/xfs/xfs_message.h
> > +++ b/fs/xfs/xfs_message.h
> > @@ -6,33 +6,36 @@
> >  
> >  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, ...);
> >  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_printk_level(
> > +	const char *kern_level,
> > +	const struct xfs_mount *mp,
> > +	const char *fmt, ...);
> 
> This still needs the __printf() attribute because we still want the
> compiler to check the printf format string for issues. Also the
> format for function prototypes should follow the ones that got
> removed:

It is actually there. But it is hidden in many removed lines.

BTW: I missed it when reading the patch as well. I was surprised
     when I saw it after applying the patch ;-)

Best Regards,
Petr

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Hi Dave,

Dave Chinner writes:
>I ask, because user/kernel ABIs are usually fixed and we are not
>allowed to change them in a way that might break userspace. What
>happens when one of these format messages gets moved? What if the
>file, function and line of code all change, but the format string
>stays the same? What about duplicate format strings in different
>files/functions?

printk indexing is exposed in debugfs, and we have a long standing 
understanding that debugfs APIs are not stable, and there are no ABI 
guarantees. The statement in the initial patch that the API is "semi-stable" is 
simply wrong.

>Exactly how is this supposed to be used by userspace? Given that you
>are exposing both the file and the line of the file that the format
>string belongs to, does this mean we can no longer actually move
>this format string to any other location in the source code?

>
>IOWs, I cannot find anything that documents the implications of
>directly exposing the *raw source code* to userspace though a sysfs
>file on either developers or userspace applications.  Exposing
>anything through a sysfs file usually comes with constraints and
>guarantees and just because it is in /sys/kernel/debug means we can
>waive ABI constraints: I'll refer you to the canonical example of
>tracepoints vs powertop.
>
>With tracepoints in mind, XFS has an explicit policy that
>tracepoints do not form part of the user ABI because they expose the
>internal implementation directly to userspace. Hence if you use XFS
>tracepoints for any purpose, you get to keep all the broken bits
>when we change/add/remove tracepoints as part of our normal
>development.
>
>However, for information we explicitly expose via files in proc and
>sysfs (and via ioctls, for that matter), we have to provide explicit
>ABI guarantees, and that means we cannot remove or change the format
>or content of those files in ways that would cause userspace parsers
>and applications to break. If we are removing a proc/sysfs file, we
>have an explicit deprecation process that takes years to run so that
>userspace has time to notice that removal will be occurring and be
>updated not to depend on it by the time we remove it.

debugfs has no stability guarantees whatsoever and exists outside of the 
userspace ABI guarantees.[0]

Even if there was some guarantee (which there isn't), the guarantee would be on 
the format of the file, not the data contained within. The point of printk 
indexing is to indicate when things change, not preclude that change. Just as a 
map appearing, changing, or disappearing in /proc/pid/smaps isn't an ABI break, 
this wouldn't be either. It would just be a change in the backing data. For 
example, if a file or line changes, printk indexing helps indicate to a 
userspace tool that the printk may have gone away, or changed location.

Anyone using printk indexing has to accept that both the format and the file 
contents are not stable between kernel releases, and must accommodate for that 
during development. That's the main reason that this was put in debugfs rather 
than (for example) /proc or /sys.

>I see no statement anywhere about what this printk index ABI
>requires in terms of code stablility, format string maintenance and
>modification, etc. I've seen it referred to as "semi-stable" but
>there is no clear, easily accessible definition as to what that
>means for either kernel developers or userspace app developers that
>might want to use this information. There's zero information
>available about how userspace will use this information, too, so at
>this point I can't even guess what the policy for this new ABI
>actually is.

I don't know why Jonathan referred to it as "semi-stable". It is simply not so. 
printk indexing is a completely unstable debugfs API with no guarantees about 
either format or contents to userspace at all over kernel releases.

>If this was discussed and a policy was created, then great. But it
>*hasn't been documented* for the rest of the world to be able to
>read and understand so they know how to deal safely with the
>information this ABI now provides. So, can you please explain what
>the rules are, and then please write some documentation for the
>kernel admin guide defining the user ABI for application writers and
>what guarantees the kernel provides them with about the contents of
>this ABI.

The policy, as with all debugfs APIs by default, is that it's completely 
unstable and there are no API stability guarantees whatsoever. That's why 
there's no extensive documentation for users: because this is a feature for 
kernel developers.

0: https://lwn.net/Articles/309298/

Thanks,

Chris

Re: [PATCH v3 1/2] Simplify XFS logging methods.

[Chris Down]

Jonathan Lassoff writes:
>Rather than have a constructor to define many nearly-identical
>functions, use preprocessor macros to pass down a kernel logging level
>to a common function.
>
>Signed-off-by: Jonathan Lassoff <jof@thejof.com>

This is a good simplification, thanks.

Reviewed-by: Chris Down <chris@chrisdown.name>

>---
>
>Notes:
>    [PATCH v1]
>      * De-duplicate kernel logging levels and tidy whitespace.
>    [PATCH v2]
>      * Split changes into two patches:
>         - function and prototype de-duplication.
>         - Adding printk indexing
>    [PATCH v3]
>      * Fix some whitespace and semicolon. *facepalm*
>
> fs/xfs/xfs_message.c | 53 ++++++++++++++++++--------------------------
> fs/xfs/xfs_message.h | 47 +++++++++++++++++++++------------------
> 2 files changed, 47 insertions(+), 53 deletions(-)
>
>diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
>index bc66d95c8d4c..ede8a4f2f676 100644
>--- a/fs/xfs/xfs_message.c
>+++ b/fs/xfs/xfs_message.c
>@@ -27,37 +27,28 @@ __xfs_printk(
> 	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);
>-#ifdef DEBUG
>-define_xfs_printk_level(xfs_debug, KERN_DEBUG);
>-#endif
>+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(
>diff --git a/fs/xfs/xfs_message.h b/fs/xfs/xfs_message.h
>index bb9860ec9a93..2f609800e806 100644
>--- a/fs/xfs/xfs_message.h
>+++ b/fs/xfs/xfs_message.h
>@@ -6,33 +6,36 @@
>
> 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, ...);
> 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_printk_level(
>+	const char *kern_level,
>+	const struct xfs_mount *mp,
>+	const char *fmt, ...);
>+#define xfs_emerg(mp, fmt, ...) \
>+	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
>+#define xfs_alert(mp, fmt, ...) \
>+	xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
>+#define xfs_crit(mp, fmt, ...) \
>+	xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
>+#define xfs_err(mp, fmt, ...) \
>+	xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
>+#define xfs_warn(mp, fmt, ...) \
>+	xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
>+#define xfs_notice(mp, fmt, ...) \
>+	xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
>+#define xfs_info(mp, fmt, ...) \
>+	xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
> #ifdef DEBUG
>-extern __printf(2, 3)
>-void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...);
>+#define xfs_debug(mp, fmt, ...) \
>+	xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
> #else
>-static inline __printf(2, 3)
>-void xfs_debug(const struct xfs_mount *mp, const char *fmt, ...)
>-{
>-}
>+#define xfs_debug(mp, fmt, ...) do {} while (0)
> #endif
>
>+extern __printf(3, 4)
>+void xfs_alert_tag(const struct xfs_mount *mp, int tag, const char *fmt, ...);
>+
>+
> #define xfs_printk_ratelimited(func, dev, fmt, ...)			\
> do {									\
> 	static DEFINE_RATELIMIT_STATE(_rs,				\
>
>base-commit: 34af78c4e616c359ed428d79fe4758a35d2c5473
>-- 
>2.35.1
>

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Hi Petr,

Petr Mladek writes:
>On Fri 2022-03-25 10:19:46, 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 changeable ad-hoc format strings, while still enabling end users
>> to detect changes from release to release.
>>
>> 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>
>
>> --- a/fs/xfs/xfs_message.h
>> +++ b/fs/xfs/xfs_message.h
>> @@ -6,34 +6,45 @@
>>
>>  struct xfs_mount;
>>
>> +#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
>> +({								\
>> +	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
>
>I would probably use "%sXFS: " for the first parameter as
>a compromise here.
>
>It affects how the printk formats are shown in debugfs. With the
>current patch I see in /sys/kernel/debug/printk/index/vmlinux:
>
><4> fs/xfs/libxfs/xfs_ag.c:877 xfs_ag_shrink_space "%sXFS%s: Error %d reserving per-AG metadata reserve pool."
><1> fs/xfs/libxfs/xfs_ag.c:151 xfs_initialize_perag_data "%sXFS%s: AGF corruption. Please run xfs_repair."
><4> fs/xfs/libxfs/xfs_alloc.c:2429 xfs_agfl_reset "%sXFS%s: WARNING: Reset corrupted AGFL on AG %u. %d blocks leaked. Please unmount and run xfs_repair."
><4> fs/xfs/libxfs/xfs_alloc.c:262 xfs_alloc_get_rec "%sXFS%s: start block 0x%x block count 0x%x"
><4> fs/xfs/libxfs/xfs_alloc.c:260 xfs_alloc_get_rec "%sXFS%s: %s Freespace BTree record corruption in AG %d detected!"
><1> fs/xfs/libxfs/xfs_attr_remote.c:304 xfs_attr_rmtval_copyout "%sXFS%s: remote attribute header mismatch bno/off/len/owner (0x%llx/0x%x/Ox%x/0x%llx)"
><4> fs/xfs/libxfs/xfs_bmap.c:1129 xfs_iread_bmbt_block "%sXFS%s: corrupt dinode %llu, (btree extents)."
>
>In reality, the prefix is chosen in __xfs_printk() at runtime:
>
>	+ "%sXFS (%s): "	when mp->m_super is defined
>	+ "%sXFS: "		otherwise
>
>It means that "%sXFS: " is not perfect but it looks closer to reality
>than "%sXFS%s: ".

I think we do actually want "%sXFS%s: " here. Without that, it's not possible to 
be confident marrying up a userspace detector to its original printk 
counterpart if the detector actually looks at what's in mp->m_super->s_id (eg.  
to exclude or include some device).

Some messages in practice also typically only ever come out with mp->m_super 
present, so the userspace detector is likely to accomodate for that whether it 
uses the data in mp->m_super->s_id or not. Since we can't detect which printks 
those are at compile time, we pretty much have to use "%sXFS%s: ".

Thanks,

Chris

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Jonathan Lassoff writes:
>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 changeable ad-hoc format strings, while still enabling end users
>to detect changes from release to release.
>
>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>

After Dave's suggested whitespace/ordering fixup, feel free to add:

Reviewed-by: Chris Down <chris@chrisdown.name>

Thanks!

>---
>
>Notes:
>    [PATCH v1]
>      * De-duplicate kernel logging levels and tidy whitespace.
>    [PATCH v2]
>      * Split changes into two patches:
>         - function and prototype de-duplication.
>         - Adding printk indexing
>    [PATCH v3]
>      * Fix some whitespace and semicolon. *facepalm*
>
> fs/xfs/xfs_message.c |  2 +-
> fs/xfs/xfs_message.h | 29 ++++++++++++++++++++---------
> 2 files changed, 21 insertions(+), 10 deletions(-)
>
>diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
>index ede8a4f2f676..f01efad20420 100644
>--- a/fs/xfs/xfs_message.c
>+++ b/fs/xfs/xfs_message.c
>@@ -51,7 +51,7 @@ void xfs_printk_level(
> }
>
> 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 2f609800e806..6f9a1b67c4d7 100644
>--- a/fs/xfs/xfs_message.h
>+++ b/fs/xfs/xfs_message.h
>@@ -6,34 +6,45 @@
>
> struct xfs_mount;
>
>+#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)		\
>+({								\
>+	printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt);	\
>+	xfs_printk_level(kern_level, mp, fmt, ##__VA_ARGS__);	\
>+})
> extern __printf(3, 4)
> void xfs_printk_level(
> 	const char *kern_level,
> 	const struct xfs_mount *mp,
> 	const char *fmt, ...);
> #define xfs_emerg(mp, fmt, ...) \
>-	xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
> #define xfs_alert(mp, fmt, ...) \
>-	xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
> #define xfs_crit(mp, fmt, ...) \
>-	xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
> #define xfs_err(mp, fmt, ...) \
>-	xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_ERR, mp, fmt, ##__VA_ARGS__)
> #define xfs_warn(mp, fmt, ...) \
>-	xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
> #define xfs_notice(mp, fmt, ...) \
>-	xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
> #define xfs_info(mp, fmt, ...) \
>-	xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_INFO, mp, fmt, ##__VA_ARGS__)
> #ifdef DEBUG
> #define xfs_debug(mp, fmt, ...) \
>-	xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
>+	xfs_printk_index_wrap(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
> #else
> #define xfs_debug(mp, fmt, ...) do {} while (0)
> #endif
>
>+#define xfs_alert_tag(mp, tag, fmt, ...)			\
>+({								\
>+	printk_index_subsys_emit("%sXFS%s: ", KERN_ALERT, fmt);	\
>+	_xfs_alert_tag(mp, tag, fmt, ##__VA_ARGS__);		\
>+})
>+
> 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, ...);
>
>
> #define xfs_printk_ratelimited(func, dev, fmt, ...)			\
>-- 
>2.35.1
>

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Petr Mladek]

On Wed 2022-03-30 12:26:24, Dave Chinner wrote:
> On Tue, Mar 29, 2022 at 05:46:49PM -0700, Darrick J. Wong wrote:
> > On Wed, Mar 30, 2022 at 11:34:57AM +1100, Dave Chinner wrote:
> > > I see no statement anywhere about what this printk index ABI
> > > requires in terms of code stablility, format string maintenance and
> > > modification, etc. I've seen it referred to as "semi-stable" but
> > > there is no clear, easily accessible definition as to what that
> > > means for either kernel developers or userspace app developers that
> > > might want to use this information. There's zero information
> > > available about how userspace will use this information, too, so at
> > > this point I can't even guess what the policy for this new ABI
> > > actually is.
> > > 
> > > If this was discussed and a policy was created, then great. But it
> > > *hasn't been documented* for the rest of the world to be able to
> > > read and understand so they know how to deal safely with the
> > > information this ABI now provides. So, can you please explain what
> > > the rules are, and then please write some documentation for the
> > > kernel admin guide defining the user ABI for application writers and
> > > what guarantees the kernel provides them with about the contents of
> > > this ABI.
> > 
> > FWIW if you /did/ accept this for 5.19, I would suggest adding:
> > 
> > printk_index_subsys_emit("XFS log messages shall not be considered a stable kernel ABI as they can change at any time");
> > 
> > I base that largely on the evidence -- there's nothing saying that
> > catalogued strings are or are not a stable ABI.  That means it's up to
> > the subsystem or the maintainers or whoever to make a decision, and I
> 
> Yup, that's largely what I want clarified before we make a
> decision one way or another. There must have been some discussion
> and decisions on what the policy is before it was merged, but it's
> not easily findable.
> 
> And, IMO, instead of every single subsystem having to go through the
> same question and answer process as we are currently doing, I want
> that policy to be documented such that a simple "git grep
> printk_index_subsys_emit" search returns the file in the
> Documentation/ directory that explains all this. That makes
> everyone's lives a whole lot easier.

I understand this fear. It was my very first reaction on the printk
index feature as well.

Chris explained to me that it is exactly the opposite. I have tried to
summarize my undestanding in the following RFC patch. I could
send it separately for a proper review if you agree that
this is the right way to go.

I think that we will actually need to extend the section about
the subsystem specific prefix. It seems that Chris has another
opinion based on his real life experience with this feature.

Anyway, I send this draft now. It is getting late here. I hope
that it will answer some questions...

Here we go:

From 65a6fb3b9d183434ecdd96f286439696f868fa8e Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Wed, 30 Mar 2022 16:47:09 +0200
Subject: [RFC] printk/index: Printk index feature documentation

Document the printk index feature. The primary motivation is to
explain that it is not creating KABI from particular printk() calls.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 Documentation/core-api/printk-index.rst | 139 ++++++++++++++++++++++++
 1 file changed, 139 insertions(+)
 create mode 100644 Documentation/core-api/printk-index.rst

diff --git a/Documentation/core-api/printk-index.rst b/Documentation/core-api/printk-index.rst
new file mode 100644
index 000000000000..b5f759e97a6a
--- /dev/null
+++ b/Documentation/core-api/printk-index.rst
@@ -0,0 +1,139 @@
+.. SPDX-License-Identifier: GPL-2.0
+
+============
+Printk index
+============
+
+There are many ways how to control the state of the system. One important
+source of information is the system log. It provides a lot of information,
+including more or less important warnings and error messages.
+
+The system log can be monitored by some tool. It is especially useful
+when there are many monitored systems. Such tools try to filter out
+less important messages or known problems. They might also trigger
+some action when a particular message appears.
+
+The kernel messages are evolving together with the code. They are
+not KABI and never will be!
+
+It is a huge challenge for maintaining the system log monitors. It requires
+knowing what messages were udpated and why. Finding these changes in
+the sources would require non-trivial parsers. Also it would require
+matching the sources with the binary kernel which is not always trivial.
+Various changes might be backported. Various kernel versions might be used
+on different monitored systems.
+
+This is where the printk index feature might become useful. It provides
+a dump of printk formats used all over the source code used for the kernel
+and modules on the running system. It is accessible at runtime via debugfs.
+
+
+User interface
+==============
+
+The index of printk formats is split into separate files for
+for vmlinux and loaded modules, for example::
+
+   /sys/kernel/debug/printk/index/vmlinux
+   /sys/kernel/debug/printk/index/ext4
+   /sys/kernel/debug/printk/index/scsi_mod
+
+The content is inspired by the dynamic debug interface and looks like::
+
+   $> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
+   # <level[,flags]> filename:line function "format"
+   <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
+   <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
+   <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
+   <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
+   <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
+
+, where the meaning is::
+
+   - level: log level
+   - flags: optional flags: currently only 'c' for KERN_CONT
+   - filename:line: source filename and line number of the related
+	printk() call. Note that there are many wrappers, for example,
+	pr_warn(), pr_warn_once(), dev_warn().
+   - function: function name where the printk() call is used.
+   - format: format string
+
+The extra information makes it a bit harder to find differences
+between various kernels. Especially the line number might change
+very often. On the other hand, it helps a lot to confirm that
+it is the same string or find the commit that is responsible
+for eventual changes.
+
+
+printk() as a KABI
+==================
+
+Many developers are afraid that exporting all these implementation
+details into the user space will transform particular printk() calls
+into KABI.
+
+But it is exactly the opposite. printk() calls must _not_ be KABI.
+And the printk index helps user space tools to deal with this.
+
+It is similar to the dynamic debug interface. It shows what debugging
+strings might be enabled. But it does not create ABI from them.
+
+Or it is similar to <debugfs>/tracing/available_filter_functions.
+It provides a list of functions that can be traced. But it does
+not create KABI from the function names. It would prevent any
+further development.
+
+
+Subsystem specific printk wrappers
+==================================
+
+The printk index is generated using extra metadata that are stored in
+a dedicated .elf section ".printk_index". It is achieved using macro
+wrappers doing __printk_index_emit() together with the real printk()
+call. The same technique is used also for the metadata used by
+the dynamic debug feature.
+
+The metadata are stored for a particular message only when it is printed
+using these special wrappers. It is implemented for the commonly
+used printk() calls, including, for example, pr_warn(), or pr_once().
+
+It needs additional changes for variaous subsystem specific wrappers that
+call the original printk() via a common helper function. These needs
+they own wrappers adding __printk_index_emit().
+
+Only few subsystem specific wrappers have been updated so far,
+for example, dev_printk(). Only the generic string from the common
+helper function appears in the printk index for others.
+
+
+Subsystem specific prefix
+=========================
+
+The macro pr_fmt() macro allows to define a prefix that is printed
+before the string generated by the related printk() calls.
+
+Subsystem specific wrappers usually add even more complicated
+prefixes.
+
+These prefixes can be stored into the printk index metadata
+by an optional parameter of __printk_index_emit(). The debugfs
+interface might then show the printk formats including these prefixes.
+For example, drivers/acpi/osl.c contains::
+
+  #define pr_fmt(fmt) "ACPI: OSL: " fmt
+
+  static int __init acpi_no_auto_serialize_setup(char *str)
+  {
+	acpi_gbl_auto_serialize_methods = FALSE;
+	pr_info("Auto-serialization disabled\n");
+
+	return 1;
+  }
+
+I results into printk index entry::
+
+  <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
+
+It helps matching messages from the real log with printk index.
+Then the source file name, line number, and function name can
+be used to match the string with the source code.
-- 
2.34.1

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Petr Mladek writes:
>I understand this fear. It was my very first reaction on the printk
>index feature as well.
>
>Chris explained to me that it is exactly the opposite. I have tried to
>summarize my undestanding in the following RFC patch. I could
>send it separately for a proper review if you agree that
>this is the right way to go.
>
>I think that we will actually need to extend the section about
>the subsystem specific prefix. It seems that Chris has another
>opinion based on his real life experience with this feature.

Wow, thanks for writing this up! This looks great to me, feel free to send it 
as a real patch and I will happily add my Reviewed-by.

My general opinion is that debugfs files don't mandate user-facing 
documentation since they are by their very nature kernel developer features, 
but you're right that it would reduce confusion here to have something written 
to reference for people who want to add printk index entries, so this makes 
sense.

>Anyway, I send this draft now. It is getting late here. I hope
>that it will answer some questions...
>
>Here we go:
>
>From 65a6fb3b9d183434ecdd96f286439696f868fa8e Mon Sep 17 00:00:00 2001
>From: Petr Mladek <pmladek@suse.com>
>Date: Wed, 30 Mar 2022 16:47:09 +0200
>Subject: [RFC] printk/index: Printk index feature documentation
>
>Document the printk index feature. The primary motivation is to
>explain that it is not creating KABI from particular printk() calls.
>
>Signed-off-by: Petr Mladek <pmladek@suse.com>
>---
> Documentation/core-api/printk-index.rst | 139 ++++++++++++++++++++++++
> 1 file changed, 139 insertions(+)
> create mode 100644 Documentation/core-api/printk-index.rst
>
>diff --git a/Documentation/core-api/printk-index.rst b/Documentation/core-api/printk-index.rst
>new file mode 100644
>index 000000000000..b5f759e97a6a
>--- /dev/null
>+++ b/Documentation/core-api/printk-index.rst
>@@ -0,0 +1,139 @@
>+.. SPDX-License-Identifier: GPL-2.0
>+
>+============
>+Printk index
>+============
>+
>+There are many ways how to control the state of the system. One important
>+source of information is the system log. It provides a lot of information,
>+including more or less important warnings and error messages.
>+
>+The system log can be monitored by some tool. It is especially useful
>+when there are many monitored systems. Such tools try to filter out
>+less important messages or known problems. They might also trigger
>+some action when a particular message appears.
>+
>+The kernel messages are evolving together with the code. They are
>+not KABI and never will be!
>+
>+It is a huge challenge for maintaining the system log monitors. It requires
>+knowing what messages were udpated and why. Finding these changes in
>+the sources would require non-trivial parsers. Also it would require
>+matching the sources with the binary kernel which is not always trivial.
>+Various changes might be backported. Various kernel versions might be used
>+on different monitored systems.
>+
>+This is where the printk index feature might become useful. It provides
>+a dump of printk formats used all over the source code used for the kernel
>+and modules on the running system. It is accessible at runtime via debugfs.
>+
>+
>+User interface
>+==============
>+
>+The index of printk formats is split into separate files for
>+for vmlinux and loaded modules, for example::
>+
>+   /sys/kernel/debug/printk/index/vmlinux
>+   /sys/kernel/debug/printk/index/ext4
>+   /sys/kernel/debug/printk/index/scsi_mod
>+
>+The content is inspired by the dynamic debug interface and looks like::
>+
>+   $> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
>+   # <level[,flags]> filename:line function "format"
>+   <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
>+   <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
>+   <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
>+   <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
>+   <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
>+
>+, where the meaning is::
>+
>+   - level: log level
>+   - flags: optional flags: currently only 'c' for KERN_CONT
>+   - filename:line: source filename and line number of the related
>+	printk() call. Note that there are many wrappers, for example,
>+	pr_warn(), pr_warn_once(), dev_warn().
>+   - function: function name where the printk() call is used.
>+   - format: format string
>+
>+The extra information makes it a bit harder to find differences
>+between various kernels. Especially the line number might change
>+very often. On the other hand, it helps a lot to confirm that
>+it is the same string or find the commit that is responsible
>+for eventual changes.
>+
>+
>+printk() as a KABI
>+==================
>+
>+Many developers are afraid that exporting all these implementation
>+details into the user space will transform particular printk() calls
>+into KABI.
>+
>+But it is exactly the opposite. printk() calls must _not_ be KABI.
>+And the printk index helps user space tools to deal with this.
>+
>+It is similar to the dynamic debug interface. It shows what debugging
>+strings might be enabled. But it does not create ABI from them.
>+
>+Or it is similar to <debugfs>/tracing/available_filter_functions.
>+It provides a list of functions that can be traced. But it does
>+not create KABI from the function names. It would prevent any
>+further development.
>+
>+
>+Subsystem specific printk wrappers
>+==================================
>+
>+The printk index is generated using extra metadata that are stored in
>+a dedicated .elf section ".printk_index". It is achieved using macro
>+wrappers doing __printk_index_emit() together with the real printk()
>+call. The same technique is used also for the metadata used by
>+the dynamic debug feature.
>+
>+The metadata are stored for a particular message only when it is printed
>+using these special wrappers. It is implemented for the commonly
>+used printk() calls, including, for example, pr_warn(), or pr_once().
>+
>+It needs additional changes for variaous subsystem specific wrappers that
>+call the original printk() via a common helper function. These needs
>+they own wrappers adding __printk_index_emit().
>+
>+Only few subsystem specific wrappers have been updated so far,
>+for example, dev_printk(). Only the generic string from the common
>+helper function appears in the printk index for others.
>+
>+
>+Subsystem specific prefix
>+=========================
>+
>+The macro pr_fmt() macro allows to define a prefix that is printed
>+before the string generated by the related printk() calls.
>+
>+Subsystem specific wrappers usually add even more complicated
>+prefixes.
>+
>+These prefixes can be stored into the printk index metadata
>+by an optional parameter of __printk_index_emit(). The debugfs
>+interface might then show the printk formats including these prefixes.
>+For example, drivers/acpi/osl.c contains::
>+
>+  #define pr_fmt(fmt) "ACPI: OSL: " fmt
>+
>+  static int __init acpi_no_auto_serialize_setup(char *str)
>+  {
>+	acpi_gbl_auto_serialize_methods = FALSE;
>+	pr_info("Auto-serialization disabled\n");
>+
>+	return 1;
>+  }
>+
>+I results into printk index entry::
>+
>+  <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
>+
>+It helps matching messages from the real log with printk index.
>+Then the source file name, line number, and function name can
>+be used to match the string with the source code.
>-- 
>2.34.1

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Steven Rostedt]

On Wed, 30 Mar 2022 12:52:58 +0100
Chris Down <chris@chrisdown.name> wrote:

> The policy, as with all debugfs APIs by default, is that it's completely 
> unstable and there are no API stability guarantees whatsoever. That's why 
> there's no extensive documentation for users: because this is a feature for 
> kernel developers.
> 
> 0: https://lwn.net/Articles/309298/

That article you reference states the opposite of what you said. And I got
burnt by it before. Because Linus stated, if it is available for users, it
is an ABI.

From the article above:

"Linus put it this way:

   The fact that something is documented (whether correctly or not) has
   absolutely _zero_ impact on anything at all. What makes something an ABI is
   that it's useful and available. The only way something isn't an ABI is by
   _explicitly_ making sure that it's not available even by mistake in a
   stable form for binary use. Example: kernel internal data structures and
   function calls. We make sure that you simply _cannot_ make a binary that
   works across kernel versions. That is the only way for an ABI to not form."

IOW, files in debugfs are available for users, and if something is written
that depends on it and it is useful, it becomes ABI. The way I fixed my
issue was to go and send patches to all the users that depended on the ABI,
taking away the dependency, and then I was able to update debugfs.

-- Steve

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Steven Rostedt writes:
>On Wed, 30 Mar 2022 12:52:58 +0100
>Chris Down <chris@chrisdown.name> wrote:
>
>> The policy, as with all debugfs APIs by default, is that it's completely
>> unstable and there are no API stability guarantees whatsoever. That's why
>> there's no extensive documentation for users: because this is a feature for
>> kernel developers.
>>
>> 0: https://lwn.net/Articles/309298/
>
>That article you reference states the opposite of what you said. And I got
>burnt by it before. Because Linus stated, if it is available for users, it
>is an ABI.

Hmm, even in 2011 after that article there were discussions about debugfs 
explicitly being the "wild west"[0], no? I heard the same during LSFMM 
discussions during recent years as well. Although I confess that I am not 
frequently in discussions about debugfs so I don't really know where the 
majority opinion is nowadays.

Either way, as discussed the contents wouldn't be the ABI (as with my 
/proc/self/smaps allusion), the file format would be, so it wouldn't imply that 
printk() calls themselves or their locations become an ABI.

0: https://lwn.net/Articles/429321/

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Chris Down writes:
>>That article you reference states the opposite of what you said. And I got
>>burnt by it before. Because Linus stated, if it is available for users, it
>>is an ABI.
>
>Hmm, even in 2011 after that article there were discussions about 
>debugfs explicitly being the "wild west"[0], no? I heard the same 
>during LSFMM discussions during recent years as well. Although I 
>confess that I am not frequently in discussions about debugfs so I 
>don't really know where the majority opinion is nowadays.
>
>Either way, as discussed the contents wouldn't be the ABI (as with my 
>/proc/self/smaps allusion), the file format would be, so it wouldn't 
>imply that printk() calls themselves or their locations become an ABI.
>
>0: https://lwn.net/Articles/429321/

(To be clear, that article basically says that debugfs should become less of a 
"wild west", of course. I mostly just am not sure that it's so clear to 
everyone what the ABI status of debugfs currently is, although probably your 
recent experience with Linus is a reasonable thermometer on the whole thing.)

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Steven Rostedt]

On Wed, 30 Mar 2022 18:09:28 +0100
Chris Down <chris@chrisdown.name> wrote:

> Steven Rostedt writes:
> >On Wed, 30 Mar 2022 12:52:58 +0100
> >Chris Down <chris@chrisdown.name> wrote:
> >  
> >> The policy, as with all debugfs APIs by default, is that it's completely
> >> unstable and there are no API stability guarantees whatsoever. That's why
> >> there's no extensive documentation for users: because this is a feature for
> >> kernel developers.
> >>
> >> 0: https://lwn.net/Articles/309298/  
> >
> >That article you reference states the opposite of what you said. And I got
> >burnt by it before. Because Linus stated, if it is available for users, it
> >is an ABI.  
> 
> Hmm, even in 2011 after that article there were discussions about debugfs 
> explicitly being the "wild west"[0], no? I heard the same during LSFMM 
> discussions during recent years as well. Although I confess that I am not 
> frequently in discussions about debugfs so I don't really know where the 
> majority opinion is nowadays.

There isn't a majority opinion on this. There's only one opinion, and
that's Linus's ;-)

-- Steve


> 
> Either way, as discussed the contents wouldn't be the ABI (as with my 
> /proc/self/smaps allusion), the file format would be, so it wouldn't imply that 
> printk() calls themselves or their locations become an ABI.
> 
> 0: https://lwn.net/Articles/429321/

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Chris Down]

Steven Rostedt writes:
>There isn't a majority opinion on this. There's only one opinion, and
>that's Linus's ;-)

Fair enough :-)

Regardless, I don't think we need to get too into the weeds about whether 
debugfs is a stable ABI or not here. Even if it is considered to be so, the ABI 
here would be the format and location of the printk index -- printk entries 
being added, changed, or removed are just backing data changes in the same way 
that adding or removing a map and that then being reflected in /proc/self/smaps 
isn't an ABI break either.

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Dave Chinner]

On Wed, Mar 30, 2022 at 12:47:39PM -0400, Steven Rostedt wrote:
> On Wed, 30 Mar 2022 12:52:58 +0100
> Chris Down <chris@chrisdown.name> wrote:
> 
> > The policy, as with all debugfs APIs by default, is that it's completely 
> > unstable and there are no API stability guarantees whatsoever. That's why 
> > there's no extensive documentation for users: because this is a feature for 
> > kernel developers.
> > 
> > 0: https://lwn.net/Articles/309298/
> 
> That article you reference states the opposite of what you said. And I got
> burnt by it before. Because Linus stated, if it is available for users, it
> is an ABI.
> 
> From the article above:
> 
> "Linus put it this way:
> 
>    The fact that something is documented (whether correctly or not) has
>    absolutely _zero_ impact on anything at all. What makes something an ABI is
>    that it's useful and available. The only way something isn't an ABI is by
>    _explicitly_ making sure that it's not available even by mistake in a
>    stable form for binary use. Example: kernel internal data structures and
>    function calls. We make sure that you simply _cannot_ make a binary that
>    works across kernel versions. That is the only way for an ABI to not form."
> 
> IOW, files in debugfs are available for users, and if something is written
> that depends on it and it is useful, it becomes ABI.

Yup, that's exactly what happened with powertop and the tracepoints
it used and why I pointed to it as is the canonical example of
information exposed from within debugfs unintentionally becoming
stable KABI....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Jonathan Lassoff]

Thanks for the useful feedback from all. I've integrated the
formatting suggestions and will follow up with a [PATCH v4] set.

My initial commit message describing a "semi-stable interface" was a
poor choice of words on my part. My idea of "interface" was users
comparing the index entries from release to release and developing on
top of that; I didn't take into consideration the contextual meaning
of "interface" in Kernel development. This change doesn't create or
alter any interfaces, this just makes the backing store of information
for an existing interface more correct and complete.
It is my hope that once these changes are made, XFS maintainers will
hardly need to engage with or keep track of this printk indexing
effort. These are only needed because printk() isn't called directly.

-- jof

On Wed, 30 Mar 2022 at 12:07, Chris Down <chris@chrisdown.name> wrote:
>
> Jonathan Lassoff writes:
> >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 changeable ad-hoc format strings, while still enabling end users
> >to detect changes from release to release.
> >
> >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>
>
> After Dave's suggested whitespace/ordering fixup, feel free to add:
>
> Reviewed-by: Chris Down <chris@chrisdown.name>
>
> Thanks!
>
> >---
> >
> >Notes:
> >    [PATCH v1]
> >      * De-duplicate kernel logging levels and tidy whitespace.
> >    [PATCH v2]
> >      * Split changes into two patches:
> >         - function and prototype de-duplication.
> >         - Adding printk indexing
> >    [PATCH v3]
> >      * Fix some whitespace and semicolon. *facepalm*
> >
> > fs/xfs/xfs_message.c |  2 +-
> > fs/xfs/xfs_message.h | 29 ++++++++++++++++++++---------
> > 2 files changed, 21 insertions(+), 10 deletions(-)
> >
> >diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
> >index ede8a4f2f676..f01efad20420 100644
> >--- a/fs/xfs/xfs_message.c
> >+++ b/fs/xfs/xfs_message.c
> >@@ -51,7 +51,7 @@ void xfs_printk_level(
> > }
> >
> > 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 2f609800e806..6f9a1b67c4d7 100644
> >--- a/fs/xfs/xfs_message.h
> >+++ b/fs/xfs/xfs_message.h
> >@@ -6,34 +6,45 @@
> >
> > struct xfs_mount;
> >
> >+#define xfs_printk_index_wrap(kern_level, mp, fmt, ...)               \
> >+({                                                            \
> >+      printk_index_subsys_emit("%sXFS%s: ", kern_level, fmt); \
> >+      xfs_printk_level(kern_level, mp, fmt, ##__VA_ARGS__);   \
> >+})
> > extern __printf(3, 4)
> > void xfs_printk_level(
> >       const char *kern_level,
> >       const struct xfs_mount *mp,
> >       const char *fmt, ...);
> > #define xfs_emerg(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_EMERG, mp, fmt, ##__VA_ARGS__)
> > #define xfs_alert(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_ALERT, mp, fmt, ##__VA_ARGS__)
> > #define xfs_crit(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_CRIT, mp, fmt, ##__VA_ARGS__)
> > #define xfs_err(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_ERR, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_ERR, mp, fmt, ##__VA_ARGS__)
> > #define xfs_warn(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_WARNING, mp, fmt, ##__VA_ARGS__)
> > #define xfs_notice(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_NOTICE, mp, fmt, ##__VA_ARGS__)
> > #define xfs_info(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_INFO, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_INFO, mp, fmt, ##__VA_ARGS__)
> > #ifdef DEBUG
> > #define xfs_debug(mp, fmt, ...) \
> >-      xfs_printk_level(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
> >+      xfs_printk_index_wrap(KERN_DEBUG, mp, fmt, ##__VA_ARGS__)
> > #else
> > #define xfs_debug(mp, fmt, ...) do {} while (0)
> > #endif
> >
> >+#define xfs_alert_tag(mp, tag, fmt, ...)                      \
> >+({                                                            \
> >+      printk_index_subsys_emit("%sXFS%s: ", KERN_ALERT, fmt); \
> >+      _xfs_alert_tag(mp, tag, fmt, ##__VA_ARGS__);            \
> >+})
> >+
> > 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, ...);
> >
> >
> > #define xfs_printk_ratelimited(func, dev, fmt, ...)                   \
> >--
> >2.35.1
> >

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Sergey Senozhatsky]

On (22/03/30 16:59), Petr Mladek wrote:
> Document the printk index feature. The primary motivation is to
> explain that it is not creating KABI from particular printk() calls.
> 
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Great write up!

Acked-by: Sergey Senozhatsky <senozhatsky@chromium.org>

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Petr Mladek]

On Thu 2022-03-31 08:02:19, Dave Chinner wrote:
> On Wed, Mar 30, 2022 at 12:47:39PM -0400, Steven Rostedt wrote:
> > On Wed, 30 Mar 2022 12:52:58 +0100
> > Chris Down <chris@chrisdown.name> wrote:
> > 
> > > The policy, as with all debugfs APIs by default, is that it's completely 
> > > unstable and there are no API stability guarantees whatsoever. That's why 
> > > there's no extensive documentation for users: because this is a feature for 
> > > kernel developers.
> > > 
> > > 0: https://lwn.net/Articles/309298/
> > 
> > That article you reference states the opposite of what you said. And I got
> > burnt by it before. Because Linus stated, if it is available for users, it
> > is an ABI.
> > 
> > From the article above:
> > 
> > "Linus put it this way:
> > 
> >    The fact that something is documented (whether correctly or not) has
> >    absolutely _zero_ impact on anything at all. What makes something an ABI is
> >    that it's useful and available. The only way something isn't an ABI is by
> >    _explicitly_ making sure that it's not available even by mistake in a
> >    stable form for binary use. Example: kernel internal data structures and
> >    function calls. We make sure that you simply _cannot_ make a binary that
> >    works across kernel versions. That is the only way for an ABI to not form."
> > 
> > IOW, files in debugfs are available for users, and if something is written
> > that depends on it and it is useful, it becomes ABI.
> 
> Yup, that's exactly what happened with powertop and the tracepoints
> it used and why I pointed to it as is the canonical example of
> information exposed from within debugfs unintentionally becoming
> stable KABI....

To be sure that we are on the same page.

Please, fix me if I am wrong. I am not that familiar with tracepoints.
It is a rather complex feature. Each tracepoint has a name, arguments,
fields, prints a message. I guess that the KABI aspects are:

    + name of the tracepoint
    + situation when they are triggered
    + names, type, and meaning of the parameters/fields
    + format and meaning or the printed messages

In compare, a potential KABI aspects of a particular printk format
(message) are:

    + situation when it is printed
    + format and meaning of the printed message

They clearly have something in common. I guess that this causes the
fear that the printk index feature might make convert a particular
printk message into KABI.


Note that the above summary is not talking about debugfs at all.
Is it really debugfs what made tracepoints considered a KABI?
Are tracepoints usable without debugfs?

It is clear that the debugfs interface might be KABI on its own.
There are many tools that use the interface to actually use
the tracepoints. A change in the interface might break the tools.
But it will be about the interface and not about the particular
tracepoints.

But I think that tracepoints are KABI even without the debugfs
interface. We could create 10 different interfaces for tracepoints
between the kernel and userspace. And all will break userspace
if the functionality of a tracepoint is modified.


I want to say. IMHO, it is is not debugfs what made KABI from
tracepoints. I think that tracepoints can be considered KABI on
its own. The tracepoints were created together with the debugfs
interface. They would not make any sense without each other.

This is not the case for printk() messages. They were always there.

The printk index is not an interface for using the messages.
It is like /proc/config.gz. The printk index describes what
pieces are available in the kernel.

IMHO, printk messages might already be considered KABI. There
are clearly monitors checking particular messages. The printk index
does not make any difference. Yes, it might be used to create a KABI
checker. But a KABI checker does not create the KABI. KABI
checkers exist only because something has already been considered
KABI before.

Or am I too naive or completely wrong, please?

Best Regards,
Petr

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Darrick J. Wong]

On Wed, Mar 30, 2022 at 04:07:36PM +0100, Chris Down wrote:
> Petr Mladek writes:
> > I understand this fear. It was my very first reaction on the printk
> > index feature as well.
> > 
> > Chris explained to me that it is exactly the opposite. I have tried to
> > summarize my undestanding in the following RFC patch. I could
> > send it separately for a proper review if you agree that
> > this is the right way to go.
> > 
> > I think that we will actually need to extend the section about
> > the subsystem specific prefix. It seems that Chris has another
> > opinion based on his real life experience with this feature.
> 
> Wow, thanks for writing this up! This looks great to me, feel free to send
> it as a real patch and I will happily add my Reviewed-by.
> 
> My general opinion is that debugfs files don't mandate user-facing
> documentation since they are by their very nature kernel developer features,
> but you're right that it would reduce confusion here to have something
> written to reference for people who want to add printk index entries, so
> this makes sense.
> 
> > Anyway, I send this draft now. It is getting late here. I hope
> > that it will answer some questions...
> > 
> > Here we go:
> > 
> > From 65a6fb3b9d183434ecdd96f286439696f868fa8e Mon Sep 17 00:00:00 2001
> > From: Petr Mladek <pmladek@suse.com>
> > Date: Wed, 30 Mar 2022 16:47:09 +0200
> > Subject: [RFC] printk/index: Printk index feature documentation
> > 
> > Document the printk index feature. The primary motivation is to
> > explain that it is not creating KABI from particular printk() calls.
> > 
> > Signed-off-by: Petr Mladek <pmladek@suse.com>
> > ---
> > Documentation/core-api/printk-index.rst | 139 ++++++++++++++++++++++++
> > 1 file changed, 139 insertions(+)
> > create mode 100644 Documentation/core-api/printk-index.rst
> > 
> > diff --git a/Documentation/core-api/printk-index.rst b/Documentation/core-api/printk-index.rst
> > new file mode 100644
> > index 000000000000..b5f759e97a6a
> > --- /dev/null
> > +++ b/Documentation/core-api/printk-index.rst
> > @@ -0,0 +1,139 @@
> > +.. SPDX-License-Identifier: GPL-2.0
> > +
> > +============
> > +Printk index
> > +============
> > +
> > +There are many ways how to control the state of the system. One important

I would say this is monitoring the state of the system more than it's
controlling it.

> > +source of information is the system log. It provides a lot of information,
> > +including more or less important warnings and error messages.
> > +
> > +The system log can be monitored by some tool. It is especially useful
> > +when there are many monitored systems. Such tools try to filter out
> > +less important messages or known problems. They might also trigger
> > +some action when a particular message appears.

TBH I thought the bigger promise of the printk index is the ability to
find where in the source code a message might have come from.

I would like to see the problem statement part of this doc develop
further.  What do you think about reworking the above paragraph like so?

"Often it is useful for developers and support specialists to be able to
trace a kernel log message back to its exact position in source code.
Moreover, there are monitoring tools that filter and take action based
on messages logged.  For both of these use cases, it would be helpful to
provide an index of all possible printk format strings for the running
kernel."

> > +
> > +The kernel messages are evolving together with the code. They are
> > +not KABI and never will be!

Ok.  You might want to make it explicit here that the format of the
debugfs file itself shouldn't change, unlike the file/line/formatspecificer
*contents* of those files.

> > +It is a huge challenge for maintaining the system log monitors. It requires
> > +knowing what messages were udpated and why. Finding these changes in

s/udpated/updated/

> > +the sources would require non-trivial parsers. Also it would require
> > +matching the sources with the binary kernel which is not always trivial.
> > +Various changes might be backported. Various kernel versions might be used
> > +on different monitored systems.
> > +
> > +This is where the printk index feature might become useful. It provides
> > +a dump of printk formats used all over the source code used for the kernel
> > +and modules on the running system. It is accessible at runtime via debugfs.
> > +
> > +
> > +User interface
> > +==============
> > +
> > +The index of printk formats is split into separate files for
> > +for vmlinux and loaded modules, for example::
> > +
> > +   /sys/kernel/debug/printk/index/vmlinux
> > +   /sys/kernel/debug/printk/index/ext4
> > +   /sys/kernel/debug/printk/index/scsi_mod

If ext4 is built into the kernel (and not as a module), does its format
strings end up in index/vmlinux or index/ext4?

> > +
> > +The content is inspired by the dynamic debug interface and looks like::
> > +
> > +   $> head -1 /sys/kernel/debug/printk/index/vmlinux; shuf -n 5 vmlinux
> > +   # <level[,flags]> filename:line function "format"
> > +   <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
> > +   <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
> > +   <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
> > +   <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
> > +   <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
> > +
> > +, where the meaning is::
> > +
> > +   - level: log level
> > +   - flags: optional flags: currently only 'c' for KERN_CONT
> > +   - filename:line: source filename and line number of the related
> > +	printk() call. Note that there are many wrappers, for example,
> > +	pr_warn(), pr_warn_once(), dev_warn().
> > +   - function: function name where the printk() call is used.
> > +   - format: format string
> > +
> > +The extra information makes it a bit harder to find differences
> > +between various kernels. Especially the line number might change
> > +very often. On the other hand, it helps a lot to confirm that
> > +it is the same string or find the commit that is responsible
> > +for eventual changes.
> > +
> > +
> > +printk() as a KABI

You might just call this "printk() is not a stable KABI".

> > +==================
> > +
> > +Many developers are afraid that exporting all these implementation
> > +details into the user space will transform particular printk() calls
> > +into KABI.
> > +
> > +But it is exactly the opposite. printk() calls must _not_ be KABI.
> > +And the printk index helps user space tools to deal with this.
> > +
> > +It is similar to the dynamic debug interface. It shows what debugging
> > +strings might be enabled. But it does not create ABI from them.
> > +
> > +Or it is similar to <debugfs>/tracing/available_filter_functions.

"It is also similar to..."

> > +It provides a list of functions that can be traced. But it does
> > +not create KABI from the function names. It would prevent any
> > +further development.
> > +
> > +
> > +Subsystem specific printk wrappers
> > +==================================
> > +
> > +The printk index is generated using extra metadata that are stored in
> > +a dedicated .elf section ".printk_index". It is achieved using macro
> > +wrappers doing __printk_index_emit() together with the real printk()
> > +call. The same technique is used also for the metadata used by
> > +the dynamic debug feature.
> > +
> > +The metadata are stored for a particular message only when it is printed
> > +using these special wrappers. It is implemented for the commonly
> > +used printk() calls, including, for example, pr_warn(), or pr_once().
> > +
> > +It needs additional changes for variaous subsystem specific wrappers that

"Additional changes are necessary for various subsystem specific
wrappers..."

> > +call the original printk() via a common helper function. These needs
> > +they own wrappers adding __printk_index_emit().

"These need their own wrappers..."

> > +
> > +Only few subsystem specific wrappers have been updated so far,
> > +for example, dev_printk(). Only the generic string from the common
> > +helper function appears in the printk index for others.
> > +
> > +
> > +Subsystem specific prefix
> > +=========================
> > +
> > +The macro pr_fmt() macro allows to define a prefix that is printed
> > +before the string generated by the related printk() calls.
> > +
> > +Subsystem specific wrappers usually add even more complicated
> > +prefixes.
> > +
> > +These prefixes can be stored into the printk index metadata
> > +by an optional parameter of __printk_index_emit(). The debugfs
> > +interface might then show the printk formats including these prefixes.
> > +For example, drivers/acpi/osl.c contains::
> > +
> > +  #define pr_fmt(fmt) "ACPI: OSL: " fmt
> > +
> > +  static int __init acpi_no_auto_serialize_setup(char *str)
> > +  {
> > +	acpi_gbl_auto_serialize_methods = FALSE;
> > +	pr_info("Auto-serialization disabled\n");
> > +
> > +	return 1;
> > +  }
> > +
> > +I results into printk index entry::

"This results in the following printk index entry::"

> > +
> > +  <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"
> > +
> > +It helps matching messages from the real log with printk index.
> > +Then the source file name, line number, and function name can
> > +be used to match the string with the source code.

--D

> > -- 
> > 2.34.1

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Dave Chinner]

On Thu, Mar 31, 2022 at 04:09:23PM +0200, Petr Mladek wrote:
> On Thu 2022-03-31 08:02:19, Dave Chinner wrote:
> > On Wed, Mar 30, 2022 at 12:47:39PM -0400, Steven Rostedt wrote:
> > > On Wed, 30 Mar 2022 12:52:58 +0100
> > > Chris Down <chris@chrisdown.name> wrote:
> > > 
> > > > The policy, as with all debugfs APIs by default, is that it's completely 
> > > > unstable and there are no API stability guarantees whatsoever. That's why 
> > > > there's no extensive documentation for users: because this is a feature for 
> > > > kernel developers.
> > > > 
> > > > 0: https://lwn.net/Articles/309298/
> > > 
> > > That article you reference states the opposite of what you said. And I got
> > > burnt by it before. Because Linus stated, if it is available for users, it
> > > is an ABI.
> > > 
> > > From the article above:
> > > 
> > > "Linus put it this way:
> > > 
> > >    The fact that something is documented (whether correctly or not) has
> > >    absolutely _zero_ impact on anything at all. What makes something an ABI is
> > >    that it's useful and available. The only way something isn't an ABI is by
> > >    _explicitly_ making sure that it's not available even by mistake in a
> > >    stable form for binary use. Example: kernel internal data structures and
> > >    function calls. We make sure that you simply _cannot_ make a binary that
> > >    works across kernel versions. That is the only way for an ABI to not form."
> > > 
> > > IOW, files in debugfs are available for users, and if something is written
> > > that depends on it and it is useful, it becomes ABI.
> > 
> > Yup, that's exactly what happened with powertop and the tracepoints
> > it used and why I pointed to it as is the canonical example of
> > information exposed from within debugfs unintentionally becoming
> > stable KABI....
> 
> To be sure that we are on the same page.
> 
> Please, fix me if I am wrong. I am not that familiar with tracepoints.
> It is a rather complex feature. Each tracepoint has a name, arguments,
> fields, prints a message. I guess that the KABI aspects are:
> 
>     + name of the tracepoint
>     + situation when they are triggered
>     + names, type, and meaning of the parameters/fields
>     + format and meaning or the printed messages

These -aren't- things that make up the tracepoint KABI - this is the
-data- that the tracepoint infrastructure generates. This data
contains a *lot* of information about the internal implementation of
a subsystem. e.g. there are over 550 individual tracepoints in XFS
that span every single subsystem from IO paths to allocation to log
space reseverations.

> In compare, a potential KABI aspects of a particular printk format
> (message) are:
> 
>     + situation when it is printed
>     + format and meaning of the printed message

Again, I see this as the data being generated by the printk index,
not the KABI defined for ensuring access to the data doesn't change.

> They clearly have something in common. I guess that this causes the
> fear that the printk index feature might make convert a particular
> printk message into KABI.
> 
> Note that the above summary is not talking about debugfs at all.
> Is it really debugfs what made tracepoints considered a KABI?
> Are tracepoints usable without debugfs?

No, but....

A large number of the tracepoints in XFS come from Irix kernel
debugging infrastructure from the early/mid 1990s. Irix had a built
in kernel debugger (idb) and kernel crash dump tools that could also
run on a live kernel (icrash). XFS had code in it to add commands to
both of these tools to iterate the tracing events that were built
into the code.

commit 8a2bc927ff399dff08d4242c8cec9cb33e31eac2
Author: Doug Doucette <doucette@engr.sgi.com>
Date:   Mon May 9 04:38:21 1994 +0000

    Add a bunch of tracing code for bmap btrees.

That used generic, built in kernel tracing infrastructure that the
Irix kernel and kernel debugger provided developers, and that was
back in 1994.

When XFS was ported to Linux, SGI also ported idb and icrash to
linux - idg became kdb, and icrash is waht we now know as "crash".
The XFS CVS tree carried kdb patches and all the interfacing code
to add the tracing output commands to kdb.

Then, eventually, tracepoints came along and we did a macro
conversion of the original XFS tracing code to the new tracepoint
infrastructure.

IOWs, the tracing events we export via tracepoints in XFS has a long
history of existence before the linux kernel tracepoint
infrastructure ever existed, hence the method of extracting the
tracing data from the kernel doesn't magically make the *tracing
data* part of the kernel ABI.

The tracepoint KABI covers the debugfs interface and file
formats/protocols - the thing that applications like trace-cmd,
perf, PCP, etc interface with to configure and extract tracepoint
data from the kernel. Those binaries need to work across multiple
kernel versions to be cause to control and extract tracepoint
-data-. The data itself can change from kernel to kernel without
those tools breaking, but the data format, the debugfs control
interfaces, etc must all remain unchaged (or at least backward
compatible).

> It is clear that the debugfs interface might be KABI on its own.
> There are many tools that use the interface to actually use
> the tracepoints. A change in the interface might break the tools.
> But it will be about the interface and not about the particular
> tracepoints.

Right. Here's the problem with powertop, from 2010:

https://lwn.net/Articles/442113/

It hard coded a dependency on a *specific set of data* that a
specific tracepoint exported, and so when that tracepoint changed
powertop then broke. The article discusses how this made the
tracepoint data part of the KABI, then read what I said about
that idea w.r.t. XFS:

https://lwn.net/Articles/442340/

Now compare that situation to the concerns I raised about the printk
index.

That is, I'm concerned that the -data- that is exported through this
new printk indexing KABI in debugfs will get retconned as KABI.
That's the same concerns I raised with tracepoints way back then and
history has shown that I was right. i.e. that tracepoint -data-
should never be considered part of the KABI. I don't want to have to
spend the next 10 years making the same arguments about the XFS
printk index *data* not being KABI as we had with tracepoint data.

> But I think that tracepoints are KABI even without the debugfs
> interface. We could create 10 different interfaces for tracepoints
> between the kernel and userspace. And all will break userspace
> if the functionality of a tracepoint is modified.

Yes, the -control interface- is covered by KABI. However, the -data-
that is extracted through that control interface is not covered by
KABI - we can and do change that at will and give no guarantees
about the consistency or stability of the data from kernel to
kernel.

The printk index has the same concerns - the debugfs interface has
to conform to KABI rules, otherwise we break applications. The
-data- that it exposes, OTOH, is tightly tied to internal
implementation details and so must not be tied to KABI. It must be
allowed to chagne at will and applications need to consider it to be
unstable from kernel to kernel and use it appropriately.

> I want to say. IMHO, it is is not debugfs what made KABI from
> tracepoints. I think that tracepoints can be considered KABI on
> its own. The tracepoints were created together with the debugfs
> interface. They would not make any sense without each other.
> 
> This is not the case for printk() messages. They were always there.

So was the internal XFS tracing infrastructure and trace events. :)

> The printk index is not an interface for using the messages.
> It is like /proc/config.gz. The printk index describes what
> pieces are available in the kernel.
>
> IMHO, printk messages might already be considered KABI. There
> are clearly monitors checking particular messages. The printk index
> does not make any difference. Yes, it might be used to create a KABI
> checker. But a KABI checker does not create the KABI. KABI
> checkers exist only because something has already been considered
> KABI before.

AFAIA, printk messages have never been part of the KABI. Anyone who
writes a log scraper knows that messages can and do change over time
and that's their problem to deal with. As kernel developers we give
-zero- regard to KABI when writing, modifying or removing log
messages. That is how it should be, and this directly indicates that
the printk index -data- is not KABI, either.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH v3 2/2] Add XFS messages to printk index

[Petr Mladek]

On Thu 2022-03-31 08:06:18, Darrick J. Wong wrote:
> On Wed, Mar 30, 2022 at 04:07:36PM +0100, Chris Down wrote:
> > Petr Mladek writes:
> > > Subject: [RFC] printk/index: Printk index feature documentation
> > > 
> > > Document the printk index feature. The primary motivation is to
> > > explain that it is not creating KABI from particular printk() calls.
> > > 
> > > --- /dev/null
> > > +++ b/Documentation/core-api/printk-index.rst
> > > @@ -0,0 +1,139 @@
> > > +.. SPDX-License-Identifier: GPL-2.0
> > > +
> > > +============
> > > +Printk index
> > > +============
> > > +
> > > +There are many ways how to control the state of the system. One important
> 
> I would say this is monitoring the state of the system more than it's
> controlling it.
> 
> > > +source of information is the system log. It provides a lot of information,
> > > +including more or less important warnings and error messages.
> > > +
> > > +The system log can be monitored by some tool. It is especially useful
> > > +when there are many monitored systems. Such tools try to filter out
> > > +less important messages or known problems. They might also trigger
> > > +some action when a particular message appears.
> 
> TBH I thought the bigger promise of the printk index is the ability to
> find where in the source code a message might have come from.

I personally use "git grep" to find a given message in the sources.
IMHO, it is much easier than going via printk index.

I could imagine that people might use the printk index when they do
not have the full git repo. But it should not be the main purpose
of this interface. IMHO, it would not be worth it. "grep -R" or
google does similar job.

Or maybe I miss some particular use case.

> I would like to see the problem statement part of this doc develop
> further.  What do you think about reworking the above paragraph like so?
> 
> "Often it is useful for developers and support specialists to be able to
> trace a kernel log message back to its exact position in source code.
> Moreover, there are monitoring tools that filter and take action based
> on messages logged.  For both of these use cases, it would be helpful to
> provide an index of all possible printk format strings for the running
> kernel."

I did not use this paragraph in the end. But I reworked the text a bit.


> > > +
> > > +The kernel messages are evolving together with the code. They are
> > > +not KABI and never will be!
> 
> Ok.  You might want to make it explicit here that the format of the
> debugfs file itself shouldn't change, unlike the file/line/formatspecificer
> *contents* of those files.

I rather made it more explicit that the particular messages are not
KABI.

The stability of the interface is kind of political issue. It depends
if there are any tools using it. I will do my best to keep it stable
as long as I am printk maintainer. But I do not want to promise it at the
moment. The interface is still pretty young and there are just first
users playing with it.


> > > +It is a huge challenge for maintaining the system log monitors. It requires
> > > +knowing what messages were udpated and why. Finding these changes in
> 
> s/udpated/updated/
> 
> > > +the sources would require non-trivial parsers. Also it would require
> > > +matching the sources with the binary kernel which is not always trivial.
> > > +Various changes might be backported. Various kernel versions might be used
> > > +on different monitored systems.
> > > +
> > > +This is where the printk index feature might become useful. It provides
> > > +a dump of printk formats used all over the source code used for the kernel
> > > +and modules on the running system. It is accessible at runtime via debugfs.
> > > +
> > > +
> > > +User interface
> > > +==============
> > > +
> > > +The index of printk formats is split into separate files for
> > > +for vmlinux and loaded modules, for example::
> > > +
> > > +   /sys/kernel/debug/printk/index/vmlinux
> > > +   /sys/kernel/debug/printk/index/ext4
> > > +   /sys/kernel/debug/printk/index/scsi_mod
> 
> If ext4 is built into the kernel (and not as a module), does its format
> strings end up in index/vmlinux or index/ext4?

It will be in vmlinux when the module is built-in. I mentioned this in v1.

> > > +
> > > +The content is inspired by the dynamic debug interface and looks like::
> > > +

Thanks a lot for the valuable feedback and suggestions. I used most of
them, see
https://lore.kernel.org/r/20220405114829.31837-1-pmladek@suse.com

Best Regards,
Petr