Android FireTV Video Time always 00:00 no stepforward
#1
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:

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...)
Reply
#2
I have this same problem. I have both mediacodec and libstagefright turned off and in the hardware fire tv thread, someone mentioned that having only libstagefright turned on, fixed the problem for them
Reply
#3
(2014-05-12, 18:18)DaveNinja Wrote: I have this same problem. I have both mediacodec and libstagefright turned off and in the hardware fire tv thread, someone mentioned that having only libstagefright turned on, fixed the problem for them

Yeah, but that's a 166 pages (and counting) of 20 different topics, I figured I might get more traction opening a new thread specific to the problem.
Reply
#4
turn libstagefright on and mediacodec off, reset fire tv, fixed the problem for me.
Reply
#5
(2014-05-12, 20:15)nrk666 Wrote:
(2014-05-12, 18:18)DaveNinja Wrote: I have this same problem. I have both mediacodec and libstagefright turned off and in the hardware fire tv thread, someone mentioned that having only libstagefright turned on, fixed the problem for them

Yeah, but that's a 166 pages (and counting) of 20 different topics, I figured I might get more traction opening a new thread specific to the problem.

I totally agree. I was glad to see a Fire TV specific post in this section.
Reply
#6
(2014-05-12, 20:24)sams0n Wrote: turn libstagefright on and mediacodec off, reset fire tv, fixed the problem for me.

I thought I had tested this with mediacodec off, but I'll try it again.
Reply
#7
(2014-05-12, 23:06)nrk666 Wrote:
(2014-05-12, 20:24)sams0n Wrote: turn libstagefright on and mediacodec off, reset fire tv, fixed the problem for me.

I thought I had tested this with mediacodec off, but I'll try it again.

So I was able to duplicate this without mediacodec enabled. I disabled mediacodec and rebooted the FireTV and watched some video for a few hours. I then for fun disabled libstagefright but left "Hardware Acceleration" checked which grays out the multiprocessor software decoding. I started playing a 12k bitrate 1080p file, it was dropping frames bad, but that's expected for software decoding and the 00:00 time symptoms were instantly there. If you ignore the struggling processor trying to software decode a 12k bitrate file, the symptoms were almost exact. The decoder being used was ff-h264. If you compare this to the log above where I captured the problem without forcing it, it looks like mediacodec failed as well as libstagefright and it defaulted to ffmpeg/ff-h264.
Reply
#8
I had the same issue. Hard power cycling after turning off mediacodec and leaving libstagefright on seemed to do the trick for me.
I had even gone so far as to uninstall xbmc and reinstall it.

It was only after the hard power cycle that it was fixed.
Reply
#9
+1 I have the same issue as well.

LJ
Reply
#10
+1 - Same issue. I have tried everything in the above thread. Best results so far are from leaving libstagefright on. Still crashes video randomly.

Here's my log: http://xbmclogs.com/show.php?id=208806

Video crashed and skipped to next in playlist 3 times in this log.

EDIT: It appears the error is related to this message:

ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true

Google returns nothing for this error that is FIRE TV specific...
Reply
#11
Yep, confirmed.
ffmpeg decoding of at least mkv + h264 shows this if multi-threaded is not enabled.

Same thing work on Windows, though, so something specific to arm I'd say...

[EDIT] Confirmed to work on Android + x86, so definitely specific to ARM

[EDIT2] Would someone have an Rpi handy to test (as it is ARM, too) ?
Reply
#12
+1 same issue.

All of my 720p MKV h264 files played on the FTV XBMC would not advance the play bar at all. It just stays at 00:00:00, even though the video itself playbacks just fine. Skip ahead/fast forward doesn't quite work right and it doesn't save progress to resume where left off. Skip back and rewind, just goes right back to the start of the file. mp4 files seem to work just fine; the progress bar advances as the file is played, and it remembers to resume where I left off.

Playing the same files in XBMC 13.0 running on a Windows7 PC, the progress is tracked just fine, resume works, ff and rr work. Both the FTV and the Win7 XBMC's look to the same SMB file share on a Windows 2008 server to get these video files.

I've uninstalled XBMC 13.0 from the FTV, and reinstalled via ADB to clear out anything I could have done. I still see the same behavior. I've uninstalled 13.0 and installed 13.1, same behavior.

After learning of this thread, I rebooted the FTV and bam, everything started working again.. I have both mediacodec and libstagefright turned on. I'll turn off mediacodec, reboot, and see if the problem creeps up again.
Reply
#13
@Koying,

I'm running OpenELEC 4.0.4 on my RPi and haven't seen this issue with it, even though I do see in on my AFTV.

I also don't have THIS issue on my RPi, but do on the AFTV.

I'm not sure if they are related or not.
Forum Rules (wiki) | Banned add-ons (wiki) | Wiki (wiki) | Quick start guide (wiki)
Reply
#14
+1 same issue

rebooting the fire TV solved the problem for now, I will check wether this issue resurfaces after some time.
Reply
#15
I have the same issue too. Rebooting the AFTV fixes the problem. No need to mess with the codecs, just unplug the AFTV and plug it back in. Quitting or force killing XBMC and launching it again doesn't help.

I've tried to narrow down the cause a bit but it's really hard to pin down. It's not a particular video. It seems based on time, after a reboot I have a good 7-8 hours of video watching before the next one will exhibit this problem.
Reply

Logout Mark Read Team Forum Stats Members Help
FireTV Video Time always 00:00 no stepforward0