Login at Kodi Home

vindicator · 2017-01-30, 16:04

Kodi: 18.0-ALPHA1 Git:20170128-6d5a87b
TVH: 4.1-2415~ge5f5a4278-dirty (HTSPv26)
Pertinent Kodi Debug Log:

Code:
42:46.458 T:139733311875328   DEBUG: DoWork - Marking video item pvr://recordings/tv/active/<tv show 1>, TV%20(<tv channel 1>), 20170130_053000, 1261285051.pvr as watched

42:46.727 T:139732657145600   DEBUG: CAnnouncementManager - Announcement: OnUpdate from xbmc

42:46.727 T:139732657145600   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnUpdate

42:46.729 T:139733311875328   DEBUG: Loading settings for pvr://recordings/tv/active/<tv show 2>, TV%20(<tv channel 2>), 20170130_130000, 2096465009.pvr

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers(pvr://recordings/tv/active/<tv show 2>, 20170130_130000, 2096465009.pvr)

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv

42:46.730 T:139733311875328   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1

42:46.730 T:139733311875328   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players

42:46.730 T:139733311875328  NOTICE: CVideoPlayer::CloseFile()

42:46.730 T:139733311875328  NOTICE: VideoPlayer: waiting for threads to exit

42:46.738 T:139730184304384  NOTICE: CVideoPlayer::OnExit()

42:46.738 T:139730184304384  NOTICE: Closing stream player 1

42:46.738 T:139730184304384  NOTICE: Waiting for audio thread to exit

42:46.776 T:139730765018880  NOTICE: thread end: CVideoPlayerAudio::OnExit()

42:46.776 T:139730184304384  NOTICE: Closing audio device

42:46.776 T:139730765018880   DEBUG: Thread VideoPlayerAudio 139730765018880 terminating

42:46.776 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:46.776 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:46.776 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107 SR:0.000000

42:46.776 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000 SR:0.707107

42:46.826 T:139730184304384   DEBUG: CDVDAudio::Flush - flush audio stream

42:46.826 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107 SR:0.000000

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000 SR:0.707107

42:46.827 T:139732640360192   DEBUG: CActiveAE::DiscardStream - audio stream deleted

42:46.827 T:139732640360192   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107 SR:0.000000

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000 SR:0.707107

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FL:1.000000 FR:0.000000 FC:0.707107 LFE:0.000000 SL:0.707107 SR:0.000000

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FL:0.000000 FR:1.000000 FC:0.707107 LFE:0.000000 SL:0.000000 SR:0.707107

42:46.827 T:139732640360192   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

42:46.827 T:139730184304384   DEBUG: Previous line repeats 1 times.

42:46.827 T:139730184304384  NOTICE: Deleting audio codec

42:46.827 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:46.827 T:139730184304384  NOTICE: Closing stream player 2

42:46.827 T:139730184304384  NOTICE: waiting for video thread to exit

42:46.828 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:46.828 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FC:0.707107

42:46.828 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FC:0.707107

42:46.828 T:139732631967488    INFO: CActiveAESink::OpenSink - initialize sink

42:46.857 T:139730477557504  NOTICE: thread end: video_thread

42:46.857 T:139730477557504   DEBUG: Thread VideoPlayerVideo 139730477557504 terminating

42:46.857 T:139730184304384  NOTICE: deleting video codec

42:46.857 T:139730184304384   DEBUG: VAAPI::Release pre-cleanup

42:46.857 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - vfs close id=3

42:46.999 T:139732631967488   DEBUG: CActiveAESink::OpenSink - trying to open device PULSE:Default

42:46.999 T:139732631967488   DEBUG: PulseAudio: Context authorizing

42:47.000 T:139732631967488   DEBUG: PulseAudio: Context setting name

42:47.000 T:139732631967488   DEBUG: PulseAudio: Context ready

42:47.000 T:139732631967488   DEBUG: PulseAudio: Stream ready

42:47.000 T:139732631967488  NOTICE: PulseAudio: Opened device Default in pcm mode with Buffersize 150 ms

42:47.000 T:139732631967488   DEBUG: CActiveAESink::OpenSink - PULSE Initialized:

42:47.000 T:139732631967488   DEBUG:   Output Device : Default

42:47.000 T:139732631967488   DEBUG:   Sample Rate   : 44100

42:47.000 T:139732631967488   DEBUG:   Sample Format : AE_FMT_FLOAT

42:47.000 T:139732631967488   DEBUG:   Channel Count : 2

42:47.000 T:139732631967488   DEBUG:   Channel Layout: FL,FR

42:47.000 T:139732631967488   DEBUG:   Frames        : 2205

42:47.000 T:139732631967488   DEBUG:   Frame Size    : 8

42:47.001 T:139732631967488   DEBUG: ffmpeg[7F1609E45700]: [SWR] Using fltp internally between filters

42:47.001 T:139732640360192   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted

42:47.001 T:139732640360192   DEBUG: Previous line repeats 1 times.

42:47.001 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:50.010 T:139731767187200   DEBUG: weather.yahoo: no weather data, retry

42:51.858 T:139730184304384   DEBUG: Previous line repeats 1 times.

42:51.858 T:139730184304384   ERROR: AddOnLog: Tvheadend HTSP Client: pvr.hts - Command fileClose failed: No response received

42:51.858 T:139730184304384   DEBUG: CDVDInputStreamPVRManager::Close - stream closed

42:51.858 T:139730184304384   DEBUG: OnPlayBackStopped: play state was 2, starting 1

42:51.858 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - new connection requested

42:51.858 T:139730184304384   DEBUG: Thread VideoPlayer 139730184304384 terminating

42:51.858 T:139733311875328  NOTICE: VideoPlayer: finished waiting

42:51.858 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connecting to <server ip>:<server port>

42:51.858 T:139733311875328   DEBUG: DeleteRenderer - deleting renderer

42:51.858 T:139733311875328  NOTICE: VAAPI::Close

42:51.858 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connected

42:51.858 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - sending hello

42:51.859 T:139730467186432  NOTICE: COutput::OnExit: Output Thread terminated

42:51.859 T:139730467186432   DEBUG: Thread Vaapi-Output 139730467186432 terminating

42:51.859 T:139733311875328   DEBUG: VAAPI::FiniVAAPIOutput destroying 0 video surfaces

42:51.859 T:139733311875328  NOTICE: VAAPI::Close - closing decoder context

42:51.860 T:139733311875328   DEBUG: LinuxRendererGL: Cleaning up GL resources

42:51.860 T:139733311875328  NOTICE: VideoPlayer: Opening: pvr://recordings/tv/active/<tv show 2>, 20170130_130000, 2096465009.pvr

42:51.860 T:139733311875328   DEBUG: LinuxRendererGL: Cleaning up GL resources

42:51.860 T:139733311875328   DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16

42:51.860 T:139730467186432   DEBUG: Thread VideoPlayer start, auto delete: false

42:51.860 T:139730467186432  NOTICE: Creating InputStream

42:51.860 T:139730467186432   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - vfs open file=dvr/2096465009

42:52.002 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:52.360 T:139733311875328   DEBUG: ------ Window Init (DialogBusy.xml) ------

42:52.362 T:139729896367872   DEBUG: DoWork - Saving file state for video item pvr://recordings/tv/active/<tv show 1>, TV%20(<tv channel 1>), 20170130_053000, 1261285051.pvr

42:52.362 T:139733311875328   DEBUG: ------ Window Init (DialogSeekBar.xml) ------

42:52.362 T:139733311875328   DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------

42:52.363 T:139729896367872   DEBUG: DoWork - Marking video item pvr://recordings/tv/active/<tv show 1>, TV%20(<tv channel 1>), 20170130_053000, 1261285051.pvr as watched

42:52.611 T:139732657145600   DEBUG: CAnnouncementManager - Announcement: OnUpdate from xbmc

42:52.611 T:139732657145600   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnUpdate

42:52.850 T:139731767187200   DEBUG: weather.yahoo: no weather data, retry

42:53.662 T:139730756626176   ERROR: AddOnLog: Tvheadend HTSP Client: pvr.hts - Command getDiskSpace failed: No response received

42:56.858 T:139730184304384   ERROR: AddOnLog: Tvheadend HTSP Client: pvr.hts - Command hello failed: No response received

42:56.859 T:139730184304384   ERROR: AddOnLog: Tvheadend HTSP Client: pvr.hts - failed to send hello

42:56.859 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connection state change (5 -> 2)

42:56.859 T:139730184304384   DEBUG: PVR - PVRConnectionStateChange - state for connection '<server ip>:<server port>' on client 'Tvheadend HTSP Client' changed from '5' to '2'

42:57.004 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

42:57.005 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

42:57.005 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FC:0.707107

42:57.005 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FC:0.707107

42:59.106 T:139731767187200   DEBUG: weather.yahoo: no weather data, retry

43:01.859 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - new connection requested

43:01.859 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connecting to <server ip>:<server port>

43:01.859 T:139730773411584   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connected

43:01.860 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - sending hello

43:01.860 T:139730467186432   ERROR: AddOnLog: Tvheadend HTSP Client: pvr.hts - vfs failed to open file

43:01.860 T:139730467186432   ERROR: CVideoPlayer::OpenInputStream - error opening [pvr://recordings/tv/active/<tv show 2>, 20170130_130000, 2096465009.pvr]

43:01.860 T:139730467186432  NOTICE: CVideoPlayer::OnExit()

43:01.860 T:139730467186432   DEBUG: CDVDInputStreamPVRManager::Close - stream closed

43:01.860 T:139730467186432   DEBUG: OnPlayBackStopped: play state was 1, starting 1

43:01.860 T:139730467186432   DEBUG: Thread VideoPlayer 139730467186432 terminating

43:01.862 T:139733311875328   DEBUG: OnPlayBackStopped: play state was 3, starting 0

43:01.862 T:139732657145600   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc

43:01.862 T:139733311875328   DEBUG: SECTION:UnloadDelayed(DLL: special://xbmcbin/system/libsse4-x86_64-linux.so)

43:01.862 T:139732657145600   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop

43:01.863 T:139733311875328   DEBUG: ------ Window Init (DialogNotification.xml) ------

43:01.863 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Using fltp internally between filters

43:01.864 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connected to Tvheadend / 4.1-2415~ge5f5a4278-dirty (HTSPv26)

43:01.864 T:139733311875328   DEBUG: ------ Window Deinit (DialogBusy.xml) ------

43:01.864 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - sending auth

43:01.864 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] Matrix coefficients:

43:01.864 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FL: FC:0.707107

43:01.864 T:139732640360192   DEBUG: ffmpeg[7F160A646700]: [SWR] FR: FC:0.707107

43:01.865 T:139733311875328  NOTICE: CVideoPlayer::CloseFile()

43:01.865 T:139733311875328  NOTICE: VideoPlayer: waiting for threads to exit

43:01.865 T:139733311875328  NOTICE: VideoPlayer: finished waiting

43:01.865 T:139733311875328   DEBUG: DeleteRenderer - deleting renderer

43:01.865 T:139733311875328   DEBUG: LinuxRendererGL: Cleaning up GL resources

43:01.865 T:139733311875328  NOTICE: CVideoPlayer::CloseFile()

43:01.866 T:139733311875328  NOTICE: VideoPlayer: waiting for threads to exit

43:01.866 T:139733311875328  NOTICE: VideoPlayer: finished waiting

43:01.866 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - rebuilding state

43:01.866 T:139733311875328   DEBUG: Radio UECP (RDS) Processor - delete ~CDVDRadioRDSData

43:01.866 T:139733311875328   DEBUG: CGUIWindowManager::PreviousWindow: Deactivate

43:01.866 T:139733311875328   DEBUG: ------ Window Deinit (VideoFullScreen.xml) ------

43:01.867 T:139730184304384    INFO: AddOnLog: Tvheadend HTSP Client: pvr.hts - async updates requested

43:01.867 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - registered

43:01.867 T:139730184304384   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - connection state change (2 -> 5)

43:01.867 T:139730184304384   DEBUG: PVR - PVRConnectionStateChange - state for connection '<server ip>:<server port>' on client 'Tvheadend HTSP Client' changed from '2' to '5'

Pertinent Server Log:

Code:
Jan 30 07:42:12 <server name> tvheadend[8285]: dvr: delete entry bbae2dcb22e208240c85bd7eb93f6d37 "<tv show>" on "<tv channel>" s

Jan 30 07:42:27 <server name> tvheadend[8285]: htsp: ::ffff:<client ip> [ kodi | Kodi Media Center ]: Disconnected

Jan 30 07:42:27 <server name> tvheadend[8285]: htsp: ::ffff:<client ip> [ kodi | Kodi Media Center ]: Write error -- Broken pipe

Jan 30 07:42:27 <server name> tvheadend[8285]: htsp: Got connection from ::ffff:<sanitized>

Jan 30 07:42:27 <server name> tvheadend[8285]: htsp: ::ffff:<client ip>: Welcomed client software: Kodi Media Center (HTSPv25)

Jan 30 07:42:27 <server name> tvheadend[8285]: htsp: ::ffff:<client ip> [ Kodi Media Center ]: Disconnected

Jan 30 07:42:31 <server name> tvheadend[8285]: htsp: Got connection from ::ffff:<sanitized>

Jan 30 07:42:31 <server name> tvheadend[8285]: htsp: ::ffff:<client ip>: Welcomed client software: Kodi Media Center (HTSPv25)

Jan 30 07:42:31 <server name> tvheadend[8285]: htsp: ::ffff:<client ip> [ Kodi Media Center ]: Identified as user '<username>'

Jan 30 07:42:31 <server name> tvheadend[8285]: htsp: ::ffff:<client ip> [ kodi | Kodi Media Center ]: Privileges updated

vindicator · 2017-01-31, 02:42

It isn't even about changing channels apparently.
I simply deleted a show I had finished watching and was looking around before viewing another recording when I heard the kodi "sound" denoting my connection dropped.

Code:
Jan 30 18:31:50 <server> tvheadend[8285]: dvr: delete entry a275d55ba0a14eff0b6c9d8365cbbdb9 "<tv show>" on "<channel>" start time 2017-01-30 17:28:30, scheduled for recording by "<server>", retention "On file removal" removal "Forever"

Jan 30 18:32:41 <server> tvheadend[8285]: htsp: ::ffff:<client ip> [ kodi | Kodi Media Center ]: Write error -- Broken pipe

Jan 30 18:32:43 <server> tvheadend[8285]: htsp: ::ffff:<client ip> [ kodi | Kodi Media Center ]: Disconnected

Jan 30 18:32:43 <server> tvheadend[8285]: htsp: Got connection from ::ffff:<client ip>

Jan 30 18:32:43 <server> tvheadend[8285]: htsp: Got connection from ::ffff:<client ip>

Jan 30 18:32:43 <server> tvheadend[8285]: htsp: ::ffff:<client ip>: Welcomed client software: Kodi Media Center (HTSPv25)

Would there be some sort of timeout error if a "delete" takes too long (btrfs)? Going from an ext4 to btrfs fs is one of the changes I've made besides updating tvheadend and kodi.