Weird problem where TV Server "half-crashes" (1 Viewer)

[Alphathon]

Recently (the past two or three weeks at a guess), I've been having a really strange issue with TV Server. It's kinda difficult to explain so bear with me.

At seemingly arbitrary times it will stop writing to the log files, and after that point will not record anything. Also, if after this point one tries to watch TV via the client (single seat) the client will stop working. The client is however able to access channel lists, the EPG etc, so the TV Server hasn't crashed entirely. Prior to the server ceasing to work it (the server) works normally, with recordings, watching of TV etc working as expected.

On some, rarer occasions a similar and probably related issue manifests, where the server identifies all the cards as "N/A" (rather than DVB-S, DVB-T etc), so won't tune anything. When this happens, the Client simply says there is no free card available rather than locking up. I'm not sure if it writes to the logs when this happens. This, unlike the other issue manifests as soon as the server starts up - there is no period prior to it not working where it behaves normally.

In both cases a restart of the TV server fixes the issue. With the former TvService.exe has to be manually killed from the task manager; the service cannot be stopped from within the config utility or from within the Windows services windows (services.msc or the "services" tab of the task manager) - when trying to do so, it will sit in the "stopping" state indefinitely.

My hypothesis for the linking of the two is that whatever is causing the second problem ("N/A" type cards) is the same as the first, but with the first it manifests later and thus rather than the cards simply not being recognised properly it ceases to be able to access them in the way it is supposed to (i.e. it tries to access a card as, say, DVB-T but can't). It should be noted that I have three TV cards (listed in my system specs), and this affects all of them, as well as the integrated Radio Webstream soft-card.

Since the TV server stops writing to the logs during this problem I'm not sure if posting logs would be any use. I've had a look and I've seen multiple different things listed as the last items in the logs. The most recent, which seems to be it gearing up to record an episode of Family Guy on VIVA Deutschland, is posted below. However, as I said, there seems to be no pattern with what is the last recorded action in the log. For example, I remember seeing something along the lines of "RemoteControl - Connected" repeated several times on one occasion.

2012-09-11 20:15:14.220326 [scheduler thread(10)]: Scheduler: Check recordings for schedule Family Guy...
2012-09-11 20:15:14.316332 [scheduler thread(10)]: Scheduler: Time to record VIVA Deutschland 20:15-20:50 Family Guy
2012-09-11 20:15:14.319332 [scheduler thread(10)]: Controller: find free card for channel VIVA Deutschland
2012-09-11 20:15:14.322332 [scheduler thread(10)]: Controller: find card for channel VIVA Deutschland
2012-09-11 20:15:14.326332 [scheduler thread(10)]: Controller:  got 1 tuning details for VIVA Deutschland
2012-09-11 20:15:14.330332 [scheduler thread(10)]: Controller:  channel #1 DVBS:tv:MTV Networks Europe VIVA Germany Freq:11973000 ONID:1 TSID:1078 SID:28676 PMT:0x1A0 FTA:True LCN:3494 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:Level1AB band:Universal Pilot:NotSet RollOff:NotSet
2012-09-11 20:15:14.334333 [scheduler thread(10)]: Controller:    card:18 type:DvbS can tune to channel
2012-09-11 20:15:14.337333 [scheduler thread(10)]: Controller:    card:18 type:DvbS users: 0
2012-09-11 20:15:14.341333 [scheduler thread(10)]: Controller:    card:19 type:DvbS can tune to channel
2012-09-11 20:15:14.344333 [scheduler thread(10)]: Controller:    card:19 type:DvbS users: 0
2012-09-11 20:15:14.348333 [scheduler thread(10)]: Controller:    card:14 type:DvbT cannot tune to channel
2012-09-11 20:15:14.350334 [scheduler thread(10)]: Controller:    card:15 type:DvbT cannot tune to channel
2012-09-11 20:15:14.353334 [scheduler thread(10)]: Controller:    card:5 type:DvbT cannot tune to channel
2012-09-11 20:15:14.356334 [scheduler thread(10)]: Controller:    card:4 type:DvbT cannot tune to channel
2012-09-11 20:15:14.358334 [scheduler thread(10)]: Controller:    card:2 type:DvbC is disabled
2012-09-11 20:15:14.361334 [scheduler thread(10)]: Controller:    card:3 type:DvbC is disabled
2012-09-11 20:15:14.364334 [scheduler thread(10)]: Controller:    card:6 type:DvbT is disabled
2012-09-11 20:15:14.367335 [scheduler thread(10)]: Controller:    card:7 type:DvbT is disabled
2012-09-11 20:15:14.370335 [scheduler thread(10)]: Controller:    card:11 type:RadioWebStream is disabled
2012-09-11 20:15:14.373335 [scheduler thread(10)]: Controller:    card:10 type:Analog cannot tune to channel
2012-09-11 20:15:14.376335 [scheduler thread(10)]: Controller: found 2 card(s) for channel
2012-09-11 20:15:14.378335 [scheduler thread(10)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 56 msec
2012-09-11 20:15:14.381335 [scheduler thread(10)]: Controller:    card:18 type:DvbS is available
2012-09-11 20:15:14.384336 [scheduler thread(10)]: Controller:    card:19 type:DvbS is available
2012-09-11 20:15:14.387336 [scheduler thread(10)]: Controller: found 2 free card(s)
2012-09-11 20:15:14.389336 [scheduler thread(10)]: AdvancedCardAllocation.GetFreeCardsForChannel took 70 msec
2012-09-11 20:15:14.392336 [scheduler thread(10)]: scheduler: try max 2 of 2 FREE cards for recording
2012-09-11 20:15:14.396336 [scheduler thread(10)]: Controller: epg stop
2012-09-11 20:15:14.407337 [scheduler thread(10)]: user:epg remove
2012-09-11 20:15:14.409337 [scheduler thread(10)]: Scheduler : record, first tune to channel
2012-09-11 20:15:14.412337 [scheduler thread(10)]: card: Tune 18 to VIVA Germany
2012-09-11 20:15:14.415337 [scheduler thread(10)]: card: user: scheduler4087:18:-1 tune DVBS:tv:MTV Networks Europe VIVA Germany Freq:11973000 ONID:1 TSID:1078 SID:28676 PMT:0x1A0 FTA:True LCN:3494 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:Level1AB band:Universal Pilot:NotSet RollOff:NotSet
2012-09-11 20:15:14.427338 [scheduler thread(10)]: dvbs: Tune:DVBS:tv:MTV Networks Europe VIVA Germany Freq:11973000 ONID:1 TSID:1078 SID:28676 PMT:0x1A0 FTA:True LCN:3494 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:Level1AB band:Universal Pilot:NotSet RollOff:NotSet
2012-09-11 20:15:14.430338 [scheduler thread(10)]: dvbs:  Tune:DVBS:tv:MTV Networks Europe VIVA Germany Freq:11973000 ONID:1 TSID:1078 SID:28676 PMT:0x1A0 FTA:True LCN:3494 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:Level1AB band:Universal Pilot:NotSet RollOff:NotSet
2012-09-11 20:15:14.433338 [scheduler thread(10)]: dvb:GetNewSubChannel:0 #1

I intend to compile a set of logs of when this manifests, but as yet I only have today's. I'll post them once I have if need be.

Further information:
I have not changed my MediaPortal setup recently, so this hasn't been caused by the addition of a new plugin/extension. It may however be some kind of conflict with another piece (or pieces) of software, since that kind of thing changes all the time.

 

[mm1352000]

Hello Alphathon

Looks like a problem that I'm familiar with - TsWriter deadlock, related to the EPG grabber.

@DJBlu thinks he may have found the problem. There is a patch for MP 1.3a -->here<--. I *think* that may still work for MP 1.2.3. Worth giving it a crack.

Re: tuners showing up as type N/A (unknown)...
This is likely unrelated.
Do you use standby/resume, or does the PC get shutdown?
The NOVA-T 500 is famed for its slow startup... so I guess you have a TV service startup delay?
http://wiki.team-mediaportal.com/1_...ration/06_General#Delay_for_TV_card_detection

Maybe try bumping it up a little more.

mm

 

[Alphathon]

Thanks, I'll give the patch a try tomorrow. What exactly is TsWriter deadlock, and is there any way to alleviate it beyond the patch (through particular settings etc)?

As for the N/A tuners, no, I don't use standby or hibernate other than on very rare occasions, and haven't done so since long before the problem has manifested. I don't use startup delay, but I've never had any problems in that regard before so I never tried.

 

[mm1352000]

Thanks, I'll give the patch a try tomorrow. What exactly is TsWriter deadlock, and is there any way to alleviate it beyond the patch (through particular settings etc)?

It is technical - a little difficult to explain.
You might think of a deadlock like two children fighting over a toy. The toy has to be shared for optimal happiness; when one child refuses to give up the toy, bad things happen.

TsWriter (responsible for TV Server grunt work like writing recording and timeshifting files to disk, decoding the service information in the stream, grabbing and decoding EPG etc.) has "toys" called locks. These are used to ensure that TV Server keeps functioning correctly when you're recording/timeshifting multiple channels with a single tuner. Sometimes, certain sequences of events or bugs or corruptions in the stream seem to be able to cause TsWriter to not release these locks when it should. Like a child that doesn't want to share their toys with another child, this causes major problems for the TV library and wider TV service. TsWriter becomes unresponsive, and this causes all the other symptoms (eg. requiring task manager to kill TVService.exe, live TV not starting, recordings not working).

Some people have reported success by unticking "enable CRC check" in the DVB EPG grabber section of TV Server configuration. Other than that, there is nothing I can suggest except trying the patch or not using the EPG grabber at all.

This deadlock has been a very frustrating issue for us as we haven't been able to find a way to consistently reproduce it. We would *really* appreciate it if you could help us in this regard by testing the patch and reporting your results. If this is happening to you on a regular basis - even hourly - then it also might help if we could get a sample of the full stream from your TV provider. The tv.log and TsWriter***.log are also critical pieces of information.

As for the N/A tuners, no, I don't use standby or hibernate other than on very rare occasions, and haven't done so since long before the problem has manifested. I don't use startup delay, but I've never had any problems in that regard before so I never tried.

At this point I'm not able to imagine how the N/A tuner issue could be connected to the deadlock. I'll keep considering...

mm

 

[Alphathon]

TsWriter becomes unresponsive, and this causes all the other symptoms (eg. requiring task manager to kill TVService.exe, live TV not starting, recordings not working.

That's something else I should probably have mentioned: recordings still play fine when this happens as far as I can tell. I only really use the TV portion of MP, so I don't know if other parts also function properly.

Some people have reported success by unticking "enable CRC check" in the DVB EPG grabber section of TV Server configuration. Other than that, there is nothing I can suggest except trying the patch or not using the EPG grabber at all.

That's a shame. I don't use CRC check as it is.

This deadlock has been a very frustrating issue for us as we haven't been able to find a way to consistently reproduce it. We would *really* appreciate it if you could help us in this regard by testing the patch and reporting your results. If this is happening to you on a regular basis - even hourly - then it also might help if we could get a sample of the full stream from your TV provider. The tv.log and TsWriter***.log are also critical pieces of information.

I'll do what I can, assuming it is a deadlock problem. As for frequency, I've never had it manifest more than once a day to my knowledge (although I don't normally notice until I see a scheduled recording in the EPG which should be recording "now" but isn't; I watch most of my TV after the fact), and it happens maybe 4 days a week, although that's a very rough guess. In my case I wouldn't be at all surprised if it's related to mysql timeouts, since I've had quite a few of those since installing my sat card (presumably due to the database roughly trebling in size), in fact, I had to set WebEPG to export to XMLTV rather than writing to the database itself since the built in one didn't seem to be able to handle it (worked fine before when only 4 channels were being imported, but now I have ≈100 14 day listings, although many of those are duplicated for regional channel variations).

 

[Phathid]

This sounds like my issue except my computer completely locks up and I have to restart by holding the power button (task manager won't even appear)

Only started happening with 1.3 alpha so am loss tempted to go back to 1.2.3 if the patch doesn't work

 

[mm1352000]

This sounds like my issue except my computer completely locks up and I have to restart by holding the power button (task manager won't even appear)

Only started happening with 1.3 alpha so am loss tempted to go back to 1.2.3 if the patch doesn't work

I suggest you post logs before doing that. There is every chance that it is something totally different.

 

[Paranoid Delusion]

A total system crash is more likely to be hardware or driver related, memory\power supplies failing are very common at causing these kind of symptoms, as have had both happen to me a few times over the years.

 

[Alphathon]

Well, while I can't say it's fixed the problem yet (we'll see) the patched TsWriter.ax certainly seems to be compatible with 1.2.3. I'll keep you posted.

 

[Alphathon]

So far so good; everything that was supposed to be recorded has been since switching to the new TsWriter.ax, and the TV Server has remained responsive.

I have however had the "N/A" tuner error, but looking at the logs this does seem to be a separate issue related to the TV Service being unable to access the database when it starts up. My thinking in this case is maybe the TV Service starts up prior to MySQL being ready. Are there any changes to either (perhaps change the boot order somehow) I can set so as to make sure the server is ready to be accessed before the TV server tries to start up?