[LSF/MM/BPF TOPIC] tracing the source of errors

[LSF/MM/BPF TOPIC] tracing the source of errors

[Miklos Szeredi]

[I'm not planning to attend LSF this year, but I thought this topic
might be of interest to those who will.]

The errno thing is really ancient and yet quite usable.  But when
trying to find out where a particular EINVAL is coming from, that's
often mission impossible.

Would it make sense to add infrastructure to allow tracing the source
of errors?  E.g.

strace --errno-trace ls -l foo
...
statx(AT_FDCWD, "foo", ...) = -1 ENOENT [fs/namei.c:1852]
...

Don't know about others, but this issue comes up quite often for me.

I would implement this with macros that record the place where a
particular error has originated, and some way to query the last one
(which wouldn't be 100% accurate, but good enough I guess).

Thanks,
Miklos

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Jan Kara]

On Wed 07-02-24 10:54:34, Miklos Szeredi via Lsf-pc wrote:
> [I'm not planning to attend LSF this year, but I thought this topic
> might be of interest to those who will.]
> 
> The errno thing is really ancient and yet quite usable.  But when
> trying to find out where a particular EINVAL is coming from, that's
> often mission impossible.
> 
> Would it make sense to add infrastructure to allow tracing the source
> of errors?  E.g.
> 
> strace --errno-trace ls -l foo
> ...
> statx(AT_FDCWD, "foo", ...) = -1 ENOENT [fs/namei.c:1852]
> ...
> 
> Don't know about others, but this issue comes up quite often for me.

Yes, having this available would be really useful at times. Sometimes I
had to resort to kprobes or good old printks.

> I would implement this with macros that record the place where a
> particular error has originated, and some way to query the last one
> (which wouldn't be 100% accurate, but good enough I guess).

The problem always has been how to implement this functionality in a
transparent way so the code does not become a mess. So if you have some
idea, I'd say go for it :)

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Miklos Szeredi]

On Wed, 7 Feb 2024 at 12:00, Jan Kara <jack@suse.cz> wrote:

> The problem always has been how to implement this functionality in a
> transparent way so the code does not become a mess. So if you have some
> idea, I'd say go for it :)

My first idea would be to wrap all instances of E* (e.g. ERR(E*)).
But this could be made completely transparent by renaming current
definition of E* to _E* and defining E* to be the wrapped ones.
There's probably a catch (or several catches) somewhere, though.

Thanks,
Miklos

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Matthew Wilcox]

On Wed, Feb 07, 2024 at 12:23:41PM +0100, Miklos Szeredi wrote:
> On Wed, 7 Feb 2024 at 12:00, Jan Kara <jack@suse.cz> wrote:
> 
> > The problem always has been how to implement this functionality in a
> > transparent way so the code does not become a mess. So if you have some
> > idea, I'd say go for it :)
> 
> My first idea would be to wrap all instances of E* (e.g. ERR(E*)).
> But this could be made completely transparent by renaming current
> definition of E* to _E* and defining E* to be the wrapped ones.
> There's probably a catch (or several catches) somewhere, though.

To be perfectly clear, you're suggesting two things.

Option (a) change "all" code like this:
-	ret = -EINVAL;
+	ret = -ERR(EINVAL);

where ERR would do some magic with __func__ and __LINE__.

Option (b)

-#define EINVAL		22
+#define E_INVAL	22
+#define EINVAL		ERR(E_INVAL)

and then change all code that does something like:

	if (err == -EINVAL)
to
	if (err == -E_INVAL)

Or have I misunderstood?

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Miklos Szeredi]

On Wed, 7 Feb 2024 at 13:00, Matthew Wilcox <willy@infradead.org> wrote:

> To be perfectly clear, you're suggesting two things.
>
> Option (a) change "all" code like this:
> -       ret = -EINVAL;
> +       ret = -ERR(EINVAL);
>
> where ERR would do some magic with __func__ and __LINE__.
>
> Option (b)
>
> -#define EINVAL         22
> +#define E_INVAL        22
> +#define EINVAL         ERR(E_INVAL)
>
> and then change all code that does something like:
>
>         if (err == -EINVAL)
> to
>         if (err == -E_INVAL)
>
> Or have I misunderstood?

Something like that, yes.

Thanks,
Miklos

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Gabriel Krisman Bertazi]

