Login at Kodi Home

rykr · 2016-02-14, 21:40

Anyone figure this out. Seeing the same thing here on Jarvis RC3 and latest NPVR

MrReis · 2016-03-28, 17:11

(2016-02-14, 21:40)rykr Wrote: Anyone figure this out. Seeing the same thing here on Jarvis RC3 and latest NPVR

Ditto.

Russell797 · 2016-04-02, 19:02

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.

sub3 · (This post was last modified: 2016-04-02, 20:15 by sub3.)

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..

MrMC · 2016-04-02, 21:16

logs would tell, oh wait, no logs Smile

Russell797 · (This post was last modified: 2016-04-03, 00:00 by Russell797.)

(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.

sub3 · 2016-04-03, 00:31

If you post your debug kodi.log when this problem happens, we can see what it says.

MrReis · (This post was last modified: 2016-05-26, 16:41 by MrReis.)

(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:
35:35 T:9492  NOTICE: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switched to channel 'FOX NEWS HD'

35:35 T:10208   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc

35:35 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop

35:35 T:10208   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc

35:35 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay

35:35 T:10208   DEBUG: UPnP: Building didl for object 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr'

35:35 T:9492  NOTICE: Creating Demuxer

35:35 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------

35:35 T:10076    INFO: XCURL::DllLibCurlGlobal::CheckIdle - Closing session to https://offshoregit.com (easy=0B4B0618, multi=0B143B38)

35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:36 T:3732  NOTICE: Thread FileCache start, auto delete: false

35:36 T:3732    INFO: CFileCache::Process - Hit eof.

35:36 T:3732   DEBUG: Thread FileCache 3732 terminating

35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:36 T:6964  NOTICE: Thread FileCache start, auto delete: false

35:36 T:6964    INFO: CFileCache::Process - Hit eof.

35:36 T:6964   DEBUG: Thread FileCache 6964 terminating

35:36 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:36 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:36 T:9148  NOTICE: Thread FileCache start, auto delete: false

35:36 T:9148    INFO: CFileCache::Process - Hit eof.

35:36 T:9148   DEBUG: Thread FileCache 9148 terminating

35:37 T:9492    INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':

35:37 T:9492    INFO: ffmpeg[2514]:   Duration: N/A, bitrate: N/A

35:37 T:9492    INFO: ffmpeg[2514]:   Program 5030

35:37 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 2

35:37 T:9492   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr)

35:37 T:10076   DEBUG: ------ Window Init (DialogSeekBar.xml) ------

35:38 T:9492   DEBUG: CDVDDemuxFFmpeg::Read() fetching extradata, extradata_size(86)

35:38 T:10076   DEBUG: Keyboard: scancode: 0x20, sym: 0x0064, unicode: 0x0064, modifier: 0x0

35:38 T:10076   DEBUG: CInputManager::OnKey: d (0xf044) pressed, action is Notification(Keypress, You pressed D!, 3)

35:38 T:10076   DEBUG: ------ Window Init (DialogKaiToast.xml) ------

35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:39 T:5676  NOTICE: Thread FileCache start, auto delete: false

35:39 T:5676    INFO: CFileCache::Process - Hit eof.

35:39 T:5676   DEBUG: Thread FileCache 5676 terminating

35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:39 T:6408  NOTICE: Thread FileCache start, auto delete: false

35:39 T:6408    INFO: CFileCache::Process - Hit eof.

35:39 T:6408   DEBUG: Thread FileCache 6408 terminating

35:39 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:39 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:39 T:5088  NOTICE: Thread FileCache start, auto delete: false

35:39 T:5088    INFO: CFileCache::Process - Hit eof.

35:39 T:5088   DEBUG: Thread FileCache 5088 terminating

35:40 T:10076   DEBUG: Keyboard: scancode: 0x0d, sym: 0x003d, unicode: 0x003d, modifier: 0x0

35:40 T:10076   DEBUG: CInputManager::OnKey: equals (0xf03d) pressed, action is ChannelUp

35:40 T:7228   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE

35:40 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 3

35:40 T:9516   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE

35:40 T:9492   DEBUG: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switching to channel 'FOX BUSINESS HD'

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: SwitchChannel(761:FOX BUSINESS HD)

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream(761:FOX BUSINESS HD) (oid=7329)

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream() informing NextPVR of existing channel stream closing

35:40 T:9492   DEBUG: CFileCache::Open - opening <service> using cache

35:40 T:9492   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=channel.stop&sid=e85fb06be41c45759df3899acae2c4d0

35:40 T:4684  NOTICE: Thread FileCache start, auto delete: false

35:40 T:4684    INFO: CFileCache::Process - Hit eof.

35:40 T:4684   DEBUG: Thread FileCache 4684 terminating

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@1

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@2

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: HTTP/1.1 200 OK

                                            Server: NextPVR

                                            Connection: Close

                                            Content-Range: *

                                            Content-Type: video/MP2T

35:40 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: OpenLiveStream()@exit

35:40 T:6976   DEBUG: CSaveFileStateJob::DoWork - Saving file state for video item pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr

35:40 T:9492   DEBUG: Loading settings for pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr

35:40 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------

35:41 T:9492  NOTICE: PVRManager - PVR::CPVRManager::PerformChannelSwitch - switched to channel 'FOX BUSINESS HD'

35:41 T:10208   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc

35:41 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop

35:41 T:10208   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc

35:41 T:10208   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay

35:41 T:10208   DEBUG: UPnP: Building didl for object 'pvr://channels/tv/All TV channels/pvr.nextpvr_7328.pvr'

35:41 T:9492  NOTICE: Creating Demuxer

35:41 T:9492    INFO: ffmpeg[2514]: Input #0, mpegts, from 'pvr://channels/tv/All TV channels/pvr.nextpvr_7327.pvr':

35:41 T:9492    INFO: ffmpeg[2514]:   Duration: N/A, bitrate: N/A

35:41 T:9492    INFO: ffmpeg[2514]:   Program 5109

35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:0[0xf7e]: Video: mpeg2video ([2][0][0][0] / 0x0002), none, 90k tbn

35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:1[0xf7f](eng): Audio: ac3 ([129][0][0][0] / 0x0081), 0 channels

35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:2[0xf80]: Unknown: none ([134][0][0][0] / 0x0086)

35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:3[0xf81]: Unknown: none (ETV1 / 0x31565445)

35:41 T:9492    INFO: ffmpeg[2514]:     Stream #0:4[0xf82]: Unknown: none (ETV1 / 0x31565445)

35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0

35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1

35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(2, ...) -> 2

35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(3, ...) -> 3

35:41 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(4, ...) -> 4

35:41 T:9492  NOTICE: Opening stream: 0 source: 256

35:41 T:9492  NOTICE: Creating video codec with codec id: 2

35:41 T:9492   DEBUG: CDVDFactoryCodec: compiled in hardware support: AMCodec:no MediaCodec:no DXVA:yes iMXVPU:no MMAL:no

35:41 T:9492   DEBUG: FactoryCodec - Video:  - Opening

35:41 T:9492  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: MPEG-2 video

35:41 T:9492   DEBUG: FactoryCodec - Video: ff-mpeg2video - Opened

35:41 T:9492  NOTICE: Opening stream: 1 source: 256

35:41 T:9492  NOTICE: Finding audio codec for: 86019

35:41 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Opening

35:41 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Failed

35:41 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opening

35:41 T:9516   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 291815112

35:41 T:9516  NOTICE: DXVA::CDecoder::Close - closing decoder

35:41 T:9516  NOTICE: DXVA::Close - closing decoder context

35:41 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opened

35:41 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 2

35:41 T:9492   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr)

