Login at Kodi Home

sharky1337 · (This post was last modified: 2017-07-06, 22:33 by sharky1337.)

Hello ,

I'm trying to use vnsi plugin with kodi17 on my mac.

If a zap to a program called ZDF HD , Kodi does show one or two pictures from that channel sound work well but than the stream stops and kodi crashes.

Debug log got a lot of these errors.

root@tv-server:~# vdr -V
vdr (2.2.0/2.2.0) - The Video Disk Recorder
vnsiserver (1.5.2) - VDR-Network-Streaming-Interface (VNSI) Server

Quote:21:40:28.603 T:123145501323264 ERROR: ffmpeg[70000BDCB000]: [h264] Missing reference picture, default is 0
21:40:28.603 T:123145501323264 ERROR: ffmpeg[70000BDCB000]: [h264] decode_slice_header error
21:40:28.604 T:123145501323264 ERROR: ffmpeg[70000BDCB000]: [h264] hardware accelerator failed to decode picture
21:40:28.604 T:123145501323264 ERROR: Decode - avcodec_decode_video returned failure
21:40:28.604 T:123145501323264 DEBUG: CVideoPlayerVideo - video decoder returned error
21:40:28.808 T:123145501323264 ERROR: Decode - avcodec_decode_video returned failure
21:40:28.808 T:123145501323264 DEBUG: CVideoPlayerVideo - video decoder returned error
21:40:28.808 T:123145501323264 INFO: CVideoPlayerVideo - Stillframe detected, switching to forced 50.000000 fps
21:40:28.818 T:123145500786688 WARNING: VideoPlayer::Sync - stream player video does not start, flushing buffers
21:40:28.818 T:123145500786688 DEBUG: CVideoPlayer::FlushBuffers - flushing buffers
21:40:28.827 T:123145507225600 DEBUG: CDVDAudio::Flush - flush audio stream
21:40:28.827 T:123145507225600 DEBUG: CDVDAudio:ause - pausing audio stream
21:40:28.827 T:123145507225600 DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
21:40:28.827 T:123145501323264 DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
21:40:28.827 T:123145500786688 DEBUG: CVideoPlayer::SetCaching - caching state 2
21:40:28.827 T:123145500786688 DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
21:40:28.836 T:123145501323264 INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback
21:40:28.836 T:123145501323264 DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
21:40:28.838 T:123145507225600 DEBUG: CDVDAudio:ause - pausing audio stream
21:40:28.845 T:123145501323264 DEBUG: CDVDVideoCodecFFmpeg - Updated codec: ff-h264
21:40:28.854 T:123145501323264 INFO: CBitstreamConverter::Open annexb to bitstream init
21:40:28.854 T:123145500786688 DEBUG: CVideoPlayer::HandleMessages - player started 1
21:40:28.873 T:123145501323264 DEBUG: CDVDVideoCodecFFmpeg - Updated codec: ff-h264-vtb
21:40:28.878 T:123145501323264 DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
21:40:28.880 T:123145501323264 ERROR: ffmpeg[70000BDCB000]: [h264] co located POCs unavailable

Crashlog https://pastebin.com/s0jPPE0L

Anyone interested to dig deeper ?

FernetMenta · 2017-07-08, 07:27

Did you try with hardware acceleration (videotoolbox) disabled?

sharky1337 · (This post was last modified: 2017-07-10, 22:09 by sharky1337.)

Thank you @FernetMenta . ZDF HD now works perfectly with VTB disabled , but there are other HD Channels which have similar problems for example VOX HD & n-tv HD . On these nothing changed at all. Still many interrupts while watching.

Code:
57:01.142 T:123145427927040   DEBUG: Initialize: using buffer size: 16384 (0.046440 ms)

57:01.142 T:123145427927040   DEBUG: CActiveAESink::OpenSink - DARWINOSX Initialized:

57:01.142 T:123145427927040   DEBUG:   Output Device : Default

57:01.142 T:123145427927040   DEBUG:   Sample Rate   : 44100

57:01.143 T:123145427927040   DEBUG:   Sample Format : AE_FMT_FLOAT

57:01.143 T:123145427927040   DEBUG:   Channel Count : 2

57:01.143 T:123145427927040   DEBUG:   Channel Layout: FL,FR

57:01.143 T:123145427927040   DEBUG:   Frames        : 512

57:01.143 T:123145427927040   DEBUG:   Frame Size    : 8

57:01.144 T:123145427390464   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

57:27.538 T:140736441635776   DEBUG: Previous line repeats 1 times.

57:27.538 T:140736441635776   DEBUG: ------ Window Init (Pointer.xml) ------

57:28.353 T:140736441635776   DEBUG: ProcessMouse: trying mouse action leftclick

57:28.353 T:140736441635776   DEBUG: Activating window ID: 10700

57:28.655 T:140736441635776   DEBUG: ------ Window Deinit (Home.xml) ------

57:28.669 T:140736441635776   DEBUG: ------ Window Init (MyPVRChannels.xml) ------

