[mythtv-users] "Disabling Audio" message on video playback start since last (mythbuntu) update

Kingsley Turner krt at krt.com.au
Sat Mar 12 07:48:29 UTC 2016


On 29/02/16 08:16, Kingsley Turner wrote:
> Hi-ya,
>
> I updated the Myth box the other day - first time in months. Mainly only 
> to pickup the latest security patches.
>
> It's a Mythbuntu installation (myth 0.27).
>
> Anyway, now that I have pulled in a bunch of updates, every second or 
> third time we play a video, the big red "X" with the message "Disabling 
> Audio" comes up when starting, and there's no sound at all.
>
> Has there been any updates recently that might have caused this?
>
> Hmm, I guess I better run with verbose logging and hope to catch it out.
>

G'day,

I finally caught this with the log on.
it seems to happen more if the box is sitting idle for a while.

Looks like the problem is this:

2016-03-12 14:46:12.292102 I  AOBase: Opening audio device 
'hdmi:CARD=NVidia,DEV=1' ch 2(2) sr 48000 sf signed 16 bit reenc 0
2016-03-12 14:46:12.292105 I  ALSA: OpenDevice hdmi:CARD=NVidia,DEV=1
2016-03-12 14:46:12.292333 E  ALSA: snd_pcm_open("hdmi:CARD=NVidia,DEV=1"): 
Device or resource busy
2016-03-12 14:46:12.292342 E  AudioOutput Error: Aborting reconfigure
2016-03-12 14:46:12.292346 N  AudioPlayer: Disabling Audio, reason is: 
Aborting reconfigure

But the full log is below.

I wonder if the device is still open or suchlike?

cheers,
-kt