35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::Read() fetching extradata, extradata_size(86)

35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0

35:42 T:9492  NOTICE: Opening stream: 0 source: 256

35:42 T:9492  NOTICE: Creating video codec with codec id: 2

35:42 T:9492   DEBUG: CDVDFactoryCodec: compiled in hardware support: AMCodec:no MediaCodec:no DXVA:yes iMXVPU:no MMAL:no

35:42 T:9492   DEBUG: FactoryCodec - Video:  - Opening

35:42 T:9492  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: MPEG-2 video

35:42 T:9492   DEBUG: FactoryCodec - Video: ff-mpeg2video - Opened

35:42 T:9516   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(6684059177.777778, 1)

35:42 T:9516  NOTICE: CDVDVideoCodecFFmpeg::GetFormat - Creating DXVA(1280x720)

35:42 T:9516   DEBUG: DXVA - open decoder

35:42 T:9516   DEBUG: DXVA - supports 'MPEG1/2 VLD'

35:42 T:9516   DEBUG: DXVA - supports 'MPEG2 VLD'

35:42 T:9516   DEBUG: DXVA - supports 6F3EC719-3735-42cc-8063-65cc3cb36616

35:42 T:9516   DEBUG: DXVA - supports 'VC-1 VLD 2010'

35:42 T:9516   DEBUG: DXVA - supports 'VC-1 VLD'