Matthew Wilcox <willy@infradead.org> writes:

> Option (b)
>
> -#define EINVAL		22
> +#define E_INVAL	22
> +#define EINVAL		ERR(E_INVAL)

Note there will surely be cases where EINVAL is used as a soft failure
and the kernel will just try something else, instead of propagating the
error up the stack.  In this case, there is no point in logging the
first case of error, as it will just be expected behavior.

So there's really no way around explicitly annotating (ERR (EINVAL))
in place where it really matters, instead of changing the definition
of -EINVAL itself or automatically converting check sites.

>
> and then change all code that does something like:
>
> 	if (err == -EINVAL)
> to
> 	if (err == -E_INVAL)
>
> Or have I misunderstood?



-- 
Gabriel Krisman Bertazi

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Eric Sandeen]

On 2/7/24 5:23 AM, Miklos Szeredi wrote:
> On Wed, 7 Feb 2024 at 12:00, Jan Kara <jack@suse.cz> wrote:
> 
>> The problem always has been how to implement this functionality in a
>> transparent way so the code does not become a mess. So if you have some
>> idea, I'd say go for it :)
> 
> My first idea would be to wrap all instances of E* (e.g. ERR(E*)).
> But this could be made completely transparent by renaming current
> definition of E* to _E* and defining E* to be the wrapped ones.
> There's probably a catch (or several catches) somewhere, though.
> 
> Thanks,
> Miklos
> 

Just FWIW, XFS has kind of been there and back again on wrapping error returns
with macros.

Long ago, we had an XFS_ERROR() macro, i.e.

 	if (error)
		return -XFS_ERROR(error);

sprinkled (randomly) throughout the code.

(it didn't make it out through strace, and was pretty clunky but could printk or
BUG based on which error you were looking for, IIRC.)

In 2014(!) I removed it, pointing out that systemtap could essentially do the
same thing, and do it more flexibly (see: [PATCH 2/2] xfs: Nuke XFS_ERROR macro):

# probe module("xfs").function("xfs_*").return { if (@defined($return) &&
$return == VALUE) { ... } }

hch pointed out that systemtap was not a viable option for many, and further
discussion turned up a slightly kludgey way to use kprobes:

-- from dchinner --
#!/bin/bash

TRACEDIR=/sys/kernel/debug/tracing

grep -i 't xfs_' /proc/kallsyms | awk '{print $3}' ; while read F; do
	echo "r:ret_$F $F \$retval" >> $TRACEDIR/kprobe_events
done

for E in $TRACEDIR/events/kprobes/ret_xfs_*/enable; do
	echo 1 > $E
done;

echo 'arg1 > 0xffffffffffffff00' > $TRACEDIR/events/kprobes/filter

for T in $TRACEDIR/events/kprobes/ret_xfs_*/trigger; do
	echo 'traceoff if arg1 > 0xffffffffffffff00' > $T
done
--------

which yields i.e.:

# dd if=/dev/zero of=/mnt/scratch/newfile bs=513 oflag=direct
dd: error writing ¿/mnt/scratch/newfile¿: Invalid argument
1+0 records in
0+0 records out
0 bytes (0 B) copied, 0.000259882 s, 0.0 kB/s
root@test4:~# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:16
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-8073  [006] d... 145740.460546: ret_xfs_file_dio_aio_write:
(xfs_file_aio_write+0x170/0x180 <- xfs_file_dio_aio_write) arg1=0xffffffffffffffea

where that last negative number is the errno.

Not the prettiest thing but something that works today and could maybe be improved?

-Eric

Re: [Lsf-pc] [LSF/MM/BPF TOPIC] tracing the source of errors

[Gabriel Krisman Bertazi]

Jan Kara <jack@suse.cz> writes:

