Bug Random channels no longer load in Kodi, only buffer
#16
Anyone figure this out. Seeing the same thing here on Jarvis RC3 and latest NPVR
Reply
#17
(2016-02-14, 21:40)rykr Wrote: Anyone figure this out. Seeing the same thing here on Jarvis RC3 and latest NPVR

Ditto.
Reply
#18
Same issue here. At least two channels (Boston Channel HD 5) and The History Channel (HD) both can be watched from within NextPVR but not from Kodi. Not always, but intermittently.

I have Kodi on both the Windows NextPVR backend and on the Ubuntu front end which feeds my TV. Same issue on both platforms.
Reply
#19
Quote:Same issue here. At least two channels (Boston Channel HD 5) and The History Channel (HD) both can be watched from within NextPVR but not from Kodi. Not always, but intermittently.
Do recordings from those channels play? ie, is it just a live problem?

At this stage I'm assuming it's some kodi playback issue, so nothing much I can do about it from NextPVR..
Reply
#20
logs would tell, oh wait, no logs Smile
MrMC Forums : http://forum.mrmc.tv
Reply
#21
(2016-04-02, 20:12)sub3 Wrote:
Quote:Same issue here. At least two channels (Boston Channel HD 5) and The History Channel (HD) both can be watched from within NextPVR but not from Kodi. Not always, but intermittently.
Do recordings from those channels play? ie, is it just a live problem?

At this stage I'm assuming it's some kodi playback issue, so nothing much I can do about it from NextPVR..

Just the other night I successfully recorded Channel 5. So yes, it seems to be a live TV issue.

This morning, Channel 5 could be watched, but History Channel was still no go. Just check again and they both work.

Using Ceton cable 4 tuner card on back end.
Reply
#22
If you post your debug kodi.log when this problem happens, we can see what it says.
Reply
#23
(2016-04-03, 00:31)sub3 Wrote: If you post your debug kodi.log when this problem happens, we can see what it says.

The following is my KODI-16 debug log of the problem.

A channel that does not display (i.e., Buffering ... 0%) starts at 07:35:35 T:9492 NOTICE:...
A channel that does display correctly starts at 07:35:41 T:9492 NOTICE:...

Also- this problem does not exist with XBMC-13.2