35:42 T:9516   DEBUG: DXVA - supports 32FCFE3F-de46-4a49-861b-ac71110649d5

35:42 T:9516   DEBUG: DXVA - supports D79BE8DA-0cf1-4c81-b82a-69a4e236f43d

35:42 T:9516   DEBUG: DXVA - supports F9AACCBB-c2b6-4cfc-8779-5707b1760552

35:42 T:9516   DEBUG: DXVA - supports 'H.264 VLD, no FGT'

35:42 T:9516   DEBUG: DXVA - supports 'HEVC / H.265 variable-length decoder, main'

35:42 T:9516   DEBUG: DXVA - supports EFD64D74-c9e8-41d7-a5e9-e9b0e39fa319

35:42 T:9516   DEBUG: DXVA - supports ED418A9F-010d-4eda-9ae3-9a65358d8d2e

35:42 T:9516   DEBUG: DXVA - supports 9947EC6F-689b-11dc-a320-0019dbbc4184

35:42 T:9516   DEBUG: DXVA - supports 33FCFE41-de46-4a49-861b-ac71110649d5

35:42 T:9516   DEBUG: DXVA - supports 6AFFD11E-1d96-42b1-a215-93a31f09a53d

35:42 T:9516   DEBUG: DXVA - supports 914C84A3-4078-4fa9-984c-e2f262cb5c9c

35:42 T:9516   DEBUG: DXVA - trying 'MPEG2 VLD'

35:42 T:9516   DEBUG: DXVA - source requires 1 references

35:42 T:9516   DEBUG: DXVA - config 0: bitstream type 1

35:42 T:9516   DEBUG: DXVA - allocating 11 surfaces

35:42 T:9492   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1

35:42 T:9492  NOTICE: Opening stream: 1 source: 256

35:42 T:9492  NOTICE: Finding audio codec for: 86019

35:42 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Opening

35:42 T:9492   DEBUG: FactoryCodec - Audio: passthrough - Failed

35:42 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opening

35:42 T:9492   DEBUG: FactoryCodec - Audio: FFmpeg - Opened

35:42 T:7228   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(6683120300.000000, 1)

35:42 T:7228   DEBUG: CDVDPlayerAudio:: synctype set to 0: clock feedback

35:42 T:9492   DEBUG: CDVDPlayer::HandleMessages - player started 1

35:42 T:9516  NOTICE:  fps: 0.000000, pwidth: 1280, pheight: 720, dwidth: 1280, dheight: 720

35:42 T:9516   DEBUG: CDVDPlayerVideo::OutputPicture - change configuration. 1280x720. framerate: 0.00. format: DXVA

35:42 T:9516  NOTICE: D3D: rendering method forced to DXVA processor

35:42 T:9516   DEBUG: DXVA::CProcessorHD::OpenProcessor - processor selected 95F4EDF4-6e03-4cd7-be1b-3075d665aa52.

35:42 T:9516   DEBUG: CWinRenderer::SelectRenderMethod: Selected render method 3: DXVA

35:42 T:9516   DEBUG: CXBMCRenderManager::Configure - 6

35:42 T:10076   DEBUG: created video buffer 0

35:42 T:10076   DEBUG: created video buffer 1

35:42 T:10076   DEBUG: created video buffer 2

35:42 T:10076   DEBUG: created video buffer 3

35:42 T:10076   DEBUG: created video buffer 4

35:42 T:10076   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context

35:42 T:10076   DEBUG: created video buffer 5

35:42 T:10076 WARNING: CWinRenderer::UpdateVideoFilter - chosen scaling method 1 is not supported by renderer

35:42 T:9492   DEBUG: CDVDPlayer::HandleMessages - player started 2

35:42 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:42 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:42 T:6228  NOTICE: Thread FileCache start, auto delete: false

