[PATCH] log: Add helpers for calling log_msg_ret() et al

[Simon Glass]

Hi Quentin,

On Tue, 25 Mar 2025 at 04:20, Quentin Schulz <quentin.schulz at cherry.de> wrote:
>
> Hi Simon,
>
> On 3/20/25 4:26 AM, Simon Glass wrote:
> > Hi Quentin,
> >
> > On Wed, 19 Mar 2025 at 16:31, Quentin Schulz <quentin.schulz at cherry.de> wrote:
> >>
> >> Hi Simon
> >>
> >> On 3/19/25 4:03 PM, Simon Glass wrote:
> >>> Hi Quentin,
> >>>
> >>> On Wed, 19 Mar 2025 at 13:04, Quentin Schulz <quentin.schulz at cherry.de> wrote:
> >>>>
> >>>> Hi Simon,
> >>>>
> >>>> On 3/19/25 12:49 PM, Simon Glass wrote:
> >>>>> Logging of function return-values is used very frequently in U-Boot now.
> >>>>> Add a few helper macros to make it less verbose to use.
> >>>>>
> >>>>> It turns out that the log_ret() variants are not so useful, since it is
> >>>>> not obviously where the error is coming from. So only the log_msg_ret()
> >>>>> variants are worthy of these macros.
> >>>>>
> >>>>> Signed-off-by: Simon Glass <sjg at chromium.org>
> >>>>> ---
> >>>>>
> >>>>>     include/log.h | 26 ++++++++++++++++++++++++++
> >>>>>     1 file changed, 26 insertions(+)
> >>>>>
> >>>>> diff --git a/include/log.h b/include/log.h
> >>>>> index 4f6d6a2c2cf..bdda7af570c 100644
> >>>>> --- a/include/log.h
> >>>>> +++ b/include/log.h
> >>>>> @@ -380,6 +380,32 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line,
> >>>>>     #define log_msg_retz(_msg, _ret) ((void)(_msg), _ret)
> >>>>>     #endif
> >>>>>
> >>>>> +/*
> >>>>> + * LOGR() - helper macro for calling a function and logging error returns
> >>>>> + *
> >>>>> + * Logs if the function returns a negative value
> >>>>> + *
> >>>>> + * Usage:   LOGR("abc", my_function(...));
> >>>>> + */
> >>>>> +#define LOGR(_msg, _expr)    do {            \
> >>>>> +     int _ret = _expr;                       \
> >>>>> +     if (_ret < 0)                           \
> >>>>> +             return log_msg_ret(_msg, _ret); \
> >>>>> +     } while (0)
> >>>>> +
> >>>>> +/*
> >>>>> + * LOGZ() - helper macro for calling a function and logging error returns
> >>>>> + *
> >>>>> + * Logs if the function returns a non-zero value
> >>>>> + *
> >>>>> + * Usage:   LOGZ("abc", my_function(...));
> >>>>> + */
> >>>>> +#define LOGZ(_msg, _expr)    do {            \
> >>>>> +     int _ret = _expr;                       \
> >>>>> +     if (_ret)                               \
> >>>>> +             return log_msg_retz(_msg, _ret);        \
> >>>>> +     } while (0)
> >>>>> +
> >>>>
> >>>> Mmmm not sure this forced return call is a good idea, this would forbid
> >>>> us from performing some unwinding for example.
> >>>
> >>> Yes, it is really only for simple cases. Without the return, there
> >>> isn't much value and you may as well not use this macro.
> >>>
> >>>>
> >>>> I don't really see how that is better than simply calling
> >>>>
> >>>> return log_msg_retz("abc", my_function());
> >>>
> >>> That's not the intention. It actually replaces:
> >>>
> >>> ret = my_function();
> >>> if (ret)
> >>>       return_log_msg_ret("abc", ret);
> >>>
> >>> I use this a lot in my code. You can't always just return, since there
> >>> may not be an error.
> >>>
> >>
> >> I see, I read too fast again. Only return if it's an error.
> >>
> >>>>
> >>>> ?
> >>>>
> >>>> If we were to keep this, I would recommend to rename the macro and fix
> >>>> the docstring because it does not only log if the function returns a
> >>>> non-zero value. It does actually return.
> >>>>
> >>>> So something like
> >>>>
> >>>> LOGZ_AND_RETURN(_msg, _expr)
> >>>>
> >>>> maybe?
> >>>
> >>> Sure, longer names are easier to learn, but then it is so long I doubt
> >>> anyone would use it.
> >>>
> >>> Perhaps LOG_RET() and LOG_RETZ() ? But they might get confused with
> >>> log_ret() and log_retz(), which I am actually thinking of deleting.
> >>>
> >>> I would like the shortest possible name to avoid spilling functions
> >>> onto the next line all the time.
> >>>
> >>
> >> It should be absolutely obvious from the macro name that this can in
> >> fact return because missing to unwind code is among the things
> >> developers typically easily miss already, so with this macro it'll be
> >> even easier to forget about undoing things.
> >>
> >
> > Yes that's true. We don't have a huge amount of tests for this 'undo'
> > code either. I would bet that a code-coverage map would show that.
> >
>
> Yeah but that's not a reason to make it even harder to spot issues in
> the undo code :)

