> On May 31, 2016, at 3:23 PM, Michael Niedermayer <mich...@niedermayer.cc>
> wrote:
>
> adding demuxer and other logs should be easy
> This forces single threaded decoding for simplicity
> It also requires pthreads, this could be avoided either with
> some lockless tricks or simply by assuming av_log would never be called from
> another thread.
I’ve been testing this patch, but currently the logging does not appear within
the log node. For instance with a fuzzed mpeg2video in QuickTime when I run:
./ffprobe -i /Users/davidrice/fuzzed_mpeg2video.mov -show_log 1 -show_frames
-of xml
Then the output is like:
ffprobe version N-80154-g9c023a7 Copyright (c) 2007-2016 the FFmpeg developers
built with Apple LLVM version 7.3.0 (clang-703.0.31)
configuration: --disable-dwt
libavutil 55. 24.100 / 55. 24.100
libavcodec 57. 44.100 / 57. 44.100
libavformat 57. 37.101 / 57. 37.101
libavdevice 57. 0.101 / 57. 0.101
libavfilter 6. 46.100 / 6. 46.100
libswscale 4. 1.100 / 4. 1.100
libswresample 2. 0.101 / 2. 0.101
<?xml version="1.0" encoding="UTF-8"?>
<ffprobe>
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from
'/Users/davidrice/fuzzed_mpeg2video.mov':
Metadata:
major_brand : qt
minor_version : 512
compatible_brands: qt
encoder : Lavf57.34.103
Duration: 00:00:04.00, start: 0.000000, bitrate: 2668 kb/s
Stream #0:0(eng): Video: mpeg2video (Main) (m2v1 / 0x3176326D),
yuv420p(tv), 640x480 [SAR 1:1 DAR 4:3], 2666 kb/s, 25 fps, 25 tbr, 12800 tbn
(default)
Metadata:
handler_name : DataHandler
encoder : Lavc57.38.100 mpeg2video
<frames>
[mpeg2video @ 0x7fcfda817600] skipped MB in I frame at 3 18
[mpeg2video @ 0x7fcfda817600] Warning MVs not available
[mpeg2video @ 0x7fcfda817600] concealing 40 DC, 40 AC, 40 MV errors in I frame
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="0"
pkt_pts_time="0.000000" pkt_dts="0" pkt_dts_time="0.000000"
best_effort_timestamp="0" best_effort_timestamp_time="0.000000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="36" pkt_size="29682"
width="640" height="480" pix_fmt="yuv420p" sample_aspect_ratio="1:1"
pict_type="I" coded_picture_number="0" display_picture_number="0"
interlaced_frame="0" top_field_first="0" repeat_pict="0">
<logs>
</logs>
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:01"/>
</side_data_list>
</frame>
[mpeg2video @ 0x7fcfda817600] skipped MB in I frame at 27 6
[mpeg2video @ 0x7fcfda817600] Warning MVs not available
[mpeg2video @ 0x7fcfda817600] concealing 40 DC, 40 AC, 40 MV errors in I frame
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="512"
pkt_pts_time="0.040000" pkt_dts="512" pkt_dts_time="0.040000"
best_effort_timestamp="512" best_effort_timestamp_time="0.040000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="29718"
pkt_size="45833" width="640" height="480" pix_fmt="yuv420p"
sample_aspect_ratio="1:1" pict_type="I" coded_picture_number="1"
display_picture_number="0" interlaced_frame="0" top_field_first="0"
repeat_pict="0">
<logs>
</logs>
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:02"/>
</side_data_list>
</frame>
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="1024"
pkt_pts_time="0.080000" pkt_dts="1024" pkt_dts_time="0.080000"
best_effort_timestamp="1024" best_effort_timestamp_time="0.080000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="75551"
pkt_size="45751" width="640" height="480" pix_fmt="yuv420p"
sample_aspect_ratio="1:1" pict_type="I" coded_picture_number="2"
display_picture_number="0" interlaced_frame="0" top_field_first="0"
repeat_pict="0">
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:03"/>
</side_data_list>
</frame>
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="1536"
pkt_pts_time="0.120000" pkt_dts="1536" pkt_dts_time="0.120000"
best_effort_timestamp="1536" best_effort_timestamp_time="0.120000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="121302"
pkt_size="46273" width="640" height="480" pix_fmt="yuv420p"
sample_aspect_ratio="1:1" pict_type="I" coded_picture_number="3"
display_picture_number="0" interlaced_frame="0" top_field_first="0"
repeat_pict="0">
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:04"/>
</side_data_list>
</frame>
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="2048"
pkt_pts_time="0.160000" pkt_dts="2048" pkt_dts_time="0.160000"
best_effort_timestamp="2048" best_effort_timestamp_time="0.160000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="167575"
pkt_size="30432" width="640" height="480" pix_fmt="yuv420p"
sample_aspect_ratio="1:1" pict_type="I" coded_picture_number="4"
display_picture_number="0" interlaced_frame="0" top_field_first="0"
repeat_pict="0">
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:05"/>
</side_data_list>
</frame>
[mpeg2video @ 0x7fcfda817600] skipped MB in I frame at 16 13
[mpeg2video @ 0x7fcfda817600] skipped MB in I frame at 29 25
[mpeg2video @ 0x7fcfda817600] Warning MVs not available
[mpeg2video @ 0x7fcfda817600] concealing 80 DC, 80 AC, 80 MV errors in I frame
<frame media_type="video" stream_index="0" key_frame="1" pkt_pts="2560"
pkt_pts_time="0.200000" pkt_dts="2560" pkt_dts_time="0.200000"
best_effort_timestamp="2560" best_effort_timestamp_time="0.200000"
pkt_duration="512" pkt_duration_time="0.040000" pkt_pos="198007"
pkt_size="21454" width="640" height="480" pix_fmt="yuv420p"
sample_aspect_ratio="1:1" pict_type="I" coded_picture_number="5"
display_picture_number="0" interlaced_frame="0" top_field_first="0"
repeat_pict="0">
<logs>
</logs>
<side_data_list>
<side_data side_data_type="GOP timecode" side_data_size="8"
timecode="00:00:00:06"/>
</side_data_list>
</frame>
</frames>
</ffprobe>
When the mpeg2video decoding log appears in sdterr, then the <logs> node is
written but empty. During a frame when there is no logged message, there is no
<logs> node.
Also I’m uncertain what the value to use with -show_log means. I’m using
-show_log 1 for now. Is this for verbosity?
Dave Rice
> doc/ffprobe.xsd update missing (TODO & help welcome)
>
> Fixes Ticket5521
>
> Signed-off-by: Michael Niedermayer <mich...@niedermayer.cc>
> ---
> ffprobe.c | 154 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
> 1 file changed, 153 insertions(+), 1 deletion(-)
>
> diff --git a/ffprobe.c b/ffprobe.c
> index a7e329c..07b61ec 100644
> --- a/ffprobe.c
> +++ b/ffprobe.c
> @@ -49,6 +49,19 @@
> #include "libpostproc/postprocess.h"
> #include "cmdutils.h"
>
> +#if HAVE_PTHREADS
> +# include <pthread.h>
> +#else
> +# ifdef pthread_mutex_lock
> +# undef pthread_mutex_lock
> +# endif
> +# define pthread_mutex_lock(a)
> +# ifdef pthread_mutex_unlock
> +# undef pthread_mutex_unlock
> +# endif
> +# define pthread_mutex_unlock(a)
> +#endif
> +
> typedef struct InputStream {
> AVStream *st;
>
> @@ -84,6 +97,7 @@ static int do_show_library_versions = 0;
> static int do_show_pixel_formats = 0;
> static int do_show_pixel_format_flags = 0;
> static int do_show_pixel_format_components = 0;
> +static int do_show_log = 0;
>
> static int do_show_chapter_tags = 0;
> static int do_show_format_tags = 0;
> @@ -92,6 +106,7 @@ static int do_show_program_tags = 0;
> static int do_show_stream_tags = 0;
> static int do_show_packet_tags = 0;
>
> +
> static int show_value_unit = 0;
> static int use_value_prefix = 0;
> static int use_byte_value_binary_prefix = 0;
> @@ -146,6 +161,8 @@ typedef enum {
> SECTION_ID_FRAME_TAGS,
> SECTION_ID_FRAME_SIDE_DATA_LIST,
> SECTION_ID_FRAME_SIDE_DATA,
> + SECTION_ID_FRAME_LOG,
> + SECTION_ID_FRAME_LOGS,
> SECTION_ID_LIBRARY_VERSION,
> SECTION_ID_LIBRARY_VERSIONS,
> SECTION_ID_PACKET,
> @@ -185,10 +202,12 @@ static struct section sections[] = {
> [SECTION_ID_FORMAT] = { SECTION_ID_FORMAT, "format", 0, {
> SECTION_ID_FORMAT_TAGS, -1 } },
> [SECTION_ID_FORMAT_TAGS] = { SECTION_ID_FORMAT_TAGS, "tags",
> SECTION_FLAG_HAS_VARIABLE_FIELDS, { -1 }, .element_name = "tag", .unique_name
> = "format_tags" },
> [SECTION_ID_FRAMES] = { SECTION_ID_FRAMES, "frames",
> SECTION_FLAG_IS_ARRAY, { SECTION_ID_FRAME, SECTION_ID_SUBTITLE, -1 } },
> - [SECTION_ID_FRAME] = { SECTION_ID_FRAME, "frame", 0, {
> SECTION_ID_FRAME_TAGS, SECTION_ID_FRAME_SIDE_DATA_LIST, -1 } },
> + [SECTION_ID_FRAME] = { SECTION_ID_FRAME, "frame", 0, {
> SECTION_ID_FRAME_TAGS, SECTION_ID_FRAME_SIDE_DATA_LIST,
> SECTION_ID_FRAME_LOGS, -1 } },
> [SECTION_ID_FRAME_TAGS] = { SECTION_ID_FRAME_TAGS, "tags",
> SECTION_FLAG_HAS_VARIABLE_FIELDS, { -1 }, .element_name = "tag", .unique_name
> = "frame_tags" },
> [SECTION_ID_FRAME_SIDE_DATA_LIST] ={ SECTION_ID_FRAME_SIDE_DATA_LIST,
> "side_data_list", SECTION_FLAG_IS_ARRAY, { SECTION_ID_FRAME_SIDE_DATA, -1 } },
> [SECTION_ID_FRAME_SIDE_DATA] = { SECTION_ID_FRAME_SIDE_DATA,
> "side_data", 0, { -1 } },
> + [SECTION_ID_FRAME_LOGS] = { SECTION_ID_FRAME_LOGS, "logs",
> SECTION_FLAG_IS_ARRAY, { SECTION_ID_FRAME_LOG, -1 } },
> + [SECTION_ID_FRAME_LOG] = { SECTION_ID_FRAME_LOG, "log",
> SECTION_FLAG_HAS_VARIABLE_FIELDS, { -1 } },
> [SECTION_ID_LIBRARY_VERSIONS] = { SECTION_ID_LIBRARY_VERSIONS,
> "library_versions", SECTION_FLAG_IS_ARRAY, { SECTION_ID_LIBRARY_VERSION, -1 }
> },
> [SECTION_ID_LIBRARY_VERSION] = { SECTION_ID_LIBRARY_VERSION,
> "library_version", 0, { -1 } },
> [SECTION_ID_PACKETS] = { SECTION_ID_PACKETS, "packets",
> SECTION_FLAG_IS_ARRAY, { SECTION_ID_PACKET, -1} },
> @@ -255,11 +274,73 @@ static uint64_t *nb_streams_packets;
> static uint64_t *nb_streams_frames;
> static int *selected_streams;
>
> +#if HAVE_PTHREADS
> +pthread_mutex_t log_mutex;
> +#endif
> +typedef struct LogBuffer {
> + char *context_name;
> + int log_level;
> + char *log_message;
> + AVClassCategory category;
> + char *parent_name;
> + AVClassCategory parent_category;
> +}LogBuffer;
> +
> +static LogBuffer *log_buffer;
> +static int log_buffer_size;
> +
> +static void log_callback(void *ptr, int level, const char *fmt, va_list vl)
> +{
> + AVClass* avc = ptr ? *(AVClass **) ptr : NULL;
> + va_list vl2;
> + char line[1024];
> + static int print_prefix = 1;
> + void *new_log_buffer;
> +
> + va_copy(vl2, vl);
> + av_log_default_callback(ptr, level, fmt, vl);
> + av_log_format_line(ptr, level, fmt, vl2, line, sizeof(line),
> &print_prefix);
> + va_end(vl2);
> +
> +#if HAVE_PTHREADS
> + pthread_mutex_lock(&log_mutex);
> +
> + new_log_buffer = av_realloc_array(log_buffer, log_buffer_size + 1,
> sizeof(*log_buffer));
> + if (new_log_buffer) {
> + log_buffer = new_log_buffer;
> + memset(&log_buffer[log_buffer_size], 0,
> sizeof(log_buffer[log_buffer_size]));
> + log_buffer[log_buffer_size].context_name= avc ?
> av_strdup(avc->item_name(ptr)) : NULL;
> + if (avc) {
> + if (avc->get_category) log_buffer[log_buffer_size].category =
> avc->get_category(ptr);
> + else log_buffer[log_buffer_size].category =
> avc->category;
> + }
> + log_buffer[log_buffer_size].log_level = level;
> + log_buffer[log_buffer_size].log_message = av_strdup(line);
> + if (avc && avc->parent_log_context_offset) {
> + AVClass** parent = *(AVClass ***) (((uint8_t *) ptr) +
> + avc->parent_log_context_offset);
> + if (parent && *parent) {
> + log_buffer[log_buffer_size].parent_name =
> av_strdup((*parent)->item_name(parent));
> + log_buffer[log_buffer_size].parent_category =
> + (*parent)->get_category ?
> (*parent)->get_category(parent) :(*parent)->category;
> + }
> + }
> + log_buffer_size ++;
> + }
> +
> + pthread_mutex_unlock(&log_mutex);
> +#endif
> +}
> +
> static void ffprobe_cleanup(int ret)
> {
> int i;
> for (i = 0; i < FF_ARRAY_ELEMS(sections); i++)
> av_dict_free(&(sections[i].entries_to_show));
> +
> +#if HAVE_PTHREADS
> + pthread_mutex_destroy(&log_mutex);
> +#endif
> }
>
> struct unit_value {
> @@ -1759,6 +1840,56 @@ static inline int show_tags(WriterContext *w,
> AVDictionary *tags, int section_id
> return ret;
> }
>
> +static void clear_log(int need_lock)
> +{
> + int i;
> +
> + if (need_lock)
> + pthread_mutex_lock(&log_mutex);
> + for (i=0; i<log_buffer_size; i++) {
> + av_freep(&log_buffer[i].context_name);
> + av_freep(&log_buffer[i].log_message);
> + }
> + log_buffer_size = 0;
> + if(need_lock)
> + pthread_mutex_unlock(&log_mutex);
> +}
> +
> +static int show_log(WriterContext *w, int section_ids, int section_id, int
> log_level)
> +{
> + int i;
> + pthread_mutex_lock(&log_mutex);
> + if (!log_buffer_size) {
> + pthread_mutex_unlock(&log_mutex);
> + return 0;
> + }
> + writer_print_section_header(w, section_ids);
> +
> + for (i=0; i<log_buffer_size; i++) {
> + if (log_buffer[i].log_level <= log_level) {
> + writer_print_section_header(w, section_id);
> + print_str("context", log_buffer[i].context_name);
> + print_int("level", log_buffer[i].log_level);
> + print_int("category", log_buffer[i].category);
> + if (log_buffer[i].parent_name) {
> + print_str("parent_context", log_buffer[i].parent_name);
> + print_int("parent_category", log_buffer[i].parent_category);
> + } else {
> + print_str_opt("parent_context", "N/A");
> + print_str_opt("parent_category", "N/A");
> + }
> + print_str("message", log_buffer[i].log_message);
> + writer_print_section_footer(w);
> + }
> + }
> + clear_log(0);
> + pthread_mutex_unlock(&log_mutex);
> +
> + writer_print_section_footer(w);
> +
> + return 0;
> +}
> +
> static void show_packet(WriterContext *w, InputFile *ifile, AVPacket *pkt,
> int packet_idx)
> {
> char val_str[128];
> @@ -1917,6 +2048,8 @@ static void show_frame(WriterContext *w, AVFrame
> *frame, AVStream *stream,
> }
> if (do_show_frame_tags)
> show_tags(w, av_frame_get_metadata(frame), SECTION_ID_FRAME_TAGS);
> + if (do_show_log)
> + show_log(w, SECTION_ID_FRAME_LOGS, SECTION_ID_FRAME_LOG,
> do_show_log);
> if (frame->nb_side_data) {
> writer_print_section_header(w, SECTION_ID_FRAME_SIDE_DATA_LIST);
> for (i = 0; i < frame->nb_side_data; i++) {
> @@ -1956,6 +2089,7 @@ static av_always_inline int process_frame(WriterContext
> *w,
> AVSubtitle sub;
> int ret = 0, got_frame = 0;
>
> + clear_log(1);
> if (dec_ctx && dec_ctx->codec) {
> switch (par->codec_type) {
> case AVMEDIA_TYPE_VIDEO:
> @@ -2604,6 +2738,13 @@ static int open_input_file(InputFile *ifile, const
> char *filename)
> if (err < 0)
> exit(1);
>
> + if (do_show_log) {
> + // For loging it is needed to disable at least frame threads
> as otherwise
> + // the log information would need to be reordered and
> matches up to contexts and frames
> + // That is in fact possible but not trivial
> + av_dict_set(&codec_opts, "threads", "1", 0);
> + }
> +
> ist->dec_ctx->pkt_timebase = stream->time_base;
> #if FF_API_LAVF_AVCTX
> ist->dec_ctx->time_base = stream->codec->time_base;
> @@ -3191,6 +3332,9 @@ static const OptionDef real_options[] = {
> "show a particular entry from the format/container info", "entry" },
> { "show_entries", HAS_ARG, {.func_arg = opt_show_entries},
> "show a set of specified entries", "entry_list" },
> +#if HAVE_PTHREADS
> + { "show_log", OPT_INT|HAS_ARG, {(void*)&do_show_log}, "show log" },
> +#endif
> { "show_packets", 0, {(void*)&opt_show_packets}, "show packets info" },
> { "show_programs", 0, {(void*)&opt_show_programs}, "show programs info" },
> { "show_streams", 0, {(void*)&opt_show_streams}, "show streams info" },
> @@ -3235,6 +3379,14 @@ int main(int argc, char **argv)
> char *w_name = NULL, *w_args = NULL;
> int ret, i;
>
> +#if HAVE_PTHREADS
> + ret = pthread_mutex_init(&log_mutex, NULL);
> + if (ret != 0) {
> + goto end;
> + }
> +#endif
> + av_log_set_callback(log_callback);
> +
> av_log_set_flags(AV_LOG_SKIP_REPEATED);
> register_exit(ffprobe_cleanup);
>
> --
> 1.7.9.5
>
> _______________________________________________
> ffmpeg-devel mailing list
> ffmpeg-devel@ffmpeg.org
> http://ffmpeg.org/mailman/listinfo/ffmpeg-devel
_______________________________________________
ffmpeg-devel mailing list
ffmpeg-devel@ffmpeg.org
http://ffmpeg.org/mailman/listinfo/ffmpeg-devel