35:42 T:6228    INFO: CFileCache::Process - Hit eof.

35:43 T:6228   DEBUG: Thread FileCache 6228 terminating

35:43 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:43 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:43 T:8764  NOTICE: Thread FileCache start, auto delete: false

35:43 T:8764    INFO: CFileCache::Process - Hit eof.

35:43 T:8764   DEBUG: Thread FileCache 8764 terminating

35:43 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:43 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:43 T:6628  NOTICE: Thread FileCache start, auto delete: false

35:43 T:6628    INFO: CFileCache::Process - Hit eof.

35:43 T:6628   DEBUG: Thread FileCache 6628 terminating

35:43 T:9492   DEBUG: set caching from pvr to done. audio (1) = 21. video (1) = 21

35:43 T:9492   DEBUG: CDVDPlayer::SetCaching - caching state 0

35:43 T:9516   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 0

35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32

35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket duplicate 1 packets of duration 32

35:43 T:9516  NOTICE: Previous line repeats 1 times.

35:43 T:9516   DEBUG: CDVDPlayerVideo::CalcDropRequirement - hurry: 1

35:43 T:7228  NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32

35:44 T:7228   DEBUG: CDVDPlayerAudio::HandleSyncError - average error 3309.925472 below threshold of 50000.000000

35:44 T:10076   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------

35:44 T:10076   DEBUG: Keyboard: scancode: 0x20, sym: 0x0064, unicode: 0x0064, modifier: 0x0

35:44 T:10076   DEBUG: CInputManager::OnKey: d (0xf044) pressed, action is Notification(Keypress, You pressed D!, 3)

35:44 T:10076   DEBUG: ------ Window Init (DialogKaiToast.xml) ------

35:45 T:10076   DEBUG: ------ Window Init (Pointer.xml) ------

35:45 T:10076   DEBUG: ------ Window Init (VideoOSD.xml) ------

35:45 T:10076    INFO: Loading skin file: VideoOSD.xml, load type: KEEP_IN_MEMORY

35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:46 T:4808  NOTICE: Thread FileCache start, auto delete: false

35:46 T:4808    INFO: CFileCache::Process - Hit eof.

35:46 T:4808   DEBUG: Thread FileCache 4808 terminating

35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:46 T:10076   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------

35:46 T:9912  NOTICE: Thread FileCache start, auto delete: false

35:46 T:9912    INFO: CFileCache::Process - Hit eof.

35:46 T:9912   DEBUG: Thread FileCache 9912 terminating

35:46 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:46 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:46 T:8916  NOTICE: Thread FileCache start, auto delete: false

35:46 T:8916    INFO: CFileCache::Process - Hit eof.

35:46 T:8916   DEBUG: Thread FileCache 8916 terminating

35:47 T:9516   DEBUG: CPullupCorrection: detected pattern of length 1: 16683.33, frameduration: 16683.333333

35:48 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick

35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()

35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit

35:48 T:9492  NOTICE: CDVDPlayer::OnExit()

35:48 T:9492  NOTICE: Closing stream player 1

35:48 T:9492  NOTICE: Waiting for audio thread to exit

35:48 T:7228  NOTICE: thread end: CDVDPlayerAudio::OnExit()

35:48 T:9492  NOTICE: Closing audio device

35:48 T:7228   DEBUG: Thread DVDPlayerAudio 7228 terminating

35:48 T:8148   DEBUG: CActiveAE::DiscardStream - audio stream deleted

35:48 T:9492  NOTICE: Deleting audio codec

35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

35:48 T:9492  NOTICE: Closing stream player 2

35:48 T:9492  NOTICE: waiting for video thread to exit

35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

35:48 T:7816    INFO: CActiveAESink::OpenSink - initialize sink

35:48 T:7816   DEBUG: CAESinkDirectSound::Deinitialize: Cleaning up

35:48 T:7816   DEBUG: CActiveAESink::OpenSink - trying to open device DIRECTSOUND:{B5157D03-DB33-4428-940E-DB96CDEA44C4}

35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: Using Window handle: 1706624

35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: secondary buffer created

35:48 T:7816   DEBUG: CAESinkDirectSound::Initialize: Initializing DirectSound with the following parameters:

35:48 T:7816   DEBUG:   Audio Device    : Speakers (SoundMAX Integrated Digital HD Audio)

