[confirm] TV-server crash (1 Viewer)

[HakanThn]

MediaPortal Version: 1.2 Beta
MediaPortal Skin: PurevisionHD
Windows Version: Vista Home Premium 64bit
CPU Type: AMD 4850e
HDD: Samsung Spinpoint F1 1TB
Memory: 4GB 800
Motherboard: Gigabyte GA-MA78GM-S2H
Video Card: HD4550
Video Card Driver: Catalyst 10.2
Sound Card:
Sound Card AC3:
Sound Card Driver:
1. TV Card: Digital Devices Cine-S2
1. TV Card Type: DVB-S2
1. TV Card Driver:
2. TV Card: Hauppauge Nova-TD
2. TV Card Type: DVB-T
2. TV Card Driver:
3. TV Card:
3. TV Card Type:
3. TV Card Driver:
4. TV Card:
4. TV Card Type:
4. TV Card Driver:
MPEG2 Video Codec: (SAF v4)
MPEG2 Audio Codec:
h.264 Video Codec:
Satelite/CableTV Provider: Canal Digital Sweden
HTPC Case: Chieftec HM-03
Cooling:
Power Supply:
Remote: iMON
TV: Hyundai Q400 & LGW1952
TV - HTPC Connection: HDMI through Harman Kardon AVR255 and Gefen HDMI detective

Not sure if my problem is a 1.2 bug, but I give it a try.

TV-server hangs now and then on my system, I think it is connected to recordings. Have though not found a way to reproduce it at will. Have now been using MP 1.2B for a week, and it seems more stable. Today I had a TV-server hang again though.

