1. No user installed addons are supported, python or otherwise.
2. No, they really are not supported.
3. They are not coming back
4. Read from 1. again

Any mention of illegal streaming sites, addons or any pirated material will not be tolerated. This is not democracy and any offenders will be banned and posts deleted immediately without warning.

Other than that, we hope you enjoy MrMC so far and we welcome any input and feedback you might have.

Team MrMC.

Audio problems after other apps used..

Any issues that are tvOS specific
Post Reply
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Audio problems after other apps used..

Post by Resnick »

I hope this makes sense and I have supplied the relevant info, rushed post I'm afraid....

Sound issue in brief: Returning to MrMC after using Netflix or Hulu I get audio stutters playing files within MrMc in pretty much all video files I have tried so far. This consists of stutters and clicks while the video appears okay on screen. Restarting the ATV 4K fixes the issue but the problem returns after using aforementioned apps again.

I downloaded Infuse and there are no issues playing the same files within infuse after Hulu / Netflix etc.

Setup: ATV > Sony HTNT5 soundbar with surround speakers > TV all by HDMI cable.
Passthrough in MrMc currently off
ATV settings currently 5.1, reduce loud sounds off, audio mode auto (although I’ve tried many permutations & combinations)

Debug log playing file when sound is working:

Code: Select all