57:28.670 T:140736441635776   DEBUG: CGUIMediaWindow::GetDirectory (pvr://channels/tv/All channels/)

57:28.671 T:140736441635776   DEBUG:   ParentPath = [pvr://channels/tv/All channels/]

57:28.671 T:140736441635776   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/All channels)

57:29.239 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

57:30.483 T:123145423097856   DEBUG: Thread JobWorker 123145423097856 terminating (autodelete)

57:30.486 T:123145422561280   DEBUG: Thread JobWorker 123145422561280 terminating (autodelete)

57:28.353 T:140736441635776   DEBUG: ProcessMouse: trying mouse action leftclick

57:28.353 T:140736441635776   DEBUG: Activating window ID: 10700

57:28.655 T:140736441635776   DEBUG: ------ Window Deinit (Home.xml) ------

57:28.669 T:140736441635776   DEBUG: ------ Window Init (MyPVRChannels.xml) ------

57:28.670 T:140736441635776   DEBUG: CGUIMediaWindow::GetDirectory (pvr://channels/tv/All channels/)

57:28.671 T:140736441635776   DEBUG:   ParentPath = [pvr://channels/tv/All channels/]

57:28.671 T:140736441635776   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/All channels)

57:29.239 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

57:30.483 T:123145423097856   DEBUG: Thread JobWorker 123145423097856 terminating (autodelete)

57:30.486 T:123145422561280   DEBUG: Thread JobWorker 123145422561280 terminating (autodelete)

57:52.374 T:140736441635776   DEBUG: ------ Window Init (Pointer.xml) ------

57:53.374 T:140736441635776   DEBUG: ProcessMouse: trying mouse action wheeldown

57:55.321 T:140736441635776   DEBUG: Previous line repeats 3 times.

57:55.321 T:140736441635776   DEBUG: ProcessMouse: trying mouse action leftclick

57:55.365 T:140736441635776   DEBUG: Loading settings for pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers(pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr)

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv

57:55.366 T:140736441635776   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1

57:55.366 T:140736441635776   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players

57:55.367 T:140736441635776   DEBUG: Radio UECP (RDS) Processor - new CDVDRadioRDSData

57:55.367 T:140736441635776  NOTICE: VideoPlayer: Opening: pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr

57:55.367 T:140736441635776 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED

57:55.367 T:140736441635776   DEBUG: LinuxRendererGL: Cleaning up GL resources

57:55.367 T:140736441635776   DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16

57:55.367 T:123145423097856   DEBUG: Thread VideoPlayer start, auto delete: false

57:55.367 T:123145423097856  NOTICE: Creating InputStream

57:55.367 T:123145423097856   DEBUG: PVRManager - OpenLiveStream - opening live stream on channel 'n-tv HD'

57:55.367 T:123145423097856   DEBUG: opening live stream for channel 'n-tv HD'

57:55.374 T:123145423097856  NOTICE: AddOnLog: VDR VNSI Client: Logged in at '1499716675+7200' to 'VDR-Network-Streaming-Interface (VNSI) Server' Version: '1.5.2' with protocol version '10'

57:55.374 T:123145423097856   DEBUG: AddOnLog: VDR VNSI Client: changing to channel 12

57:55.394 T:123145423097856   DEBUG: CDVDInputStreamPVRManager - Open - playback has started on filename pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr

57:55.394 T:123145423097856   DEBUG: CDVDInputStreamPVRManager::Open - stream opened: pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr

57:55.394 T:123145423097856  NOTICE: Creating Demuxer

57:55.394 T:123145423097856   DEBUG: OnPlayBackStarted: play state was 1, starting 1

57:55.394 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 2

57:55.394 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

57:55.394 T:140736441635776   DEBUG: PlayFile: OpenFile succeed, play state 2

57:55.394 T:140736441635776   DEBUG: OnPlayBackStarted: play state was 2, starting 0

57:55.404 T:123145423634432   DEBUG: Thread JobWorker start, auto delete: true

57:55.404 T:123145423634432   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr)

57:55.406 T:123145425780736   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc

57:55.406 T:123145425780736   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay

57:57.390 T:123145423097856   DEBUG: CDVDDemuxClient::RequestStreams(): added/updated stream 36 with codec_id 94215

57:57.390 T:123145423097856   DEBUG: CDVDDemuxClient::RequestStreams(): added/updated stream 1279 with codec_id 28

57:57.390 T:123145423097856   DEBUG: CDVDDemuxClient::RequestStreams(): added/updated stream 1283 with codec_id 86019

57:57.390 T:123145423097856   DEBUG: CDVDDemuxClient::RequestStreams(): added/updated stream 1284 with codec_id 86019

57:57.390 T:123145423097856  NOTICE: Opening stream: 1279 source: 256

57:57.390 T:123145423097856  NOTICE: Creating video codec with codec id: 28

57:57.390 T:123145423097856   DEBUG: FactoryCodec - Video:  - Opening

57:57.390 T:123145423097856  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10

57:57.390 T:123145423097856   DEBUG: CDVDVideoCodecFFmpeg - open frame threaded with 6 threads

57:57.390 T:123145423097856   DEBUG: CDVDVideoCodecFFmpeg - Updated codec: ff-h264

57:57.390 T:123145423097856   DEBUG: FactoryCodec - Video: ff-h264 - Opened

57:57.390 T:123145423097856   DEBUG: CVideoPlayerVideo::OpenStream - open stream with codec id: 28

57:57.390 T:123145423097856  NOTICE: Creating video thread

57:57.390 T:123145439809536   DEBUG: Thread VideoPlayerVideo start, auto delete: false

57:57.390 T:123145423097856  NOTICE: Opening stream: 1283 source: 256

57:57.390 T:123145439809536  NOTICE: running thread: video_thread

57:57.390 T:123145423097856  NOTICE: Finding audio codec for: 86019

57:57.391 T:123145423097856   DEBUG: FactoryCodec - Audio: FFmpeg - Opening

57:57.391 T:123145423097856   DEBUG: FactoryCodec - Audio: FFmpeg - Opened

57:57.391 T:123145423097856  NOTICE: Creating audio thread

57:57.391 T:123145440882688   DEBUG: Thread VideoPlayerAudio start, auto delete: false

57:57.391 T:123145423097856  NOTICE: Opening stream: 36 source: 256

57:57.391 T:123145440882688  NOTICE: running thread: CVideoPlayerAudio::Process()

57:57.391 T:123145423097856  NOTICE: waiting for teletext data thread to exit

57:57.391 T:123145440882688   DEBUG: CDVDAudio::Pause - pausing audio stream

57:57.391 T:123145423097856  NOTICE: Creating teletext data thread

57:57.391 T:123145441419264   DEBUG: Thread DVDTeletextData start, auto delete: false

57:57.391 T:123145441419264  NOTICE: running thread: CDVDTeletextData

57:57.414 T:123145423097856   DEBUG: CDVDDemuxClient::ParsePacket - {1279} profile changed from -99 to 100

57:57.414 T:123145423097856   DEBUG: CDVDDemuxClient::ParsePacket - {1279} level changed from -99 to 40

57:57.414 T:123145423097856  NOTICE: Opening stream: 1279 source: 256

57:57.414 T:123145423097856  NOTICE: Creating video codec with codec id: 28

57:57.414 T:123145423097856   DEBUG: FactoryCodec - Video:  - Opening

57:57.414 T:123145423097856  NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10

57:57.414 T:123145423097856   DEBUG: CDVDVideoCodecFFmpeg - open frame threaded with 6 threads

57:57.415 T:123145423097856   DEBUG: CDVDVideoCodecFFmpeg - Updated codec: ff-h264

57:57.415 T:123145423097856   DEBUG: FactoryCodec - Video: ff-h264 - Opened

57:57.415 T:123145423097856  NOTICE: Opening stream: 1283 source: 256

57:57.415 T:123145423097856  NOTICE: Opening stream: 36 source: 256

57:57.415 T:123145439809536   DEBUG: CVideoPlayerVideo::OpenStream - open stream with codec id: 28

57:57.415 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0

57:57.702 T:123145440882688  NOTICE: Creating audio stream (codec id: 86019, channels: 2, sample rate: 48000, no pass-through)

57:57.703 T:123145440882688   DEBUG: CVideoPlayerAudio:: synctype set to 1: resample

57:57.706 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0

57:57.731 T:123145427927040   DEBUG: Previous line repeats 3 times.

57:57.731 T:123145427927040    INFO: CActiveAESink::OpenSink - initialize sink

57:57.732 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0

57:57.778 T:123145439809536   DEBUG: Previous line repeats 2 times.

57:57.778 T:123145439809536   DEBUG: CRenderManager::Configure - change configuration. 1920x1080. display: 1920x1080. framerate: 25.00. format: YV12

57:57.787 T:140736441635776   DEBUG: DeleteRenderer - deleting renderer

57:57.787 T:140736441635776   DEBUG: LinuxRendererGL: Cleaning up GL resources

57:57.789 T:140736441635776   DEBUG: Previous line repeats 1 times.

57:57.789 T:140736441635776   DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16

57:57.789 T:140736441635776   DEBUG: GL: Requested render method: 0

57:57.789 T:140736441635776   DEBUG: GL: BaseYUV2RGBGLSLShader: defines:

                                            #define XBMC_texture_rectangle 0

                                            #define XBMC_texture_rectangle_hack 0

                                            #define XBMC_STRETCH 0

                                            #define XBMC_YV12

57:57.789 T:140736441635776  NOTICE: GL: Selecting Single Pass YUV 2 RGB shader

57:57.790 T:140736441635776   DEBUG: GL: Vertex Shader compilation log:

57:57.790 T:140736441635776   DEBUG: GL: Vertex Shader compiled successfully

57:57.790 T:140736441635776   DEBUG: GL: Pixel Shader compilation log:

57:57.790 T:140736441635776   DEBUG: GL: Fragment Shader compiled successfully

57:57.791 T:140736441635776   DEBUG: GL: Vertex Shader compilation log:

57:57.791 T:140736441635776   DEBUG: GL: Vertex Shader compiled successfully

57:57.791 T:140736441635776   DEBUG: GL: Pixel Shader compilation log:

57:57.791 T:140736441635776   DEBUG: GL: Fragment Shader compiled successfully

57:57.792 T:140736441635776  NOTICE: GL: NPOT texture support detected

57:57.792 T:140736441635776  NOTICE: Using GL_TEXTURE_2D

57:57.792 T:140736441635776   DEBUG: CRenderManager::Configure - 4

57:57.794 T:140736441635776   DEBUG: GL: Requested render method: 0

57:57.794 T:140736441635776   DEBUG: GL: BaseYUV2RGBGLSLShader: defines:

                                            #define XBMC_texture_rectangle 0

                                            #define XBMC_texture_rectangle_hack 0

                                            #define XBMC_STRETCH 0

                                            #define XBMC_YV12

57:57.794 T:140736441635776  NOTICE: GL: Selecting Single Pass YUV 2 RGB shader

57:57.795 T:140736441635776   DEBUG: GL: Vertex Shader compilation log:

57:57.795 T:140736441635776   DEBUG: GL: Vertex Shader compiled successfully

57:57.795 T:140736441635776   DEBUG: GL: Pixel Shader compilation log:

57:57.795 T:140736441635776   DEBUG: GL: Fragment Shader compiled successfully

57:57.796 T:140736441635776  NOTICE: GL: NPOT texture support detected

57:57.868 T:123145423097856   DEBUG: CVideoPlayer::HandleMessages - player started 2

57:57.878 T:123145427927040   DEBUG: CCoreAudioStream::Close: Restoring original physical format for stream 0x002f. ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz))

