[FFmpeg-devel,1/2] avutil/log: Add av_log_once() for printing a message just once per instance

Compared to ad-hoc if(printed) ... code this allows the user to disable
it with a flag and see all repeated messages, it is also simpler

TODO: APIChanges & version bump

Signed-off-by: Michael Niedermayer <michael@niedermayer.cc>
---
 libavutil/log.c | 15 +++++++++++++++
 libavutil/log.h | 19 +++++++++++++++++++
 2 files changed, 34 insertions(+)
  

Quoting Michael Niedermayer (2020-01-16 17:51:28)
> Compared to ad-hoc if(printed) ... code this allows the user to disable
> it with a flag and see all repeated messages, it is also simpler

That flag is global state - it should be deprecated and removed, not
embedded further into the API.

> 
> TODO: APIChanges & version bump
> 
> Signed-off-by: Michael Niedermayer <michael@niedermayer.cc>
> ---
>  libavutil/log.c | 15 +++++++++++++++
>  libavutil/log.h | 19 +++++++++++++++++++
>  2 files changed, 34 insertions(+)
> 
> diff --git a/libavutil/log.c b/libavutil/log.c
> index e8a0db7716..7646e18cfa 100644
> --- a/libavutil/log.c
> +++ b/libavutil/log.c
> @@ -372,6 +372,21 @@ void av_log(void* avcl, int level, const char *fmt, ...)
>      va_end(vl);
>  }
>  
> +void av_log_once(void* avcl, int level, int *state, const char *fmt, ...)
> +{
> +    if (!((flags & AV_LOG_SKIP_REPEATED) && *state)) {
> +        AVClass* avc = avcl ? *(AVClass **) avcl : NULL;
> +        va_list vl;
> +        va_start(vl, fmt);
> +        if (avc && avc->version >= (50 << 16 | 15 << 8 | 2) &&
> +            avc->log_level_offset_offset && level >= AV_LOG_FATAL)
> +            level += *(int *) (((uint8_t *) avcl) + avc->log_level_offset_offset);

This logic is duplicated with av_log(). Why is this not done in av_vlog
anyway?

> +        av_vlog(avcl, level, fmt, vl);
> +        va_end(vl);
> +        *state = 1;
> +    }
> +}
> +
>  void av_vlog(void* avcl, int level, const char *fmt, va_list vl)
>  {
>      void (*log_callback)(void*, int, const char*, va_list) = av_log_callback;
> diff --git a/libavutil/log.h b/libavutil/log.h
> index d9554e609d..618d0d1817 100644
> --- a/libavutil/log.h
> +++ b/libavutil/log.h
> @@ -233,6 +233,25 @@ typedef struct AVClass {
>   */
>  void av_log(void *avcl, int level, const char *fmt, ...) av_printf_format(3, 4);
>  
> +/**
> + * Send the specified message to the log once if the level is less than or equal
> + * to the current av_log_level. By default, all logging messages are sent to
> + * stderr. This behavior can be altered by setting a different logging callback
> + * function.
> + * If AV_LOG_SKIP_REPEATED is set each message (each unique state) will only be
> + * printed once. If its not set then this behaves live av_log()
> + * @see av_log
> + *
> + * @param avcl A pointer to an arbitrary struct of which the first field is a
> + *        pointer to an AVClass struct or NULL if general log.
> + * @param level The importance level of the message expressed using a @ref
> + *        lavu_log_constants "Logging Constant".
> + * @param fmt The format string (printf-compatible) that specifies how
> + *        subsequent arguments are converted to output.
> + * @param state a variable to keep trak of if a message has already been printed
> + *        this must be initialized to 0 before the first use.

We should either demand that the caller ensures this does not get called
simultaneously with the same state, or make the above check-and-set
atomic.
  

On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > it with a flag and see all repeated messages, it is also simpler
> 
> That flag is global state - it should be deprecated and removed, not
> embedded further into the API.

When the flag is replaced by a non global solution every of its uses
would be replaced too.

Until such a non global API exists, this is the only way the user can
indicate her choice of which log messages to print.
Code should honor the existing API and user preferrance.


> 
> > 
> > TODO: APIChanges & version bump
> > 
> > Signed-off-by: Michael Niedermayer <michael@niedermayer.cc>
> > ---
> >  libavutil/log.c | 15 +++++++++++++++
> >  libavutil/log.h | 19 +++++++++++++++++++
> >  2 files changed, 34 insertions(+)
> > 
> > diff --git a/libavutil/log.c b/libavutil/log.c
> > index e8a0db7716..7646e18cfa 100644
> > --- a/libavutil/log.c
> > +++ b/libavutil/log.c
> > @@ -372,6 +372,21 @@ void av_log(void* avcl, int level, const char *fmt, ...)
> >      va_end(vl);
> >  }
> >  
> > +void av_log_once(void* avcl, int level, int *state, const char *fmt, ...)
> > +{
> > +    if (!((flags & AV_LOG_SKIP_REPEATED) && *state)) {
> > +        AVClass* avc = avcl ? *(AVClass **) avcl : NULL;
> > +        va_list vl;
> > +        va_start(vl, fmt);
> > +        if (avc && avc->version >= (50 << 16 | 15 << 8 | 2) &&
> > +            avc->log_level_offset_offset && level >= AV_LOG_FATAL)
> > +            level += *(int *) (((uint8_t *) avcl) + avc->log_level_offset_offset);
> 
> This logic is duplicated with av_log(). 

> Why is this not done in av_vlog
> anyway?

I am not aware of a reason, ill post a patch to move it over


> 
> > +        av_vlog(avcl, level, fmt, vl);
> > +        va_end(vl);
> > +        *state = 1;
> > +    }
> > +}
> > +
> >  void av_vlog(void* avcl, int level, const char *fmt, va_list vl)
> >  {
> >      void (*log_callback)(void*, int, const char*, va_list) = av_log_callback;
> > diff --git a/libavutil/log.h b/libavutil/log.h
> > index d9554e609d..618d0d1817 100644
> > --- a/libavutil/log.h
> > +++ b/libavutil/log.h
> > @@ -233,6 +233,25 @@ typedef struct AVClass {
> >   */
> >  void av_log(void *avcl, int level, const char *fmt, ...) av_printf_format(3, 4);
> >  
> > +/**
> > + * Send the specified message to the log once if the level is less than or equal
> > + * to the current av_log_level. By default, all logging messages are sent to
> > + * stderr. This behavior can be altered by setting a different logging callback
> > + * function.
> > + * If AV_LOG_SKIP_REPEATED is set each message (each unique state) will only be
> > + * printed once. If its not set then this behaves live av_log()
> > + * @see av_log
> > + *
> > + * @param avcl A pointer to an arbitrary struct of which the first field is a
> > + *        pointer to an AVClass struct or NULL if general log.
> > + * @param level The importance level of the message expressed using a @ref
> > + *        lavu_log_constants "Logging Constant".
> > + * @param fmt The format string (printf-compatible) that specifies how
> > + *        subsequent arguments are converted to output.
> > + * @param state a variable to keep trak of if a message has already been printed
> > + *        this must be initialized to 0 before the first use.
> 
> We should either demand that the caller ensures this does not get called
> simultaneously with the same state, or make the above check-and-set
> atomic.

I had a variant with atomic locally but it felt a bit messy considering that
probably none of the callers would need it to be atomic.
(messy being that the atomic stuff needs the state explicitly inited)

ill document that each state should not be accessed by 2 threads simultaneously

Thanks

[...]
  

Quoting Michael Niedermayer (2020-01-21 15:43:48)
> On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> > Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > > it with a flag and see all repeated messages, it is also simpler
> > 
> > That flag is global state - it should be deprecated and removed, not
> > embedded further into the API.
> 
> When the flag is replaced by a non global solution every of its uses
> would be replaced too.
> 
> Until such a non global API exists, this is the only way the user can
> indicate her choice of which log messages to print.
> Code should honor the existing API and user preferrance.

The problem is that right now, flags is only used by the default log
callback. The behaviour of the default log callback is not specified by
the API, so it can be changed later without much trouble. With this
patch, the function of flags is hardcoded into the API, making its
future removal significantly harder.
  

On Tue, Jan 21, 2020 at 07:44:46PM +0100, Anton Khirnov wrote:
> Quoting Michael Niedermayer (2020-01-21 15:43:48)
> > On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> > > Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > > > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > > > it with a flag and see all repeated messages, it is also simpler
> > > 
> > > That flag is global state - it should be deprecated and removed, not
> > > embedded further into the API.
> > 
> > When the flag is replaced by a non global solution every of its uses
> > would be replaced too.
> > 
> > Until such a non global API exists, this is the only way the user can
> > indicate her choice of which log messages to print.
> > Code should honor the existing API and user preferrance.
> 
> The problem is that right now, flags is only used by the default log
> callback. The behaviour of the default log callback is not specified by
> the API, so it can be changed later without much trouble. With this
> patch, the function of flags is hardcoded into the API, making its
> future removal significantly harder.

I dont really see this concern. Because if you disable the flag "today"
you break the API as it is documented, the flag is documented to
affect the message repeation.
With this patch, disabling it still breaks a bunch of message repeating
behavior, so to me this looks like its basically the same.

But what do you suggest ?

We could send all the repeated _once() messages to the callback and leave it
to the callback to drop them. Just needs a way to tag them as repeats

We could move the (no)repeat flag to each context but this feels unwieldy
and feels like it solves a problem noone had. Because noone ever asked
AFAIR that they wanted to change repeating behavior on a per context base.
This is probably mostly used by developers wanting to check for "all"
messages. Or users produding bug reports which also would ideally have
no dropped messages.

I can also just drop the use of the flag entirely from the patch and just
leave this as a unconditional _once() log. It feels a bit like a missing
feature though because as a devleoper for debuging a simple switch to
see all repeats seems usefull.

Thanks


[...]
  

Quoting Michael Niedermayer (2020-01-24 13:04:08)
> On Tue, Jan 21, 2020 at 07:44:46PM +0100, Anton Khirnov wrote:
> > Quoting Michael Niedermayer (2020-01-21 15:43:48)
> > > On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> > > > Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > > > > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > > > > it with a flag and see all repeated messages, it is also simpler
> > > > 
> > > > That flag is global state - it should be deprecated and removed, not
> > > > embedded further into the API.
> > > 
> > > When the flag is replaced by a non global solution every of its uses
> > > would be replaced too.
> > > 
> > > Until such a non global API exists, this is the only way the user can
> > > indicate her choice of which log messages to print.
> > > Code should honor the existing API and user preferrance.
> > 
> > The problem is that right now, flags is only used by the default log
> > callback. The behaviour of the default log callback is not specified by
> > the API, so it can be changed later without much trouble. With this
> > patch, the function of flags is hardcoded into the API, making its
> > future removal significantly harder.
> 
> I dont really see this concern. Because if you disable the flag "today"
> you break the API as it is documented, the flag is documented to
> affect the message repeation.
> With this patch, disabling it still breaks a bunch of message repeating
> behavior, so to me this looks like its basically the same.

The flag is documented, but the situations where it applies are not.
Currently, it only applies to the default log callback. It has no effect
whatsoever on users who use their own callback. With your patch, its
influence spreads into the core API. Since I see the flag as something
to be removed, I would prefer it were not done.

> 
> But what do you suggest ?
> 
> We could send all the repeated _once() messages to the callback and leave it
> to the callback to drop them. Just needs a way to tag them as repeats
> 
> We could move the (no)repeat flag to each context but this feels unwieldy
> and feels like it solves a problem noone had. Because noone ever asked
> AFAIR that they wanted to change repeating behavior on a per context base.
> This is probably mostly used by developers wanting to check for "all"
> messages. Or users produding bug reports which also would ideally have
> no dropped messages.
> 
> I can also just drop the use of the flag entirely from the patch and just
> leave this as a unconditional _once() log. It feels a bit like a missing
> feature though because as a devleoper for debuging a simple switch to
> see all repeats seems usefull.

I would say that log_once() should be used only for messages that are
meaningful just once (per context). It then makes no sense to log them
multiple times. Otherwise normal logging should be used.
  

On Tue, Jan 28, 2020 at 07:38:45PM +0100, Anton Khirnov wrote:
> Quoting Michael Niedermayer (2020-01-24 13:04:08)
> > On Tue, Jan 21, 2020 at 07:44:46PM +0100, Anton Khirnov wrote:
> > > Quoting Michael Niedermayer (2020-01-21 15:43:48)
> > > > On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> > > > > Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > > > > > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > > > > > it with a flag and see all repeated messages, it is also simpler
> > > > > 
> > > > > That flag is global state - it should be deprecated and removed, not
> > > > > embedded further into the API.
> > > > 
> > > > When the flag is replaced by a non global solution every of its uses
> > > > would be replaced too.
> > > > 
> > > > Until such a non global API exists, this is the only way the user can
> > > > indicate her choice of which log messages to print.
> > > > Code should honor the existing API and user preferrance.
> > > 
> > > The problem is that right now, flags is only used by the default log
> > > callback. The behaviour of the default log callback is not specified by
> > > the API, so it can be changed later without much trouble. With this
> > > patch, the function of flags is hardcoded into the API, making its
> > > future removal significantly harder.
> > 
> > I dont really see this concern. Because if you disable the flag "today"
> > you break the API as it is documented, the flag is documented to
> > affect the message repeation.
> > With this patch, disabling it still breaks a bunch of message repeating
> > behavior, so to me this looks like its basically the same.
> 
> The flag is documented, but the situations where it applies are not.
> Currently, it only applies to the default log callback. It has no effect
> whatsoever on users who use their own callback. With your patch, its
> influence spreads into the core API. Since I see the flag as something
> to be removed, I would prefer it were not done.
> 

> > 
> > But what do you suggest ?
> > 
> > We could send all the repeated _once() messages to the callback and leave it
> > to the callback to drop them. Just needs a way to tag them as repeats
> > 
> > We could move the (no)repeat flag to each context but this feels unwieldy
> > and feels like it solves a problem noone had. Because noone ever asked
> > AFAIR that they wanted to change repeating behavior on a per context base.
> > This is probably mostly used by developers wanting to check for "all"
> > messages. Or users produding bug reports which also would ideally have
> > no dropped messages.
> > 
> > I can also just drop the use of the flag entirely from the patch and just
> > leave this as a unconditional _once() log. It feels a bit like a missing
> > feature though because as a devleoper for debuging a simple switch to
> > see all repeats seems usefull.
> 
> I would say that log_once() should be used only for messages that are
> meaningful just once (per context). It then makes no sense to log them
> multiple times. Otherwise normal logging should be used.

I cannot think of a single case for which this would be true.

All cases i can think of for which i intended to use log_once() for, and for
some of these users have asked for this. In one case theres a offer to pay
for it by a user. So this is a real case with real intrerrest behind
is where the messages do carry information in each instance (for a developer).
but are annoying to the user.

So, we sure can use log_once() with no flag to turn the "once" off. And let
the developer who needs it off edit the source and rebuild but its not correct
to say that the messages are not meaningful after their first occurance.
A developer looking into some issue with a file would want to know if a
header error occurs once or on every frame or maybe every time a vissual
issue appears.

Maybe we could have log_once() not suppress the messages after their first
occurance but reduce them to DEBUG or TRACE level.
What do you think ?


[...]
  

Quoting Michael Niedermayer (2020-01-29 12:25:42)
> On Tue, Jan 28, 2020 at 07:38:45PM +0100, Anton Khirnov wrote:
> > Quoting Michael Niedermayer (2020-01-24 13:04:08)
> > > On Tue, Jan 21, 2020 at 07:44:46PM +0100, Anton Khirnov wrote:
> > > > Quoting Michael Niedermayer (2020-01-21 15:43:48)
> > > > > On Tue, Jan 21, 2020 at 12:24:50PM +0100, Anton Khirnov wrote:
> > > > > > Quoting Michael Niedermayer (2020-01-16 17:51:28)
> > > > > > > Compared to ad-hoc if(printed) ... code this allows the user to disable
> > > > > > > it with a flag and see all repeated messages, it is also simpler
> > > > > > 
> > > > > > That flag is global state - it should be deprecated and removed, not
> > > > > > embedded further into the API.
> > > > > 
> > > > > When the flag is replaced by a non global solution every of its uses
> > > > > would be replaced too.
> > > > > 
> > > > > Until such a non global API exists, this is the only way the user can
> > > > > indicate her choice of which log messages to print.
> > > > > Code should honor the existing API and user preferrance.
> > > > 
> > > > The problem is that right now, flags is only used by the default log
> > > > callback. The behaviour of the default log callback is not specified by
> > > > the API, so it can be changed later without much trouble. With this
> > > > patch, the function of flags is hardcoded into the API, making its
> > > > future removal significantly harder.
> > > 
> > > I dont really see this concern. Because if you disable the flag "today"
> > > you break the API as it is documented, the flag is documented to
> > > affect the message repeation.
> > > With this patch, disabling it still breaks a bunch of message repeating
> > > behavior, so to me this looks like its basically the same.
> > 
> > The flag is documented, but the situations where it applies are not.
> > Currently, it only applies to the default log callback. It has no effect
> > whatsoever on users who use their own callback. With your patch, its
> > influence spreads into the core API. Since I see the flag as something
> > to be removed, I would prefer it were not done.
> > 
> 
> > > 
> > > But what do you suggest ?
> > > 
> > > We could send all the repeated _once() messages to the callback and leave it
> > > to the callback to drop them. Just needs a way to tag them as repeats
> > > 
> > > We could move the (no)repeat flag to each context but this feels unwieldy
> > > and feels like it solves a problem noone had. Because noone ever asked
> > > AFAIR that they wanted to change repeating behavior on a per context base.
> > > This is probably mostly used by developers wanting to check for "all"
> > > messages. Or users produding bug reports which also would ideally have
> > > no dropped messages.
> > > 
> > > I can also just drop the use of the flag entirely from the patch and just
> > > leave this as a unconditional _once() log. It feels a bit like a missing
> > > feature though because as a devleoper for debuging a simple switch to
> > > see all repeats seems usefull.
> > 
> > I would say that log_once() should be used only for messages that are
> > meaningful just once (per context). It then makes no sense to log them
> > multiple times. Otherwise normal logging should be used.
> 
> I cannot think of a single case for which this would be true.
> 
> All cases i can think of for which i intended to use log_once() for, and for
> some of these users have asked for this. In one case theres a offer to pay
> for it by a user. So this is a real case with real intrerrest behind
> is where the messages do carry information in each instance (for a developer).
> but are annoying to the user.
> 
> So, we sure can use log_once() with no flag to turn the "once" off. And let
> the developer who needs it off edit the source and rebuild but its not correct
> to say that the messages are not meaningful after their first occurance.
> A developer looking into some issue with a file would want to know if a
> header error occurs once or on every frame or maybe every time a vissual
> issue appears.
> 
> Maybe we could have log_once() not suppress the messages after their first
> occurance but reduce them to DEBUG or TRACE level.
> What do you think ?

Yes, a reduced loglevel sounds better to me. The only issue with that
the name no longer matches the functionality - since it no longer logs
just once - but I can't think of a better name (maybe
log_display_once(), but that's ugly and not much more descriptive) and
it's probably not a big deal.
No other objections from me.