Here's what happened:
While watching an on-going recording with about 30 min delay, there was some problems with the playback during a few seconds: video froze for about a second a few times, but after that the playback continued without problems.
This was probably at 21:38.
When the show ends, we discovered that MediaPortal was not responding (although playback continued).
Solved the problem by stopping the TV-service using Task manager and the TV-service was automatically restarted (at least that's what I think happened), and MediaPortal is working again. This was at 22:09.

Logs attached. Hope someone can see the problem in them. Thx.

 

[mm1352000]

Hi HakanThn

I'm sorry to say that your logs are essentially useless. The MP client logs are not included, and the TV logs stop at around 21:30. I don't see any errors from earlier in the logs either. Unless you can reproduce the problem again and provide full logs we will have to mark this as "not reproducible"...

mm

 

[HakanThn]

Many thx for looking at the logs.
Yes, TV server logs are empty between 21:38 and 22:09, when I assume it hangs. Hoped that there would be some error signs before that.

Very stupid of me not to include MP client logs! Now they have been erased.
I will try again next time it occurs.

Is there any idea for me to use any "debug" mode of TV-server, for log collecting etc?

 

[mm1352000]

Many thx for looking at the logs.

No problem

Hoped that there would be some error signs before that.

Unfortunately not - at least not that I can see.

I will try again next time it occurs.

Please do - I'd be happy to take look...

Is there any idea for me to use any "debug" mode of TV-server, for log collecting etc?

Are you using a single seat or multiseat setup? On a single seat setup the debug mode will include both TV Server and MediaPortal logs. The TV Server only has one logging level, so any logs are "debug" logs. With these kinds of freezes both sets of logs are important, but the MediaPortal client logs are possibly slightly more important...

mm

 

[Seidelin]

I set the thread status to further info missing. Of course that should be updated when you are able to provide proper logs.

 

[HakanThn]

Hi again,
I managed to find a way to reproduce a TV-server crash, and this time I think I also have complete logs

Here´s what I did:
Started MP in debug mode.
Started one recording on my DVB-T tuner, and another on one of the DVB-S2 tuners.
19:15: Started watching a HD channel on the second DVB-S2 tuner.
The channel is shown ok at first, but soon starts to freeze the picture more and more, and after a few minutes stops completely.
Checked in task manager: TV-service is stopped. Process "dw20.exe" (microsoft .net error reporting) use 50% CPU during a few minutes.
19:20: Restarted TV-service manually.
MP works again. Recordings are restarted automatically.
Tried to watch a channel again, but get only a black screen. (First time a saw this problem I instead got message "Program/channel not found", see below.)

I hope you can find something in the logs.

I see that there´s also a .bak file of TV-server log in the zip file. It includes the first time with this error, but seemingly with at different error code: (not run in debug mode)
2011-06-19 16:56 picture freeze, message: "No connection"
Here´s what I did this first time with this error:
Was watching a HD channel (S2 card).
Started recording of two SD channels, one on T and one on S2 card.
Got message: "Timeshifting stopped due to scheduled recording"
Tried to start watching the HD channel again, and it worked for about a minute.
At 16.56 picture freeze, message: "No connection"
In task manager: dw20.exe (microsoft .net error reporting) use 50% CPU during a few minutes. During this time, both MP and TV-server seems to halt.
MP is after this very difficult to control, very slow response
At 17.12 checked in task manager: TV-service is stopped. Restarted TV-service manually.
MP works again. Recordings are restarted automatically.
Tried to watch HD channel again. Error message "Program/channel not found".
Tried other channels - most channels don't work.
17.25 stopped recordings. Now channels do work, long time to start though.


As said before, I´m not sure the problem is connected with MP 1.2 Beta, since I had TV-server problems also in 1.1.3.
Thx for your help.

 

[mm1352000]

Thanks for the logs!

Your description with the times included was very helpful for identifying the problems. The first issue seems to start here:

[COLLAPSE]2011-06-19 19:15:45.519433 [(18)]: card: Tuner locked: True

2011-06-19 19:15:45.520433 [(18)]: **************************************************

2011-06-19 19:15:45.521433 [(18)]: ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****

2011-06-19 19:15:45.522433 [(18)]: **************************************************

2011-06-19 19:15:45.523433 [(18)]: card: tuned user: HTPC subchannel: 0

2011-06-19 19:15:45.524433 [(18)]: user:HTPC add

2011-06-19 19:15:45.525433 [(18)]: card2:HTPC 7 0

2011-06-19 19:15:45.526433 [(18)]: Controller: HTPC 7 0

2011-06-19 19:15:45.528433 [(18)]: control2:HTPC 7 0

2011-06-19 19:15:45.533433 [(18)]: Controller: delete timeshift files D:\Timeshiftbuffer\live7-0.ts

2011-06-19 19:15:45.547433 [(18)]: card: StartTimeShifting 7 D:\Timeshiftbuffer\live7-0.ts

2011-06-19 19:15:45.549433 [(18)]: card: CAM enabled : True

2011-06-19 19:15:45.552433 [(18)]: subch:0 SetTimeShiftFileName:\Timeshiftbuffer\live7-0.ts

2011-06-19 19:15:45.553433 [(18)]: Set video / audio observer

2011-06-19 19:15:45.560433 [(18)]: subch:0 SetTimeShiftFileName fill in pids

2011-06-19 19:15:45.581433 [(18)]: subch:0-0 tswriter StartTimeshifting...

2011-06-19 19:15:45.588433 [(18)]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo

2011-06-19 19:15:45.759433 [(16)]: PID seen - type = Video

2011-06-19 19:15:45.762433 [(16)]: audioVideoEventHandler Video

2011-06-19 19:15:45.784433 [(16)]: PID seen - type = Audio

2011-06-19 19:15:45.785433 [(16)]: audioVideoEventHandler Audio

2011-06-19 19:15:45.786433 [(18)]: card: WaitForTimeShiftFile - video and audio are seen after 0,198 seconds

2011-06-19 19:15:45.794433 [(18)]: TimeshiftingEPG: channel National Geographic HD is not configured for grabbing epg

2011-06-19 19:15:45.795433 [(18)]: user:HTPC card:7 sub:0 add stream:\Timeshiftbuffer\live7-0.ts.tsbuffer

2011-06-19 19:15:45.797433 [(18)]: RTSP: start streamer

2011-06-19 19:15:45.801433 [RTSP Streaming thread(22)]: RTSP: Streamer started

2011-06-19 19:15:45.802433 [(18)]: RTSP: add stream stream7.0 file:\Timeshiftbuffer\live7-0.ts.tsbuffer

2011-06-19 19:15:45.807433 [(18)]: Controller: StartTimeShifting started on card:7 to D:\Timeshiftbuffer\live7-0.ts.tsbuffer

2011-06-19 19:15:45.832433 [Channel state thread(23)]: Controller: DoSetChannelStates for 67 channels

2011-06-19 19:15:45.840433 [(16)]: PID seen - type = Audio

2011-06-19 19:15:45.844433 [(16)]: audio last seen at 2011-06-19 19:15:45

2011-06-19 19:15:45.848433 [(18)]: CiMenuSupported called cardid 7

2011-06-19 19:15:45.849433 [(18)]: CiMenuSupported card Digital Devices DVB-S/S2 Tuner 1 supported: True

2011-06-19 19:15:45.853433 [(18)]: CiMenu: registered client event for callback

2011-06-19 19:15:45.856433 [(18)]: TvController: EnableCiMenuHandler called

2011-06-19 19:15:45.857433 [(18)]: TvController: SetCiMenuHandler: result True

2011-06-19 19:15:45.865433 [Channel state thread(23)]: ChannelStates.GetChannelMapping took 27 msec

2011-06-19 19:15:45.899433 [Channel state thread(23)]: ChannelStates.GetTuningChannels took 30 msec

2011-06-19 19:15:45.914433 [Channel state thread(23)]: ChannelStates.GetAllTimeshiftingAndRecordingChannels took 10 msec

2011-06-19 19:15:45.922433 [Channel state thread(23)]: ChannelStates.DoSetChannelStates took 91 msec

2011-06-19 19:16:11.140433 [PowerScheduler poll thread(15)]: NetworkMonitorHandler: idle limit in KB/s: 2

2011-06-19 19:16:11.142433 [PowerScheduler poll thread(15)]: ActiveSharesHandler: Share monitoring is disabled.

2011-06-19 19:17:12.269433 [PowerScheduler poll thread(15)]: NetworkMonitorHandler: idle limit in KB/s: 2

2011-06-19 19:17:12.271433 [PowerScheduler poll thread(15)]: ActiveSharesHandler: Share monitoring is disabled.

2011-06-19 19:18:06.053433 [(18)]: CiMenuSupported called cardid 7

2011-06-19 19:18:06.055433 [(18)]: CiMenuSupported card Digital Devices DVB-S/S2 Tuner 1 supported: True

2011-06-19 19:18:13.442433 [PowerScheduler poll thread(15)]: NetworkMonitorHandler: idle limit in KB/s: 2

2011-06-19 19:18:13.448433 [PowerScheduler poll thread(15)]: ActiveSharesHandler: Share monitoring is disabled.

2011-06-19 19:19:16.664433 [HeartBeatMonitor(10)]: Controller: Heartbeat Monitor - kicking idle user HTPC

2011-06-19 19:19:17.598433 [HeartBeatMonitor(10)]: Controller: StopTimeShifting 7

2011-06-19 19:19:17.612433 [MPMain(1)]: TCP connect took : 32

2011-06-19 19:19:17.613433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.622433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.628433 [HeartBeatMonitor(10)]: card: StopTimeShifting user:HTPC sub:0

2011-06-19 19:19:17.629433 [HeartBeatMonitor(10)]: card not IDLE - removing user: HTPC

2011-06-19 19:19:17.633433 [HeartBeatMonitor(10)]: user:HTPC remove

2011-06-19 19:19:17.636433 [HeartBeatMonitor(10)]: subch:0-0 tswriter StopTimeshifting...

2011-06-19 19:19:17.670433 [MPMain(1)]: TCP connect took : 3

2011-06-19 19:19:17.671433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.699433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.719433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.720433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:17.766433 [MPMain(1)]: RemoteControl - Connected

2011-06-19 19:19:19.917433 [MPMain(1)]: TCP connect took : 918[/COLLAPSE]

You started the two recordings and then started watching a 3rd channel. After some time we see the line that I highlighed. Why would the Heartbeat Monitor kick you from watching the channel while you're still watching it? I don't know. Unfortunately I don't understand that area of MP very well...

With the earlier error, I see *exactly* the same thing:

[COLLAPSE]2011-06-19 16:54:27.748000 [(3)]: card: Tuner locked: True

2011-06-19 16:54:27.753000 [(3)]: **************************************************

2011-06-19 16:54:27.758000 [(3)]: ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****

2011-06-19 16:54:27.763000 [(3)]: **************************************************

2011-06-19 16:54:27.768000 [(3)]: card: tuned user: HTPC subchannel: 0

2011-06-19 16:54:27.773000 [(3)]: user:HTPC add

2011-06-19 16:54:27.778000 [(3)]: card2:HTPC 8 0

2011-06-19 16:54:27.784000 [(3)]: Controller: HTPC 8 0

2011-06-19 16:54:27.789000 [(3)]: control2:HTPC 8 0

2011-06-19 16:54:27.796000 [(3)]: Controller: delete timeshift files D:\Timeshiftbuffer\live8-0.ts

2011-06-19 16:54:27.806000 [(3)]: card: StartTimeShifting 8 D:\Timeshiftbuffer\live8-0.ts

2011-06-19 16:54:27.811000 [(3)]: card: CAM enabled : True

2011-06-19 16:54:27.816000 [(3)]: subch:0 SetTimeShiftFileName:\Timeshiftbuffer\live8-0.ts

2011-06-19 16:54:27.821000 [(3)]: Set video / audio observer

2011-06-19 16:54:27.830000 [(3)]: subch:0 SetTimeShiftFileName fill in pids

2011-06-19 16:54:27.853000 [(3)]: subch:0-0 tswriter StartTimeshifting...

2011-06-19 16:54:27.861000 [(3)]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo

2011-06-19 16:54:27.871000 [(14)]: PID seen - type = Audio

2011-06-19 16:54:27.876000 [(14)]: audioVideoEventHandler Audio

2011-06-19 16:54:27.896000 [(14)]: PID seen - type = Video

2011-06-19 16:54:27.901000 [(14)]: audioVideoEventHandler Video

2011-06-19 16:54:27.907000 [(3)]: card: WaitForTimeShiftFile - video and audio are seen after 0,044 seconds

2011-06-19 16:54:27.918000 [(3)]: TimeshiftingEPG: channel National Geographic HD is not configured for grabbing epg

2011-06-19 16:54:27.925000 [(3)]: user:HTPC card:8 sub:0 add stream:\Timeshiftbuffer\live8-0.ts.tsbuffer

2011-06-19 16:54:27.931000 [(3)]: RTSP: add stream stream8.0 file:\Timeshiftbuffer\live8-0.ts.tsbuffer

2011-06-19 16:54:27.939000 [(3)]: Controller: StartTimeShifting started on card:8 to D:\Timeshiftbuffer\live8-0.ts.tsbuffer

2011-06-19 16:54:27.948000 [Channel state thread(25)]: Controller: DoSetChannelStates for 67 channels

2011-06-19 16:54:27.963000 [(3)]: CiMenuSupported called cardid 8

2011-06-19 16:54:27.970000 [(3)]: CiMenuSupported card Digital Devices DVB-S/S2 Tuner 2 supported: True

2011-06-19 16:54:27.978000 [(3)]: CiMenu: registered client event for callback

2011-06-19 16:54:27.984000 [Channel state thread(25)]: ChannelStates.GetChannelMapping took 27 msec

2011-06-19 16:54:27.991000 [(17)]: TvController: EnableCiMenuHandler called

2011-06-19 16:54:27.998000 [(17)]: TvController: SetCiMenuHandler: result True

2011-06-19 16:54:28.003000 [(14)]: PID seen - type = Audio

2011-06-19 16:54:28.008000 [(14)]: audio last seen at 2011-06-19 16:54:27

2011-06-19 16:54:28.027000 [Channel state thread(25)]: ChannelStates.GetTuningChannels took 36 msec

2011-06-19 16:54:28.041000 [Channel state thread(25)]: ChannelStates.GetAllTimeshiftingAndRecordingChannels took 7 msec

2011-06-19 16:54:28.053000 [Channel state thread(25)]: ChannelStates.DoSetChannelStates took 101 msec

2011-06-19 16:55:10.598000 [PowerScheduler poll thread(15)]: NetworkMonitorHandler: idle limit in KB/s: 2

2011-06-19 16:55:10.685000 [PowerScheduler poll thread(15)]: ActiveSharesHandler: Share monitoring is disabled.

2011-06-19 16:55:23.518000 [(12)]: dvb:abort grabbing epg

2011-06-19 16:55:24.483000 [(12)]: Timeshifting epg grabber stopped.

2011-06-19 16:55:29.159000 [EPG Update thread(26)]: schedule.SynchProgramStatesForAll

2011-06-19 16:56:12.013000 [PowerScheduler poll thread(15)]: NetworkMonitorHandler: idle limit in KB/s: 2

2011-06-19 16:56:12.114000 [PowerScheduler poll thread(15)]: ActiveSharesHandler: Share monitoring is disabled.

2011-06-19 16:56:15.331000 [Digital Devices CiMenuHandler(16)]: Menu received (ID 1 Type 1 Choices 1)

2011-06-19 16:56:15.429000 [Digital Devices CiMenuHandler(20)]: Menu received (ID 1 Type 1 Choices 1)

2011-06-19 16:56:15.567000 [Digital Devices CiMenuHandler(20)]: Digital Devices:error in CiMenuHandler thread

System.NullReferenceException: Objektreferensen har inte angetts till en instans av ett objekt.



Server stack trace:

vid TvPlugin.TVHome.ProcessCiMenu(CiMenu Menu)

vid CiMenuHandler.CiMenuCallback(CiMenu Menu)

vid TvLibrary.Interfaces.CiMenuCallbackSink.FireCiMenuCallback(CiMenu Menu)

vid System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)