> On Wed 07-02-24 10:54:34, Miklos Szeredi via Lsf-pc wrote:
>> [I'm not planning to attend LSF this year, but I thought this topic
>> might be of interest to those who will.]
>> 
>> The errno thing is really ancient and yet quite usable.  But when
>> trying to find out where a particular EINVAL is coming from, that's
>> often mission impossible.
>> 
>> Would it make sense to add infrastructure to allow tracing the source
>> of errors?  E.g.
>> 
>> strace --errno-trace ls -l foo
>> ...
>> statx(AT_FDCWD, "foo", ...) = -1 ENOENT [fs/namei.c:1852]
>> ...
>> 
>> Don't know about others, but this issue comes up quite often for me.
>
> Yes, having this available would be really useful at times. Sometimes I
> had to resort to kprobes or good old printks.
>
>> I would implement this with macros that record the place where a
>> particular error has originated, and some way to query the last one
>> (which wouldn't be 100% accurate, but good enough I guess).
>
> The problem always has been how to implement this functionality in a
> transparent way so the code does not become a mess. So if you have some
> idea, I'd say go for it :)

I had a proposal to provide the LoC of filesystem errors as part of an
extended record of the FAN_FS_ERROR messages (fanotify interface).  It
might be a sensible interface to expose this information if not
prohibitively expensive.

One might record the position with a macro and do the fsnotify_sb_error
from a safer context.

-- 
Gabriel Krisman Bertazi

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Darrick J. Wong]

On Wed, Feb 07, 2024 at 10:54:34AM +0100, Miklos Szeredi wrote:
> [I'm not planning to attend LSF this year, but I thought this topic
> might be of interest to those who will.]
> 
> The errno thing is really ancient and yet quite usable.  But when
> trying to find out where a particular EINVAL is coming from, that's
> often mission impossible.
> 
> Would it make sense to add infrastructure to allow tracing the source
> of errors?  E.g.
> 
> strace --errno-trace ls -l foo
> ...
> statx(AT_FDCWD, "foo", ...) = -1 ENOENT [fs/namei.c:1852]
> ...
> 
> Don't know about others, but this issue comes up quite often for me.
> 
> I would implement this with macros that record the place where a
> particular error has originated, and some way to query the last one
> (which wouldn't be 100% accurate, but good enough I guess).

Hmmm, weren't Kent and Suren working on code tagging for memory
allocation profiling?  It would be kinda nice to wrap that up in the
error return paths as well.

Granted then we end up with some nasty macro mess like:

[Pretend that there's a struct errno_tag, DEFINE_ALLOC_TAG, and
__alloc_tag_add symbols that looks mostly like struct alloc_tag from [1]
and then (backslashes elided)]

#define Err(x)
({
	int __errno = (x);
	DEFINE_ERRNO_TAG(_errno_tag);

	trace_return_errno(__this_address, __errno)
	__errno_tag_add(&_errno_tag, __errno);
	__errno;
})

	foo = kmalloc(...);
	if (!foo)
		return Err(-ENOMEM);

or

	if (fs_is_messed_up())
		return Err(-EINVAL);

This would get us the ability to ftrace for where errno returns
initiate, as well as collect counters for how often we're actually
doing that in production.  You could even add time_stats too, but
annotating the entire kernel might be a stretch.

--D

[1] https://lwn.net/Articles/906660/

> Thanks,
> Miklos
> 

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Dave Chinner]

On Wed, Feb 07, 2024 at 10:54:34AM +0100, Miklos Szeredi wrote:
> [I'm not planning to attend LSF this year, but I thought this topic
> might be of interest to those who will.]
> 
> The errno thing is really ancient and yet quite usable.  But when
> trying to find out where a particular EINVAL is coming from, that's
> often mission impossible.
> 
> Would it make sense to add infrastructure to allow tracing the source
> of errors?  E.g.
> 
> strace --errno-trace ls -l foo
> ...
> statx(AT_FDCWD, "foo", ...) = -1 ENOENT [fs/namei.c:1852]
> ...
> 
> Don't know about others, but this issue comes up quite often for me.

ftrace using the function_graph tracer will emit the return values
of the functions if you use it with the 'funcgraph-retval' option.

Seems like a solved problem?

-Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Miklos Szeredi]

On Wed, 7 Feb 2024 at 22:37, Dave Chinner <david@fromorbit.com> wrote:

> ftrace using the function_graph tracer will emit the return values
> of the functions if you use it with the 'funcgraph-retval' option.
>
> Seems like a solved problem?

Except

a) this seems exceedingly difficult to set up for non-developers,
which is often where this is needed.  Even strace is pretty verbose
and the generated output too big, let alone all function calls across
the whole system.

b) can only point to the function was generated.  But the same error
is often generated for several different reasons within the same
function and the return value doesn't help there.

I think a) is the critical one, and possibly the ftrace infrastructure
could be used for something more friendly that just pointed to the
function where the error was generated without having to go through
hoops.