57:58.176 T:123145427927040   DEBUG: CCoreAudioStream::SetPhysicalFormat: Physical format for stream 0x002f. now active ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz))

57:58.176 T:123145427927040   DEBUG: CCoreAudioStream::Close: Closed stream 0x002f.

57:58.177 T:123145427927040   DEBUG: CActiveAESink::OpenSink - trying to open device DARWINOSX:default

57:58.180 T:123145427927040  NOTICE: virtual bool CAESinkDARWINOSX::Initialize(AEAudioFormat &, std::string &): Opening default device Built-in Output

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Finding stream for format AE_FMT_FLOATP

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (96000Hz) rated 1106.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (88200Hz) rated 670.500000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (48000Hz) rated 1508.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (44100Hz) rated 89.250000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (96000Hz) rated 1105.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (88200Hz) rated 669.500000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (48000Hz) rated 1507.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (44100Hz) rated 88.250000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (96000Hz) rated 1107.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (88200Hz) rated 671.500000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz) rated 1509.000000

57:58.181 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz) rated 90.250000

57:58.181 T:123145427927040   DEBUG: Initialize: Selected stream[0] - id: 0x002F, Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz)

57:58.182 T:123145427927040   DEBUG: CCoreAudioDevice::SupportsMixing: Device mixing support : 'No'.