Code:
07:35:35 T:9492  NOTICE: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switched to channel 'FOX NEWS HD'
07:35:35 T:10208   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
07:35:35 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
07:35:35 T:10208   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
07:35:35 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
07:35:35 T:10208   DEBUG: UPnP: Building didl for object 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr'
07:35:35 T:9492  NOTICE: Creating Demuxer
07:35:35 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
07:35:35 T:10076    INFO: XCURL::DllLibCurlGlobal::CheckIdle - Closing session to https://offshoregit.com (easy=0B4B0618, multi=0B143B38)
07:35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:36 T:3732  NOTICE: Thread FileCache start, auto delete: false
07:35:36 T:3732    INFO: CFileCache::Process - Hit eof.
07:35:36 T:3732   DEBUG: Thread FileCache 3732 terminating
07:35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:36 T:6964  NOTICE: Thread FileCache start, auto delete: false
07:35:36 T:6964    INFO: CFileCache::Process - Hit eof.
07:35:36 T:6964   DEBUG: Thread FileCache 6964 terminating
07:35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:36 T:9148  NOTICE: Thread FileCache start, auto delete: false
07:35:36 T:9148    INFO: CFileCache::Process - Hit eof.
07:35:36 T:9148   DEBUG: Thread FileCache 9148 terminating
07:35:37 T:9492    INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:37 T:9492    INFO: ffmpeg[2514]:   Duration: N/A, bitrate: N/A
07:35:37 T:9492    INFO: ffmpeg[2514]:   Program 5030
07:35:37 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 2
07:35:37 T:9492   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr)
07:35:37 T:10076   DEBUG: ------ Window Init (DialogSeekBar.xml) ------
07:35:38 T:9492   DEBUG: CDVDDemuxFFmpeg::Read() fetching extradata, extradata_size(86)
07:35:38 T:10076   DEBUG: Keyboard: scancode: 0x20, sym: 0x0064, unicode: 0x0064, modifier: 0x0
07:35:38 T:10076   DEBUG: CInputManager::OnKey: d (0xf044) pressed, action is Notification(Keypress, You pressed D!, 3)
07:35:38 T:10076   DEBUG: ------ Window Init (DialogKaiToast.xml) ------
07:35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:39 T:5676  NOTICE: Thread FileCache start, auto delete: false
07:35:39 T:5676    INFO: CFileCache::Process - Hit eof.
07:35:39 T:5676   DEBUG: Thread FileCache 5676 terminating
07:35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:39 T:6408  NOTICE: Thread FileCache start, auto delete: false
07:35:39 T:6408    INFO: CFileCache::Process - Hit eof.
07:35:39 T:6408   DEBUG: Thread FileCache 6408 terminating
07:35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:39 T:5088  NOTICE: Thread FileCache start, auto delete: false
07:35:39 T:5088    INFO: CFileCache::Process - Hit eof.
07:35:39 T:5088   DEBUG: Thread FileCache 5088 terminating
07:35:40 T:10076   DEBUG: Keyboard: scancode: 0x0d, sym: 0x003d, unicode: 0x003d, modifier: 0x0
07:35:40 T:10076   DEBUG: CInputManager::OnKey: equals (0xf03d) pressed, action is ChannelUp
07:35:40 T:7228   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
07:35:40 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 3
07:35:40 T:9516   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
07:35:40 T:9492   DEBUG: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switching to channel 'FOX BUSINESS HD'
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: SwitchChannel(761:FOX BUSINESS HD)
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream(761:FOX BUSINESS HD) (oid=7329)
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream() informing NextPVR of existing channel stream closing
07:35:40 T:9492   DEBUG: CFileCache::Open - opening <service> using cache
07:35:40 T:9492   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=channel.stop&sid=e85fb06be41c45759df3899acae2c4d0
07:35:40 T:4684  NOTICE: Thread FileCache start, auto delete: false
07:35:40 T:4684    INFO: CFileCache::Process - Hit eof.
07:35:40 T:4684   DEBUG: Thread FileCache 4684 terminating
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@1
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@2
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: HTTP/1.1 200 OK

                                            Server: NextPVR

                                            Connection: Close

                                            Content-Range: *

                                            Content-Type: video/MP2T