vid System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)

vid System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext)



Exception rethrown at [0]:

vid System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)

vid System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)

vid TvLibrary.Interfaces.CiMenuCallbackSink.FireCiMenuCallback(CiMenu Menu)

vid TvService.TVController.CheckForCallback()

vid TvService.TVController.OnCiMenuChoice(Int32 nChoice, String lpszText)

vid TvLibrary.Implementations.DVB.DigitalDevices.ProcessCamMenu(DD_CAM_MENU_DATA CiMenu)

vid TvLibrary.Implementations.DVB.DigitalDevices.CiMenuHandler()

2011-06-19 16:56:20.603000 [(28)]: SelectCiMenu called

2011-06-19 16:56:24.950000 [Digital Devices CiMenuHandler(16)]: Menu received (ID 2 Type 1 Choices 1)

2011-06-19 16:59:44.944000 [HeartBeatMonitor(23)]: Controller: Heartbeat Monitor - kicking idle user HTPC

2011-06-19 16:59:45.049000 [HeartBeatMonitor(23)]: Controller: StopTimeShifting 8

2011-06-19 16:59:45.112000 [HeartBeatMonitor(23)]: card Digital Devices DVB-S/S2 Tuner 2: StopTimeShifting user:HTPC sub:0

2011-06-19 16:59:45.121000 [HeartBeatMonitor(23)]: card: StopTimeShifting user:HTPC sub:0