57:58.182 T:123145427927040   DEBUG: CCoreAudioStream::Open: Opened stream 0x002f.

57:58.182 T:123145427927040   DEBUG: Initialize: Previous Virtual Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

57:58.182 T:123145427927040   DEBUG: Initialize: Previous Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

57:58.484 T:123145445175296    INFO: CCoreAudioStream::HardwareStreamListener: Hardware physical format changed to [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz)

57:58.484 T:123145445175296    INFO: CCoreAudioStream::HardwareStreamListener: Hardware virtual format changed to [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz)

57:58.487 T:123145427927040   DEBUG: CCoreAudioStream::SetPhysicalFormat: Physical format for stream 0x002f. now active ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz))

57:58.491 T:123145427927040   DEBUG: Initialize: New Virtual Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz)

57:58.491 T:123145427927040   DEBUG: Initialize: New Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz)

57:58.492 T:123145427927040   DEBUG: GetAEChannelMap Engine requests layout FL,FR

57:58.492 T:123145427927040   DEBUG: GetAEChannelMap trying to map to stereo layout: [Left] [Right]

57:58.492 T:123145427927040   DEBUG: GetAEChannelMap mapped channels to layout FL,FR

57:58.492 T:123145427927040   DEBUG: Initialize: using buffer size: 16384 (0.042667 ms)

57:58.492 T:123145427927040   DEBUG: CActiveAESink::OpenSink - DARWINOSX Initialized:

57:58.492 T:123145427927040   DEBUG:   Output Device : Default

57:58.492 T:123145427927040   DEBUG:   Sample Rate   : 48000

57:58.492 T:123145427927040   DEBUG:   Sample Format : AE_FMT_FLOAT

57:58.492 T:123145427927040   DEBUG:   Channel Count : 2

57:58.492 T:123145427927040   DEBUG:   Channel Layout: FL,FR

57:58.492 T:123145427927040   DEBUG:   Frames        : 512

57:58.492 T:123145427927040   DEBUG:   Frame Size    : 8

57:58.494 T:123145427390464   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

57:58.558 T:123145423097856   DEBUG: Previous line repeats 1 times.

57:58.558 T:123145423097856   DEBUG: CVideoPlayer::HandleMessages - player started 1

57:58.558 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 3

57:58.558 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

57:58.558 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 0

57:58.558 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

57:58.558 T:123145423097856   DEBUG: VideoPlayer::Sync - Audio - pts: 69783525756.000000, cache: 230520.844658, totalcache: 442666.679621

57:58.558 T:123145423097856   DEBUG: VideoPlayer::Sync - Video - pts: 69784381033.000000, cache: 50000.000000, totalcache: 100000.000000

57:58.558 T:123145440882688   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(69782683089.320374)

57:58.558 T:123145439809536   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(69782683089.320374)

57:58.558 T:123145440882688   DEBUG: CDVDAudio::Resume - resume audio stream

57:58.558 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

57:58.559 T:123145427390464   DEBUG: ActiveAE - start sync of audio stream

57:58.559 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

57:58.658 T:123145427390464   DEBUG: Previous line repeats 2 times.

57:58.658 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error of 625.631049, start adjusting

57:59.119 T:123145439809536 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

57:59.293 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error 15.833675, last average error: 625.631049

57:59.377 T:140736441635776   DEBUG: Keyboard: scancode: 0x35, sym: 0x001b, unicode: 0x001b, modifier: 0x0