18:30:30 T:6103543808   DEBUG: Previous line repeats 2 times.
18:30:30 T:6103543808   DEBUG: ------ Window Init (DialogBusy.xml) ------
18:30:30 T:6103543808   DEBUG: CPU used = 13/300 percent, App Memory: 207.98 MBs, delta = -36880384 bytes
18:30:30 T:6103543808   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
18:30:30 T:6103543808   DEBUG: RunQuery took 1 ms for 15 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=485
18:30:31 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:32 T:6103543808   DEBUG: Previous line repeats 1 times.
18:30:32 T:6103543808   DEBUG: OnPlayMedia smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:30:32 T:6103543808   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:30:32 T:6103543808   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:30:32 T:6103543808   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:30:32 T:6103543808   DEBUG: Loading settings for smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers(smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv)
18:30:32 T:6103543808   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
18:30:32 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
18:30:32 T:6103543808  NOTICE: CDVDPlayer::Opening: smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:30:32 T:6103543808 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
18:30:32 T:6101823488  NOTICE: Creating InputStream
18:30:32 T:6101823488   DEBUG: CSMBFile::Open - opened homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv, fd=10000
18:30:32 T:6101823488   DEBUG: ScanForExternalSubtitles: Searching for subtitles...
18:30:32 T:6101823488   DEBUG: ScanForExternalSubtitles: END (total time: 3 ms)
18:30:32 T:6101823488  NOTICE: Creating Demuxer
18:30:32 T:6101823488   DEBUG: Open - m_ioContext->max_packet_size(1) = 32768
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 32768
18:30:32 T:6101823488   DEBUG: Open - probing detected format [matroska,webm]
18:30:32 T:6101823488   DEBUG: Open - avformat_find_stream_info starting
18:30:32 T:6101823488   DEBUG: ffmpeg[16BB27000]: [h264] Reinit context to 1920x1088, pix_fmt: yuv420p
18:30:32 T:6101823488   DEBUG: Open - av_find_stream_info finished
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]: Input #0, matroska,webm, smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mk':
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]:   Metadata:
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]:     ENCODER         : Lavf55.19.104
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]:   Duration: 00:00:48.97, start: 0.000000, bitrate: 21791 kb/s
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]:     Stream #0:0(eng): Video: h264 (Constrained Baseline), yuv420p(progressive), 1920x1080 [SAR 1:1 DAR 16:9], 25 fps, 25 tbr, 1k tbn, 50 tbc (default)
18:30:32 T:6101823488    INFO: ffmpeg[16BB27000]:     Stream #0:1: Audio: dts (DTS), 48000 Hz, 5.1(side), fltp, 1536 kb/s
18:30:32 T:6101823488   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
18:30:32 T:6101823488   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
18:30:32 T:6101823488  NOTICE: Opening stream: 0 source: 256
18:30:32 T:6101823488  NOTICE: Creating video codec with codec id: 28
18:30:32 T:6101823488   DEBUG: FactoryCodec - Video: vtb - Opening
18:30:32 T:6101823488  NOTICE: Constructing new format description
18:30:32 T:6101823488   DEBUG: VideoToolBox: opened width(1920), height(1080)
18:30:32 T:6101823488   DEBUG: FactoryCodec - Video: vtb-h264 - Opened
18:30:32 T:6101823488  NOTICE: Creating video thread
18:30:32 T:6101823488  NOTICE: Opening stream: 1 source: 256
18:30:32 T:6106411008   DEBUG: CVideoSyncIos::Setup setting up OSX
18:30:32 T:6101823488  NOTICE: Finding audio codec for: 86020
18:30:32 T:6117306368  NOTICE: running thread: video_thread
18:30:32 T:6106411008   DEBUG: CVideoSyncIos: setting up displaylink
18:30:32 T:6106411008   DEBUG: CVideoSyncIos::GetFps Detected refreshrate: 59.940060 hertz
18:30:32 T:6106411008   DEBUG: CVideoReferenceClock: Detected refreshrate: 59.940 hertz
18:30:32 T:6101823488   DEBUG: FactoryCodec - Audio: FFmpeg - Opening
18:30:32 T:6101823488   DEBUG: FactoryCodec - Audio: FFmpeg - Opened
18:30:32 T:6101823488  NOTICE: Creating audio thread
18:30:32 T:6101823488   DEBUG: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:30:32 T:6117879808  NOTICE: running thread: CDVDPlayerAudio::Process()
18:30:32 T:6101823488   DEBUG: OnPlayBackStarted: play state was 1, starting 1
18:30:32 T:6117306368    INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
18:30:32 T:6103543808   DEBUG: PlayFile: OpenFile succeed, play state 2
18:30:32 T:6103543808   DEBUG: OnPlayBackStarted: play state was 2, starting 0
18:30:32 T:6103543808   DEBUG: CGUIInfoManager::SetCurrentMovie(smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv)
18:30:32 T:6103543808   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:30:32 T:6103543808   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:30:32 T:6103543808   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:30:32 T:6103543808   DEBUG: CTraktServiceJob::Announce OnPlay currentSeconds = 0.000000
18:30:32 T:6116732928   DEBUG: CTraktServiceJob::OnPlay currentTime = 0.000000
18:30:32 T:6116732928   DEBUG: CTraktServices::ReportProgress status = start, percentage = 0.000000
18:30:32 T:6117879808  NOTICE: Creating audio stream (codec id: 86020, channels: 6, sample rate: 48000, no pass-through)
18:30:32 T:6117879808   DEBUG: CDVDPlayerAudio:: synctype set to 1: resample
18:30:32 T:6105264128    INFO: CActiveAESink::OpenSink - initialize sink
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 74068
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 96650
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 126990
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 147792
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 164332
18:30:32 T:6105264128   DEBUG: CActiveAESink::OpenSink - trying to open device DARWINIOS:default
18:30:32 T:6105264128   DEBUG: virtual bool CAESinkDARWINIOS::Initialize(AEAudioFormat &, std::string &): AudioStreamBasicDescription: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz) pcm
18:30:32 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting channels 6
18:30:32 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting samplerate 48000.000000
18:30:32 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting buffer duration to 0.128000
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 183247
18:30:32 T:6117306368   DEBUG: GetPicture - VTBDecoderDecode dts(-4503599627370496.000000), pts(0.000000), old_pts(26920000.000000)
18:30:32 T:6117306368  NOTICE:  fps: 25.000000, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080, colorrange: Limited, colorspace: unknown, colortransfer: unknown
18:30:32 T:6117306368   DEBUG: OutputPicture - change configuration. 1920x1080. framerate: 25.00. format: BGRA
18:30:32 T:6117306368  NOTICE: Display resolution DESKTOP : 3840x2160@ 59.94 - Full Screen (16)
18:30:32 T:6117306368   DEBUG: displayRateSwitch request: refreshRate = 25.00, dynamicRange = SDR
18:30:32 T:6117306368   DEBUG: CXBMCRenderManager::Configure - 4
18:30:32 T:6117306368   DEBUG: CVideoReferenceClock: Clock speed 99.900099%
18:30:32 T:7261201088   DEBUG: CWinSystemIOS::AnnounceOnLostDevice
18:30:32 T:6103543808   DEBUG: Activating window ID: 12005
18:30:32 T:6103543808   DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
18:30:32 T:6103543808   DEBUG: ------ Window Init (VideoFullScreen.xml) ------
18:30:32 T:6103543808   DEBUG: ------ Window Init (DialogSeekBar.xml) ------
18:30:32 T:6103543808  NOTICE: Using GL_TEXTURE_2D
18:30:32 T:6103543808   DEBUG: GL: Requested render method: 0
18:30:32 T:6103543808  NOTICE: GL: Selecting Single Pass YUV 2 RGB shader
18:30:32 T:6103543808   ERROR: GL: BaseYUV2RGBGLSLShader - unsupported format 13
18:30:32 T:6103543808   ERROR: Previous line repeats 1 times.
18:30:32 T:6103543808  NOTICE: GL: NPOT texture support detected
18:30:32 T:6101823488   DEBUG: CDVDPlayer::HandleMessages - player started DVDPLAYER_VIDEO
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 197207
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 207212
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 273892
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 276660
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 340970
18:30:32 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() total latency = 0.072000
18:30:32 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setup audio format: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz)
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() audio route = HDMIOutput
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() sampleRate 48000.000000
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputLatency 0.040000
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() IOBufferDuration 0.032000
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputNumberOfChannels 6
18:30:32 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() maximumOutputNumberOfChannels 6
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: void dumpAVAudioSessionProperties()
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: input count = 0
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: output count = 1
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions : portName, Apple TV
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 1
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:30:32 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 2
18:30:32 T:6101823488   DEBUG: Read - max read bytes = 343717
18:30:33 T:6105264128   DEBUG: CActiveAESink::OpenSink - DARWINIOS Initialized:
18:30:33 T:6105264128   DEBUG:   Output Device : Default
18:30:33 T:6105264128   DEBUG:   Sample Rate   : 48000
18:30:33 T:6105264128   DEBUG:   Sample Format : AE_FMT_FLOAT
18:30:33 T:6105264128   DEBUG:   Channel Count : 6
18:30:33 T:6105264128   DEBUG:   Channel Layout: FL,FC,FR,BL,BR,LFE
18:30:33 T:6105264128   DEBUG:   Frames        : 1024
18:30:33 T:6105264128   DEBUG:   Frame Size    : 24
18:30:33 T:6105264128   DEBUG: CActiveAESink::GenerateNoise - noiseFactor = 0.000010
18:30:33 T:6104690688   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
18:30:33 T:6101823488   DEBUG: Read - max read bytes = 362730
18:30:33 T:6101823488   DEBUG: Read - max read bytes = 394539
18:30:33 T:7261201088  NOTICE: CDVDPlayer: OnLostDevice received
18:30:33 T:7261201088   DEBUG: displayModeSwitchInProgress == YES, refreshRate = 25.00, dynamicRange = SDR
18:30:33 T:6117306368   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_PAUSE: 1
18:30:33 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:33 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:30:33 T:6100103168   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:33 T:6105837568   DEBUG: JSONRPC: Value does not lay between minimum and maximum in type playlistid
18:30:33 T:7261201088   DEBUG: -[MainController displayLinkTick:]: displayRate = 50.000000
18:30:33 T:6100103168   DEBUG: webserver: request received for /jsonrpc?Player.GetItem
18:30:33 T:6100103168   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:30:33 T:6100103168   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:30:33 T:6100103168   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:30:33 T:6100103168   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:33 T:6103543808   DEBUG: CPU used = 13/300 percent, App Memory: 260.50 MBs, delta = 55066624 bytes
18:30:33 T:6117879808   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
18:30:33 T:6117879808   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_PAUSE: 1
18:30:34 T:6100103168   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:34 T:6100103168   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:30:34 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:34 T:6105837568   DEBUG: webserver: request received for /image/image://video@smb%253a%252f%252f192.168.1.143%252fhomes%252fadmin%252fTest%2520Videos%252fdts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv/
18:30:35 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:35 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:35 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:30:35 T:7261201088   DEBUG: CWinSystemIOS::AnnounceOnResetDevice
18:30:35 T:7261201088  NOTICE: CDVDPlayer: OnResetDevice received
18:30:35 T:6104690688   DEBUG: CActiveAE - display reset event
18:30:35 T:7261201088   DEBUG: displayModeSwitchInProgress == DONE, refreshRate = 50.00, dynamicRange = SDR
18:30:35 T:6105264128    INFO: CActiveAESink::OpenSink - initialize sink
18:30:35 T:6105264128   DEBUG: CActiveAESink::OpenSink - trying to open device DARWINIOS:default
18:30:35 T:6105264128   DEBUG: virtual bool CAESinkDARWINIOS::Initialize(AEAudioFormat &, std::string &): AudioStreamBasicDescription: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz) pcm
18:30:35 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting channels 6
18:30:35 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting samplerate 48000.000000
18:30:35 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting buffer duration to 0.128000
18:30:35 T:6106411008   DEBUG: CVideoSyncIos::Cleanup cleaning up OSX
18:30:35 T:6106411008   DEBUG: CVideoSyncIos::Setup setting up OSX
18:30:35 T:6106411008   DEBUG: CVideoSyncIos: setting up displaylink
18:30:35 T:6106411008   DEBUG: CVideoSyncIos::GetFps Detected refreshrate: 50.000000 hertz
18:30:35 T:6106411008   DEBUG: CVideoReferenceClock: Detected refreshrate: 50.000 hertz
18:30:35 T:6103543808   DEBUG: CPU used = 13/300 percent, App Memory: 251.58 MBs, delta = -9355264 bytes
18:30:36 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:36 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:36 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:30:36 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() total latency = 0.072000
18:30:36 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setup audio format: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz)
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() audio route = HDMIOutput
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() sampleRate 48000.000000
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputLatency 0.040000
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() IOBufferDuration 0.032000
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputNumberOfChannels 6
18:30:36 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() maximumOutputNumberOfChannels 6
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: void dumpAVAudioSessionProperties()
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: input count = 0
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: output count = 1
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions : portName, Apple TV
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 1
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:30:36 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 2
18:30:36 T:6105264128   DEBUG: CActiveAESink::OpenSink - DARWINIOS Initialized:
18:30:36 T:6105264128   DEBUG:   Output Device : Default
18:30:36 T:6105264128   DEBUG:   Sample Rate   : 48000
18:30:36 T:6105264128   DEBUG:   Sample Format : AE_FMT_FLOAT
18:30:36 T:6105264128   DEBUG:   Channel Count : 6
18:30:36 T:6105264128   DEBUG:   Channel Layout: FL,FC,FR,BL,BR,LFE
18:30:36 T:6105264128   DEBUG:   Frames        : 1024
18:30:36 T:6105264128   DEBUG:   Frame Size    : 24
18:30:36 T:6105264128   DEBUG: CActiveAESink::GenerateNoise - noiseFactor = 0.000010
18:30:36 T:6104690688   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
18:30:37 T:6105837568   DEBUG: Previous line repeats 3 times.
18:30:37 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:37 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:37 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:30:38 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:30:38 T:6105837568   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:30:38 T:6105837568   DEBUG: webserver: request received for /jsonrpc?System.IsLite
18:30:38 T:6105837568   DEBUG: webserver: request received for /vfs%2Fspecial%3A%2F%2Flogs%2Fmrmc.log?1530167433213