2011-06-19 16:59:45.127000 [HeartBeatMonitor(23)]: card not IDLE - removing user: HTPC

2011-06-19 16:59:45.134000 [HeartBeatMonitor(23)]: user:HTPC remove

2011-06-19 16:59:45.142000 [HeartBeatMonitor(23)]: subch:0-0 tswriter StopTimeshifting...

2011-06-19 16:59:45.161000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: RemoteControl - Connected

2011-06-19 16:59:46.170000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: RemoteControl - Connected

2011-06-19 16:59:46.518000 [MPMain(1)]: RemoteControl - Connected

2011-06-19 16:59:47.177000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: RemoteControl - Connected

2011-06-19 16:59:51.177000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: TCP connect took : 999

2011-06-19 16:59:52.188000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: TCP connect took : 996

2011-06-19 16:59:52.193000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: RemoteControl - Connected

2011-06-19 16:59:54.197000 [TvClient-TvHome: HeartBeat transmitter thread(12)]: TCP connect took : 999[/COLLAPSE]

So it seems that there is definitely a problem, but I'm not sure how to solve it. I've just arrived at work so I'll need to take a look at the code when I get home.

PS: You should use "stop mode" with the Digital Devices tuners (see here and here).

 

[HakanThn]

Thx for helping me!

Here´s some more testing results:
1. Recording two channels, and start watchning a third channel, but this time the watched channel is SD not HD. Now everything works fine!
2. Reproduced problem again with a HD channel, and took some better notes on the timings: 08:22 start watching, all ok. 08:23 Picture starts to stutter a little bit, gets worse. 08:25 Picture freeze completely.08:26 log shows Heartbeat monitor kicking user. Hence the problem starts long before Heartbeat monitor kicks user. I find no sign of problem in the TV-server log before this though... (but most of the logs I don't understand ). Could the "Heartbeat monitor kick" simply be the result of the TV-server crashing?


I changed to "stop mode" for DD tuners, that did though not have any effect on this problem.

Note: At the same time I removed remnants from my old hybrid card in TV-server setup, and now it´s noticeably faster to tune to a channel! Don´t now wether its the "stop mode" or hybrid card remnants removal that made a difference.

 

[Seidelin]

Here´s some more testing results:
1. Recording two channels, and start watchning a third channel, but this time the watched channel is SD not HD. Now everything works fine!
2. Reproduced problem again with a HD channel, and took some better notes on the timings: 08:22 start watching, all ok. 08:23 Picture starts to stutter a little bit, gets worse. 08:25 Picture freeze completely.08:26 log shows Heartbeat monitor kicking user. Hence the problem starts long before Heartbeat monitor kicks user. I find no sign of problem in the TV-server log before this though... (but most of the logs I don't understand ). Could the "Heartbeat monitor kick" simply be the result of the TV-server crashing?

Where are those logs? Did you forget to attach them

 

[HakanThn]

Where are those logs? Did you forget to attach them

Sorry, thought you didn´t need them since the error was identical

Here are some of the logs from the event described in last post, though not collected with debug mode. Time of TV server crash is 2011-06-20 08:22 to 08:26.