57:59.405 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error of -32.299154, start adjusting

57:59.405 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error -22.299154 below threshold of 30.000000

57:59.425 T:140736441635776   DEBUG: OnKey: escape (0xf01b) pressed, action is PreviousMenu

57:59.425 T:140736441635776   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate

57:59.426 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

57:59.636 T:123145439809536 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

57:59.755 T:140736441635776   DEBUG: ------ Window Deinit (MyPVRChannels.xml) ------

57:59.756 T:140736441635776   DEBUG: CGUIWindowManager::PreviousWindow: Activate new

57:59.756 T:140736441635776   DEBUG: ------ Window Init (Home.xml) ------

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/video/]: refreshing..

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/audio/]: refreshing..

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/executable/]: refreshing..

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/image/]: refreshing..

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[pvr://channels/tv/*?view=lastplayed]: refreshing..

57:59.757 T:140736441635776   DEBUG: CDirectoryProvider[pvr://channels/radio/*?view=lastplayed]: refreshing..

57:59.757 T:123145446248448   DEBUG: Thread JobWorker start, auto delete: true

57:59.758 T:140736441635776   DEBUG: Keyboard: scancode: 0x35, sym: 0x001b, unicode: 0x0000, modifier: 0x0

57:59.760 T:140736441635776   DEBUG: ------ Window Init (Pointer.xml) ------

57:59.764 T:123145423634432   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/*?view=lastplayed)

57:59.766 T:123145446248448   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/radio/*?view=lastplayed)

57:59.768 T:123145423634432 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.tbn

57:59.768 T:123145423634432 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_118294079.tbn

57:59.768 T:123145423634432 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1620961810.tbn

57:59.768 T:123145423634432 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1055743585.tbn

57:59.768 T:123145423634432 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1281493562.tbn

58:00.152 T:123145439809536 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

58:00.489 T:140736441635776   DEBUG: ProcessMouse: trying mouse action leftclick

58:00.489 T:140736441635776   DEBUG: Activating window ID: 12005

58:00.489 T:140736441635776   DEBUG: ------ Window Deinit (Home.xml) ------

58:00.489 T:140736441635776   DEBUG: ------ Window Init (VideoFullScreen.xml) ------

58:00.520 T:140736441635776   DEBUG: ------ Window Init (VideoOSD.xml) ------

58:00.523 T:140736441635776   ERROR: Control 602 in window 12901 has been asked to focus, but it can't

58:00.523 T:140736441635776   DEBUG: ------ Window Init (DialogSeekBar.xml) ------

58:00.523 T:140736441635776   DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------

58:00.554 T:140736441635776   ERROR: Control 602 in window 12901 has been asked to focus, but it can't

58:00.604 T:123145439809536   ERROR: Previous line repeats 2 times.

58:00.604 T:123145439809536  NOTICE: CDVDVideoCodecFFmpeg::CDropControl: calculated diff time: 47272

58:02.760 T:123145439809536   DEBUG: CPullupCorrection: detected pattern of length 1: 20000.00, frameduration: 20000.000000

58:08.756 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

58:12.071 T:140736441635776   DEBUG: ------ Window Deinit (VideoOSD.xml) ------

58:12.087 T:140736441635776   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------

58:12.087 T:140736441635776   DEBUG: ------ Window Deinit (Custom_1109_TopBarOverlay.xml) ------

58:18.921 T:123145440882688  NOTICE: CVideoPlayerAudio::Process - stream stalled

58:19.122 T:123145423097856   DEBUG: CVideoPlayer::CheckContinuity - resync forward :2, prev:69804461033.000000, curr:69806061033.000000, diff:1560000.000000

58:19.122 T:123145423097856   DEBUG: Stream stalled, start buffering. Audio: 0 - Video: 11

58:19.122 T:123145423097856   DEBUG: CVideoPlayer::FlushBuffers - flushing buffers

58:19.131 T:123145440882688   DEBUG: CDVDAudio::Flush - flush audio stream

58:19.131 T:123145440882688   DEBUG: CDVDAudio::Pause - pausing audio stream

58:19.131 T:123145440882688   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE

58:19.131 T:123145439809536   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE

58:19.131 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 2

58:19.131 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

58:19.142 T:123145440882688   DEBUG: CDVDAudio::Pause - pausing audio stream

58:19.147 T:123145439809536    INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback

58:19.147 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0

58:19.256 T:123145423097856   DEBUG: Previous line repeats 2 times.

58:19.256 T:123145423097856   DEBUG: CVideoPlayer::HandleMessages - player started 1

58:19.256 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0

58:20.718 T:123145423097856   DEBUG: Previous line repeats 36 times.

58:20.718 T:123145423097856   DEBUG: CVideoPlayer::HandleMessages - player started 2

58:20.718 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 3

58:20.718 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

58:20.718 T:123145423097856   DEBUG: CVideoPlayer::SetCaching - caching state 0

58:20.718 T:123145423097856   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

58:20.718 T:123145423097856   DEBUG: VideoPlayer::Sync - Audio - pts: 69805253756.000000, cache: 243139.460575, totalcache: 442666.679621

58:20.718 T:123145423097856   DEBUG: VideoPlayer::Sync - Video - pts: 69807421033.000000, cache: 50000.000000, totalcache: 100000.000000

58:20.718 T:123145440882688   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(69804411089.320374)

58:20.718 T:123145440882688   DEBUG: CDVDAudio::Resume - resume audio stream

58:20.719 T:123145439809536   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(69804411089.320374)

58:20.719 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

58:20.722 T:123145427390464   DEBUG: ActiveAE - start sync of audio stream

58:20.830 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error of 626.772998, start adjusting

58:21.236 T:123145439809536 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

58:21.470 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error 24.735256, last average error: 626.772998

58:21.487 T:140736441635776   DEBUG: ------ Window Init (Pointer.xml) ------

58:21.503 T:140736441635776   DEBUG: ------ Window Init (VideoOSD.xml) ------

58:21.506 T:140736441635776   ERROR: Control 602 in window 12901 has been asked to focus, but it can't

58:21.507 T:140736441635776   DEBUG: ------ Window Init (DialogSeekBar.xml) ------

58:21.507 T:140736441635776   DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------

58:21.577 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error of -24.745895, start adjusting

58:21.577 T:123145427390464   DEBUG: ActiveAE::SyncStream - average error -14.745895 below threshold of 30.000000

58:21.752 T:123145439809536 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

58:23.389 T:123145439809536 WARNING: Previous line repeats 3 times.

58:23.389 T:123145439809536   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

58:26.194 T:123145439809536   DEBUG: CPullupCorrection: detected pattern of length 1: 20000.00, frameduration: 20000.000000

58:27.305 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

58:28.289 T:140736441635776   DEBUG: ------ Window Init (Pointer.xml) ------

58:28.505 T:140736441635776   ERROR: Control 602 in window 12901 has been asked to focus, but it can't

58:29.255 T:140736441635776   ERROR: Previous line repeats 21 times.

58:29.255 T:140736441635776   DEBUG: ProcessMouse: trying mouse action leftclick

58:29.255 T:140736441635776  NOTICE: CVideoPlayer::CloseFile()

58:29.255 T:140736441635776  NOTICE: VideoPlayer: waiting for threads to exit

58:29.332 T:123145423097856  NOTICE: CVideoPlayer::OnExit()

58:29.332 T:123145423097856  NOTICE: Closing stream player 1

58:29.332 T:123145423097856  NOTICE: Waiting for audio thread to exit

58:29.353 T:123145440882688  NOTICE: thread end: CVideoPlayerAudio::OnExit()

58:29.353 T:123145440882688   DEBUG: Thread VideoPlayerAudio 123145440882688 terminating

58:29.353 T:123145423097856  NOTICE: Closing audio device

58:29.364 T:123145423097856   DEBUG: CDVDAudio::Flush - flush audio stream

58:29.364 T:123145427390464   DEBUG: CActiveAE::DiscardStream - audio stream deleted

58:29.364 T:123145427390464   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

58:29.364 T:123145423097856   DEBUG: Previous line repeats 2 times.

58:29.364 T:123145423097856  NOTICE: Deleting audio codec

58:29.364 T:123145427927040    INFO: CActiveAESink::OpenSink - initialize sink

58:29.364 T:123145423097856  NOTICE: Closing stream player 2

58:29.364 T:123145423097856  NOTICE: waiting for video thread to exit

58:29.406 T:123145445711872 WARNING: DARWINOSX: underflow (1600 vs 4096 bytes)

58:29.418 T:123145439809536  NOTICE: thread end: video_thread

58:29.418 T:123145439809536   DEBUG: Thread VideoPlayerVideo 123145439809536 terminating

58:29.418 T:123145423097856  NOTICE: deleting video codec

58:29.430 T:123145423097856  NOTICE: Closing stream player 4

58:29.430 T:123145423097856  NOTICE: waiting for teletext data thread to exit

58:29.430 T:123145441419264   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true (-1)

58:29.430 T:123145441419264  NOTICE: thread end: data_thread

58:29.430 T:123145441419264   DEBUG: Thread DVDTeletextData 123145441419264 terminating

58:29.434 T:123145446248448   DEBUG: DoWork - Saving file state for video item pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.pvr

58:29.434 T:123145423097856   DEBUG: AddOnLog: VDR VNSI Client: closing demuxer

58:29.465 T:123145423097856   DEBUG: CDVDInputStreamPVRManager::Close - stream closed

58:29.465 T:123145423097856   DEBUG: OnPlayBackStopped: play state was 2, starting 0

58:29.465 T:123145423097856   DEBUG: Thread VideoPlayer 123145423097856 terminating

58:29.465 T:140736441635776  NOTICE: VideoPlayer: finished waiting

58:29.465 T:123145425780736   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc

58:29.465 T:140736441635776   DEBUG: DeleteRenderer - deleting renderer

58:29.465 T:140736441635776   DEBUG: LinuxRendererGL: Cleaning up GL resources

58:29.465 T:123145425780736   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop

58:29.467 T:140736441635776   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate

58:29.467 T:140736441635776   DEBUG: ------ Window Deinit (VideoOSD.xml) ------

58:29.467 T:140736441635776   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------

58:29.469 T:140736441635776   DEBUG: CGUIWindowManager::PreviousWindow: Activate new

58:29.469 T:140736441635776   DEBUG: ------ Window Init (Home.xml) ------

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/video/]: refreshing..

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/audio/]: refreshing..

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/executable/]: refreshing..

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[addons://sources/image/]: refreshing..

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[pvr://channels/tv/*?view=lastplayed]: refreshing..

58:29.469 T:140736441635776   DEBUG: CDirectoryProvider[pvr://channels/radio/*?view=lastplayed]: refreshing..

58:29.471 T:123145423097856   DEBUG: Thread JobWorker start, auto delete: true

58:29.471 T:140736441635776   ERROR: Control 803 in window 10000 has been asked to focus, but it can't

58:29.478 T:123145446248448   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/*?view=lastplayed)

58:29.481 T:123145423097856   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/radio/*?view=lastplayed)

58:29.485 T:123145446248448 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1317513966.tbn

58:29.485 T:123145446248448 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_118294079.tbn

58:29.485 T:123145446248448 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1620961810.tbn

58:29.485 T:123145446248448 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1055743585.tbn

58:29.486 T:123145446248448 WARNING: CreateLoader - unsupported protocol(pvr) in pvr://channels/tv/All channels/pvr.vdr.vnsi_1281493562.tbn

58:29.508 T:123145427927040   DEBUG: CCoreAudioStream::Close: Restoring original physical format for stream 0x002f. ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz))

58:29.539 T:140736441635776   DEBUG: ------ Window Deinit (Pointer.xml) ------

58:29.541 T:140736441635776  NOTICE: CVideoPlayer::CloseFile()

58:29.541 T:140736441635776  NOTICE: VideoPlayer: waiting for threads to exit

58:29.541 T:140736441635776  NOTICE: VideoPlayer: finished waiting

58:29.541 T:140736441635776  NOTICE: CVideoPlayer::CloseFile()

58:29.541 T:140736441635776  NOTICE: VideoPlayer: waiting for threads to exit

58:29.541 T:140736441635776  NOTICE: VideoPlayer: finished waiting

58:29.544 T:140736441635776   DEBUG: Radio UECP (RDS) Processor - delete ~CDVDRadioRDSData

58:29.545 T:140736441635776   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------

58:29.556 T:140736441635776   DEBUG: ------ Window Deinit (Custom_1109_TopBarOverlay.xml) ------

58:29.907 T:123145427927040   DEBUG: CCoreAudioStream::SetPhysicalFormat: Physical format for stream 0x002f. now active ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz))

58:29.907 T:123145427927040   DEBUG: CCoreAudioStream::Close: Closed stream 0x002f.

58:29.907 T:123145427927040   DEBUG: CActiveAESink::OpenSink - trying to open device DARWINOSX:default

58:29.908 T:123145427927040  NOTICE: virtual bool CAESinkDARWINOSX::Initialize(AEAudioFormat &, std::string &): Opening default device Built-in Output

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Finding stream for format AE_FMT_FLOAT

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (96000Hz) rated 929.129272

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (88200Hz) rated 1106.000000

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (48000Hz) rated 1419.564697

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 24-bit Signed Integer LE (44100Hz) rated 1508.000000

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (96000Hz) rated 928.129272

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (88200Hz) rated 1105.000000

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (48000Hz) rated 1418.564697

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 16-bit Signed Integer LE (44100Hz) rated 1507.000000

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (96000Hz) rated 930.129272

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (88200Hz) rated 1107.000000

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (48000Hz) rated 1420.564697

58:29.909 T:123145427927040   DEBUG: FindSuitableFormatForStream: Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz) rated 1509.000000

58:29.909 T:123145427927040   DEBUG: Initialize: Selected stream[0] - id: 0x002F, Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

58:29.909 T:123145427927040   DEBUG: CCoreAudioDevice::SupportsMixing: Device mixing support : 'No'.

58:29.909 T:123145427927040   DEBUG: CCoreAudioStream::Open: Opened stream 0x002f.

58:29.909 T:123145427927040   DEBUG: Initialize: Previous Virtual Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

58:29.909 T:123145427927040   DEBUG: Initialize: Previous Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

58:30.200 T:123145427927040   DEBUG: CCoreAudioStream::SetPhysicalFormat: Physical format for stream 0x002f. now active ([lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz))

58:30.203 T:123145427927040   DEBUG: Initialize: New Virtual Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

58:30.203 T:123145427927040   DEBUG: Initialize: New Physical Format: [lpcm] Mixable Interleaved 2 Channel 32-bit Floating Point LE (44100Hz)

58:30.204 T:123145427927040   DEBUG: GetAEChannelMap Engine requests layout FL,FR

58:30.204 T:123145427927040   DEBUG: GetAEChannelMap trying to map to stereo layout: [Left] [Right]

58:30.204 T:123145427927040   DEBUG: GetAEChannelMap mapped channels to layout FL,FR

58:30.204 T:123145427927040   DEBUG: Initialize: using buffer size: 16384 (0.046440 ms)

58:30.204 T:123145427927040   DEBUG: CActiveAESink::OpenSink - DARWINOSX Initialized:

58:30.204 T:123145427927040   DEBUG:   Output Device : Default

58:30.204 T:123145427927040   DEBUG:   Sample Rate   : 44100

58:30.204 T:123145427927040   DEBUG:   Sample Format : AE_FMT_FLOAT

58:30.204 T:123145427927040   DEBUG:   Channel Count : 2

58:30.204 T:123145427927040   DEBUG:   Channel Layout: FL,FR

58:30.204 T:123145427927040   DEBUG:   Frames        : 512

58:30.204 T:123145427927040   DEBUG:   Frame Size    : 8

58:30.205 T:123145427390464   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

I can watch the same channel via http without issues , so it is related to the vnsi plugin ?

sharky@tv-server:~$ vdr -V
vdr (2.3.8/2.3.8) - The Video Disk Recorder
ddci2 (1.0.5) - External Digital Devices CI-Adapter
live (2.3.1) - Live Interactive VDR Environment
permashift (1.0.3) - Auto-buffer live TV
streamdev-server (0.6.1-git) - VDR Streaming Server
vnsiserver (1.5.2) - VDR-Network-Streaming-Interface (VNSI) Server

Updated my system to the latest dev version, but the same problem occur on vdr 2.2.0 .

FernetMenta · 2017-07-11, 22:58

Can you try a nightly please.
Please post logs on pastebin (or similar) not directly here.

sharky1337 · 2017-07-13, 18:04

Issue still occur with nightly

18.0-ALPHA1 Git:20170712-9b94915). Platform: OS X x86 64-bit

https://pastebin.com/2X5CfZrZ

FernetMenta · 2017-07-14, 14:54

My guess is a weak network connectivity. How is you Mac and vdr server connected to the network?

FernetMenta · 2017-07-14, 14:58

BTW: I don't obderve those issues on my Mac no matter what vdr channel. (vdr 2.3.7)

sharky1337 · 2017-07-14, 16:45

I will check that, but normally than all other protocols should have glitches too and http runs smooth.

FernetMenta · 2017-07-14, 16:54

(2017-07-14, 16:45)sharky1337 Wrote: I will check that, but normally than all other protocols should have glitches too and http runs smooth.

Nope, because live tv are realtime streams. That means that buffers won't fill once playback has been started. By changing playback speed slightly VideoPlayer holds level of demuxer queued above 5%, that is approximately 400ms. If you don't get packets in this timeframe, a/v streams stall.

sharky1337 · (This post was last modified: 2017-07-14, 17:50 by sharky1337.)

No , sorry I mean real live streams via http (streamdev ) works fine . Playback via kodi iptv plugin or vlc is super smooth. If I there were packet loss than we should see it on both protocols http and vnsi .

FernetMenta · 2017-07-15, 13:31

hmm, this is from my Mac playing ZDF: https://pastebin.com/byzumbqk

Mac and vdr server are connected via wired LAN.

Do you use wireless? If so, can you test with cables?

sharky1337 · 2017-07-16, 14:06

Hey ,

yes I tried both and now I'm only testing on the cable path, the wireless adapter disabled.

I don't know that much about how different plugins in vdr work together, but everytime the "hicup" occur this message show up in the vdr debug log.

Code:
Jul 14 22:22:39 tv-server vdr: [4042] VNSI: CAM error, try reset

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: re-tuning...

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: close video input ...

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: activate live receiver: 0

Jul 14 22:22:39 tv-server vdr: [4042] CAM 1: unassigned from device 1

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: Dummy receiver (0x7f56100049a0) deactivated

Jul 14 22:22:39 tv-server vdr: [4042] CAM 1/1: reusing MTD CAM slot

Jul 14 22:22:39 tv-server vdr: [4089] device 1 TS buffer thread ended (pid=4015, tid=4089)

Jul 14 22:22:39 tv-server vdr: [4088] buffer stats: 255492 (4%) used

Jul 14 22:22:39 tv-server vdr: [4088] device 1 receiver thread ended (pid=4015, tid=4088)

Jul 14 22:22:39 tv-server vdr: [4042] CAM 1: assigned to device 1

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: Successfully found following device: 0xe3a050 (1) for receiving, priority=0

Jul 14 22:22:39 tv-server vdr: [4090] device 1 receiver thread started (pid=4015, tid=4090, prio=high)

Jul 14 22:22:39 tv-server vdr: [4091] device 1 TS buffer thread started (pid=4015, tid=4091, prio=high)

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: Dummy receiver (0x7f56100049a0) activated

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: activate live receiver: 1

I'm using the ddci2 plugin for decrypting the channel , but I don't know if this messages is returned by vnsi or ddci

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: CAM error, try reset

To troubelshoot this further, do I have to use gdp version of the plugins ?

FernetMenta · 2017-07-16, 15:37

Jul 14 22:22:39 tv-server vdr: [4042] VNSI: CAM error, try reset

This means that vnsiserver got a scrambled (encrypted) PES packet from vdr at a time when the cam has already stated working. As a fist step I would try vdr 2.3.7

sharky1337 · (This post was last modified: 2017-07-16, 21:33 by sharky1337.)

I asked other people on vdr-portal and they would like to know why are you doing a retune if the Scrambed Bit is set in ts stream . Maybe you can join the following discussion.

http://www.vdr-portal.de/board18-vdr-har...dex20.html

I think you know some german if you're from munich ;-)

FernetMenta · 2017-07-17, 21:27

(2017-07-16, 21:32)sharky1337 Wrote: I asked other people on vdr-portal and they would like to know why are you doing a retune if the Scrambed Bit is set in ts stream . Maybe you can join the following discussion.

http://www.vdr-portal.de/board18-vdr-har...dex20.html

I think you know some german if you're from munich ;-)

If the scramble bit is set, we have an error condition that not necessarely is recoverable. By retuning vnsiserver recovers from this error.
Sure, vnsiserver could be more fault tolerant by i.e. wait with reset for x errors in a row. This issue seems to be limited to ddci