TVServer stops 'serving'...? (1 Viewer)

[CanadianEh]

Good afternoon,

I'm breaking this off of another thread, since the issue I'm experiencing no longer seems to be related to the other topic ( https://forum.team-mediaportal.com/...e-when-using-spdif.118549/page-4#post-1050516 )

Anyway, so the issue is that at the end of a buffer file, the TV Server service will randomly quit creating more buffer files, causing the client PC to appear 'frozen' while watching TV. In the example below, it almost looks like the TV3BlasterPlugin caused this instance. Any thoughts as to why this would occur, or better ways to debug this?

As a first step, I am disabling the TVServerXBMC plugin I hardly use to see if things stabilize.

Thank you!

TVService.log:



[2014-01-05 13:16:24,349] [Log ] [30 ] [INFO ] - RTSP: add stream stream3.0 file:E:\Timeshift\live3-0.ts.tsbuffer

[2014-01-05 13:16:24,351] [Log ] [30 ] [INFO ] - Controller: StartTimeShifting started on card:3 to E:\Timeshift\live3-0.ts.tsbuffer

[2014-01-05 13:16:24,351] [Log ] [30 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=47, tuningdetails=tv:USAHD Freq:0 Channel:242 Country:United States Tuner:Cable Video:YRYBYInput1 AudioPDIFInput1

[2014-01-05 13:16:24,351] [Log ] [30 ] [INFO ] - Controller: ITX 3 0

[2014-01-05 13:16:24,352] [Log ] [30 ] [DEBUG] - TV3BlasterPlugin: Received TV Server Event "EndZapChannel"

[2014-01-05 13:16:24,352] [Log ] [30 ] [DEBUG] - TVServerXBMC: OnTvServerEvent: EndZapChannel

[2014-01-05 13:16:24,352] [Log ] [30 ] [DEBUG] - CardReservation.CancelCardReservation id=48

[2014-01-05 13:16:24,353] [Log ] [30 ] [INFO ] - control2:ITX 3 0

[2014-01-05 13:16:24,354] [Log ] [Channel state thread] [DEBUG] - Controller: DoSetChannelStates for 243 channels

[2014-01-05 13:16:24,357] [Log ] [30 ] [DEBUG] - CiMenuSupported called cardid 3

[2014-01-05 13:16:24,357] [Log ] [30 ] [DEBUG] - CiMenuSupported card Hauppauge HD PVR Crossbar supported: False

[2014-01-05 13:16:24,363] [Log ] [Channel state thread] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec

[2014-01-05 13:16:25,331] [Log ] [Channel state thread] [INFO ] - ChannelStates.DoSetChannelStates took 976 msec

[2014-01-05 13:21:07,069] [Log ] [30 ] [DEBUG] - TV3BlasterPlugin: Received TV Server Event "EndTimeShifting"

[2014-01-05 13:21:07,070] [Log ] [30 ] [DEBUG] - TVServerXBMC: OnTvServerEvent: EndTimeShifting

[2014-01-05 13:21:07,070] [Log ] [30 ] [INFO ] - Controller: StopTimeShifting 3

[2014-01-05 13:21:07,072] [Log ] [30 ] [DEBUG] - CardTuner.RequestCardStopReservation: placed reservation with id=49, user=ITX

[2014-01-05 13:21:07,172] [Log ] [30 ] [DEBUG] - CardTuner.Stop: ticket id=49, found=True

[2014-01-05 13:21:07,172] [Log ] [30 ] [INFO ] - Stop cardid=3, ticket=49, tunestate=Idle, stopstate=Stopping

[2014-01-05 13:21:07,172] [Log ] [30 ] [INFO ] - card Hauppauge HD PVR Crossbar: StopTimeShifting user:ITX sub:0







TSWriter.log:



[2014-01-05 13:16:24,339] [b2766a8] [14f4] - Recorder: TIMESHIFT Start 'E:\Timeshift\live3-0.ts.tsbuffer'

[2014-01-05 13:16:24,345] [b2766a8] [1260] - Recorder: TIMESHIFT start of audio detected

[2014-01-05 13:16:24,346] [b2766a8] [1260] - Recorder: TIMESHIFT start of video detected

[2014-01-05 13:16:24,379] [b2766a8] [1260] - Recorder: TIMESHIFT clear TS packet queue

[2014-01-05 13:16:24,379] [b2766a8] [1260] - CDiskRecorder::WriteToTimeshiftFile() - Reset write buffer throttle

[2014-01-05 13:16:24,379] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 376 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - Recorder: TIMESHIFT Info : Next broadcaster program clock reference rollover : 1 days 02:30:40 0

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 564 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 940 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 940 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 940 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 940 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 940 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 1880 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 1880 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 1880 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 1880 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 1880 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 3760 bytes

[2014-01-05 13:16:24,381] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 3760 bytes

[2014-01-05 13:16:24,394] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 3760 bytes

[2014-01-05 13:16:24,394] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 6016 bytes

[2014-01-05 13:16:24,394] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 7520 bytes

[2014-01-05 13:16:24,413] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 9400 bytes

[2014-01-05 13:16:24,413] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 15416 bytes

[2014-01-05 13:16:24,430] [b2766a8] [1260] - CDiskRecorder::Flush() - Throttle to 32336 bytes (max)

[2014-01-05 13:21:07,174] [b2766a8] [14f4] - Recorder: TIMESHIFT Stop 'E:\Timeshift\live3-0.ts.tsbuffer'

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - Recorder: TIMESHIFT Reset

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - CDiskRecorder::Reset() - Reset write buffer throttle

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - debug: DeleteChannel()

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pVideoAnalyzer

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - analyzer: reset

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pPmtGrabber

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pRecorder

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pTimeShifting

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pTeletextGrabber

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del m_pCaGrabber

[2014-01-05 13:21:07,175] [b2766a8] [14f4] - del done...

[2014-01-05 13:21:07,177] [b2766a8] [14f4] - CMpTsFilter:ause()

[2014-01-05 13:21:07,177] [b2766a8] [14f4] - Pause filter...

[2014-01-05 13:21:07,177] [b2766a8] [14f4] - HRESULT = 0x0

[2014-01-05 13:21:09,972] [b2766a8] [14f4] - CMpTsFilter:top()

[2014-01-05 13:21:09,972] [b2766a8] [14f4] - Stop streaming...

 

[regeszter]

Can you attache the full logs?

 

[mm1352000]

I don't think the logs shows creation of buffer files unless the files fail to be created. Equally, I think we'd have a massive number of reports of problems if TV Server just stopped creating buffer files randomly.

@CanadianEh Where were you monitoring the timeshift folder from? Client or server? If client, I'd say that the files exist on the server and the client is just not seeing an updated view of the share.

 

[CanadianEh]

@mm1352000, I was montoring the timeshift folder directly from the server. No new file was created, which explains why the client appears to freeze. I do agree with your comment that you would likely be receiving tons of reports, but this appears to be the case, at least on the surface, with something regarding my specific setup. Beyond the logging I've already provided, is there any additional logging I could turn on and then upload when this occurs again?

@regeszter there is a full set of logs in the thread I referenced above, however I will grab another set of logs when the issue occurs again. It seems to occur a couple of times a day, usually when watching hour long shows or greater.

Thanks!

 

[mm1352000]

I was montoring the timeshift folder directly from the server.

Okay... and did you F5 to refresh the folder? Also, I take it you know that TsWriter reuses buffer files as per your timeshift configuration?

I do agree with your comment that you would likely be receiving tons of reports, but this appears to be the case, at least on the surface, with something regarding my specific setup. Beyond the logging I've already provided, is there any additional logging I could turn on and then upload when this occurs again?

No there is no additional logging. We'd have to build a custom build of TsWriter to log when it creates or reuses a file to get the level of detail required to track this... but TsWriter should already log when it fails to create or reuse a buffer file. That's the thing that doesn't make sense to me. I don't mean to offend but since there are no blatant TsWriter error messages I'm currently sceptical as to whether this is happening in the way you think it is happening.

 

[CanadianEh]

You're not offending me at all I'm just puzzled by the whole thing, as well. I never had this issue until the last few MP releases, either.

As for refreshing the folder, yes I did do an F5 to make sure. I figured TsWrite would reuse buffer files, but I was just going by file timestamps. The next time the issue occurs, I'll grab both client and server logs, as well as a screenshot of my timeshift folder. I must be missing something here

Thank you again for helping figure this one out... it is bizarre.

 

[CanadianEh]

Okay, my girlfriend experienced a 'freeze' while watching live TV at approximately 11:53am this morning. Attached are server and client logs. Unfortunately, since I was not around at that time, I couldn't get a screenshot of the Timeshift folder contents.

Thank you for looking!

 

[CanadianEh]

Better yet, another freeze tonight, at approximately 5:54pm, in which I eventually pressed stop on the remote and closed the MP Client. I also was able to capture a screenshot of the timeshift folder before pressing "stop" on the remote.

Thanks!

 

[mm1352000]

I take it the screenshot doesn't match the log files?
...and did you mean to say 6:54 pm? It looks like the files were created/updated much later than 5:54 anyway. Based on the rate of file creation - one every 14 minutes - it looks like TsWriter is due to make a new one at around 6:56...

 

[CanadianEh]

Yes, sorry - I meant to type 6:54pm.

So, the logs show that MP client / tsreader is trying to open live3-0.ts.tsbuffer1.ts at 6:54pm, which is odd since I allow for several buffer files to be open, so I'm not sure why it would be reusing the first buffer file again so soon. Regardless, the tsbuffer1.ts file shows a timestamp of 6:14pm, so to me, it looks like this is an old file - unless when TVServer/tswriter reuses a file, it doesn't update the creation date/time?

Attached is a screenshot of my timeshifting settings from within the TV Server config tool. I see that I have the minimum number of files set to 3.... What does that mean in regards to my issue - should I attempt increasing the minimum number to something higher as a test?

Thanks again!