Thanks,
Miklos

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Dave Chinner]

On Thu, Feb 08, 2024 at 10:09:36AM +0100, Miklos Szeredi wrote:
> On Wed, 7 Feb 2024 at 22:37, Dave Chinner <david@fromorbit.com> wrote:
> 
> > ftrace using the function_graph tracer will emit the return values
> > of the functions if you use it with the 'funcgraph-retval' option.
> >
> > Seems like a solved problem?
> 
> Except
> 
> a) this seems exceedingly difficult to set up for non-developers,
> which is often where this is needed.  Even strace is pretty verbose
> and the generated output too big, let alone all function calls across
> the whole system.

trace-cmd is your friend.

# trace-cmd record -p function_graph -l vfs_statx sleep 1
# trace-cmd report
....

There's also 'perf ftrace ...' as another wrapper for ftrace based
profiling, though I have never used that at all.

> b) can only point to the function was generated.  But the same error
> is often generated for several different reasons within the same
> function and the return value doesn't help there.

In most cases knowing waht the function call parameters are
and the return value is enough to determine which error check
failed. Seems like that's within the scope of what ftrace could
provide us with...

> I think a) is the critical one, and possibly the ftrace infrastructure
> could be used for something more friendly that just pointed to the
> function where the error was generated without having to go through
> hoops.

*nod*

I don't use ftrace directly - never have. trace-cmd has been around
for a long time and does pretty much everything I've ever needed
over the past 15 years. That said, trace-cmd does not export all of
ftrace's features, but most of them are there and there are a lot of
users and developers already familiar with trace-cmd as a way of
seeing what is going on inside the kernel when things go wrong....

Hence I just don't see the "ftrace is difficult to use" argument as
being relevant to "how do we trace the source of the error"
discussions.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Matthew Wilcox]

On Thu, Feb 08, 2024 at 08:37:29AM +1100, Dave Chinner wrote:
> ftrace using the function_graph tracer will emit the return values
> of the functions if you use it with the 'funcgraph-retval' option.

OK, but that may not be fine grained enough.  Why is mmap() returning
-ENOMEM?

unsigned long do_mmap(struct file *file, unsigned long addr,
...
       /* Careful about overflows.. */
        len = PAGE_ALIGN(len);
        if (!len)
                return -ENOMEM;
...
        /* Too many mappings? */
        if (mm->map_count > sysctl_max_map_count)
                return -ENOMEM;

So it can distinguish between mmap() returning ENOMEM because
get_unmapped_area() returned ENOMEM and do_mmap() returning ENOMEM of
its own accord (right?), but it can't tell you which of the above two
cases you hit.  Or can it?

Re: [LSF/MM/BPF TOPIC] tracing the source of errors

[Dave Chinner]

On Thu, Feb 08, 2024 at 03:57:27PM +0000, Matthew Wilcox wrote:
> On Thu, Feb 08, 2024 at 08:37:29AM +1100, Dave Chinner wrote:
> > ftrace using the function_graph tracer will emit the return values
> > of the functions if you use it with the 'funcgraph-retval' option.
> 
> OK, but that may not be fine grained enough.  Why is mmap() returning
> -ENOMEM?
> 
> unsigned long do_mmap(struct file *file, unsigned long addr,
> ...
>        /* Careful about overflows.. */
>         len = PAGE_ALIGN(len);
>         if (!len)
>                 return -ENOMEM;
> ...
>         /* Too many mappings? */
>         if (mm->map_count > sysctl_max_map_count)
>                 return -ENOMEM;
> 
> So it can distinguish between mmap() returning ENOMEM because
> get_unmapped_area() returned ENOMEM and do_mmap() returning ENOMEM of
> its own accord (right?),

The call stack trace should tell you which function the error
originated from, yes?

> but it can't tell you which of the above two
> cases you hit.  Or can it?

Never used it, but it might be able to - the "sym-offset" option
will display exact offsets of the function in the trace. If you then
add "funcgraph-tail" it will emit the function being returned from.
If the return location is generated with an offset indicating the
actual return, then it might tell you the exact location.

If it doesn't, then this would seem like a reasonable thing to add
to ftrace - function return tracing with a filter to grab the return
location when the return value is less than 0 seems exactly the sort
of thing ftrace was intended to be used for...

-Dave.
-- 
Dave Chinner
david@fromorbit.com