lots of libav* log messages

[Wayne Gibson <gr8gib@…>]

With revision 20854 I have been getting alot of the log errors mentioned in the subject line. I have not seen any "bad" things happen as a result of these messages. It seems to recover and move on just fine. So I found the spot in avformatdecoder.cpp that was generating these messages and commented out the lines that were logging the messages. It looks like the code is trying to figure out the VERBOSE level programatically. Perhaps the VERBOSE level should just be hard coded. Anyway, I didn't see the need for them and they really just use up tons of logging space, so again I just commented them out. I have attached a patch for this.

[anonymous]

Since when is it good practice to hide error messages? I too saw these messages but I saw them when trying to run mythcommflag over a recording made with r20851. The commflag failed by the way. I'm now running a newer rev and will attempt to duplicate this and post again in this ticket.

[Wayne Gibson <gr8gib@…>]

Since when is it good practice to hide error messages?<<

Since it uses tons of logging space in my log file. I thought I made it apparent that commenting out the error messages wasn't exactly the best way to "fix" this. But Since it's not apparently clear to some, I'll say it as clear as I can here. THIS IS PROBABLY NOT THE BEST WAY TO "FIX" THIS. I am not a developer, just a hacker that happens to like MythTV. I don't expect this patch to make it into the main code base. I just thought that the developer could use a little help pinpointing the exact location of said error messages. If I stepped on the developers toes with this patch, then I apologize. As I stated in my original posts "I"(meaning me alone, nobody else) have not had any "bad" things happen as a result of these error messages. So take the patch or leave the patch, I don't care. My MythTV is working great and my disk space isn't getting used up from those (useless to me) error messages.

[anonymous]

Trac is not a place for flames. The new build still reported some of the errors that the OP posted about but the commflag job has started this time as opposed to spamming the logs with the error and never finding the logo as it did last time. Once the logo was found and the commflag started the errors were nolonger being reported.

[Wayne Gibson <gr8gib@…>]

I think this ticket should be closed as I think 2 different things are happening here. I was not trying to debug anything with these error messages, they were just making my log file huge. I'm not really sure what you mean when you talk about a commflag job(I do know what a commflag job is). I never mentioned doing a commflag job in my original post. So, maybe your trying to debug the commflag code? If so, then again if I stepped on some toes, I apologize. Anyway, I think you can just close this ticket and forget about the patch as it was more an FYI kind of thing anyway.

[janne]

the error messages were added in the ffmpeg sync in [20797], they might be actual errors in the file or showing a problem how we feed data to the mpeg2 decoder.

please use move_av_error_log_messages_VB_LIBAV.diff to silence the messages

[janne]

(In [20940]) maps libav messages more fine grained to mythtv verbose levels

fatal errors are VB_IMPORTANT, non fatal errors VB_GENERAL warnings VB_LIBAV, verbose and info messages VB_LIBAV|VB_EXTRA

Refs #6729, that message is a non fatal error and can thus repressed by -v nogeneral

[janne]

(In [20961]) be more cautious when to create a new AVPacket in mpegts_push_section

syncs the mpegts demuxers a little bit more to the upstream version and fixes parsing bug introduced in [20811].

Might fixes Refs #6716 and Refs #6729

[janne]

There were several commits which might fixed this if the messages weren't caused by a broken file. Please recheck.

[stuartm]

No response to request for information after 30 days

[janne]

still occuring, see message from Joe Ripley from Aug 21, mythtv devel ml

[mdean]

Also reported on #7419:

2009-10-23 17:03:05.969 AFD Error: Unknown decoding error
2009-10-23 17:03:08.992 [h264 @ 0x7f481abbcd80]B picture before any references, skipping
2009-10-23 17:03:08.992 [h264 @ 0x7f481abbcd80]decode_slice_header error
2009-10-23 17:03:08.992 [h264 @ 0x7f481abbcd80]no frame!
2009-10-23 17:03:08.992 AFD Error: Unknown decoding error

[danielk]

Please confirm this is still a problem after [23404].

[Paul Kendall <paul@…>]

A lot of the noise has gone away, but I still get a lot of the following messages when starting to watch a recording or live TV.