I suspect people will just have to learn the macros, as they have with

>
> > Subce the macro only returns if there is an error,that could be
> > important if we are trying to have a descriptive name. Perhaps the
> > logging bit is less important.
> >
> > How about ERR_RET() or RET_ON_ERR() ? The last one is getting long too.
> >
>
> RET_ON_ERR() would be better.
>
> It doesn't really convey that a log message will be output. I'm
> wondering if we should have a variadic macro?

It doesn't actually output a log message until there is an error and
CONFIG_LOG_ERROR_RETURN is enabled.

Also, now that I look at it again, my suggestion RET_ON_ERR() doesn't
indicate that it has anything to do with logging.

>
> RET_ON_ERR(expr) would return on error but say nothing
> RET_ON_ERR(expr, msg) would return on error but say msg on error too,
> maybe even RET_ON_ERR(expr, msg, vars) with vars to pass to variadic
> log/printf.

We could perhaps add the printf formatting later, but the
log_msg_ret() function is designed to provide a fairly low-overhead*
way to figure out the root cause of an error, after it has propagated
up a dozen levels.

Sample output:

  scene_txt_set_font() find: returning err=-2
             add_val() wvk: returning err=-129
           write_val() swB: returning err=-129
    sstate_write_str() swb: returning err=-129
        simple_start() spi: returning err=-129
Boot failed (err=-129: Unknown error)

* It isn't really low-overhead, since it still emits a log record. We
could perhaps change that so that it only outputs the string and the
error code. Then the cost would be perhaps 10-20 bytes per site, when
enabled.

>
> I assume we could extend that in the future if we need it. I would have
> the expr first and the msg second though, I'm more interested in what
> will run that the message that may be returned.

I initially had the message second, but it gets quite complicated
since it is a lot way from the log statement, sometimes at the end of
various bracket chains, etc.

>
> I'm personally not convinced the macro, function and variable names need
> to be really short, I would rather have them longer than confusing, but
> that's entering very subjective territory :)

The competitor to this macro is basically:

int ret;

ret = func(...);
if (ret)
   return log_msg_ret("abc", ret);

I have found that quite often I can avoid the 'int ret' with this
macro. But if the macro is too long, we end up breaking most lines
just for the macros. So the closer it is to the length of 'ret = ' the
better, IMO. Also people tend to learn macros quickly if they are
common in the code.

So really we should have LOG_RET_ON_ERR(msg, val), but I consider that
too long. I'm not seeing any great options at this point. In priority
order, I believe these are the most important things to be obvious:

- that it returns (RET)
- that it logs (LOG)
- that it only returns on error (ON_ERR)

So how about RET_LOG() ? it indicates that it returns and that it
logs. The 'on error' part you would just have to learn from the docs.
If not, then LOG_RET() would be OK, as both words will be read in one
glance.

Regards,
Simon