Debug log playing same file with sound problem (ie after playing a file in Netflix):

Code: Select all

18:33:38 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:40 T:6103543808   DEBUG: Previous line repeats 1 times.
18:33:40 T:6103543808   DEBUG: CPU used = 12/300 percent, App Memory: 240.92 MBs, delta = 16334848 bytes
18:33:40 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:42 T:6103543808   DEBUG: Previous line repeats 2 times.
18:33:42 T:6103543808   DEBUG: CPU used = 12/300 percent, App Memory: 240.73 MBs, delta = -196608 bytes
18:33:43 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:43 T:6103543808   DEBUG: RunQuery took 1 ms for 15 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=485
18:33:44 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:45 T:6103543808   DEBUG: Previous line repeats 1 times.
18:33:45 T:6103543808   DEBUG: CPU used = 9/300 percent, App Memory: 239.86 MBs, delta = -917504 bytes
18:33:46 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:46 T:6103543808   DEBUG: OnPlayMedia smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:33:46 T:6103543808   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:33:46 T:6103543808   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:33:46 T:6103543808   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:33:46 T:6103543808   DEBUG: Loading settings for smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers(smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv)
18:33:46 T:6103543808   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
18:33:46 T:6103543808   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
18:33:46 T:6103543808  NOTICE: CDVDPlayer::Opening: smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:33:46 T:6103543808 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
18:33:46 T:6100676608  NOTICE: Creating InputStream
18:33:46 T:6100676608   DEBUG: CSMBFile::Open - opened homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv, fd=10000
18:33:46 T:6100676608   DEBUG: ScanForExternalSubtitles: Searching for subtitles...
18:33:46 T:6100676608   DEBUG: ScanForExternalSubtitles: END (total time: 3 ms)
18:33:46 T:6100676608  NOTICE: Creating Demuxer
18:33:46 T:6100676608   DEBUG: Open - m_ioContext->max_packet_size(1) = 32768
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 32768
18:33:46 T:6100676608   DEBUG: Open - probing detected format [matroska,webm]
18:33:46 T:6100676608   DEBUG: Open - avformat_find_stream_info starting
18:33:46 T:6100676608   DEBUG: ffmpeg[16BA0F000]: [h264] Reinit context to 1920x1088, pix_fmt: yuv420p
18:33:46 T:6100676608   DEBUG: Open - av_find_stream_info finished
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]: Input #0, matroska,webm, smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mk':
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]:   Metadata:
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]:     ENCODER         : Lavf55.19.104
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]:   Duration: 00:00:48.97, start: 0.000000, bitrate: 21791 kb/s
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]:     Stream #0:0(eng): Video: h264 (Constrained Baseline), yuv420p(progressive), 1920x1080 [SAR 1:1 DAR 16:9], 25 fps, 25 tbr, 1k tbn, 50 tbc (default)
18:33:46 T:6100676608    INFO: ffmpeg[16BA0F000]:     Stream #0:1: Audio: dts (DTS), 48000 Hz, 5.1(side), fltp, 1536 kb/s
18:33:46 T:6100676608   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
18:33:46 T:6100676608   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
18:33:46 T:6100676608  NOTICE: Opening stream: 0 source: 256
18:33:46 T:6100676608  NOTICE: Creating video codec with codec id: 28
18:33:46 T:6100676608   DEBUG: FactoryCodec - Video: vtb - Opening
18:33:46 T:6100676608  NOTICE: Constructing new format description
18:33:46 T:6100676608   DEBUG: VideoToolBox: opened width(1920), height(1080)
18:33:46 T:6100676608   DEBUG: FactoryCodec - Video: vtb-h264 - Opened
18:33:46 T:6100676608  NOTICE: Creating video thread
18:33:46 T:6100676608  NOTICE: Opening stream: 1 source: 256
18:33:46 T:6104117248   DEBUG: CVideoSyncIos::Setup setting up OSX
18:33:46 T:6100676608  NOTICE: Finding audio codec for: 86020
18:33:46 T:6105837568  NOTICE: running thread: video_thread
18:33:46 T:6104117248   DEBUG: CVideoSyncIos: setting up displaylink
18:33:46 T:6104117248   DEBUG: CVideoSyncIos::GetFps Detected refreshrate: 59.940060 hertz
18:33:46 T:6104117248   DEBUG: CVideoReferenceClock: Detected refreshrate: 59.940 hertz
18:33:46 T:6100676608   DEBUG: FactoryCodec - Audio: FFmpeg - Opening
18:33:46 T:6100676608   DEBUG: FactoryCodec - Audio: FFmpeg - Opened
18:33:46 T:6100676608  NOTICE: Creating audio thread
18:33:46 T:6100676608   DEBUG: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv
18:33:46 T:6106984448  NOTICE: running thread: CDVDPlayerAudio::Process()
18:33:46 T:6100676608   DEBUG: OnPlayBackStarted: play state was 1, starting 1
18:33:46 T:6103543808   DEBUG: PlayFile: OpenFile succeed, play state 2
18:33:46 T:6103543808   DEBUG: OnPlayBackStarted: play state was 2, starting 0
18:33:46 T:6105837568    INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
18:33:46 T:6103543808   DEBUG: CGUIInfoManager::SetCurrentMovie(smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv)
18:33:46 T:6103543808   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:33:46 T:6103543808   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:33:46 T:6103543808   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:33:46 T:6103543808   DEBUG: CTraktServiceJob::Announce OnPlay currentSeconds = 0.000000
18:33:46 T:6101250048   DEBUG: CTraktServiceJob::OnPlay currentTime = 0.000000
18:33:46 T:6101250048   DEBUG: CTraktServices::ReportProgress status = start, percentage = 0.000000
18:33:46 T:6106984448  NOTICE: Creating audio stream (codec id: 86020, channels: 6, sample rate: 48000, no pass-through)
18:33:46 T:6106984448   DEBUG: CDVDPlayerAudio:: synctype set to 1: resample
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 74068
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 96650
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 126990
18:33:46 T:6105264128    INFO: CActiveAESink::OpenSink - initialize sink
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 147792
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 164332
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 183247
18:33:46 T:6105264128   DEBUG: CActiveAESink::OpenSink - trying to open device DARWINIOS:default
18:33:46 T:6105264128   DEBUG: virtual bool CAESinkDARWINIOS::Initialize(AEAudioFormat &, std::string &): AudioStreamBasicDescription: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz) pcm
18:33:46 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting channels 6
18:33:46 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting samplerate 48000.000000
18:33:46 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setting buffer duration to 0.128000
18:33:46 T:6105264128 WARNING: AVAudioSession setActive NO failed: 560030580
18:33:46 T:6105837568   DEBUG: GetPicture - VTBDecoderDecode dts(-4503599627370496.000000), pts(0.000000), old_pts(34560000.000000)
18:33:46 T:6105837568  NOTICE:  fps: 25.000000, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080, colorrange: Limited, colorspace: unknown, colortransfer: unknown
18:33:46 T:6105837568   DEBUG: OutputPicture - change configuration. 1920x1080. framerate: 25.00. format: BGRA
18:33:46 T:6105837568  NOTICE: Display resolution DESKTOP : 3840x2160@ 59.94 - Full Screen (16)
18:33:46 T:6105837568   DEBUG: displayRateSwitch request: refreshRate = 25.00, dynamicRange = SDR
18:33:46 T:6105837568   DEBUG: CXBMCRenderManager::Configure - 4
18:33:46 T:6105837568   DEBUG: CVideoReferenceClock: Clock speed 99.900099%
18:33:46 T:6103543808   DEBUG: Activating window ID: 12005
18:33:46 T:6103543808   DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
18:33:46 T:6103543808   DEBUG: ------ Window Init (VideoFullScreen.xml) ------
18:33:46 T:6103543808   DEBUG: ------ Window Init (DialogSeekBar.xml) ------
18:33:46 T:6103543808  NOTICE: Using GL_TEXTURE_2D
18:33:46 T:6103543808   DEBUG: GL: Requested render method: 0
18:33:46 T:6103543808  NOTICE: GL: Selecting Single Pass YUV 2 RGB shader
18:33:46 T:6103543808   ERROR: GL: BaseYUV2RGBGLSLShader - unsupported format 13
18:33:46 T:6103543808   ERROR: Previous line repeats 1 times.
18:33:46 T:6103543808  NOTICE: GL: NPOT texture support detected
18:33:46 T:6100676608   DEBUG: CDVDPlayer::HandleMessages - player started DVDPLAYER_VIDEO
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 197207
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 207212
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 273892
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 276660
18:33:46 T:6100676608   DEBUG: Read - max read bytes = 340970
18:33:47 T:6100676608   DEBUG: Read - max read bytes = 343717
18:33:47 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() total latency = 0.072000
18:33:47 T:6105264128  NOTICE: bool CAAudioUnitSink::setupAudio() setup audio format: [lpcm] Mixable Interleaved 6 Channel 32-bit Floating Point LE (48000Hz)
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() audio route = HDMIOutput
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() sampleRate 48000.000000
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputLatency 0.040000
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() IOBufferDuration 0.032000
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() outputNumberOfChannels 6
18:33:47 T:6105264128  NOTICE: void dumpAVAudioSessionProperties() maximumOutputNumberOfChannels 6
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: void dumpAVAudioSessionProperties()
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: input count = 0
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: output count = 1
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions : portName, Apple TV
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 1
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: channelLabel, -1
18:33:47 T:6105264128   DEBUG: DumpAudioDescriptions: channelName , Apple TV 2
18:33:47 T:6105264128   DEBUG: CActiveAESink::OpenSink - DARWINIOS Initialized:
18:33:47 T:6105264128   DEBUG:   Output Device : Default
18:33:47 T:6105264128   DEBUG:   Sample Rate   : 48000
18:33:47 T:6105264128   DEBUG:   Sample Format : AE_FMT_FLOAT
18:33:47 T:6105264128   DEBUG:   Channel Count : 6
18:33:47 T:6105264128   DEBUG:   Channel Layout: FL,FC,FR,BL,BR,LFE
18:33:47 T:6105264128   DEBUG:   Frames        : 1024
18:33:47 T:6105264128   DEBUG:   Frame Size    : 24
18:33:47 T:6105264128   DEBUG: CActiveAESink::GenerateNoise - noiseFactor = 0.000010
18:33:47 T:6104690688   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
18:33:47 T:6100676608   DEBUG: Previous line repeats 1 times.
18:33:47 T:6100676608   DEBUG: CDVDPlayer::HandleMessages - player started DVDPLAYER_AUDIO
18:33:47 T:6100676608   DEBUG: CDVDPlayer::Sync - Audio - pts: 299000.000000, cache: 466666.684469, totalcache: 685333.311558
18:33:47 T:6100676608   DEBUG: CDVDPlayer::Sync - Video - pts: 0.000000, cache: 50000.000000, totalcache: 100000.000000
18:33:47 T:6100676608   DEBUG: CDVDPlayer::LogCacheState(HandlePlaySpeed) - CACHESTATE_DONE
18:33:47 T:6106984448   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-167666.684469)
18:33:47 T:6105837568   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-167666.684469)
18:33:47 T:6106984448   DEBUG: CDVDAudio::Resume - resume audio stream
18:33:47 T:6105837568   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 0
18:33:47 T:6104690688   DEBUG: ActiveAE - start sync of audio stream
18:33:47 T:6105837568   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 1
18:33:47 T:6100676608   DEBUG: Read - max read bytes = 362730
18:33:47 T:6100676608   DEBUG: Read - max read bytes = 394539
18:33:47 T:6104690688   DEBUG: ActiveAE::SyncStream - average error of -12.630962, start adjusting
18:33:47 T:6104690688   DEBUG: ActiveAE::SyncStream - average error -0.005962 below threshold of 30.000000
18:33:47 T:7261201088   DEBUG: -[MainController displayLinkTick:]: displayRate = 50.000000
18:33:47 T:6103543808   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
18:33:47 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:47 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:47 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:48 T:6103543808   DEBUG: CPU used = 9/300 percent, App Memory: 252.12 MBs, delta = 12861440 bytes
18:33:48 T:6104690688   DEBUG: ffmpeg[16BDE3000]: [in] tb:1/48000 samplefmt:flt samplerate:48000 chlayout:0x3f
18:33:48 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:48 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:48 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:49 T:6104690688   DEBUG: ffmpeg[16BDE3000]: [in] tb:1/48000 samplefmt:flt samplerate:48000 chlayout:0x3f
18:33:49 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:49 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:49 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:50 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 318.674717 above threshold of 200.000000
18:33:50 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:50 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:50 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 24.674717 below threshold of 30.000000
18:33:50 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:50 T:6103543808   DEBUG: CPU used = 29/300 percent, App Memory: 254.81 MBs, delta = 2818048 bytes
18:33:51 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:51 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:51 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 228.771544 above threshold of 200.000000
18:33:51 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:51 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 18.771544 below threshold of 30.000000
18:33:52 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:52 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:52 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:52 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 228.544094 above threshold of 200.000000
18:33:52 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 18.544094 below threshold of 30.000000
18:33:53 T:6103543808   DEBUG: CPU used = 29/300 percent, App Memory: 257.95 MBs, delta = 3293184 bytes
18:33:53 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:53 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:53 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:54 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 217.675945 above threshold of 200.000000
18:33:54 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 28.675945 below threshold of 30.000000
18:33:54 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:54 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:54 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:55 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 225.321008 above threshold of 200.000000
18:33:55 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 15.321008 below threshold of 30.000000
18:33:55 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:55 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:55 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:56 T:6103543808   DEBUG: CPU used = 34/300 percent, App Memory: 252.28 MBs, delta = -5947392 bytes
18:33:56 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 211.621645 above threshold of 200.000000
18:33:56 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 22.621645 below threshold of 30.000000
18:33:56 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:56 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:56 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:57 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 214.847462 above threshold of 200.000000
18:33:57 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:57 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:57 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 25.847462 below threshold of 30.000000
18:33:58 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:58 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:58 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:58 T:6103543808   DEBUG: CPU used = 34/300 percent, App Memory: 216.88 MBs, delta = -37126144 bytes
18:33:58 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 219.687087 above threshold of 200.000000
18:33:58 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 9.687087 below threshold of 30.000000
18:33:59 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:59 T:6123040768   DEBUG: webserver: request received for /
18:33:59 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:59 T:6123040768   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:59 T:6115012608   DEBUG: webserver: request received for /css/core.css?1.3.57
18:33:59 T:6100103168   DEBUG: webserver: request received for /js/xbmc.launcher.js?v=2.1.0
18:33:59 T:6100103168   DEBUG: webserver: request received for /css/ipad.css?1.0.5
18:33:59 T:6100103168   DEBUG: webserver: request received for /js/jquery-1.8.2.min.js?2.1.0
18:33:59 T:6115012608   DEBUG: webserver: request received for /js/json2.js?2.1.0
18:33:59 T:6108131328   DEBUG: webserver: request received for /js/iscroll-min.js?2.1.0
18:33:59 T:6115586048   DEBUG: webserver: request received for /js/xbmc.core.js?2.1.0
18:33:59 T:6116732928   DEBUG: webserver: request received for /js/xbmc.rpc.js?2.1.0
18:33:59 T:6117306368   DEBUG: webserver: request received for /js/MediaLibrary.js?2.1.0
18:33:59 T:6100103168   DEBUG: webserver: request received for /js/NowPlayingManager.js?2.1.0
18:33:59 T:6115012608   DEBUG: webserver: request received for /js/xbmc.init.js?2.1.0
18:33:59 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Playlist.GetPlaylists
18:33:59 T:6117306368   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:33:59 T:6117306368   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:33:59 T:6117306368   DEBUG: JSONRPC: Value does not lay between minimum and maximum in type playlistid
18:33:59 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:59 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetItem
18:33:59 T:6115012608   DEBUG: GetMovieId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMovie from movie where idFile=849
18:33:59 T:6115012608   DEBUG: GetEpisodeId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idEpisode from episode where idFile=849
18:33:59 T:6115012608   DEBUG: GetMusicVideoId (smb://192.168.1.143/homes/admin/Test Videos/dts_living_world_of_audio_v2_long_core_1080p-thedigitaltheater.mkv), query = select idMVideo from musicvideo where idFile=849
18:33:59 T:6117306368   DEBUG: webserver: request received for /favicon.ico
18:33:59 T:6117306368   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:33:59 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 207.452339 above threshold of 200.000000
18:34:00 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 18.452339 below threshold of 30.000000
18:34:00 T:6117306368   DEBUG: webserver: request received for /jsonrpc?Player.GetActivePlayers
18:34:00 T:6117306368   DEBUG: webserver: request received for /jsonrpc?Playlist.GetItems
18:34:00 T:6115012608   DEBUG: webserver: request received for /jsonrpc?Player.GetProperties
18:34:01 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 211.054179 above threshold of 200.000000
18:34:01 T:6104690688   DEBUG: ActiveAE::SyncStream - average error 22.054179 below threshold of 30.000000
18:34:01 T:6117306368   DEBUG: webserver: request received for /jsonrpc?System.IsLite
18:34:01 T:6117306368   DEBUG: webserver: request received for /vfs%2Fspecial%3A%2F%2Flogs%2Fmrmc.log?153016763604

Any ideas?
Top
User avatar
amet
Team MrMC
Posts: 3787
Joined: 26 Oct 2015, 16:59
Location: Dubai/Novi Sad

Re: Audio problems after other apps used..

Post by amet »

Both full debuglog please on pastebin, just paste the link here
Top
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Re: Audio problems after other apps used..

Post by Resnick »

Thanks amet.

Here is the full log https://pastebin.com/9ZB99zV5. First play is Immediately after a reboot with no problems. I then exited out of MrMC, played a short clip on Netflix and then back to MrMC for second playback of same test file with obvious audio glitches.

TIA.

EDIT: I'll have another go at the log when I get home from work. Looks like it didn't do a full dump.
Top
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Re: Audio problems after other apps used..

Post by Resnick »

Okay, sorry for the early morning log snafu. Here is the full log. Same sequence of events; reboot ATV open MrMC play test file with no problems. Exit MrMC open and play show in Netflix, return to MrMC and play same test file, this time with audio glitches.

https://pastebin.com/xCSPCerF

Many thanks.
Top
User avatar
davilla
Team MrMC
Posts: 4377
Joined: 26 Oct 2015, 17:01

Re: Audio problems after other apps used..

Post by davilla »

odd,

NOTICE: void dumpAVAudioSessionProperties() outputNumberOfChannels 6

NOTICE: void dumpAVAudioSessionProperties() outputNumberOfChannels 2

it's toggling between them. How is your audio path setup ? Using an A/V receiver ?

Normally that indicates how many audio channels your AppleTV sees. And it should not change unless your audio path changes.

I also see
ARNING: AVAudioSession setActive NO failed: 560030580

This should never fail.
Top
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Re: Audio problems after other apps used..

Post by Resnick »

Thanks Davilla. Odd indeed!

Path is ATV 4k- (hdmi) - Sony HT5NT soundbar - (hdmi) - Sony TV arc.

The Same path works with MrMC on my Shield (same cables) and Infuse on the ATV 4k. I switched to Apple due to colour space issues on the Shield.

Any ideas?

edit, just found this, https://stackoverflow.com/questions/122 ... -is-paused.
Top
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Re: Audio problems after other apps used..

Post by Resnick »

So I swapped out my HDMI cables with no changes.

I noticed that if I close MrMC and reopen it without rebooting the sound problem is resolved until I use Hulu / Netflix / Prime video again. I hadn't previously tried closing MrMC as I use a Harmony remote and couldn't figure out how to do it.

Is there anything else I cound try?
Top
User avatar
davilla
Team MrMC
Posts: 4377
Joined: 26 Oct 2015, 17:01

Re: Audio problems after other apps used..

Post by davilla »

I think fixed for next testflight push
Top
Resnick
Posts: 13
Joined: 29 Apr 2018, 22:40

Re: Audio problems after other apps used..

Post by Resnick »

Great news & thanks for the attention.
Top
Post Reply

Return to “tvOS - AppleTV 4/4K”