[FFmpeg-devel] cmdutils: add log time info into report log file

Submitted by Steven Liu on June 2, 2017, 4:26 p.m.

Details

Message ID 20170602162632.1888-1-lingjiujianke@gmail.com
State New
Headers show

Commit Message

Steven Liu June 2, 2017, 4:26 p.m.
add time info into every line of log report
the time info can be used to find out error message occur time.

Signed-off-by: Steven Liu <lingjiujianke@gmail.com>
---
 cmdutils.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

Comments

Nicolas George June 2, 2017, 4:30 p.m.
Le quintidi 15 prairial, an CCXXV, Steven Liu a écrit :
> add time info into every line of log report
> the time info can be used to find out error message occur time.
> 
> Signed-off-by: Steven Liu <lingjiujianke@gmail.com>
> ---
>  cmdutils.c | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
> 
> diff --git a/cmdutils.c b/cmdutils.c
> index 3d428f3eea..b760a0565d 100644
> --- a/cmdutils.c
> +++ b/cmdutils.c
> @@ -47,6 +47,7 @@
>  #include "libavutil/libm.h"
>  #include "libavutil/parseutils.h"
>  #include "libavutil/pixdesc.h"
> +#include "libavutil/time.h"
>  #include "libavutil/eval.h"
>  #include "libavutil/dict.h"
>  #include "libavutil/opt.h"
> @@ -103,6 +104,8 @@ void log_callback_help(void *ptr, int level, const char *fmt, va_list vl)
>  static void log_callback_report(void *ptr, int level, const char *fmt, va_list vl)
>  {
>      va_list vl2;
> +    char *tmp_string = NULL;
> +    char time_value[32];
>      char line[1024];
>      static int print_prefix = 1;
>  
> @@ -111,7 +114,10 @@ static void log_callback_report(void *ptr, int level, const char *fmt, va_list v
>      av_log_format_line(ptr, level, fmt, vl2, line, sizeof(line), &print_prefix);
>      va_end(vl2);
>      if (report_file_level >= level) {
> -        fputs(line, report_file);

> +        snprintf(time_value, sizeof(time_value), "\n[%"PRId64"] - ", av_gettime());
> +        tmp_string = av_strireplace(line, "\n", time_value);

It looks like you are printing the time of a line at the beginning of
the next line. Or am I missing something.

Also, I do not like the dynamic alloc in this function, especially since
the same task can be done without: find \n, print the time and the
single line, loop.

> +        fputs(tmp_string, report_file);
> +        av_free(tmp_string);
>          fflush(report_file);
>      }
>  }

Regards,
Steven Liu June 3, 2017, 6:41 a.m.
2017-06-03 0:30 GMT+08:00 Nicolas George <george@nsup.org>:
>
> Le quintidi 15 prairial, an CCXXV, Steven Liu a écrit :
> > add time info into every line of log report
> > the time info can be used to find out error message occur time.
> >
> > Signed-off-by: Steven Liu <lingjiujianke@gmail.com>
> > ---
> >  cmdutils.c | 8 +++++++-
> >  1 file changed, 7 insertions(+), 1 deletion(-)
> >
> > diff --git a/cmdutils.c b/cmdutils.c
> > index 3d428f3eea..b760a0565d 100644
> > --- a/cmdutils.c
> > +++ b/cmdutils.c
> > @@ -47,6 +47,7 @@
> >  #include "libavutil/libm.h"
> >  #include "libavutil/parseutils.h"
> >  #include "libavutil/pixdesc.h"
> > +#include "libavutil/time.h"
> >  #include "libavutil/eval.h"
> >  #include "libavutil/dict.h"
> >  #include "libavutil/opt.h"
> > @@ -103,6 +104,8 @@ void log_callback_help(void *ptr, int level, const char *fmt, va_list vl)
> >  static void log_callback_report(void *ptr, int level, const char *fmt, va_list vl)
> >  {
> >      va_list vl2;
> > +    char *tmp_string = NULL;
> > +    char time_value[32];
> >      char line[1024];
> >      static int print_prefix = 1;
> >
> > @@ -111,7 +114,10 @@ static void log_callback_report(void *ptr, int level, const char *fmt, va_list v
> >      av_log_format_line(ptr, level, fmt, vl2, line, sizeof(line), &print_prefix);
> >      va_end(vl2);
> >      if (report_file_level >= level) {
> > -        fputs(line, report_file);
>
> > +        snprintf(time_value, sizeof(time_value), "\n[%"PRId64"] - ", av_gettime());
> > +        tmp_string = av_strireplace(line, "\n", time_value);
>
> It looks like you are printing the time of a line at the beginning of
> the next line. Or am I missing something.
>
> Also, I do not like the dynamic alloc in this function, especially since
> the same task can be done without: find \n, print the time and the
> single line, loop.
>
> > +        fputs(tmp_string, report_file);
> > +        av_free(tmp_string);
> >          fflush(report_file);
> >      }
> >  }
>
> Regards,

Hi Nicolas,

    I get some problem of the log output:

    1. the log output by multiple av_log to one line,
         for example:
             av_log(NULL, "major_brand     :");
             av_log(NULL, "isom\n");
         then if add the time to the line head, it will output looks like this:
             [1496470846077636] -     major_brand     :
[1496470846077643] - isom[1496470846077650] -

     2. but if add the time to the end of line, it maybe need control
right alignment

     3. maybe the better solution is add the time into line head when
the log level big than AV_LOG_WARNING ?

>
>
> --
>   Nicolas George
Nicolas George June 5, 2017, 5:31 p.m.
Le quintidi 15 prairial, an CCXXV, Steven Liu a écrit :
>     I get some problem of the log output:
> 
>     1. the log output by multiple av_log to one line,
>          for example:
>              av_log(NULL, "major_brand     :");
>              av_log(NULL, "isom\n");
>          then if add the time to the line head, it will output looks like this:
>              [1496470846077636] -     major_brand     :
> [1496470846077643] - isom[1496470846077650] -

Yes, you will have to come up with a solution for that. Maybe look how
the [component @ 0xaddress] prefix is added.

(But I also think we should try and get rid of these construct, make
av_log() more "send a complete message to the user" and less "print
something to the terminal", because the latter only works when there is
actually a terminal.)

>      2. but if add the time to the end of line, it maybe need control
> right alignment

Aligning to the right would be a terrible idea. And impossible on top of
that, since any later line can be longer and invalidate the alignment.

>      3. maybe the better solution is add the time into line head when
> the log level big than AV_LOG_WARNING ?

I do not think that changing the format depending on the log level is a
good idea. And it does not help anyway.

Regards,
Tobias Rapp June 6, 2017, 9:42 a.m.
On 03.06.2017 08:41, Steven Liu wrote:
> 2017-06-03 0:30 GMT+08:00 Nicolas George <george@nsup.org>:
>>
>> Le quintidi 15 prairial, an CCXXV, Steven Liu a écrit :
>>> add time info into every line of log report
>>> the time info can be used to find out error message occur time.
>>>
>>> Signed-off-by: Steven Liu <lingjiujianke@gmail.com>
>>> ---
>>>  cmdutils.c | 8 +++++++-
>>>  1 file changed, 7 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/cmdutils.c b/cmdutils.c
>>> index 3d428f3eea..b760a0565d 100644
>>> --- a/cmdutils.c
>>> +++ b/cmdutils.c
>>> @@ -47,6 +47,7 @@
>>>  #include "libavutil/libm.h"
>>>  #include "libavutil/parseutils.h"
>>>  #include "libavutil/pixdesc.h"
>>> +#include "libavutil/time.h"
>>>  #include "libavutil/eval.h"
>>>  #include "libavutil/dict.h"
>>>  #include "libavutil/opt.h"
>>> @@ -103,6 +104,8 @@ void log_callback_help(void *ptr, int level, const char *fmt, va_list vl)
>>>  static void log_callback_report(void *ptr, int level, const char *fmt, va_list vl)
>>>  {
>>>      va_list vl2;
>>> +    char *tmp_string = NULL;
>>> +    char time_value[32];
>>>      char line[1024];
>>>      static int print_prefix = 1;
>>>
>>> @@ -111,7 +114,10 @@ static void log_callback_report(void *ptr, int level, const char *fmt, va_list v
>>>      av_log_format_line(ptr, level, fmt, vl2, line, sizeof(line), &print_prefix);
>>>      va_end(vl2);
>>>      if (report_file_level >= level) {
>>> -        fputs(line, report_file);
>>
>>> +        snprintf(time_value, sizeof(time_value), "\n[%"PRId64"] - ", av_gettime());
>>> +        tmp_string = av_strireplace(line, "\n", time_value);
>>
>> It looks like you are printing the time of a line at the beginning of
>> the next line. Or am I missing something.
>>
>> Also, I do not like the dynamic alloc in this function, especially since
>> the same task can be done without: find \n, print the time and the
>> single line, loop.
>>
>>> +        fputs(tmp_string, report_file);
>>> +        av_free(tmp_string);
>>>          fflush(report_file);
>>>      }
>>>  }
>>
>> Regards,
>
> Hi Nicolas,
>
>     I get some problem of the log output:
>
>     1. the log output by multiple av_log to one line,
>          for example:
>              av_log(NULL, "major_brand     :");
>              av_log(NULL, "isom\n");
>          then if add the time to the line head, it will output looks like this:
>              [1496470846077636] -     major_brand     :
> [1496470846077643] - isom[1496470846077650] -
>
>      2. but if add the time to the end of line, it maybe need control
> right alignment
>
>      3. maybe the better solution is add the time into line head when
> the log level big than AV_LOG_WARNING ?
>

Maybe you could use the existing "print_prefix" flag to check whether a 
timestamp prefix shall be added?

And it would be good if the timestamp prefix would be made optional 
similar to the AV_LOG_PRINT_LEVEL flag.

Regards,
Tobias
Moritz Barsnick June 6, 2017, 12:01 p.m.
On Tue, Jun 06, 2017 at 11:42:10 +0200, Tobias Rapp wrote:
> And it would be good if the timestamp prefix would be made optional 
> similar to the AV_LOG_PRINT_LEVEL flag.

Yes indeed, please. It's already hard diff'ing two logfiles, this would
require even more awk-ward stuff on the command line (or plain
frustration under Windows).

Moritz

Patch hide | download patch | download mbox

diff --git a/cmdutils.c b/cmdutils.c
index 3d428f3eea..b760a0565d 100644
--- a/cmdutils.c
+++ b/cmdutils.c
@@ -47,6 +47,7 @@ 
 #include "libavutil/libm.h"
 #include "libavutil/parseutils.h"
 #include "libavutil/pixdesc.h"
+#include "libavutil/time.h"
 #include "libavutil/eval.h"
 #include "libavutil/dict.h"
 #include "libavutil/opt.h"
@@ -103,6 +104,8 @@  void log_callback_help(void *ptr, int level, const char *fmt, va_list vl)
 static void log_callback_report(void *ptr, int level, const char *fmt, va_list vl)
 {
     va_list vl2;
+    char *tmp_string = NULL;
+    char time_value[32];
     char line[1024];
     static int print_prefix = 1;
 
@@ -111,7 +114,10 @@  static void log_callback_report(void *ptr, int level, const char *fmt, va_list v
     av_log_format_line(ptr, level, fmt, vl2, line, sizeof(line), &print_prefix);
     va_end(vl2);
     if (report_file_level >= level) {
-        fputs(line, report_file);
+        snprintf(time_value, sizeof(time_value), "\n[%"PRId64"] - ", av_gettime());
+        tmp_string = av_strireplace(line, "\n", time_value);
+        fputs(tmp_string, report_file);
+        av_free(tmp_string);
         fflush(report_file);
     }
 }