35:48 T:7816   DEBUG:   Sample Rate     : 44100

35:48 T:7816   DEBUG:   Sample Format   : AE_FMT_FLOAT

35:48 T:7816   DEBUG:   Bits Per Sample : 32

35:48 T:7816   DEBUG:   Valid Bits/Samp : 32

35:48 T:7816   DEBUG:   Channel Count   : 2

35:48 T:7816   DEBUG:   Block Align     : 8

35:48 T:7816   DEBUG:   Avg. Bytes Sec  : 352800

35:48 T:7816   DEBUG:   Samples/Block   : 32

35:48 T:7816   DEBUG:   Format cBSize   : 22

35:48 T:7816   DEBUG:   Channel Layout  : FL,FR

35:48 T:7816   DEBUG:   Channel Mask    : 3

35:48 T:7816   DEBUG:   Frames          : 661

35:48 T:7816   DEBUG:   Frame Samples   : 1322

35:48 T:7816   DEBUG:   Frame Size      : 8

35:48 T:7816   DEBUG: CActiveAESink::OpenSink - DIRECTSOUND Initialized:

35:48 T:7816   DEBUG:   Output Device : Speakers - Speakers (SoundMAX Integrated Digital HD Audio)

35:48 T:7816   DEBUG:   Sample Rate   : 44100

35:48 T:7816   DEBUG:   Sample Format : AE_FMT_FLOAT

35:48 T:7816   DEBUG:   Channel Count : 2

35:48 T:7816   DEBUG:   Channel Layout: FL,FR

35:48 T:7816   DEBUG:   Frames        : 661

35:48 T:7816   DEBUG:   Frame Samples : 1322

35:48 T:7816   DEBUG:   Frame Size    : 8

35:48 T:8148   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

35:48 T:9516  NOTICE: thread end: video_thread

35:48 T:9492  NOTICE: deleting video codec

35:48 T:9492   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 291815112

35:48 T:9516   DEBUG: Thread DVDPlayerVideo 9516 terminating

35:48 T:9492  NOTICE: DXVA::CDecoder::Close - closing decoder

35:48 T:9492  NOTICE: DXVA::Close - closing decoder context

35:48 T:7816   DEBUG: CAESinkDirectSound::CheckPlayStatus: Resuming Playback

35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: CloseLiveStream

35:48 T:6976   DEBUG: CSaveFileStateJob::DoWork - Saving file state for video item pvr://channels/tv/All TV channels/pvr.nextpvr_7329.pvr

35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: Telling backend of live session closure

35:48 T:9492   DEBUG: CFileCache::Open - opening <service> using cache

35:48 T:9492   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=channel.stop&sid=e85fb06be41c45759df3899acae2c4d0

35:48 T:9308  NOTICE: Thread FileCache start, auto delete: false

35:48 T:9308    INFO: CFileCache::Process - Hit eof.

35:48 T:9308   DEBUG: Thread FileCache 9308 terminating

35:48 T:9492   DEBUG: AddOnLog: NextPVR PVR Client: CloseLiveStream@exit

35:48 T:9492   DEBUG: CDVDInputStreamPVRManager::Close - stream closed

35:48 T:9492   DEBUG: CApplication::OnPlayBackStopped: play state was 2, starting 0

35:48 T:9492   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc

35:48 T:9492   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop

35:48 T:9492   DEBUG: Thread DVDPlayer 9492 terminating

35:48 T:10076  NOTICE: DVDPlayer: finished waiting

35:48 T:10076   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context

35:48 T:10076   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate

35:48 T:10076   DEBUG: ------ Window Deinit (VideoOSD.xml) ------

35:48 T:10076   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------

35:48 T:3972  NOTICE: 1Channel: Service: Playback Stopped

35:48 T:3972  NOTICE: 1Channel: Service: Resetting...

35:48 T:10076   DEBUG: CGUIWindowManager::PreviousWindow: Activate new

35:48 T:10076   DEBUG: ------ Window Init (MyPVRChannels.xml) ------