07:35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@exit
07:35:40 T:6976   DEBUG: CSaveFileStateJob::DoWork - Saving file state for video item pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr
07:35:40 T:9492   DEBUG: Loading settings for pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr
07:35:40 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
07:35:41 T:9492  NOTICE: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switched to channel 'FOX BUSINESS HD'
07:35:41 T:10208   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
07:35:41 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
07:35:41 T:10208   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
07:35:41 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
07:35:41 T:10208   DEBUG: UPnP: Building didl for object 'pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr'
07:35:41 T:9492  NOTICE: Creating Demuxer
07:35:41 T:9492    INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:41 T:9492    INFO: ffmpeg[2514]:   Duration: N/A, bitrate: N/A
07:35:41 T:9492    INFO: ffmpeg[2514]:   Program 5109
07:35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:0[0xf7e]: Video: mpeg2video ([2][0][0][0] / 0x0002), none, 90k tbn
07:35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:1[0xf7f](eng): Audio: ac3 ([129][0][0][0] / 0x0081), 0 channels
07:35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:2[0xf80]: Unknown: none ([134][0][0][0] / 0x0086)
07:35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:3[0xf81]: Unknown: none (ETV1 / 0x31565445)
07:35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:4[0xf82]: Unknown: none (ETV1 / 0x31565445)
07:35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
07:35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
07:35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(2, ...) -> 2
07:35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(3, ...) -> 3
07:35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(4, ...) -> 4
07:35:41 T:9492  NOTICE: Opening stream: 0 source: 256
07:35:41 T:9492  NOTICE: Creating video codec with codec id: 2
07:35:41 T:9492   DEBUG: CDVDFactoryCodec: compiled in hardware support: AMCodec:no MediaCodec:no DXVA:yes iMXVPU:no MMAL:no
07:35:41 T:9492   DEBUG: FactoryCodec - Video:  - Opening
07:35:41 T:9492  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: MPEG-2 video
07:35:41 T:9492   DEBUG: FactoryCodec - Video: ff-mpeg2video - Opened
07:35:41 T:9492  NOTICE: Opening stream: 1 source: 256
07:35:41 T:9492  NOTICE: Finding audio codec for: 86019
07:35:41 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Opening
07:35:41 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Failed
07:35:41 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opening
07:35:41 T:9516   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 291815112
07:35:41 T:9516  NOTICE: DXVA::CDecoder::Close - closing decoder
07:35:41 T:9516  NOTICE: DXVA::Close - closing decoder context
07:35:41 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opened
07:35:41 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 2
07:35:41 T:9492   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr)
07:35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::Read() fetching extradata, extradata_size(86)
07:35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
07:35:42 T:9492  NOTICE: Opening stream: 0 source: 256
07:35:42 T:9492  NOTICE: Creating video codec with codec id: 2
07:35:42 T:9492   DEBUG: CDVDFactoryCodec: compiled in hardware support: AMCodec:no MediaCodec:no DXVA:yes iMXVPU:no MMAL:no
07:35:42 T:9492   DEBUG: FactoryCodec - Video:  - Opening
07:35:42 T:9492  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: MPEG-2 video
07:35:42 T:9492   DEBUG: FactoryCodec - Video: ff-mpeg2video - Opened
07:35:42 T:9516   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(6684059177.777778, 1)
07:35:42 T:9516  NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)
07:35:42 T:9516   DEBUG: DXVA - open decoder
07:35:42 T:9516   DEBUG: DXVA - supports 'MPEG1/2 VLD'
07:35:42 T:9516   DEBUG: DXVA - supports 'MPEG2 VLD'
07:35:42 T:9516   DEBUG: DXVA - supports 6F3EC719-3735-42cc-8063-65cc3cb36616
07:35:42 T:9516   DEBUG: DXVA - supports 'VC-1 VLD 2010'
07:35:42 T:9516   DEBUG: DXVA - supports 'VC-1 VLD'
07:35:42 T:9516   DEBUG: DXVA - supports 32FCFE3F-de46-4a49-861b-ac71110649d5
07:35:42 T:9516   DEBUG: DXVA - supports D79BE8DA-0cf1-4c81-b82a-69a4e236f43d
07:35:42 T:9516   DEBUG: DXVA - supports F9AACCBB-c2b6-4cfc-8779-5707b1760552
07:35:42 T:9516   DEBUG: DXVA - supports 'H.264 VLD, no FGT'
07:35:42 T:9516   DEBUG: DXVA - supports 'HEVC / H.265 variable-length decoder, main'
07:35:42 T:9516   DEBUG: DXVA - supports EFD64D74-c9e8-41d7-a5e9-e9b0e39fa319
07:35:42 T:9516   DEBUG: DXVA - supports ED418A9F-010d-4eda-9ae3-9a65358d8d2e
07:35:42 T:9516   DEBUG: DXVA - supports 9947EC6F-689b-11dc-a320-0019dbbc4184
07:35:42 T:9516   DEBUG: DXVA - supports 33FCFE41-de46-4a49-861b-ac71110649d5
07:35:42 T:9516   DEBUG: DXVA - supports 6AFFD11E-1d96-42b1-a215-93a31f09a53d
07:35:42 T:9516   DEBUG: DXVA - supports 914C84A3-4078-4fa9-984c-e2f262cb5c9c
07:35:42 T:9516   DEBUG: DXVA - trying 'MPEG2 VLD'
07:35:42 T:9516   DEBUG: DXVA - source requires 1 references
07:35:42 T:9516   DEBUG: DXVA - config 0: bitstream type 1
07:35:42 T:9516   DEBUG: DXVA - allocating 11 surfaces
07:35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
07:35:42 T:9492  NOTICE: Opening stream: 1 source: 256
07:35:42 T:9492  NOTICE: Finding audio codec for: 86019
07:35:42 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Opening
07:35:42 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Failed
07:35:42 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opening
07:35:42 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opened
07:35:42 T:7228   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(6683120300.000000, 1)
07:35:42 T:7228   DEBUG: CDVDPlayerAudio:: synctype set to 0: clock feedback
07:35:42 T:9492   DEBUG: CDVDPlayer::HandleMessages - player started 1
07:35:42 T:9516  NOTICE:  fps: 0.000000, pwidth: 1280, pheight: 720, dwidth: 1280, dheight: 720
07:35:42 T:9516   DEBUG: CDVDPlayerVideo::OutputPicture - change configuration. 1280x720. framerate: 0.00. format: DXVA
07:35:42 T:9516  NOTICE: D3D: rendering method forced to DXVA processor
07:35:42 T:9516   DEBUG: DXVA::CProcessorHD::OpenProcessor - processor selected 95F4EDF4-6e03-4cd7-be1b-3075d665aa52.
07:35:42 T:9516   DEBUG: CWinRenderer::SelectRenderMethod: Selected render method 3: DXVA
07:35:42 T:9516   DEBUG: CXBMCRenderManager::Configure - 6
07:35:42 T:10076   DEBUG: created video buffer 0
07:35:42 T:10076   DEBUG: created video buffer 1
07:35:42 T:10076   DEBUG: created video buffer 2
07:35:42 T:10076   DEBUG: created video buffer 3
07:35:42 T:10076   DEBUG: created video buffer 4
07:35:42 T:10076   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context
07:35:42 T:10076   DEBUG: created video buffer 5
07:35:42 T:10076 WARNING: CWinRenderer::UpdateVideoFilter - chosen scaling method 1 is not supported by renderer
07:35:42 T:9492   DEBUG: CDVDPlayer::HandleMessages - player started 2
07:35:42 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:42 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:42 T:6228  NOTICE: Thread FileCache start, auto delete: false
07:35:42 T:6228    INFO: CFileCache::Process - Hit eof.
07:35:43 T:6228   DEBUG: Thread FileCache 6228 terminating
07:35:43 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:43 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:43 T:8764  NOTICE: Thread FileCache start, auto delete: false
07:35:43 T:8764    INFO: CFileCache::Process - Hit eof.
07:35:43 T:8764   DEBUG: Thread FileCache 8764 terminating
07:35:43 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:43 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:43 T:6628  NOTICE: Thread FileCache start, auto delete: false
07:35:43 T:6628    INFO: CFileCache::Process - Hit eof.
07:35:43 T:6628   DEBUG: Thread FileCache 6628 terminating
07:35:43 T:9492   DEBUG: set caching from pvr to done. audio (1) = 21. video (1) = 21
07:35:43 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 0
07:35:43 T:9516   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 0
07:35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32
07:35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket duplicate 1 packets of duration 32
07:35:43 T:9516  NOTICE: Previous line repeats 1 times.
07:35:43 T:9516   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 1
07:35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32
07:35:44 T:7228   DEBUG: CDVDPlayerAudio::HandleSyncError - average error 3309.925472 below threshold of 50000.000000
07:35:44 T:10076   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
07:35:44 T:10076   DEBUG: Keyboard: scancode: 0x20, sym: 0x0064, unicode: 0x0064, modifier: 0x0
07:35:44 T:10076   DEBUG: CInputManager::OnKey: d (0xf044) pressed, action is Notification(Keypress, You pressed D!, 3)
07:35:44 T:10076   DEBUG: ------ Window Init (DialogKaiToast.xml) ------
07:35:45 T:10076   DEBUG: ------ Window Init (Pointer.xml) ------
07:35:45 T:10076   DEBUG: ------ Window Init (VideoOSD.xml) ------
07:35:45 T:10076    INFO: Loading skin file: VideoOSD.xml, load type: KEEP_IN_MEMORY
07:35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:46 T:4808  NOTICE: Thread FileCache start, auto delete: false
07:35:46 T:4808    INFO: CFileCache::Process - Hit eof.
07:35:46 T:4808   DEBUG: Thread FileCache 4808 terminating
07:35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:46 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
07:35:46 T:9912  NOTICE: Thread FileCache start, auto delete: false
07:35:46 T:9912    INFO: CFileCache::Process - Hit eof.
07:35:46 T:9912   DEBUG: Thread FileCache 9912 terminating
07:35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:46 T:8916  NOTICE: Thread FileCache start, auto delete: false
07:35:46 T:8916    INFO: CFileCache::Process - Hit eof.
07:35:46 T:8916   DEBUG: Thread FileCache 8916 terminating
07:35:47 T:9516   DEBUG: CPullupCorrection: detected pattern of length 1: 16683.33, frameduration: 16683.333333
07:35:48 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick
07:35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()
07:35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit
07:35:48 T:9492  NOTICE: CDVDPlayer::OnExit()
07:35:48 T:9492  NOTICE: Closing stream player 1
07:35:48 T:9492  NOTICE: Waiting for audio thread to exit
07:35:48 T:7228  NOTICE: thread end: CDVDPlayerAudio::OnExit()
07:35:48 T:9492  NOTICE: Closing audio device
07:35:48 T:7228   DEBUG: Thread DVDPlayerAudio 7228 terminating
07:35:48 T:8148   DEBUG: CActiveAE::DiscardStream - audio stream deleted
07:35:48 T:9492  NOTICE: Deleting audio codec
07:35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
07:35:48 T:9492  NOTICE: Closing stream player 2
07:35:48 T:9492  NOTICE: waiting for video thread to exit
07:35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
07:35:48 T:7816    INFO: CActiveAESink::OpenSink - initialize sink
07:35:48 T:7816   DEBUG: CAESinkDirectSound::Deinitialize: Cleaning up
07:35:48 T:7816   DEBUG: CActiveAESink::OpenSink - trying to open device DIRECTSOUND:{B5157D03-DB33-4428-940E-DB96CDEA44C4}
07:35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: Using Window handle: 1706624
07:35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: secondary buffer created
07:35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: Initializing DirectSound with the following parameters:
07:35:48 T:7816   DEBUG:   Audio Device    : Speakers (SoundMAX Integrated Digital HD Audio)
07:35:48 T:7816   DEBUG:   Sample Rate     : 44100
07:35:48 T:7816   DEBUG:   Sample Format   : AE_FMT_FLOAT
07:35:48 T:7816   DEBUG:   Bits Per Sample : 32
07:35:48 T:7816   DEBUG:   Valid Bits/Samp : 32
07:35:48 T:7816   DEBUG:   Channel Count   : 2
07:35:48 T:7816   DEBUG:   Block Align     : 8
07:35:48 T:7816   DEBUG:   Avg. Bytes Sec  : 352800
07:35:48 T:7816   DEBUG:   Samples/Block   : 32
07:35:48 T:7816   DEBUG:   Format cBSize   : 22
07:35:48 T:7816   DEBUG:   Channel Layout  : FL,FR
07:35:48 T:7816   DEBUG:   Channel Mask    : 3
07:35:48 T:7816   DEBUG:   Frames          : 661
07:35:48 T:7816   DEBUG:   Frame Samples   : 1322
07:35:48 T:7816   DEBUG:   Frame Size      : 8
07:35:48 T:7816   DEBUG: CActiveAESink::OpenSink - DIRECTSOUND Initialized:
07:35:48 T:7816   DEBUG:   Output Device : Speakers - Speakers (SoundMAX Integrated Digital HD Audio)
07:35:48 T:7816   DEBUG:   Sample Rate   : 44100
07:35:48 T:7816   DEBUG:   Sample Format : AE_FMT_FLOAT
07:35:48 T:7816   DEBUG:   Channel Count : 2
07:35:48 T:7816   DEBUG:   Channel Layout: FL,FR
07:35:48 T:7816   DEBUG:   Frames        : 661
07:35:48 T:7816   DEBUG:   Frame Samples : 1322
07:35:48 T:7816   DEBUG:   Frame Size    : 8
07:35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
07:35:48 T:9516  NOTICE: thread end: video_thread
07:35:48 T:9492  NOTICE: deleting video codec
07:35:48 T:9492   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 291815112
07:35:48 T:9516   DEBUG: Thread DVDPlayerVideo 9516 terminating
07:35:48 T:9492  NOTICE: DXVA::CDecoder::Close - closing decoder
07:35:48 T:9492  NOTICE: DXVA::Close - closing decoder context
07:35:48 T:7816   DEBUG: CAESinkDirectSound::CheckPlayStatus: Resuming Playback
07:35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: CloseLiveStream
07:35:48 T:6976   DEBUG: CSaveFileStateJob::DoWork - Saving file state for video item pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr
07:35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: Telling backend of live session closure
07:35:48 T:9492   DEBUG: CFileCache::Open - opening <service> using cache
07:35:48 T:9492   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=channel.stop&sid=e85fb06be41c45759df3899acae2c4d0
07:35:48 T:9308  NOTICE: Thread FileCache start, auto delete: false
07:35:48 T:9308    INFO: CFileCache::Process - Hit eof.
07:35:48 T:9308   DEBUG: Thread FileCache 9308 terminating
07:35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: CloseLiveStream@exit
07:35:48 T:9492   DEBUG: CDVDInputStreamPVRManager::Close - stream closed
07:35:48 T:9492   DEBUG: CApplication::OnPlayBackStopped: play state was 2, starting 0
07:35:48 T:9492   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
07:35:48 T:9492   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
07:35:48 T:9492   DEBUG: Thread DVDPlayer 9492 terminating
07:35:48 T:10076  NOTICE: DVDPlayer: finished waiting
07:35:48 T:10076   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context
07:35:48 T:10076   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate
07:35:48 T:10076   DEBUG: ------ Window Deinit (VideoOSD.xml) ------
07:35:48 T:10076   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------
07:35:48 T:3972  NOTICE: 1Channel: Service: Playback Stopped
07:35:48 T:3972  NOTICE: 1Channel: Service: Resetting...
07:35:48 T:10076   DEBUG: CGUIWindowManager::PreviousWindow: Activate new
07:35:48 T:10076   DEBUG: ------ Window Init (MyPVRChannels.xml) ------
07:35:48 T:10076   DEBUG: CGUIMediaWindow::GetDirectory (pvr://channels/tv/All TV channels/)
07:35:48 T:10076   DEBUG:   ParentPath = [pvr://channels/tv/All TV channels/]
07:35:48 T:10076   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/All TV channels)
07:35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()
07:35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit
07:35:48 T:10076  NOTICE: DVDPlayer: finished waiting
07:35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()
07:35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit
07:35:48 T:10076  NOTICE: DVDPlayer: finished waiting
07:35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:49 T:8424  NOTICE: Thread FileCache start, auto delete: false
07:35:49 T:8424    INFO: CFileCache::Process - Hit eof.
07:35:49 T:8424   DEBUG: Thread FileCache 8424 terminating
07:35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:49 T:5064  NOTICE: Thread FileCache start, auto delete: false
07:35:49 T:5064    INFO: CFileCache::Process - Hit eof.
07:35:49 T:5064   DEBUG: Thread FileCache 5064 terminating
07:35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:49 T:9536  NOTICE: Thread FileCache start, auto delete: false
07:35:49 T:9536    INFO: CFileCache::Process - Hit eof.
07:35:49 T:9536   DEBUG: Thread FileCache 9536 terminating
07:35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:52 T:9508  NOTICE: Thread FileCache start, auto delete: false
07:35:52 T:9508    INFO: CFileCache::Process - Hit eof.
07:35:52 T:9508   DEBUG: Thread FileCache 9508 terminating
07:35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:52 T:6712  NOTICE: Thread FileCache start, auto delete: false
07:35:52 T:6712    INFO: CFileCache::Process - Hit eof.
07:35:52 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick
07:35:52 T:10076   DEBUG: Activating window ID: 10000
07:35:52 T:6712   DEBUG: Thread FileCache 6712 terminating
07:35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:52 T:10224  NOTICE: Thread FileCache start, auto delete: false
07:35:52 T:10224    INFO: CFileCache::Process - Hit eof.
07:35:52 T:10224   DEBUG: Thread FileCache 10224 terminating
07:35:52 T:10076   DEBUG: ------ Window Deinit (MyPVRChannels.xml) ------
07:35:52 T:10076   DEBUG: ------ Window Init (Home.xml) ------
07:35:54 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick
07:35:54 T:10076   DEBUG: Activating window ID: 10111
07:35:54 T:10076   DEBUG: ------ Window Init (DialogButtonMenu.xml) ------
07:35:54 T:10076    INFO: Loading skin file: DialogButtonMenu.xml, load type: KEEP_IN_MEMORY
07:35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0
07:35:55 T:8736  NOTICE: Thread FileCache start, auto delete: false
07:35:55 T:8736    INFO: CFileCache::Process - Hit eof.
07:35:55 T:8736   DEBUG: Thread FileCache 8736 terminating
07:35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0
07:35:55 T:5892  NOTICE: Thread FileCache start, auto delete: false
07:35:55 T:5892    INFO: CFileCache::Process - Hit eof.
07:35:55 T:5892   DEBUG: Thread FileCache 5892 terminating
07:35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache
07:35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0
07:35:55 T:3424  NOTICE: Thread FileCache start, auto delete: false
07:35:55 T:3424    INFO: CFileCache::Process - Hit eof.
07:35:56 T:3424   DEBUG: Thread FileCache 3424 terminating
07:35:56 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick
07:35:56 T:10076   DEBUG: CAnnouncementManager - Announcement: OnQuit from xbmc
07:35:56 T:10076   DEBUG: GOT ANNOUNCEMENT, type: 8, from xbmc, message OnQuit
Reply
#24
(2016-04-03, 17:37)MrReis Wrote:
(2016-04-03, 00:31)sub3 Wrote: If you post your debug kodi.log when this problem happens, we can see what it says.

The following is my KODI-15.2 debug log of the problem.

A channel the does not display (i.e., 0% Buffering) starts at 07:35:35 T:9492 NOTICE:...
A channel that does display correctly starts at 07:35:41 T:9492 NOTICE:...
It looks like for some reason the ffmpeg demuxing components in Kodi are sometimes failing to identify the audio/video streams
Quote: 07:35:37 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:37 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:37 T:9492 INFO: ffmpeg[2514]: Program 5030

If you just try the same channel over and over, stopping it between each attempt, do they all fail, or just some attempts?

Unfortunately I know next to nothing about the internals of Kodi though, so can't offer too much advice. If you were having the problem in NextPVR itself, I'd be better placed to help you through it.

Quote:Also- this problem does not exist with XBMC-13.2
I do remember they made changes post-XBMC13 to help speed up channel changes. It took some logic that spent some time probing the source to find audio/video streams, and replaced it with some other approach. I'm guessing it's something to do with this.
Reply
#25
Thank you for your thoughtful reply.

(2016-04-03, 19:43)sub3 Wrote: If you just try the same channel over and over, stopping it between each attempt, do they all fail, or just some attempts?

I just tried tuning the same channel 25 times (stopping it between each attempt) and all tuning attempts failed.

Are there any other logs I can provide that would give more information to solve this problem?
Reply
#26
(2016-04-03, 20:45)MrReis Wrote: Thank you for your thoughtful reply.

(2016-04-03, 19:43)sub3 Wrote: If you just try the same channel over and over, stopping it between each attempt, do they all fail, or just some attempts?

I just tried tuning the same channel 25 times (stopping it between each attempt) and all tuning attempts failed.
So, a recording made about the same time as these failed live tv attempts (so that the channel has the same characteristics), does that recording play?

Quote:Are there any other logs I can provide that would give more information to solve this problem?
To be honest, I'm really not sure who on the Kodi side could look into this for us. I'm not that involved in Kodi project.
Reply
#27
(2016-04-03, 21:01)sub3 Wrote: So, a recording made about the same time as these failed live tv attempts (so that the channel has the same characteristics), does that recording play?
I have found that when a live TV channel does not display (Buffering ... 0%) I am able to do an instant recording of the same channel that does in fact play correctly.
Reply
#28
(2016-04-03, 19:43)sub3 Wrote: It looks like for some reason the ffmpeg demuxing components in Kodi are sometimes failing to identify the audio/video streams

07:35:37 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:37 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:37 T:9492 INFO: ffmpeg[2514]: Program 5030

The three lines from the log (above) for the channel that does not play correctly (Buffering ... 0%) are the same as the following three lines from the log (below) for the channel that does play correctly.

07:35:41 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:41 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:41 T:9492 INFO: ffmpeg[2514]: Program 5109

Why do you believe "the ffmpeg demuxing components in Kodi are sometimes failing to identify the audio/video streams?"
Reply
#29
(2016-04-04, 01:37)MrReis Wrote: The three lines from the log (above) for the channel that does not display correctly (0% buffering) are the same as the following three lines from the log (below) for the channel that does display correctly.

07:35:41 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:41 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:41 T:9492 INFO: ffmpeg[2514]: Program 5109

Why do you believe "the ffmpeg demuxing components in Kodi are sometimes failing to identify the audio/video streams?"
I was working on the assumption that section of ffmpeg logging was failing to list the streams, so the demux must have failed to identify the streams in the transport stream. It wasn't those specific lines, but rather the absense of the few that I thought should follow it. ie, constrast with this example, where that logging continues for a few more lines, listing the audio/video streams found.
07:35:41 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:41 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:41 T:9492 INFO: ffmpeg[2514]: Program 5109
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:0[0xf7e]: Video: mpeg2video ([2][0][0][0] / 0x0002), none, 90k tbn
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:1[0xf7f](eng): Audio: ac3 ([129][0][0][0] / 0x0081), 0 channels
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:2[0xf80]: Unknown: none ([134][0][0][0] / 0x0086)
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:3[0xf81]: Unknown: none (ETV1 / 0x31565445)
Reply
#30
(2016-04-04, 02:46)sub3 Wrote:
(2016-04-04, 01:37)MrReis Wrote: Why do you believe "the ffmpeg demuxing components in Kodi are sometimes failing to identify the audio/video streams?"
I was working on the assumption that section of ffmpeg logging was failing to list the streams, so the demux must have failed to identify the streams in the transport stream. It wasn't those specific lines, but rather the absense of the few that I thought should follow it. ie, constrast with this example, where that logging continues for a few more lines, listing the audio/video streams found.
07:35:41 T:9492 INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':
07:35:41 T:9492 INFO: ffmpeg[2514]: Duration: N/A, bitrate: N/A
07:35:41 T:9492 INFO: ffmpeg[2514]: Program 5109
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:0[0xf7e]: Video: mpeg2video ([2][0][0][0] / 0x0002), none, 90k tbn
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:1[0xf7f](eng): Audio: ac3 ([129][0][0][0] / 0x0081), 0 channels
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:2[0xf80]: Unknown: none ([134][0][0][0] / 0x0086)
07:35:41 T:9492 INFO: ffmpeg[2514]: Stream #0:3[0xf81]: Unknown: none (ETV1 / 0x31565445)

Oh. Yes, I see the difference now in the log following the lines that you quoted.

The two odd things about this problem are (1) there is no obvious reason why some channels don't display correctly (0% buffering) - at least it's not the signal strength, signal quality or network rate and (2) the channels that don't display correctly change with time (usually days).
Reply

Logout Mark Read Team Forum Stats Members Help
Random channels no longer load in Kodi, only buffer0
This forum uses Lukasz Tkacz MyBB addons.