2013-03-30, 04:45
Hi all,
I noticed earlier today that XBMC 12.1 will not properly transcode DTS to AC3 5.1 for playback on my old Denon AVR-2700 receiver. I get stereo instead and no DD sync light on the receiver.
I rolled back to 12.0 and same problem. I rolled back to 11.0 and DTS to AC3 transcoding worked again.
I have triple-checked the settings. The only radio button selected on the audio settings screen in XBMC is "AC3 Capable Receiver". "HDMI" output is enabled as was confusingly recommended in the wiki here.
My mac mini is older and doesn't have HDMI output, I use a DVI to HDMI adapter for video, and optical out straight to the Denon.
I took a look at the debug logs and it says that XBMC opened a 6 channel, non passthrough audio stream, but my receiver only plays back stereo.
I suspect it's my very old receiver being finicky about the AC3 signal generated by AudioEngine as opposed to the AC3 signal generated by the old XBMC transcode process in 11.0. Any help would be greatly appreciated. I don't want to be stuck on 11.0 forever.
Log excerpt from DTS playback test:
I noticed earlier today that XBMC 12.1 will not properly transcode DTS to AC3 5.1 for playback on my old Denon AVR-2700 receiver. I get stereo instead and no DD sync light on the receiver.
I rolled back to 12.0 and same problem. I rolled back to 11.0 and DTS to AC3 transcoding worked again.
I have triple-checked the settings. The only radio button selected on the audio settings screen in XBMC is "AC3 Capable Receiver". "HDMI" output is enabled as was confusingly recommended in the wiki here.
My mac mini is older and doesn't have HDMI output, I use a DVI to HDMI adapter for video, and optical out straight to the Denon.
I took a look at the debug logs and it says that XBMC opened a 6 channel, non passthrough audio stream, but my receiver only plays back stereo.
I suspect it's my very old receiver being finicky about the AC3 signal generated by AudioEngine as opposed to the AC3 signal generated by the old XBMC transcode process in 11.0. Any help would be greatly appreciated. I don't want to be stuck on 11.0 forever.
Log excerpt from DTS playback test:
Code:
22:27:52 T:2685711680 DEBUG: Keyboard: scancode: 24, sym: 000d, unicode: 000d, modifier: 0
22:27:52 T:2685711680 DEBUG: OnKey: return (f00d) pressed, action is Select
22:27:52 T:2685711680 DEBUG: OnPlayMedia smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv
22:27:52 T:2685711680 DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
22:27:52 T:2685711680 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
22:27:52 T:2685711680 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
22:27:52 T:2685711680 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers(smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv)
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtv
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: hdhomerun/myth/mms/udp
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
22:27:52 T:2685711680 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
22:27:52 T:2685711680 DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
22:27:52 T:2685711680 NOTICE: DVDPlayer: Opening: smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv
22:27:52 T:2685711680 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
22:27:52 T:2685711680 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
22:27:52 T:2685711680 DEBUG: LinuxRendererGL: Cleaning up GL resources
22:27:52 T:2685711680 DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16
22:27:52 T:2957688832 NOTICE: Thread CDVDPlayer start, auto delete: false
22:27:52 T:2957688832 NOTICE: Creating InputStream
22:27:52 T:2957688832 DEBUG: CSmbFile::Open - opened Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv, fd=10000
22:27:52 T:2957688832 DEBUG: ScanForExternalSubtitles: Searching for subtitles...
22:27:52 T:2957688832 DEBUG: OpenDir - Using authentication url smb://r:[email protected]/Video/Movies/Action
22:27:52 T:2685711680 DEBUG: ------ Window Init (DialogBusy.xml) ------
22:27:52 T:2957688832 INFO: ScanForExternalSubtitles: found subtitle file smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.srt
22:27:52 T:2957688832 DEBUG: ScanForExternalSubtitles: END (total time: 199 ms)
22:27:52 T:2957688832 NOTICE: Creating Demuxer
22:27:52 T:2957688832 DEBUG: Open - probing detected format [matroska,webm]
22:27:52 T:2957688832 DEBUG: Open - avformat_find_stream_info starting
22:27:52 T:2957688832 DEBUG: Open - av_find_stream_info finished
22:27:52 T:2957688832 INFO: ffmpeg[B04AC000]: Input #0, matroska,webm, from 'smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv':
22:27:52 T:2957688832 INFO: ffmpeg[B04AC000]: Duration: 02:37:49.46, start: 0.000000, bitrate: 5949 kb/s
22:27:52 T:2957688832 INFO: ffmpeg[B04AC000]: Stream #0:0(eng): Video: h264 (High), yuv420p, 1280x536, SAR 1:1 DAR 160:67, 23.98 fps, 23.98 tbr, 1k tbn, 47.95 tbc (default)
22:27:52 T:2957688832 INFO: ffmpeg[B04AC000]: Stream #0:1: Audio: dts (DTS), 48000 Hz, 5.1(side), s16, 1536 kb/s (default)
22:27:52 T:2957688832 INFO: ffmpeg[B04AC000]: Stream #0:2(eng): Subtitle: text (default)
22:27:52 T:2957688832 NOTICE: Opening video stream: 0 source: 256
22:27:52 T:2957688832 NOTICE: Creating video codec with codec id: 28
22:27:52 T:2957688832 DEBUG: CDVDFactoryCodec: compiled in hardware support: VDADecoder:yes VideoToolBoxDecoder:no CrystalHD:yes OpenMax:no
22:27:52 T:2957688832 DEBUG: FactoryCodec - Video: vda- - Opening
22:27:52 T:2957688832 NOTICE: Open - VDADecoder Codec failed to open, status(-12470), profile(100), level(41)
22:27:52 T:2957688832 DEBUG: FactoryCodec - Video: vda-h264 - Failed
22:27:52 T:2957688832 DEBUG: FactoryCodec - Video: - Opening
22:27:52 T:2957688832 NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
22:27:52 T:2957688832 DEBUG: FactoryCodec - Video: ff-h264 - Opened
22:27:52 T:2957688832 NOTICE: Creating video thread
22:27:52 T:2959818752 NOTICE: Thread CDVDPlayerVideo start, auto delete: false
22:27:52 T:2959818752 NOTICE: running thread: video_thread
22:27:52 T:2957688832 NOTICE: Opening audio stream: 1 source: 256
22:27:52 T:2957688832 NOTICE: Finding audio codec for: 86020
22:27:52 T:2959818752 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: PassthroughFFmpeg - Opening
22:27:52 T:2957688832 DEBUG: Error: Requested setting (audiooutput.passthroughaac) was not found. It must be case-sensitive
22:27:52 T:2957688832 ERROR: CDVDAudioCodecPassthroughFFmpeg::Open - FFmpeg SPDIF muxer does not support this codec
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: PassthroughFFmpeg - Failed
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: passthrough - Opening
22:27:52 T:2957688832 DEBUG: Error: Requested setting (audiooutput.truehdpassthrough) was not found. It must be case-sensitive
22:27:52 T:2957688832 DEBUG: Error: Requested setting (audiooutput.dtshdpassthrough) was not found. It must be case-sensitive
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: passthrough - Failed
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: FFmpeg - Opening
22:27:52 T:2957688832 DEBUG: FactoryCodec - Audio: FFmpeg - Opened
22:27:52 T:2957688832 NOTICE: Creating audio thread
22:27:52 T:2967326720 NOTICE: Thread CDVDPlayerAudio start, auto delete: false
22:27:52 T:2967326720 NOTICE: running thread: CDVDPlayerAudio::Process()
22:27:52 T:2957688832 NOTICE: Opening Subtitle stream: 0 source: 1024
22:27:52 T:2957688832 DEBUG: CSmbFile::Open - opened Video/Movies/Action/DTS Test Video 720p BluRay x264.srt, fd=10001
22:27:52 T:2957688832 DEBUG: CSmbFile::Close closing fd 10001
22:27:52 T:2957688832 DEBUG: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv
22:27:52 T:2957688832 DEBUG: CDVDPlayer::SetCaching - caching state 3
22:27:52 T:2959818752 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
22:27:52 T:2967326720 NOTICE: Creating audio stream (codec id: 86020, channels: 6, sample rate: 48000, no pass-through)
22:27:52 T:2967326720 INFO: CCoreAudioAE::MakeStream - AE_FMT_S16NE, 48000, 48000, FL,FR,FC,LFE,SL,SR
22:27:52 T:2967326720 DEBUG: AERemap: Downmix normalization is enabled
22:27:52 T:2967326720 DEBUG: CCoreAudioAEStream::CCoreAudioAEStream - Converting from AE_FMT_S16NE to AE_FMT_FLOAT
22:27:52 T:2959818752 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(42000.000000, 0)
22:27:52 T:2967326720 DEBUG: CCoreAudioGraph::Open: Mixer Output Format: 6 channels, 48.0 kHz, 32 bits, 4 bytes per frame
22:27:52 T:2959818752 INFO: ffmpeg[B06B4000]: [h264] Cannot parallelize deblocking type 1, decoding such frames in sequential order
22:27:52 T:2685711680 DEBUG: CGUIInfoManager::SetCurrentMovie(smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv)
22:27:52 T:2959818752 NOTICE: fps: 23.976024, pwidth: 1280, pheight: 536, dwidth: 1280, dheight: 536
22:27:52 T:2959818752 DEBUG: OutputPicture - change configuration. 1280x536. framerate: 23.98. format: YV12
22:27:52 T:2685711680 DEBUG: GetMovieId (smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv), query = select idMovie from movie where idFile=6494
22:27:52 T:2685711680 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
22:27:52 T:2685711680 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
22:27:52 T:2685711680 DEBUG: Building didl for object 'smb://r:[email protected]/Video/Movies/Action/DTS Test Video 720p BluRay x264.mkv'
22:27:52 T:2957688832 DEBUG: CDVDPlayer::HandleMessages - player started 1
22:27:52 T:2959818752 WARNING: CRenderManager::Configure - timeout waiting for previous frame
22:27:52 T:2959818752 NOTICE: Display resolution DESKTOP : 1920x1080 @ 60.00 - Full Screen (16)
22:27:52 T:2685711680 DEBUG: Activating window ID: 12005
22:27:52 T:2685711680 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
22:27:52 T:2685711680 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
22:27:52 T:2957688832 DEBUG: CDVDPlayer::SetCaching - caching state 0
22:27:52 T:2967326720 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(10000.000000, 1)
22:27:52 T:2967326720 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:-6990.165667, should be:-6988.869667, error:1.296000
22:27:52 T:2685711680 NOTICE: Using GL_TEXTURE_2D
22:27:52 T:2685711680 DEBUG: GL: Requested render method: 0
22:27:52 T:2685711680 NOTICE: GL: ARB shaders support detected
22:27:52 T:2685711680 DEBUG: GL: YUV2RGBProgressiveShaderARB: loading yuv2rgb_basic_2d.arb
22:27:52 T:2685711680 NOTICE: GL: Selecting Single Pass ARB YUV2RGB shader
22:27:52 T:2685711680 NOTICE: GL: No vertex shader, fixed pipeline in use
22:27:52 T:2685711680 NOTICE: GL: NPOT texture support detected
22:27:52 T:2685711680 NOTICE: GL: Using GL_ARB_pixel_buffer_object
22:27:52 T:2685711680 DEBUG: CCoreAudioAE::GarbageCollect - Acquire CA HAL.
22:27:52 T:2967326720 DEBUG: CDVDPlayerAudio:: synctype set to 0: clock feedback
22:27:52 T:2685711680 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
22:27:52 T:2957688832 DEBUG: CDVDPlayer::HandleMessages - player started 2
22:27:52 T:2967326720 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:103707.414333, should be:241031.907333, error:137324.493000
22:27:57 T:2959818752 DEBUG: CPullupCorrection: detected pattern of length 1: 41708.33, frameduration: 41708.333333
22:27:58 T:2685711680 DEBUG: Keyboard: scancode: 07, sym: 0078, unicode: 0078, modifier: 0
22:27:58 T:2685711680 DEBUG: OnKey: x (f058) pressed, action is Stop
22:27:58 T:2685711680 NOTICE: CDVDPlayer::CloseFile()
22:27:58 T:2685711680 NOTICE: DVDPlayer: waiting for threads to exit
22:27:58 T:2957688832 NOTICE: CDVDPlayer::OnExit()
22:27:58 T:2957688832 NOTICE: DVDPlayer: closing audio stream
22:27:58 T:2957688832 NOTICE: Closing audio stream
22:27:58 T:2957688832 NOTICE: Waiting for audio thread to exit
22:27:58 T:2967326720 NOTICE: thread end: CDVDPlayerAudio::OnExit()
22:27:58 T:2967326720 DEBUG: Thread CDVDPlayerAudio 2967326720 terminating
22:27:58 T:2957688832 NOTICE: Closing audio device
22:27:58 T:2957688832 DEBUG: CCoreAudioAEStream::~CCoreAudioAEStream - Destructed
22:27:58 T:2957688832 NOTICE: Deleting audio codec
22:27:58 T:2957688832 NOTICE: DVDPlayer: closing video stream
22:27:58 T:2957688832 NOTICE: Closing video stream
22:27:58 T:2957688832 NOTICE: waiting for video thread to exit
22:27:58 T:2959818752 NOTICE: thread end: video_thread
22:27:58 T:2959818752 DEBUG: Thread CDVDPlayerVideo 2959818752 terminating
22:27:58 T:2957688832 NOTICE: deleting video codec
22:27:58 T:2957688832 NOTICE: DVDPlayer: closing subtitle stream
22:27:58 T:2957688832 NOTICE: Closing subtitle stream
22:27:58 T:2957688832 NOTICE: CDVDPlayer::OnExit() deleting demuxer
22:27:58 T:2957688832 NOTICE: CDVDPlayer::OnExit() deleting input stream
22:27:58 T:2957688832 DEBUG: CSmbFile::Close closing fd 10000
22:27:58 T:2957688832 DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
22:27:58 T:2957688832 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
22:27:58 T:2957688832 DEBUG: Thread CDVDPlayer 2957688832 terminating
22:27:58 T:2685711680 NOTICE: DVDPlayer: finished waiting
22:27:58 T:2685711680 DEBUG: LinuxRendererGL: Cleaning up GL resources
22:27:58 T:2685711680 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
22:27:58 T:2685711680 DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------
22:27:58 T:2685711680 DEBUG: CGUIWindowManager::PreviousWindow: Activate new
22:27:58 T:2685711680 DEBUG: ------ Window Init (MyVideoNav.xml) ------
22:27:58 T:2685711680 DEBUG: CGUIMediaWindow::GetDirectory (smb://r:[email protected]/Video/Movies/Action/)
22:27:58 T:2685711680 DEBUG: ParentPath = [smb://r:[email protected]/Video/Movies/Action/]
22:27:58 T:2685711680 DEBUG: OpenDir - Using authentication url smb://r:[email protected]/Video/Movies/Action
22:27:58 T:2685711680 DEBUG: RunQuery took 13 ms for 97 items query: select * from movieview WHERE c23=1389
22:27:58 T:2685711680 DEBUG: RunQuery took 1 ms for 97 items query: SELECT files.strFilename, files.playCount, bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files LEFT JOIN bookmark ON files.idFile = bookmark.idFile AND bookmark.type = 1 WHERE files.idPath=1389
22:27:58 T:2957688832 NOTICE: Thread Background Loader start, auto delete: false
22:27:58 T:2957156352 DEBUG: DoWork - trying to extract filestream details from video file smb://r:[email protected]/Video/Movies/Action/Gladiator.1080p.eng.DTS.2.DVD9.disk.2 (2000).TM.mkv
22:27:58 T:2957688832 DEBUG: Thread Background Loader 2957688832 terminating
22:27:58 T:2957688832 NOTICE: Thread Background Loader start, auto delete: false
22:27:58 T:2957688832 DEBUG: Thread Background Loader 2957688832 terminating
22:27:58 T:2957156352 DEBUG: DoWork - trying to extract filestream details from video file smb://r:[email protected]/Video/Movies/Action/Gladiator.1080p.eng.DTS.2.DVD9.disk.2 (2000).TM.mkv
22:27:58 T:2956017664 DEBUG: OpenDir - Using authentication url smb://192.168.0.5/Video/Movies/Action/extrafanart
22:27:58 T:2956017664 ERROR: SMBDirectory->GetDirectory: Unable to open directory : 'smb://192.168.0.5/Video/Movies/Action/extrafanart'
unix_err:'d' error : 'Permission denied'
22:27:58 T:2956017664 ERROR: GetDirectory - Error getting smb://192.168.0.5/Video/Movies/Action/extrafanart/
22:27:58 T:2953850880 DEBUG: OpenDir - Using authentication url smb://192.168.0.5/Video/Movies/Action/extrafanart
22:27:58 T:2953850880 ERROR: SMBDirectory->GetDirectory: Unable to open directory : 'smb://192.168.0.5/Video/Movies/Action/extrafanart'
unix_err:'d' error : 'Permission denied'
22:27:58 T:2953850880 ERROR: GetDirectory - Error getting smb://192.168.0.5/Video/Movies/Action/extrafanart/
22:27:58 T:2957156352 DEBUG: OpenDir - Using authentication url smb://192.168.0.5/Video/Movies/Action/extrathumbs
22:27:58 T:2957156352 ERROR: SMBDirectory->GetDirectory: Unable to open directory : 'smb://192.168.0.5/Video/Movies/Action/extrathumbs'
unix_err:'d' error : 'Permission denied'
22:27:58 T:2957156352 ERROR: GetDirectory - Error getting smb://192.168.0.5/Video/Movies/Action/extrathumbs/
22:27:58 T:2685711680 NOTICE: CDVDPlayer::CloseFile()
22:27:58 T:2685711680 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
22:27:58 T:2685711680 NOTICE: DVDPlayer: waiting for threads to exit
22:27:58 T:2685711680 NOTICE: DVDPlayer: finished waiting
[/code]