2010-02-01 15:32:45.245 Checking to see if there's a new livetv program to switch to..
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.475 [h264 @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:45.493 [h264 @ 0x7fcffe25a820]mmco: unref short failure
2010-02-01 15:32:46.584 VDPAU: Created 2 output surfaces.
2010-02-01 15:32:46.584 VDPAU: Created VDPAU render device 1440x900
2010-02-01 15:32:46.620 NVP(0): Forcing decode extra audio option on (Video method requires it).
2010-02-01 15:32:46.631 AFD: Opened codec 0x7fcfe075afd0, id(H264) type(Video)
2010-02-01 15:32:46.631 AFD: codec AAC/LATM has 2 channels
2010-02-01 15:32:46.631 AFD: Opened codec 0x7fcfe0781290, id(AAC/LATM) type(Audio)
2010-02-01 15:32:46.631 AFD: codec AC3 has 6 channels
2010-02-01 15:32:46.631 AFD: Opened codec 0x7fcfe07818d0, id(AC3) type(Audio)
2010-02-01 15:32:47.211 Opening audio device 'default'. ch 2(2) sr 48000 (reenc 0)
2010-02-01 15:32:47.211 Opening ALSA audio device 'default'.
2010-02-01 15:32:47.293 mixer unable to find control Master 1
2010-02-01 15:32:47.293 NVP(0): Enabling Audio
2010-02-01 15:32:47.341 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.341 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.341 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.341 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.341 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.342 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.342 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.342 [h264_vdpau @ 0x7fcffe25a820]number of reference frames exceeds max (probably corrupt input), discarding one
2010-02-01 15:32:47.342 [h264_vdpau @ 0x7fcffe25a820]mmco: unref short failure
2010-02-01 15:32:47.361 [h264_vdpau @ 0x7fcffe25a820]mmco: unref short failure

Also, note that I get a lot of similar messages in the backend log when comm-flagging is running.

[Robin Gilks <g8ecj@…>]

Still occuring in [23907] as per #8367. 180k of log in 4-5 seconds :-(

[kevin.wells@…]

Count repeated log messages instead of logging them individually

[anonymous]

Copied from comment:3:ticket:8367.

High frequency log messages were a big problem for me in 0.22. Messages were logged so frequently that it prevented MythTV working reliably. My system was spending most of its time flushing to disk (presumably a flush for each line written to the log file).

After a short time my mythbackend.log file was 143MiB and 1,183,981 out of 1,161,018 lines contained errors like this:

2009-12-31 00:32:53.547 [h264 @ 0x7fa3038b7820]number of reference \
        frames exceeds max (probably corrupt input), discarding one

In my opinion if the same message is repeated many times it should be logged like this:

2009-12-31 00:32:53.547 [h264 @ 0x7fa3038b7820]number of reference \
        frames exceeds max (probably corrupt input), discarding one
2009-12-31 00:32:57.530 last message repeated 152 times

This means the error is still logged, but when the frequency of logging is very high the system will not lock up as a result.

There is code in av_log_default_callback to handle repeated messages, but no code in myth_av_log or my_av_print`. The log_count_repeats_24221.patch above adds support for counting of repeated messages to myth_av_log and my_av_print.

Warning - I have been using this code without any problems since Dec 2009 (against revision 23245 and Ubuntu mythtv-0.22.0+fixes22594). Today I modified the patch to work on Trunk as at revision 24221, tested that it compiled, and submitted it. I have not run the code built from Trunk because of VDPAU related linking problems.

Future work - There is code to handle repeated log messages in libs/libavutil/log.c, libs/libmyth/mythcontext.cpp, libs/libmythtv/avformatdecoder.cpp, and programs/mythtranscode/mpeg2fix.cpp. Perhaps this could should be re-factored into a single function.

[janne]

(In [24235]) H264: respect ref_frame_count when adding short term refs after a frame num gap

this silences the "number of reference frames exceeds max (probably corrupt input), discarding one" message in the uninteresting cases, i.e. after seeking, playback start Refs #6729 Refs #8367

[beirdo]

The above patch disables the log messages in h264 decode as mentioned (and one other that was spamming me). I don't think this will ever get officially included, but if you are being plagued by this, this is a temporary workaround until we can find the reason mythcommflag (at least for me) is spewing these errors on HDPVR recordings (playback doesn't seem to for me)

[mdean]

"Fixed" by e4dfc719d ?

Since e4dfc719d changes the policy that AV_LOG_ERROR should be shown in a default-verbosity MythTV log as an error, it seems it will prevent users from seeing the error messages that they didn't like to see. They will now have to explicitly enable -v libav to see them.

I'm closing this as fixed because it's not really helpful to leave the ticket open--whatever policy we choose is the way it will be.