35:48 T:10076   DEBUG: CGUIMediaWindow::GetDirectory (pvr://channels/tv/All TV channels/)

35:48 T:10076   DEBUG:   ParentPath = [pvr://channels/tv/All TV channels/]

35:48 T:10076   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/All TV channels)

35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()

35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit

35:48 T:10076  NOTICE: DVDPlayer: finished waiting

35:48 T:10076  NOTICE: CDVDPlayer::CloseFile()

35:48 T:10076  NOTICE: DVDPlayer: waiting for threads to exit

35:48 T:10076  NOTICE: DVDPlayer: finished waiting

35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:49 T:8424  NOTICE: Thread FileCache start, auto delete: false

35:49 T:8424    INFO: CFileCache::Process - Hit eof.

35:49 T:8424   DEBUG: Thread FileCache 8424 terminating

35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:49 T:5064  NOTICE: Thread FileCache start, auto delete: false

35:49 T:5064    INFO: CFileCache::Process - Hit eof.

35:49 T:5064   DEBUG: Thread FileCache 5064 terminating

35:49 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:49 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:49 T:9536  NOTICE: Thread FileCache start, auto delete: false

35:49 T:9536    INFO: CFileCache::Process - Hit eof.

35:49 T:9536   DEBUG: Thread FileCache 9536 terminating

35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:52 T:9508  NOTICE: Thread FileCache start, auto delete: false

35:52 T:9508    INFO: CFileCache::Process - Hit eof.

35:52 T:9508   DEBUG: Thread FileCache 9508 terminating

35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:52 T:6712  NOTICE: Thread FileCache start, auto delete: false

35:52 T:6712    INFO: CFileCache::Process - Hit eof.

35:52 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick

35:52 T:10076   DEBUG: Activating window ID: 10000

35:52 T:6712   DEBUG: Thread FileCache 6712 terminating

35:52 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:52 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:52 T:10224  NOTICE: Thread FileCache start, auto delete: false

35:52 T:10224    INFO: CFileCache::Process - Hit eof.

35:52 T:10224   DEBUG: Thread FileCache 10224 terminating

35:52 T:10076   DEBUG: ------ Window Deinit (MyPVRChannels.xml) ------

35:52 T:10076   DEBUG: ------ Window Init (Home.xml) ------

35:54 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick

35:54 T:10076   DEBUG: Activating window ID: 10111

35:54 T:10076   DEBUG: ------ Window Init (DialogButtonMenu.xml) ------

35:54 T:10076    INFO: Loading skin file: DialogButtonMenu.xml, load type: KEEP_IN_MEMORY

35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.recurring.list&sid=e85fb06be41c45759df3899acae2c4d0

35:55 T:8736  NOTICE: Thread FileCache start, auto delete: false

35:55 T:8736    INFO: CFileCache::Process - Hit eof.

35:55 T:8736   DEBUG: Thread FileCache 8736 terminating

35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=pending&sid=e85fb06be41c45759df3899acae2c4d0

35:55 T:5892  NOTICE: Thread FileCache start, auto delete: false

35:55 T:5892    INFO: CFileCache::Process - Hit eof.

35:55 T:5892   DEBUG: Thread FileCache 5892 terminating

35:55 T:10148   DEBUG: CFileCache::Open - opening <service> using cache

35:55 T:10148   DEBUG: CurlFile::Open(0B73D318) http://127.0.0.1:8866/service?method=recording.list&filter=ready&sid=e85fb06be41c45759df3899acae2c4d0

35:55 T:3424  NOTICE: Thread FileCache start, auto delete: false

35:55 T:3424    INFO: CFileCache::Process - Hit eof.

35:56 T:3424   DEBUG: Thread FileCache 3424 terminating

35:56 T:10076   DEBUG: CInputManager::ProcessMouse: trying mouse action leftclick

35:56 T:10076   DEBUG: CAnnouncementManager - Announcement: OnQuit from xbmc

35:56 T:10076   DEBUG: GOT ANNOUNCEMENT, type: 8, from xbmc, message OnQuit

sub3 · 2016-04-03, 19:43

(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.

MrReis · (This post was last modified: 2016-04-03, 20:48 by MrReis.)

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?

sub3 · (This post was last modified: 2016-04-03, 21:01 by sub3.)

(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.

MrReis · (This post was last modified: 2016-05-26, 17:09 by MrReis.)

(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.

MrReis · (This post was last modified: 2016-05-26, 17:10 by MrReis.)

(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?"

sub3 · (This post was last modified: 2016-04-04, 02:48 by sub3.)

(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)

MrReis · 2016-04-04, 03:29

(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).