Another report of this issue my side
After happily using MP with XBMC for quite some time (massive fan of all your hard work, margro), I've just done a fresh install of both server and clients (they're all now OpenELEC with the only Windows machine being the server), and am now experiencing this same issue. (In my case, I use Analog channels)
I'm using MP 1.5 (with the 1.4 addon) but have also tried with previous versions (including MP 1.4 and 1.23, with their applicable server addons.).
Timers work great, recordings play perfectly and I can play a recording whilst it's recording. (The XBMC machine can also access the Samba TS share fine in the XBMC File Manager).
But if I start a channel on the Channels list, I almost always get an XBMC crash-then-restart.
If it does work, then a reboot of the XBMC client box will yield the crashes from then on; until (it appears) the server is rebooted.
The full XBMC log is
here
The last few lines of the log are:
Code:
21:55:06 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: CVTPTransceiver::ReadResponse - timeout waiting for response, retrying... (5)
21:55:06 T:2773791840 INFO: AddOnLog: MediaPortal PVR Client: Channel stream URL: rtsp://192.168.2.5/stream3.0, timeshift buffer: F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer
21:55:06 T:2773791840 INFO: AddOnLog: MediaPortal PVR Client: Creating a new TsReader...
21:55:06 T:2773791840 NOTICE: AddOnLog: MediaPortal PVR Client: CTsReader::Open(F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer)
21:55:06 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: Multiseat mode; need to translate 'F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer' to UNC filename.
21:55:06 T:2773791840 INFO: AddOnLog: MediaPortal PVR Client: CTsReader:TranslatePath F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer -> smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer
21:55:06 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: FileReader::OpenFile() Trying to open smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer
21:55:06 T:2773791840 INFO: AddOnLog: MediaPortal PVR Client: FileReader::OpenFile() smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer.
21:55:06 T:2773791840 DEBUG: CSmbFile::Open - opened RecordedTV/TS/live3-0.ts.tsbuffer, fd=10000
21:55:06 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: OpenFile: OpenFile(smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer) succeeded.
21:55:06 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: MultiFileReader: buffer file opened return code 0.
21:55:06 T:2773791840 DEBUG: CSmbFile::Open - opened RecordedTV/TS/live3-0.ts.tsbuffer1.ts, fd=10001
21:55:06 T:2773791840 DEBUG: CSmbFile::Close closing fd 10001
21:55:07 T:2773791840 DEBUG: PVRFile - Open - playback has started on filename pvr://channels/tv/All TV channels/4.pvr
21:55:07 T:2773791840 DEBUG: CDVDInputStreamPVRManager::Open - stream opened: pvr://channels/tv/All TV channels/4.pvr
21:55:07 T:2773791840 NOTICE: Creating Demuxer
21:55:07 T:2773791840 DEBUG: DllAvUtilBase: Using libavutil system library
21:55:07 T:2773791840 DEBUG: DllAvCodec: Using libavcodec system library
21:55:07 T:2773791840 DEBUG: DllAvFormat: Using libavformat system library
21:55:07 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: FileReader::OpenFile() Trying to open smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer1.ts
21:55:07 T:2773791840 INFO: AddOnLog: MediaPortal PVR Client: FileReader::OpenFile() smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer1.ts.
21:55:07 T:2773791840 DEBUG: CSmbFile::Open - opened RecordedTV/TS/live3-0.ts.tsbuffer1.ts, fd=10001
21:55:07 T:2773791840 DEBUG: AddOnLog: MediaPortal PVR Client: OpenFile: OpenFile(smb://Guest@HPPROLIANT/RecordedTV/TS/live3-0.ts.tsbuffer1.ts) succeeded.
...not very helpful, I'm afraid
After this happens, Previewing channels within MP SetupTV still work fine; and in fact whilst previewing, I can browse from the freshly-crashed XBMC box to the TS folder and play the TS file of the channel being previewed!
This particular log is from a Pi; but OpenELEC (version 3.2.3 Official) on my 2 other HTPC's (one an ION_64 build of OpenELEC; the other a GENERIC build) produce the same behavior.
Looks like a similar issue as to that reported
here.
So there's a possibility it's related to the Server. Or interaction between XBMC on Linux-based builds (such as OE) and the server.
The server logs don't yield much: "streaming server.Log" contains:
Code:
03-11-2013 22:17:42.893 Stream server: add timeshift mpeg-2 transport stream stream3.0 filename:F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer
03-11-2013 22:17:42.893 Stream server: url for stream is rtsp://192.168.2.5/stream3.0
03-11-2013 22:17:43.876 Stream server:Stream server: remove stream stream3.0
My "MPFileWriter.Log" after a crash is
here.
My "TVService.Log" after a crash is
here. It ends like this:
Code:
[2013-11-03 22:17:40,694] [Log ] [3 ] [DEBUG] - TVServerXBMC: OnTvServerEvent: StartTimeShifting
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - Controller: epg stop
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - card: StartTimeShifting 3 F:\Contents\Videos\Recorded TV\TS\live3-0.ts
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - card: CAM enabled : False
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - analog:SetTimeShiftFileName:F:\Contents\Videos\Recorded TV\TS\live3-0.ts
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - analog:SetTimeShiftFileName: uses .ts
[2013-11-03 22:17:40,694] [Log ] [3 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
[2013-11-03 22:17:42,878] [Log ] [5 ] [INFO ] - PID seen - type = Audio
[2013-11-03 22:17:42,878] [Log ] [5 ] [INFO ] - audioVideoEventHandler Audio
[2013-11-03 22:17:42,878] [Log ] [5 ] [INFO ] - PID seen - type = Video
[2013-11-03 22:17:42,878] [Log ] [5 ] [INFO ] - audioVideoEventHandler Video
[2013-11-03 22:17:42,878] [Log ] [3 ] [INFO ] - card: WaitForFile - video and audio are seen after 2.1840038 seconds
[2013-11-03 22:17:42,893] [Log ] [3 ] [INFO ] - user:XBMCpvrclient15 card:3 sub:0 add stream:F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer
[2013-11-03 22:17:42,893] [Log ] [3 ] [INFO ] - RTSP: add stream stream3.0 file:F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer
[2013-11-03 22:17:42,893] [Log ] [3 ] [INFO ] - Controller: StartTimeShifting started on card:3 to F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer
[2013-11-03 22:17:42,893] [Log ] [3 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=36, tuningdetails=tv:CHAN3 Freq:247259994 Channel:70 Tuner:Antenna Video:Tuner Audio:Automatic
[2013-11-03 22:17:42,893] [Log ] [3 ] [INFO ] - Controller: XBMCpvrclient15 3 0
[2013-11-03 22:17:42,893] [Log ] [3 ] [DEBUG] - TVServerXBMC: OnTvServerEvent: EndZapChannel
[2013-11-03 22:17:42,893] [Log ] [3 ] [INFO ] - control2:XBMCpvrclient15 3 0
[2013-11-03 22:17:43,003] [Log ] [3 ] [DEBUG] - TVServerXBMC: Timeshift started for channel: 'CHAN3' on device 'Hauppauge Cx23100 Tuner'
[2013-11-03 22:17:43,003] [Log ] [3 ] [DEBUG] - TVServerXBMC: TV Server returned 'rtsp://HPProliant:554/stream3.0' as timeshift URL and F:\Contents\Videos\Recorded TV\TS\live3-0.ts.tsbuffer as timeshift file
[2013-11-03 22:17:43,003] [Log ] [3 ] [DEBUG] - TVServerXBMC: Remote server='HPProliant'
[2013-11-03 22:17:43,018] [Log ] [3 ] [DEBUG] - TVServerXBMC: StartTimeShifting took 19825 ms
[2013-11-03 22:17:43,018] [Log ] [3 ] [DEBUG] - TVServerXBMC: PlayChannel 11 => URL=rtsp://192.168.2.5/stream3.0
[2013-11-03 22:17:43,143] [Log ] [3 ] [DEBUG] - TVServerXBMC: Handling command: GetSignalQuality
[2013-11-03 22:17:43,221] [Log ] [3 ] [DEBUG] - TVServerXBMC: Connection closed
[2013-11-03 22:17:43,221] [Log ] [3 ] [DEBUG] - TVServerXBMC: OnTvServerEvent: EndTimeShifting
[2013-11-03 22:17:43,221] [Log ] [3 ] [INFO ] - Controller: StopTimeShifting 3
[2013-11-03 22:17:43,221] [Log ] [3 ] [DEBUG] - CardTuner.RequestCardStopReservation: placed reservation with id=37, user=XBMCpvrclient15
[2013-11-03 22:17:43,330] [Log ] [3 ] [DEBUG] - CardTuner.Stop: ticket id=37, found=True
[2013-11-03 22:17:43,330] [Log ] [3 ] [INFO ] - Stop cardid=3, ticket=37, tunestate=Idle, stopstate=Stopping
[2013-11-03 22:17:43,330] [Log ] [3 ] [INFO ] - card Hauppauge Cx23100 Tuner: StopTimeShifting user:XBMCpvrclient15 sub:0
[2013-11-03 22:17:43,330] [Log ] [3 ] [DEBUG] - card not IDLE - removing user: XBMCpvrclient15
[2013-11-03 22:17:43,330] [Log ] [3 ] [DEBUG] - usermanagement.RemoveUser: XBMCpvrclient15, subch: 0 of 1, card: 3
[2013-11-03 22:17:43,330] [Log ] [3 ] [INFO ] - user:XBMCpvrclient15 remove
[2013-11-03 22:17:43,330] [Log ] [3 ] [INFO ] - analog: StopTimeShifting()
[2013-11-03 22:17:43,346] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-11-03 22:17:43,346] [Log ] [3 ] [INFO ] - analog subch:0 Decompose()
[2013-11-03 22:17:43,346] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-11-03 22:17:43,346] [Log ] [3 ] [INFO ] - tvcard:FreeAllSubChannels
[2013-11-03 22:17:43,346] [Log ] [3 ] [INFO ] - analog: StopGraph state:Running
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - analog: Graph stopped
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - tvcard:FreeAllSubChannels
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - analog: StopGraph state:Stopped
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - user:XBMCpvrclient15 remove
[2013-11-03 22:17:43,876] [Log ] [3 ] [DEBUG] - CardReservation.RemoveStopTicket: removed STOP reservation with id=37
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - Controller:Timeshifting stopped on card:3
[2013-11-03 22:17:43,876] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files F:\Contents\Videos\Recorded TV\TS\live3-0.ts
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - RTSP: remove stream stream3.0
[2013-11-03 22:17:43,876] [Log ] [3 ] [INFO ] - Controller: epg start
I've spent most of the last two days trying to figure out what's happening, but I concede - even after previously running MP + XBMC for 6 months without incident - I'm stumped! Any help would be appreciated :-)
EDIT: So in summary: the server appears to be creating the TS buffer fine. The XBMC client has access to this file. The client can play it fine manually. Just when played from the Channels list is it failing.
Shot in the dark: How much time does the PVR client addon wait for before attempting to play this buffer file? Perhaps newer versions of XBMC (used in OE) are having a problem with the file if it's too new? Too little video data to play? Samba file-share link not fully established? (I've adjusted the 'time between channel changes' addon setting to no avail)? Or am I grasping at straws... :-)