016-03-12 14:46:11.725149 I 
FileRingBuf(/var/lib/mythtv/videos//In/00_NEW/Redacted.avi): 
OpenFile(/var/lib/mythtv/videos//In/00_NEW/Redacted.avi, 2000 ms)
2016-03-12 14:46:11.935049 I  TV: StartPlayer(0, WatchingVideo, main) -- begin
2016-03-12 14:46:11.935057 I  TV: Elapsed time since TV constructor was 
called: 219 ms
2016-03-12 14:46:12.034804 I  Pulse: Operation: success 0 remaining 1
2016-03-12 14:46:12.034814 I  Pulse: Operation: success 0 remaining 0
2016-03-12 14:46:12.045183 I  Pulse: PulseAudio suspend OK
2016-03-12 14:46:12.045730 I  ALSA: OpenDevice hdmi:CARD=NVidia,DEV=1
2016-03-12 14:46:12.046000 E  ALSA: snd_pcm_open("hdmi:CARD=NVidia,DEV=1"): 
Device or resource busy
2016-03-12 14:46:12.046020 N  AudioPlayer: Enabling Audio
2016-03-12 14:46:12.048002 I  Player(d): Stretch Factor 1, allow passthru
2016-03-12 14:46:12.048090 I  AFD: Buffer size: 32768 streamed 0 seekable 1
2016-03-12 14:46:12.291100 I  AFD: Stream #0, has id 0x0 codec id MPEG4, 
type Video, bitrate 0 at 0x74304c0
2016-03-12 14:46:12.291108 I  AFD: Stream #1, has id 0x1 codec id MP3, type 
Audio, bitrate 156520 at 0xb484760
2016-03-12 14:46:12.291111 I  AFD: codec MP3 has 2 channels
2016-03-12 14:46:12.291113 I  AFD: Looking for decoder for MP3
2016-03-12 14:46:12.291130 I  AFD: Opened codec 0xb484a40, id(MP3) type(Audio)
2016-03-12 14:46:12.291154 I  AFD: Audio Track #1, of type (Normal) is A/V 
stream #1 (id=0x1) and has 2 channels in the Undetermined language(7695972).
2016-03-12 14:46:12.291157 I  AFD: Trying to select best video track
2016-03-12 14:46:12.291164 I  AFD: Selected track #0 (id 0x0 codec id MPEG4, 
type Video, bitrate 500000 at 0x74304c0)
2016-03-12 14:46:12.291952 I  VDP: Accepting: cmp(>= 0 0) dec(vdpau) cpus(4) 
skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) 
deint(vdpauadvanceddoublerate,none) filt(vdpaucolorspace=auto,  vdpauhqscaling)
2016-03-12 14:46:12.291959 I  VDP: LoadBestPreferences(2048x2048, 0)
2016-03-12 14:46:12.291968 I  VDP: LoadBestPreferences(2048x2048, 60)
2016-03-12 14:46:12.291974 I  VDP: LoadBestPreferences(624x352, 60)
2016-03-12 14:46:12.291985 I  AFD: Using 1 CPUs for decoding
2016-03-12 14:46:12.291988 I  AFD: InitVideoCodec() 0x6134080 id(MPEG4) type 
(Video).
2016-03-12 14:46:12.292004 I  AFD: Selected FPS is 23.976 (avg 0 codec 
23.9791 container 23.976 estimated 23.976)
2016-03-12 14:46:12.292010 I  Player(d): SetFrameInterval ps:1 scan:3
2016-03-12 14:46:12.292017 I  Player(d): detectInterlace(Detect Scan, 
Interlaced Scan, 23.976, 352) ->Interlaced Scan
2016-03-12 14:46:12.292045 I  AFD: Using vdpau for video decoding
2016-03-12 14:46:12.292054 I  AFD: Opened codec 0x6134080, id(MPEG4) type(Video)
2016-03-12 14:46:12.292065 I  AFD: Selected track 1: Undetermined MP0 2ch 
(A/V Stream #1)
2016-03-12 14:46:12.292068 I  AFD: Audio data is planar
2016-03-12 14:46:12.292075 I  AFD: Initializing audio parms from audio track #1
2016-03-12 14:46:12.292082 I  AFD: Audio format changed
             from id(NONE)     -1Hz -1ch -1bps     (profile 0) to id( MP3)  
48000Hz  2ch 16bps     (profile 0)
2016-03-12 14:46:12.292088 I  AOBase: Killing AudioOutputDSP
2016-03-12 14:46:12.292093 I  AOBase: Original codec was MP3, signed 16 bit, 
48 kHz, 2 channels
2016-03-12 14:46:12.292098 I  AOBase: enc(0), passthru(0), features () 
configured_channels(2), 2 channels supported(1) max_channels(2)
2016-03-12 14:46:12.292102 I  AOBase: Opening audio device 
'hdmi:CARD=NVidia,DEV=1' ch 2(2) sr 48000 sf signed 16 bit reenc 0
2016-03-12 14:46:12.292105 I  ALSA: OpenDevice hdmi:CARD=NVidia,DEV=1
2016-03-12 14:46:12.292333 E  ALSA: snd_pcm_open("hdmi:CARD=NVidia,DEV=1"): 
Device or resource busy
2016-03-12 14:46:12.292342 E  AudioOutput Error: Aborting reconfigure
2016-03-12 14:46:12.292346 N  AudioPlayer: Disabling Audio, reason is: 
Aborting reconfigure
2016-03-12 14:46:12.292396 I  Dec: Selected track #1 (type 2) in the Unknown 
language(0)
2016-03-12 14:46:12.292400 I  Dec: Resyncing position map. posmapStarted = 0 
livetv(0) watchingRec(0)
2016-03-12 14:46:12.293433 I  Dec: SyncPositionMap prerecorded, from DB: 0 
entries
2016-03-12 14:46:12.293611 I  AFD: Recording has no position -- using 
libavformat seeking.
2016-03-12 14:46:12.293625 I  AFD: Successfully opened decoder for file: 
"/var/lib/mythtv/videos//In/00_NEW/Redacted.avi". novideo(0)
2016-03-12 14:46:12.294059 I  VideoOutput: Allowed renderers: vdpau
2016-03-12 14:46:12.294065 I  VideoOutput: Allowed renderers (filt: vdpau): 
vdpau
2016-03-12 14:46:12.294268 I  VDP: Accepting: cmp(>= 0 0) dec(vdpau) cpus(4) 
skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) 
deint(vdpauadvanceddoublerate,none) filt(vdpaucolorspace=auto,  vdpauhqscaling)
2016-03-12 14:46:12.294273 I  VDP: LoadBestPreferences(2048x2048, 0)
2016-03-12 14:46:12.294280 I  VDP: LoadBestPreferences(2048x2048, 60)
2016-03-12 14:46:12.294284 I  VDP: LoadBestPreferences(624x352, 60)
2016-03-12 14:46:12.294289 I  VideoOutput: Preferred renderer: vdpau
2016-03-12 14:46:12.294293 I  VideoOutput: Trying video renderer: 'vdpau'
2016-03-12 14:46:12.294711 I  VDP: Accepting: cmp(>= 0 0) dec(vdpau) cpus(4) 
skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) 
deint(vdpauadvanceddoublerate,none) filt(vdpaucolorspace=auto,  vdpauhqscaling)
2016-03-12 14:46:12.294716 I  VDP: LoadBestPreferences(2048x2048, 0)
2016-03-12 14:46:12.294722 I  VDP: LoadBestPreferences(2048x2048, 60)
2016-03-12 14:46:12.294730 I  VideoOutWindow::SetPIPState. pip_state: 0]
2016-03-12 14:46:12.294733 I  VDP: LoadBestPreferences(2048x2048, 23.976)
2016-03-12 14:46:12.294738 I  Clearing OpenGL painter cache.
2016-03-12 14:46:12.310688 I  Display Rect  left: 0, top: 134, width: 1920, 
height: 812, aspect: 1.33333
2016-03-12 14:46:12.310697 I  Video Rect    left: 0, top: 0, width: 624, 
height: 352, aspect: 1.77273
2016-03-12 14:46:12.310703 I  VDP: LoadBestPreferences(624x352, 23.976)
2016-03-12 14:46:12.310718 I  Display Rect  left: 0, top: 134, width: 1920, 
height: 812, aspect: 1.33333
2016-03-12 14:46:12.310724 I  Video Rect    left: 0, top: 0, width: 624, 
height: 352, aspect: 1.77273
2016-03-12 14:46:12.310727 I  VDP: SetVideoRenderer(vdpau)
2016-03-12 14:46:12.310732 I  VDP: SetVideoRender(vdpau) == GetVideoRenderer()
2016-03-12 14:46:12.311005 I  VideoOutput: Pixel dimensions: Screen 
1920x1080, window 1920x1080
2016-03-12 14:46:12.311014 I  VideoOutput: Actual display dimensions: 
1219x686 mm  Aspect: 1.77697
2016-03-12 14:46:12.311019 I  VideoOutput: Estimated window dimensions: 
1219x686 mm  Aspect: 1.77697
2016-03-12 14:46:12.311034 I  VidOutVDPAU: Requesting high quality scaling.
2016-03-12 14:46:12.346436 I  VDPAU: Created 2 output surfaces.
2016-03-12 14:46:12.346446 I  VDPAU: Set colorkey to 0x20202
2016-03-12 14:46:12.346453 I  VDPAU: Created VDPAU render device 1920x1080
2016-03-12 14:46:12.346466 I  VidOutVDPAU: Created VDPAU osd (1920x1080)
2016-03-12 14:46:12.350059 I  VDPAU: Enabling high quality scaling.
2016-03-12 14:46:12.350230 I  ColourSpace: PictureAttributes: Brightness, 
Contrast, Colour, Hue, Studio Levels,
2016-03-12 14:46:12.350234 I  VidOutVDPAU: Using ITU BT.601 colorspace
2016-03-12 14:46:12.350248 I  Display Rect  left: 0, top: 0, width: 1920, 
height: 1080, aspect: 1.77778
2016-03-12 14:46:12.350255 I  Video Rect    left: 0, top: 0, width: 624, 
height: 352, aspect: 1.77273
2016-03-12 14:46:12.350257 I  VidOutVDPAU: Created VDPAU context (GPU decode)
2016-03-12 14:46:12.350268 I  Over/underscan. V: 0, H: 0
2016-03-12 14:46:12.350274 I  Display Rect  left: 0, top: 0, width: 1920, 
height: 1080, aspect: 1.77778
2016-03-12 14:46:12.350280 I  Video Rect    left: 0, top: 0, width: 624, 
height: 352, aspect: 1.77273
2016-03-12 14:46:12.350287 N  Player(d): Forcing decode extra audio option 
on (Video method requires it).
2016-03-12 14:46:12.350300 I  FilterManager: GetFilterInfo(convert) 
returning: 0x0
2016-03-12 14:46:12.350313 I  Player(d): LoadFilters('vdpaucolorspace=auto,  
vdpauhqscaling'..) -> 0x0
2016-03-12 14:46:12.350881 I  Player(d): Decoder thread starting.
2016-03-12 14:46:12.353332 I  OSD: Loaded window osd_message
2016-03-12 14:46:12.355608 I  OSD: Loaded window osd_input
2016-03-12 14:46:12.360098 I  OSD: Loaded window program_info
2016-03-12 14:46:12.361917 I  OSD: Loaded window browse_info
2016-03-12 14:46:12.363631 I  OSD: Loaded window osd_status
2016-03-12 14:46:12.365456 I  OSD: Loaded window osd_program_editor
2016-03-12 14:46:12.367914 I  OSD: Loaded window osd_debug
2016-03-12 14:46:12.367921 I  OSD: Loaded OSD: size 1920x1080 offset 0+0
2016-03-12 14:46:12.367961 I  OSD: Created window aa_OSD_SUBTITLES
2016-03-12 14:46:12.367989 I  Player(d): ClearAfterSeek(0)
2016-03-12 14:46:12.368884 I  VDP: GetFilteredDeint() : vdpau -> 
'vdpauadvanceddoublerate'
2016-03-12 14:46:12.369030 I  VDPAU: Enabling high quality scaling.
2016-03-12 14:46:12.369355 I  VidOutVDPAU: Enabled deinterlacing.
2016-03-12 14:46:12.369367 E  VSYNC: DRMVideoSync: VBlank ioctl did not 
work, unimplemented in this driver?
2016-03-12 14:46:12.369381 E  VSYNC: RTCVideoSync: Could not set RTC frequency:
             eno: Permission denied (13)
2016-03-12 14:46:12.369681 I  Player(d): Video timing method: USleep with 
busy wait
2016-03-12 14:46:12.369688 I  Player(d): Display Refresh Rate: 59.999 Video 
Frame Rate: 23.976
2016-03-12 14:46:12.369692 I  Player(d): SetFrameInterval ps:1 scan:1
2016-03-12 14:46:12.370180 I  playCtx: StartPlaying(): took 0 ms to start 
player.
2016-03-12 14:46:12.370236 I  TV: Created player.
2016-03-12 14:46:12.370242 I  TV: StartPlayer(0, WatchingVideo, main) -- end ok
2016-03-12 14:46:12.370247 I  TV: Changing from None to WatchingVideo
2016-03-12 14:46:12.370517 I  TV: DrawUnusedRects() -- begin
2016-03-12 14:46:12.370520 I  TV: DrawUnusedRects() -- end
2016-03-12 14:46:12.370558 I  TV: Main UI disabled.
2016-03-12 14:46:12.370561 I  TV: HandleStateChange(0) -- end
2016-03-12 14:46:12.370598 I  TV: tv->Playback() -- end
2016-03-12 14:46:12.370605 I  TV: Entering main playback loop.
2016-03-12 14:46:12.376847 I  ScreenSaverX11Private: DPMS Deactivated 1
2016-03-12 14:46:12.377868 I  Player(d): Waiting for video buffers...
2016-03-12 14:46:12.382989 I  VidOutVDPAU: Created VDPAU decoder (2 ref frames)
2016-03-12 14:46:12.383456 I  Player(d): progressive frame seen after 2 
interlaced frames
2016-03-12 14:46:12.385595 I  VDPAU: Added 2 output surfaces (total 4, max 4)
2016-03-12 14:46:12.466937 I  VDPAU: Enabling high quality scaling.
2016-03-12 14:46:12.467098 I  Player(d): Disabled deinterlacing
2016-03-12 14:46:16.387614 I  Player(d): FPS:   23.98 Mean: 41708 
Std.Dev:    53 CPUs: 100% 100% 100% 100% 100% 100% 100% 100%
2016-03-12 14:46:17.263596 I  TV: SetActive(0,w/o OSD) 0 -> 0 -- begin
2016-03-12 14:46:17.263620 I  TV: SetActive(0,w/o OSD) 0 -> 0 -- end
2016-03-12 14:46:17.306059 I  TV: HandleStateChange(0) -- begin
2016-03-12 14:46:17.306071 I  TV: Attempting to change from WatchingVideo to 
None
2016-03-12 14:46:17.306083 I  TV: StopStuff() for player ctx 0 -- begin
2016-03-12 14:46:17.306090 I  TV: SetActive(0,w/o OSD) 0 -> 0 -- begin
2016-03-12 14:46:17.306104 I  TV: SetActive(0,w/o OSD) 0 -> 0 -- end
2016-03-12 14:46:17.306112 I  Player(d): StopPlaying - begin
2016-03-12 14:46:17.318524 I  Player(d): Decoder thread exiting.
2016-03-12 14:46:17.318627 I  Player(d): Exited decoder loop.
2016-03-12 14:46:17.324118 I  VidOutVDPAU: DiscardFrames(1)
2016-03-12 14:46:17.324203 I  VideoBuffers::DiscardFrames(1): UUUUUUUAUUUAUU
2016-03-12 14:46:17.324341 I  VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAA 
-- done
2016-03-12 14:46:17.324396 I  VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAA 
-- done()
2016-03-12 14:46:17.326541 W  MythPainter: 25 images not yet de-allocated.
2016-03-12 14:46:17.326571 I  VDPAU Painter: Clearing VDPAU painter cache.
2016-03-12 14:46:17.361923 I  AOBase: Killing AudioOutputDSP
2016-03-12 14:46:17.554638 I  Pulse: Operation: success 1 remaining 1
2016-03-12 14:46:17.575292 I  Pulse: Operation: success 1 remaining 0
2016-03-12 14:46:17.585625 I  Pulse: PulseAudio resume OK
2016-03-12 14:46:17.585652 I  Player(d): StopPlaying - end
2016-03-12 14:46:17.585659 I  TV: StopStuff(): stopping ring buffer
2016-03-12 14:46:17.585711 I  TV: StopStuff(): stopping player
2016-03-12 14:46:17.585714 I  TV: StopStuff() -- end
2016-03-12 14:46:17.585739 I  TV: Changing from WatchingVideo to None
2016-03-12 14:46:17.585749 I  TV: HandleStateChange(0) -- end
2016-03-12 14:46:17.585762 I  TV: Exiting main playback loop.
2016-03-12 14:46:17.585766 I  TV: StartTV -- process events 2 begin
2016-03-12 14:46:17.586032 I  ScreenSaverX11Private: DPMS Reactivated 1
2016-03-12 14:46:17.586278 I  TV: StartTV -- process events 2 end
2016-03-12 14:46:17.586286 I  TV::~TV() -- begin
2016-03-12 14:46:17.597129 I  TV::~TV() -- lock
2016-03-12 14:46:17.597443 I  Player(d): StopPlaying - begin
2016-03-12 14:46:17.597455 I  Player(d): Exited decoder loop.
2016-03-12 14:46:17.597462 I  Player(d): StopPlaying - end
2016-03-12 14:46:17.598533 I  TV::~TV() -- end
2016-03-12 14:46:17.598605 N  Resuming idle timer
2016-03-12 14:46:17.598610 I  TV: StartTV -- end
2016-03-12 14:46:17.598623 N  Resuming idle timer



More information about the mythtv-users mailing list