2014-05-12, 18:07
Environment:
Amazon FireTV sideloaded with XBMC Gotham release (not nightly), no other custom apps installed, stock FireTV other than XBMC sideloaded with standard windows/adb procedure. I do have XBMC configured for MySQL and have a custom keymap for my remote (option #2 on the XBMC/FireTV Wiki Custom Remote Profiles).
Conditions:
This issue only happens after the FireTV/XBMC have been in use for a long time, sometimes it takes a day or more for this bug to occur. Rebooting the FireTV solves the problem (but it creeps back every other day or so), restarting the XBMC (after force stop) does not solve the problem. I've spent a week or two figuring out how to recreate it and making sure it wasn't the pre-release nightly builds I was using, but the same problem happens on the release build.
Issue:
After the FireTV has been on running XBMC for a day or so, a strange bug creeps in. You start a video, the video plays fine, but the time never increments past 00:00 and all "stepforward" functions reset the video back to 00:00. It doesn't happen on ALL videos, if you stop the video with the problem and play a different video, it might work fine, it might not. Going back to the original video always yields the same issue. Rebooting the FireTV solves the problem, you can then play the same video giving you the 00:00 problem just fine and everything is cool for another day or two.
Here is a debug log from when I noticed the problem, I turned on debugging and captured the relevant time segments trying to show where "StepForward" fails:
Now, before you scream "MEDIACODEC DOESN'T WORK!!", I tried this without mediacodec enabled and the same problem crops up, the debug log is just from a time I had it running. I haven't noticed any difference having mediacodec enabled or disabled for this bug to occur. I've also tried disabling mediacodec and then going back to play the file and still have the 00:00 time bug.
I can't tell if this is an XBMC bug or a platform bug, the only way I can make it go away is restarting the FireTV. Forcing the XBMC App to stop and restarting it has no effect once the bug has cropped up so I'm not sure where the issue is. (Unless the FireTV isn't really stopping XBMC...)
Amazon FireTV sideloaded with XBMC Gotham release (not nightly), no other custom apps installed, stock FireTV other than XBMC sideloaded with standard windows/adb procedure. I do have XBMC configured for MySQL and have a custom keymap for my remote (option #2 on the XBMC/FireTV Wiki Custom Remote Profiles).
Conditions:
This issue only happens after the FireTV/XBMC have been in use for a long time, sometimes it takes a day or more for this bug to occur. Rebooting the FireTV solves the problem (but it creeps back every other day or so), restarting the XBMC (after force stop) does not solve the problem. I've spent a week or two figuring out how to recreate it and making sure it wasn't the pre-release nightly builds I was using, but the same problem happens on the release build.
Issue:
After the FireTV has been on running XBMC for a day or so, a strange bug creeps in. You start a video, the video plays fine, but the time never increments past 00:00 and all "stepforward" functions reset the video back to 00:00. It doesn't happen on ALL videos, if you stop the video with the problem and play a different video, it might work fine, it might not. Going back to the original video always yields the same issue. Rebooting the FireTV solves the problem, you can then play the same video giving you the 00:00 problem just fine and everything is cool for another day or two.
Here is a debug log from when I noticed the problem, I turned on debugging and captured the relevant time segments trying to show where "StepForward" fails:
Code:
21:37:23 T:1531109760 DEBUG: Keyboard: scancode: 0x13, sym: 0x0111, unicode: 0x0000, modifier: 0x0
21:37:23 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): up (0xf080) pressed, action is Up
21:37:23 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:23 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:23 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (smb://SERVERNAME/video/)
21:37:23 T:1531109760 DEBUG: ParentPath = [smb://SERVERNAME/]
21:37:23 T:1660608584 DEBUG: int XFILE::CSMBDirectory::OpenDir(const CURL&, CStdString&) - Using authentication url smb://USERNAME:PASSWORD@SERVERNAME/video
21:37:24 T:1689634448 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:25 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:25 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:25 T:1689634448 DEBUG: Thread BackgroundLoader 1689634448 terminating
21:37:25 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (smb://SERVERNAME/video/testvideo/)
21:37:25 T:1531109760 DEBUG: ParentPath = [smb://SERVERNAME/video/]
21:37:25 T:1655044064 DEBUG: int XFILE::CSMBDirectory::OpenDir(const CURL&, CStdString&) - Using authentication url smb://USERNAME:PASSWORD@SERVERNAME/video/testvideo
21:37:25 T:1531109760 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 3 ms for 1 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=2758
21:37:25 T:1726908928 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:25 T:1726908928 DEBUG: Thread BackgroundLoader 1726908928 terminating
21:37:26 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:26 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:26 T:1531109760 DEBUG: virtual bool CGUIWindowVideoBase::OnPlayMedia(int) smb://SERVERNAME/video/testvideo/testvideo.mp4
21:37:26 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
21:37:26 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
21:37:26 T:1531109760 DEBUG: int CVideoDatabase::GetMovieId(const CStdString&) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idMovie from movie where idFile=24615
21:37:26 T:1531109760 DEBUG: int CVideoDatabase::GetEpisodeId(const CStdString&, int, int) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idEpisode from episode where idFile=24615
21:37:26 T:1531109760 DEBUG: int CVideoDatabase::GetMusicVideoId(const CStdString&) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idMVideo from musicvideo where idFile=24615
21:37:26 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
21:37:26 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers(smb://SERVERNAME/video/testvideo/testvideo.mp4)
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtv
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: hdhomerun/myth/mms/udp
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
21:37:26 T:1531109760 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
21:37:26 T:1531109760 DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
21:37:26 T:1531109760 NOTICE: DVDPlayer: Opening: smb://SERVERNAME/video/testvideo/testvideo.mp4
21:37:26 T:1531109760 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
21:37:26 T:1531109760 DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
21:37:26 T:1531109760 DEBUG: LinuxRendererGL: Cleaning up GL resources
21:37:26 T:1689634448 NOTICE: Thread DVDPlayer start, auto delete: false
21:37:26 T:1689634448 NOTICE: Creating InputStream
21:37:26 T:1689634448 DEBUG: CSmbFile::Open - opened video/testvideo/testvideo.mp4, fd=10000
21:37:26 T:1689634448 DEBUG: static void CUtil::ScanForExternalSubtitles(const CStdString&, std::vector<CStdStr<char> >&): Searching for subtitles...
21:37:26 T:1689634448 DEBUG: int XFILE::CSMBDirectory::OpenDir(const CURL&, CStdString&) - Using authentication url smb://USERNAME:PASSWORD@SERVERNAME/video/testvideo
21:37:26 T:1689634448 DEBUG: static void CUtil::ScanForExternalSubtitles(const CStdString&, std::vector<CStdStr<char> >&): END (total time: 51 ms)
21:37:26 T:1689634448 NOTICE: Creating Demuxer
21:37:26 T:1689634448 DEBUG: bool CDVDDemuxFFmpeg::Open(CDVDInputStream*) - probing detected format [mov,mp4,m4a,3gp,3g2,mj2]
21:37:27 T:1531109760 DEBUG: ------ Window Init (DialogBusy.xml) ------
21:37:27 T:1531109760 DEBUG: Window DialogBusy.xml was already loaded
21:37:27 T:1531109760 DEBUG: Alloc resources: 0.09m
21:37:27 T:1689634448 DEBUG: bool CDVDDemuxFFmpeg::Open(CDVDInputStream*) - avformat_find_stream_info starting
21:37:27 T:1689634448 DEBUG: bool CDVDDemuxFFmpeg::Open(CDVDInputStream*) - av_find_stream_info finished
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'smb://SERVERNAME/video/testvideo/testvideo.mp4':
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Metadata:
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: major_brand : isom
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: minor_version : 512
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: compatible_brands: isomiso2avc1mp41
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: encoder : Lavf55.37.102
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Duration: 00:22:23.31, start: 0.000000, bitrate: 6947 kb/s
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p, 1920x1080 [SAR 1:1 DAR 16:9], 6787 kb/s, 29.97 fps, 29.97 tbr, 11988 tbn, 59.94 tbc
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Metadata:
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: handler_name : VideoHandler
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Stream #0:1(und): Audio: aac (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 151 kb/s
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: Metadata:
21:37:27 T:1689634448 INFO: ffmpeg[64B5C690]: handler_name : SoundHandler
21:37:27 T:1689634448 DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
21:37:27 T:1689634448 DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
21:37:27 T:1689634448 NOTICE: Opening video stream: 0 source: 256
21:37:27 T:1689634448 NOTICE: Creating video codec with codec id: 28
21:37:27 T:1689634448 DEBUG: CDVDFactoryCodec: compiled in hardware support: CrystalHD:no AMCodec:yes MediaCodec:yes OpenMax:no libstagefright:yes VDPAU:no VAAPI:no
21:37:27 T:1689634448 INFO: MediaCodec Video Decoder...
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: mediacodec - Opening
21:37:27 T:1689634448 INFO: CBitstreamConverter::Open bitstream to annexb init
21:37:27 T:1689634448 DEBUG: CDVDVideoCodecAndroidMediaCodec::Open m_codecname(OMX.qcom.video.decoder.avc), colorFormat(2141391875)
21:37:27 T:1689634448 DEBUG: CDVDVideoCodecAndroidMediaCodec::Open m_codecname(OMX.qcom.video.decoder.avc), colorFormat(19)
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: amc-h264 - Failed
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: stf-xxxx - Opening
21:37:27 T:1689634448 DEBUG: CDVDVideoCodecStageFright::virtual bool CDVDVideoCodecStageFright::Open(CDVDStreamInfo&, CDVDCodecOptions&) - trying to open, codec(28), profile(100), level(40)
21:37:27 T:1689634448 INFO: CBitstreamConverter::Open bitstream to annexb init
21:37:27 T:1689634448 ERROR: CDVDVideoCodecStageFright::virtual bool CDVDVideoCodecStageFright::Open(CDVDStreamInfo&, CDVDCodecOptions&) - failed to open, codec(28), profile(100), level(40)
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: stf-h264 - Failed
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: - Opening
21:37:27 T:1689634448 NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
21:37:27 T:1689634448 DEBUG: FactoryCodec - Video: ff-h264 - Opened
21:37:27 T:1689634448 NOTICE: Creating video thread
21:37:27 T:1564315200 NOTICE: Thread DVDPlayerVideo start, auto delete: false
21:37:27 T:1564315200 NOTICE: running thread: video_thread
21:37:27 T:1689634448 NOTICE: Opening audio stream: 1 source: 256
21:37:27 T:1689634448 NOTICE: Finding audio codec for: 86018
21:37:27 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:27 T:1689634448 DEBUG: FactoryCodec - Audio: passthrough - Opening
21:37:27 T:1689634448 DEBUG: FactoryCodec - Audio: passthrough - Failed
21:37:27 T:1689634448 DEBUG: FactoryCodec - Audio: FFmpeg - Opening
21:37:27 T:1689634448 DEBUG: FactoryCodec - Audio: FFmpeg - Opened
21:37:27 T:1689634448 NOTICE: Creating audio thread
21:37:27 T:1701017208 NOTICE: Thread DVDPlayerAudio start, auto delete: false
21:37:27 T:1701017208 NOTICE: running thread: CDVDPlayerAudio::Process()
21:37:27 T:1689634448 DEBUG: bool CEdl::ReadEditDecisionLists(const CStdString&, float, int) - Checking for edit decision lists (EDL) on local drive or remote share for: smb://SERVERNAME/video/testvideo/testvideo.mp4
21:37:27 T:1689634448 DEBUG: virtual void CApplication::OnPlayBackStarted() : play state was 1, starting 1
21:37:27 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:27 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(0.000000, 1)
21:37:27 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:27 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(23219.954649, 0)
21:37:27 T:1701017208 NOTICE: Creating audio stream (codec id: 86018, channels: 2, sample rate: 44100, no pass-through)
21:37:27 T:1701017208 DEBUG: CDVDPlayerAudio:: synctype set to 0: clock feedback
21:37:27 T:1531109760 DEBUG: PlayBackRet CApplication::PlayFile(const CFileItem&, bool) : OpenFile succeed, play state 2
21:37:27 T:1531109760 DEBUG: virtual void CApplication::OnPlayBackStarted() : play state was 2, starting 0
21:37:27 T:1564315200 INFO: ffmpeg[5D3D8E40]: [h264] Cannot parallelize deblocking type 1, decoding such frames in sequential order
21:37:27 T:1553528576 DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
21:37:27 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:27 T:1531109760 DEBUG: CGUIInfoManager::SetCurrentMovie(smb://SERVERNAME/video/testvideo/testvideo.mp4)
21:37:27 T:1564315200 NOTICE: fps: 29.970030, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080
21:37:27 T:1564315200 DEBUG: int CDVDPlayerVideo::OutputPicture(const DVDVideoPicture*, double) - change configuration. 1920x1080. framerate: 29.97. format: YV12
21:37:27 T:1564315200 NOTICE: Display resolution DESKTOP : 1920x1080 @ 60.00 - Full Screen (16)
21:37:27 T:1564315200 DEBUG: CXBMCRenderManager::Configure - 3
21:37:27 T:1531109760 DEBUG: int CVideoDatabase::GetMovieId(const CStdString&) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idMovie from movie where idFile=24615
21:37:27 T:1531109760 DEBUG: int CVideoDatabase::GetEpisodeId(const CStdString&, int, int) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idEpisode from episode where idFile=24615
21:37:27 T:1531109760 DEBUG: int CVideoDatabase::GetMusicVideoId(const CStdString&) (smb://SERVERNAME/video/testvideo/testvideo.mp4), query = select idMVideo from musicvideo where idFile=24615
21:37:27 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
21:37:27 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
21:37:27 T:1531109760 DEBUG: Activating window ID: 12005
21:37:27 T:1531109760 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
21:37:27 T:1531109760 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
21:37:27 T:1531109760 DEBUG: Window VideoFullScreen.xml was already loaded
21:37:27 T:1531109760 DEBUG: Alloc resources: 0.98m
21:37:27 T:1531109760 NOTICE: Using GL_TEXTURE_2D
21:37:27 T:1531109760 DEBUG: GL: Requested render method: 0
21:37:27 T:1531109760 DEBUG: GL: BaseYUV2RGBGLSLShader: defines:
#define XBMC_YV12
21:37:27 T:1531109760 NOTICE: GL: Selecting Single Pass YUV 2 RGB shader
21:37:27 T:1531109760 DEBUG: GL: Vertex Shader compilation log:
21:37:27 T:1531109760 DEBUG: GL: Vertex Shader compiled successfully
21:37:27 T:1531109760 DEBUG: GL: Pixel Shader compilation log:
21:37:27 T:1531109760 DEBUG: GL: Fragment Shader compiled successfully
21:37:27 T:1531109760 NOTICE: GL: NPOT texture support detected
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 1080
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 540
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 1080
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 540
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 1080
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 540
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:27 T:1531109760 DEBUG: Previous line repeats 1 times.
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 1920 x 540
21:37:27 T:1531109760 DEBUG: GL: Creating YUV NPOT texture of size 960 x 270
21:37:28 T:1689634448 DEBUG: Previous line repeats 1 times.
21:37:28 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:28 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:28 T:1531109760 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
21:37:28 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:762.940000, should be:46439.909297, error:45676.969297
21:37:28 T:1701017208 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
21:37:28 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:28 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:28 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:28 T:1689634448 DEBUG: demuxer seek to: 30200
21:37:28 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:28 T:1689634448 DEBUG: demuxer seek to: 30200, success
21:37:28 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:28 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:28 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:28 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:28 T:1531109760 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
21:37:28 T:1531109760 DEBUG: Window DialogSeekBar.xml was already loaded
21:37:28 T:1531109760 DEBUG: Alloc resources: 0.40m
21:37:29 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(30964297.630964, 1)
21:37:29 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:29 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(30975419.501134, 0)
21:37:29 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:29 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:29 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:29 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:30964969.017964, should be:30975419.501134, error:10450.483169
21:37:30 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:30 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:30 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:30 T:1689634448 DEBUG: demuxer seek to: 30173
21:37:30 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:30 T:1689634448 DEBUG: demuxer seek to: 30173, success
21:37:30 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:30 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:30 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:30 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:30 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(30964297.630964, 1)
21:37:30 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:30 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(30975419.501134, 0)
21:37:30 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:30 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:30 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:30 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:30964663.841964, should be:30975419.501134, error:10755.659169
21:37:31 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:31 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:31 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:31 T:1689634448 DEBUG: demuxer seek to: 30200
21:37:31 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:31 T:1689634448 DEBUG: demuxer seek to: 30200, success
21:37:31 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:31 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:31 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:31 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:31 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(30964297.630964, 1)
21:37:31 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:31 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(30975419.501134, 0)
21:37:31 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:31 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:31 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:31 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:30964694.359964, should be:30975419.501134, error:10725.141169
21:37:32 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:32 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:32 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:32 T:1689634448 DEBUG: demuxer seek to: 30004
21:37:32 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:32 T:1689634448 DEBUG: demuxer seek to: 30004, success
21:37:32 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:32 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:32 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:32 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:32 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(30964297.630964, 1)
21:37:32 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:32 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(30975419.501134, 0)
21:37:32 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:32 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:32 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:32 T:1689634448 DEBUG: demuxer seek to: 60099
21:37:32 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:32 T:1689634448 DEBUG: demuxer seek to: 60099, success
21:37:32 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:32 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:32 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:32 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:32 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(60994327.660994, 1)
21:37:32 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:32 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(60998820.861678, 0)
21:37:32 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:33 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:33 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:33 T:1689634448 DEBUG: demuxer seek to: 90299
21:37:33 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:33 T:1689634448 DEBUG: demuxer seek to: 90299, success
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:33 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(91024357.691024, 1)
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(91045442.176871, 0)
21:37:33 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:33 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:33 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:33 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:33 T:1689634448 DEBUG: demuxer seek to: 120414
21:37:33 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:33 T:1689634448 DEBUG: demuxer seek to: 120414, success
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:33 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(121054387.721054, 1)
21:37:33 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(121068843.537415, 0)
21:37:33 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:33 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:33 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:33 T:1689634448 DEBUG: demuxer seek to: 150614
21:37:33 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:33 T:1689634448 DEBUG: demuxer seek to: 150614, success
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:33 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(151084417.751084, 1)
21:37:33 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(151092244.897959, 0)
21:37:33 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:33 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:33 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:33 T:1689634448 DEBUG: demuxer seek to: 180723
21:37:33 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:33 T:1689634448 DEBUG: demuxer seek to: 180723, success
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:33 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:33 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:33 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(181114447.781114, 1)
21:37:33 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:33 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(181115646.258503, 0)
21:37:33 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:34 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:34 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:34 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:181114813.992114, should be:181115646.258503, error:832.266389
21:37:34 T:1701017208 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
21:37:36 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity2 - was:183146987.811503, should be:183097093.607604, error:-49894.203899
21:37:36 T:1531109760 DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
21:37:36 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:36 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is StepForward
21:37:36 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 3
21:37:36 T:1689634448 DEBUG: demuxer seek to: 30006
21:37:36 T:1689634448 DEBUG: virtual bool CDVDDemuxFFmpeg::SeekTime(int, bool, double*) - unknown position after seek
21:37:36 T:1689634448 DEBUG: demuxer seek to: 30006, success
21:37:36 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:36 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:37:36 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
21:37:36 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
21:37:36 T:1531109760 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
21:37:36 T:1531109760 DEBUG: Window DialogSeekBar.xml was already loaded
21:37:36 T:1531109760 DEBUG: Alloc resources: 0.21m
21:37:36 T:1564315200 DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(30964297.630964, 1)
21:37:36 T:1564315200 INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
21:37:36 T:1701017208 DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(30975419.501134, 0)
21:37:36 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 1
21:37:36 T:1689634448 DEBUG: CDVDPlayer::HandleMessages - player started 2
21:37:36 T:1689634448 DEBUG: CDVDPlayer::SetCaching - caching state 0
21:37:36 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:30964694.358964, should be:30975419.501134, error:10725.142169
21:37:36 T:1701017208 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
21:37:38 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity2 - was:33019792.059134, should be:32958361.143736, error:-61430.915398
21:37:39 T:1531109760 DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
21:37:41 T:1701017208 DEBUG: CDVDPlayerAudio:: Discontinuity2 - was:35070269.103736, should be:35041149.160232, error:-29119.943503
21:37:41 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:41 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Stop
21:37:41 T:1531109760 NOTICE: CDVDPlayer::CloseFile()
21:37:41 T:1531109760 NOTICE: DVDPlayer: waiting for threads to exit
21:37:41 T:1689634448 NOTICE: CDVDPlayer::OnExit()
21:37:41 T:1689634448 NOTICE: DVDPlayer: closing audio stream
21:37:41 T:1689634448 NOTICE: Closing audio stream
21:37:41 T:1689634448 NOTICE: Waiting for audio thread to exit
21:37:41 T:1701017208 NOTICE: thread end: CDVDPlayerAudio::OnExit()
21:37:41 T:1701017208 DEBUG: Thread DVDPlayerAudio 1701017208 terminating
21:37:41 T:1689634448 NOTICE: Closing audio device
21:37:41 T:1689634448 NOTICE: Deleting audio codec
21:37:41 T:1689634448 NOTICE: DVDPlayer: closing video stream
21:37:41 T:1689634448 NOTICE: Closing video stream
21:37:41 T:1689634448 NOTICE: waiting for video thread to exit
21:37:41 T:1553528576 DEBUG: CActiveAE::DiscardStream - audio stream deleted
21:37:41 T:1553528576 DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
21:37:41 T:1564315200 DEBUG: Previous line repeats 3 times.
21:37:41 T:1564315200 NOTICE: thread end: video_thread
21:37:41 T:1564315200 DEBUG: Thread DVDPlayerVideo 1564315200 terminating
21:37:41 T:1689634448 NOTICE: deleting video codec
21:37:41 T:1689634448 NOTICE: CDVDPlayer::OnExit() deleting demuxer
21:37:41 T:1689634448 NOTICE: CDVDPlayer::OnExit() deleting input stream
21:37:41 T:1689634448 DEBUG: CSmbFile::Close closing fd 10000
21:37:41 T:1689634448 DEBUG: virtual void CApplication::OnPlayBackStopped() : play state was 2, starting 0
21:37:41 T:1689634448 DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
21:37:41 T:1689634448 DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
21:37:41 T:1689634448 DEBUG: Thread DVDPlayer 1689634448 terminating
21:37:41 T:1531109760 NOTICE: DVDPlayer: finished waiting
21:37:41 T:1531109760 DEBUG: LinuxRendererGL: Cleaning up GL resources
21:37:41 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
21:37:41 T:1531109760 DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------
21:37:41 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Activate new
21:37:41 T:1531109760 DEBUG: ------ Window Init (MyVideoNav.xml) ------
21:37:41 T:1531109760 DEBUG: Window MyVideoNav.xml was already loaded
21:37:41 T:1531109760 DEBUG: Alloc resources: 6.77m
21:37:41 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (smb://SERVERNAME/video/testvideo/)
21:37:41 T:1531109760 DEBUG: ParentPath = [smb://SERVERNAME/video/testvideo/]
21:37:41 T:1531109760 DEBUG: int XFILE::CSMBDirectory::OpenDir(const CURL&, CStdString&) - Using authentication url smb://USERNAME:PASSWORD@SERVERNAME/video/testvideo
21:37:41 T:1531109760 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 3 ms for 1 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=2758
21:37:41 T:1691385592 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:41 T:1691385592 DEBUG: Thread BackgroundLoader 1691385592 terminating
21:37:41 T:1531109760 NOTICE: CDVDPlayer::CloseFile()
21:37:41 T:1531109760 NOTICE: DVDPlayer: waiting for threads to exit
21:37:41 T:1531109760 NOTICE: DVDPlayer: finished waiting
21:37:41 T:1531109760 DEBUG: LinuxRendererGL: Cleaning up GL resources
21:37:41 T:1531109760 NOTICE: CDVDPlayer::CloseFile()
21:37:41 T:1531109760 NOTICE: DVDPlayer: waiting for threads to exit
21:37:41 T:1531109760 NOTICE: DVDPlayer: finished waiting
21:37:41 T:1531109760 DEBUG: LinuxRendererGL: Cleaning up GL resources
21:37:41 T:1660608584 DEBUG: virtual bool CSaveFileStateJob::DoWork() - Saving file state for video item smb://SERVERNAME/video/testvideo/testvideo.mp4
21:37:41 T:1660608584 DEBUG: Mysql execute: update files set playCount=NULL,lastPlayed='2014-05-10 21:37:41' where idFile=24615
21:37:41 T:1660608584 DEBUG: Mysql execute: update settings set Deinterlace=1,ViewMode=0,ZoomAmount=1.000000,PixelRatio=1.000000,VerticalShift=0.000000,AudioStream=0,SubtitleStream=-1,SubtitleDelay=0.000000,SubtitlesOn=1,Brightness=50.000000,Contrast=50.000000,Gamma=20.000000,VolumeAmplification=0.000000,AudioDelay=0.000000,OutputToAllSpeakers=0,Sharpness=0.000000,NoiseReduction=0.000000,NonLinStretch=0,PostProcess=0,ScalingMethod=1,DeinterlaceMode=0,ResumeTime=0,Crop=0,CropLeft=0,CropRight=0,CropTop=0,CropBottom=0,StereoMode=0,StereoInvert=0 where idFile=24615
21:37:42 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:42 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:42 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (smb://SERVERNAME/video/)
21:37:42 T:1531109760 DEBUG: ParentPath = [smb://SERVERNAME/]
21:37:42 T:1655044064 DEBUG: int XFILE::CSMBDirectory::OpenDir(const CURL&, CStdString&) - Using authentication url smb://USERNAME:PASSWORD@SERVERNAME/video
21:37:43 T:1531109760 DEBUG: ------ Window Init (DialogBusy.xml) ------
21:37:43 T:1531109760 DEBUG: Window DialogBusy.xml was already loaded
21:37:43 T:1531109760 DEBUG: Alloc resources: 0.06m
21:37:43 T:1655492392 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:43 T:1531109760 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
21:37:46 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:46 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:46 T:1655492392 DEBUG: Thread BackgroundLoader 1655492392 terminating
21:37:46 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (smb://SERVERNAME/)
21:37:46 T:1531109760 DEBUG: ParentPath = [sources://video/]
21:37:46 T:1531109760 DEBUG: Loading items: 10, directory: smb://SERVERNAME/ sort method: 0, ascending: true
21:37:46 T:1666428248 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:46 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:46 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:46 T:1666428248 DEBUG: Thread BackgroundLoader 1666428248 terminating
21:37:46 T:1531109760 DEBUG: CGUIMediaWindow::GetDirectory (sources://video/)
21:37:46 T:1531109760 DEBUG: ParentPath = []
21:37:46 T:1666006984 NOTICE: Thread BackgroundLoader start, auto delete: false
21:37:46 T:1666006984 DEBUG: Thread BackgroundLoader 1666006984 terminating
21:37:47 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:47 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:47 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
21:37:47 T:1531109760 DEBUG: ------ Window Deinit (MyVideoNav.xml) ------
21:37:47 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Activate new
21:37:47 T:1531109760 DEBUG: ------ Window Init (Home.xml) ------
21:37:47 T:1531109760 DEBUG: Window Home.xml was already loaded
21:37:47 T:1531109760 DEBUG: Alloc resources: 5.92m
21:37:47 T:1666309056 DEBUG: CRecentlyAddedJob::UpdateMusic() - Running RecentlyAdded home screen update
21:37:47 T:1666309056 DEBUG: GetRecentlyAddedAlbumSongs() query: SELECT songview.* FROM (SELECT idAlbum FROM albumview ORDER BY idAlbum DESC LIMIT 10) AS recentalbums JOIN songview ON songview.idAlbum=recentalbums.idAlbum
21:37:47 T:1666309056 DEBUG: bool CMusicDatabase::GetRecentlyAddedAlbums(VECALBUMS&, unsigned int) query: select * from albumview where strAlbum != '' order by idAlbum desc limit 10
21:37:47 T:1666309056 DEBUG: CRecentlyAddedJob::UpdateVideos() - Running RecentlyAdded home screen update
21:37:47 T:1666309056 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 39 ms for 10 items query: select * from movieview ORDER BY dateAdded desc, idMovie desc LIMIT 10
21:37:48 T:1666309056 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 49 ms for 10 items query: select * from episodeview ORDER BY dateAdded desc, idEpisode desc LIMIT 10
21:37:48 T:1666309056 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 7 ms for 0 items query: select * from musicvideoview ORDER BY dateAdded desc, idMVideo desc LIMIT 10
21:37:48 T:1666309056 DEBUG: CRecentlyAddedJob::UpdateTotal() - Running RecentlyAdded home screen update
21:37:48 T:1531109760 DEBUG: Keyboard: scancode: 0x15, sym: 0x0114, unicode: 0x0000, modifier: 0x0
21:37:48 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): left (0xf082) pressed, action is Left
21:37:48 T:1531109760 DEBUG: Keyboard: scancode: 0x15, sym: 0x0114, unicode: 0x0000, modifier: 0x0
21:37:48 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): left (0xf082) pressed, action is Left
21:37:49 T:1531109760 DEBUG: Keyboard: scancode: 0x14, sym: 0x0112, unicode: 0x0000, modifier: 0x0
21:37:49 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): down (0xf081) pressed, action is Down
21:37:49 T:1531109760 DEBUG: SECTION:UnloadDelayed(DLL: libmad.so)
21:37:49 T:1531109760 DEBUG: Unloading: libmad.so
21:37:50 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:50 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:50 T:1531109760 DEBUG: Activating window ID: 10004
21:37:50 T:1531109760 DEBUG: ------ Window Deinit (Home.xml) ------
21:37:50 T:1531109760 DEBUG: ------ Window Init (Settings.xml) ------
21:37:50 T:1531109760 DEBUG: Window Settings.xml was already loaded
21:37:50 T:1531109760 DEBUG: Alloc resources: 0.64m
21:37:51 T:1531109760 DEBUG: Keyboard: scancode: 0x13, sym: 0x0111, unicode: 0x0000, modifier: 0x0
21:37:51 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): up (0xf080) pressed, action is Up
21:37:51 T:1531109760 DEBUG: Keyboard: scancode: 0x14, sym: 0x0112, unicode: 0x0000, modifier: 0x0
21:37:51 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): down (0xf081) pressed, action is Down
21:37:52 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:52 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:52 T:1531109760 DEBUG: Activating window ID: 10016
21:37:52 T:1531109760 DEBUG: ------ Window Deinit (Settings.xml) ------
21:37:52 T:1531109760 DEBUG: ------ Window Init (SettingsCategory.xml) ------
21:37:52 T:1531109760 DEBUG: Window SettingsCategory.xml was already loaded
21:37:52 T:1531109760 DEBUG: Alloc resources: 51.57m
21:37:53 T:1531109760 DEBUG: Keyboard: scancode: 0x13, sym: 0x0111, unicode: 0x0000, modifier: 0x0
21:37:53 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): up (0xf080) pressed, action is Up
21:37:53 T:1531109760 DEBUG: Keyboard: scancode: 0x13, sym: 0x0111, unicode: 0x0000, modifier: 0x0
21:37:53 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): up (0xf080) pressed, action is Up
21:37:54 T:1531109760 DEBUG: Keyboard: scancode: 0x16, sym: 0x0113, unicode: 0x0000, modifier: 0x0
21:37:54 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): right (0xf083) pressed, action is Right
21:37:54 T:1531109760 DEBUG: Keyboard: scancode: 0x17, sym: 0x000d, unicode: 0x0000, modifier: 0x0
21:37:54 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): return (0xf00d) pressed, action is Select
21:37:54 T:1531109760 NOTICE: Disabled debug logging due to GUI setting. Level 0.
21:37:54 T:1531109760 NOTICE: Log level changed to 0
21:37:54 T:1531109760 DEBUG: ------ Window Deinit () ------
21:37:55 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:55 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:55 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
21:37:56 T:1531109760 DEBUG: ------ Window Deinit (SettingsCategory.xml) ------
21:37:56 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Activate new
21:37:56 T:1531109760 DEBUG: ------ Window Init (Settings.xml) ------
21:37:56 T:1531109760 DEBUG: Window Settings.xml was already loaded
21:37:56 T:1531109760 DEBUG: Alloc resources: 0.61m
21:37:56 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:56 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:56 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
21:37:56 T:1531109760 DEBUG: ------ Window Deinit (Settings.xml) ------
21:37:56 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Activate new
21:37:56 T:1531109760 DEBUG: ------ Window Init (Home.xml) ------
21:37:56 T:1531109760 DEBUG: Window Home.xml was already loaded
21:37:56 T:1531109760 DEBUG: Alloc resources: 7.35m
21:37:56 T:1660608584 DEBUG: CRecentlyAddedJob::UpdateMusic() - Running RecentlyAdded home screen update
21:37:56 T:1531109760 DEBUG: Keyboard: scancode: 0x04, sym: 0x0008, unicode: 0x0000, modifier: 0x0
21:37:56 T:1531109760 DEBUG: bool CApplication::OnKey(const CKey&): backspace (0xf008) pressed, action is Back
21:37:56 T:1531109760 DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
21:37:56 T:1660608584 DEBUG: GetRecentlyAddedAlbumSongs() query: SELECT songview.* FROM (SELECT idAlbum FROM albumview ORDER BY idAlbum DESC LIMIT 10) AS recentalbums JOIN songview ON songview.idAlbum=recentalbums.idAlbum
21:37:56 T:1660608584 DEBUG: bool CMusicDatabase::GetRecentlyAddedAlbums(VECALBUMS&, unsigned int) query: select * from albumview where strAlbum != '' order by idAlbum desc limit 10
21:37:56 T:1660608584 DEBUG: CRecentlyAddedJob::UpdateVideos() - Running RecentlyAdded home screen update
21:37:56 T:1660608584 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 22 ms for 10 items query: select * from movieview ORDER BY dateAdded desc, idMovie desc LIMIT 10
21:37:57 T:1660608584 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 6 ms for 10 items query: select * from episodeview ORDER BY dateAdded desc, idEpisode desc LIMIT 10
21:37:57 T:1660608584 DEBUG: int CVideoDatabase::RunQuery(const CStdString&) took 4 ms for 0 items query: select * from musicvideoview ORDER BY dateAdded desc, idMVideo desc LIMIT 10
21:37:57 T:1660608584 DEBUG: CRecentlyAddedJob::UpdateTotal() - Running RecentlyAdded home screen update
21:38:11 T:1531109760 DEBUG: SECTION:UnloadDelayed(DLL: libpostproc-52-arm.so)
21:38:11 T:1531109760 DEBUG: Unloading: libpostproc-52-arm.so
21:38:12 T:1531109760 DEBUG: SECTION:UnloadDelayed(DLL: libavfilter-3-arm.so)
21:38:12 T:1531109760 DEBUG: Unloading: libavfilter-3-arm.so
21:38:26 T:1666309056 DEBUG: Thread JobWorker 1666309056 terminating (autodelete)
21:38:26 T:1655044064 DEBUG: Thread JobWorker 1655044064 terminating (autodelete)
21:38:27 T:1660608584 DEBUG: Thread JobWorker 1660608584 terminating (autodelete)
21:38:50 T:1651590392 DEBUG: ### [Qlock] - Delaying 240 secs
21:39:19 T:1531109760 NOTICE: Samba is idle. Closing the remaining connections
21:40:56 T:1531109760 DEBUG: CAnnouncementManager - Announcement: OnScreensaverActivated from xbmc
21:40:56 T:1531109760 DEBUG: GOT ANNOUNCEMENT, type: 4, from xbmc, message OnScreensaverActivated
21:40:56 T:1531109760 DEBUG: ------ Window Init () ------
21:40:56 T:1531109760 DEBUG: Alloc resources: 0.03ms (0.03 ms skin load)
Now, before you scream "MEDIACODEC DOESN'T WORK!!", I tried this without mediacodec enabled and the same problem crops up, the debug log is just from a time I had it running. I haven't noticed any difference having mediacodec enabled or disabled for this bug to occur. I've also tried disabling mediacodec and then going back to play the file and still have the 00:00 time bug.
I can't tell if this is an XBMC bug or a platform bug, the only way I can make it go away is restarting the FireTV. Forcing the XBMC App to stop and restarting it has no effect once the bug has cropped up so I'm not sure where the issue is. (Unless the FireTV isn't really stopping XBMC...)