[Bug] TV: missing audio stream in records (Sky) (1 Viewer)

[radical]

Hey mm, thank again for your reply. I will take a look if I still have some Logs from this time. If Not I will "create" and provide it after the weekend.

 

[The_Stig]

If I remember right you're also using the TBS 6981. Don't you have noticed this behavior?

Yeah, you remember right. But I didnt notice this. But since I am not recording too ofter and pretty seldom I can neither confirm nor reject this case. For - as far as I can tell - everything is working perfect, as usually when mm1352000 has its hands in the game!

 

[Stéphane Lenclud]

For me the patch have "bad side effects". A second starting recording/timeshift will Interrupt the first one allready running as described in Post #75 and #76.

Ok I'll keep an eye for those issues then.

 

[radical]

@mm1352000
I found some logs I safed some time ago.

I took a quick look into it I hope I remember it right.

- 19th March
- Started watching Football at 20.30
- First recording started 20.53 (TNT)
- Second recording started at 21.38 (Sky Cinema HD)

As I remember Live TV stopped or was Interrupt with starting of the second record.
And first recording was coruppt.

Don't know if this will help.

 

[mm1352000]

Thanks for the log files.

Started watching Football at 20.30

Yes, I can see this. Tuning looks okay and it looks like all streams are decrypted successfully.

First recording started 20.53 (TNT)

Same as above.

Second recording started at 21.38 (Sky Cinema HD)

Here is where it starts to get interesting.

#1 - Configuration for the plugin slot/instance count should be the same as the configured CAM limit for the tuner

When this channel was tuned, TV Server first tried to reuse the tuner that you were using for timeshifting (Sky Cinema HD is on the same transponder as Sky Sport HD 1 => can use one tuner to receive them). The log file is telling me that tuning was no problem but decrypting was not possible:

[2014-03-19 21:38:03,344] [Log ] [scheduler thread] [INFO ] - slot[1] Sky Sport HD 1
[2014-03-19 21:38:03,344] [Log ] [scheduler thread] [INFO ] - mdplug: SetChannel no free slots available for channel Sky Cinema HD (try increase limit).

This means that the "plugin" for this tuner has been configured to only decrypt one channel (slot). Since the slot was already used to decrypt Sky Sport HD 1 it was not possible to decrypt Sky Cinema HD. So TV Server does not ask the plugin to decrypt the channel, and the channel remains encrypted:

[2014-03-19 21:38:03,360] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - no audio was found after 15,0072264 seconds
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: Recording failed! 2 R:\Aufnahmen\Promised Land - Promised Land_1.ts

If the TV Server CAM limit was configured correctly (set to 1, like the plugin slot count) then it shouldn't have even tried to use this tuner. Please check your configuration.
In any case, it wouldn't have affected your timeshifting on Sky Sport HD 1 in any way.


#2 - Possible scheduler or card allocation bug.

After trying with the Sky Sport HD 1 tuner once TV Server actually tries the same tuner again. This is because the channel has two tuning details:
[collapse]
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: find card for channel Sky Cinema HD
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: got 2 tuning details for Sky Cinema HD
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: channel #1 DVBS:tvKY Sky Cinema HD Freq:11914500 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:True LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:RadioWebStream cannot tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:2 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:3 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:4 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:5 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: channel #2 DVBS:tvKY Sky Cinema HD Freq:11914000 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:True LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:RadioWebStream cannot tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:2 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:3 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:4 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: card:5 typevbS can tune to channel
[2014-03-19 21:38:03,251] [Log ] [scheduler thread] [INFO ] - Controller: found 8 card(s) for channel[/collapse]

You can see that the frequency for the two tuning details is slightly different - 11914500 vs. 11914000.

As we have seen, TV Server tried and failed to start the recording with the Sky Sport HD 1 tuner (card 2) with the first tuning detail. After that, it tried the same tuner again with the second tuning detail and that is what caused timeshifting to stop:
[collapse]
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - no audio was found after 15,0072264 seconds
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: Recording failed! 2 R:\Aufnahmen\Promised Land - Promised Land_1.ts
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: StopRecording card=2, user=scheduler3140
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - basesubchannel.StopRecording 1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch=1, subch index=1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch:1-1 tswriter StopRecording...
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - FreeSubChannel MD: freeing sub channel : 1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - mdplug: FreeChannel Sky Cinema HD
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 2 subch#1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - DVB subch:1 Decompose()
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : subchannels STILL present 1, continuing graph
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [DEBUG] - usermanagement.RemoveUser: scheduler3140, subch: 1 of 1, card: 2
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - user:scheduler3140 remove
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=10, tuningdetails=DVBS:tvKY Sky Cinema HD Freq:11914500 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - card: SignalTuneEvent card: 2 / subch: 1
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - scheduler: recording failed, lets try next available card.
[2014-03-19 21:38:18,367] [Log ] [scheduler thread] [INFO ] - Scheduler: stop failed record Sky Cinema HD 01.01.0001 00:00:00-19.03.2014 23:25:00 Promised Land
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=14, tuningdetails=DVBS:tvKY Sky Cinema HD Freq:11914000 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:True LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - Controller: epg stop
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - Scheduler : record, first tune to channel
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - card: Tune on card 2 to subchannel Sky Cinema HD
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [DEBUG] - card: user: scheduler3140:2:1 tune DVBS:tvKY Sky Cinema HD Freq:11914000 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:True LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [DEBUG] - card: to different transponder
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [DEBUG] - stop subchannel: 0 user: HTPC
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - mdplug: FreeChannel Sky Sport HD 1
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - mdplug: usage counter for channel 'Sky Sport HD 1' is zero
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
[2014-03-19 21:38:18,383] [Log ] [scheduler thread] [INFO ] - user:HTPC remove
[2014-03-19 21:38:18,570] [Log ] [scheduler thread] [INFO ] - FreeSubChannel MD: tried to free non existing sub channel : 1
[2014-03-19 21:38:18,570] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#1
[2014-03-19 21:38:18,570] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel :1 - sub channel not found
[2014-03-19 21:38:18,570] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : subchannels STILL present 1, continuing graph[/collapse]

This should not happen. Just because the tuner is tuned to the same transponder as the first tuning detail doesn't mean it is okay for the timeshifting (or recording!) to be stopped to try the second [different] tuning detail. There are 2 other cards available which should be tried first. Timeshifting should only be stopped for recording as a last resort when enabled by configuration.

@gibman
There is probably a bug here for the case where a tuner has two ways tune a channel (eg. channel is available on two transponders). Mainly this could affect satellite tuners and people that have access to multiple satellites and/or have merged tuning details.

Interestingly immediately after timeshifting was stopped, radical tried to retune Sky Sport HD 1. Surprisingly this did not result in the recording being stopped. Difference in behaviour between the recording and timeshifting allocation logic?

Presumably this also affects TVE 3.5. How hard do you think it would be to fix this?

@radical
You could avoid this problem by deleting such duplicate tuning details.


#3 - Corruption of first recording.

Without extra information I can't really say for sure what happened.
For example, if the recording was playable but had a few stutters I could say "yes, there are a few continuity errors in the log files - maybe signal quality or HDD load?".
If the recording was completely unplayable I would say "I don't see any cause for the problem - tuning and decryption seem to be successful".
If the recording stopped before the end I have an idea about a potential cause for that.

Are you able to give any further info?

Regards,
mm
PS: So far the problems in these log files are not related to the main subject of this thread. In other words I don't see any case where the video, some audio, and subtitles are decrypted but one or more audio streams are still encrypted. Maybe we should have a new thread to continue this discussion.

 

[radical]

Seems my conlusion for your patch was wrong and way to fast.

After trying with the Sky Sport HD 1 tuner once TV Server actually tries the same tuner again. This is because the channel has two tuning details:

You could avoid this problem by deleting such duplicate tuning details.

First what I've done today was deleteting every second (or third) Tuning Detail on every channel. This was really a pain in the a**.

So, now comes my first question. Is it possible to prevent tuning a second channel on a allready running tuner?
I think it will be not possible to raise the cam Limit, because I have no cam enabled and configured.

Are you able to give any further info?

Which Information do you need? The recording is playable, is complete but it have some issues.

PS: So far the problems in these log files are not related to the main subject of this thread. In other words I don't see any case where the video, some audio, and subtitles are decrypted but one or more audio streams are still encrypted. Maybe we should have a new thread to continue this discussion.

Would a Mod be so Kind and move post # 124 - 126 in another thread? Or do I have to create a new one first?

 

[mm1352000]

So, now comes my first question. Is it possible to prevent tuning a second channel on a allready running tuner?

Yes and no.
No in general, but yes for encrypted channels... and that is what I was trying to tell you earlier. You prevent tuning a second channel by setting the CAM limit to 1.

I think it will be not possible to raise the cam Limit...

I'm not telling you to raise the CAM limit. Simply telling you to set it to match the plugin configuration. If M****Cards.xml contains EnableM**** value 1 (or "yes") then you should set the CAM limit to 1. If EnableM**** is 2 then CAM limit should also be 2. Make sense?

...because I have no cam enabled and configured.

Yes, you have no CAM... but TV Server treats the plugin as if it is a CI/CAM. In other words, you have to tick "CAM enabled and present for this card":
http://wiki.team-mediaportal.com/1_...nfiguration/02_TV_Servers#Edit_Tuner_Settings

Otherwise the plugin won't be used. That section also gives you the possibility to set the CAM limit as suggested, and yes that setting will affect the plugin.

Which Information do you need? The recording is playable, is complete but it have some issues.

The information that I need is to know exactly what is wrong with it. "Corrupt" can mean many things, and each meaning could be caused by a different reason. So, you said the recording is complete and playable... but I guess there is pixellation in places? How frequent is the pixellation? Are both recordings affected, or only one? Was this recorded on the PC with the Pentium G620 CPU? If so, what is the CPU % normally when you record/timeshift 3 HD channels?

 

[radical]

You are guessing right, There are pixelations. Not much, Not frequent but enough for me to normally delete the whole recording. More Information i will provide Later when I find some time.

EDIT: Done some further testing.
Enabled Cam, and set limit to 1.
After some Trouble with the first Tuning everything seems to work fine.
So, I started to timeshift 4 channels at once.
Working as expected just 3 Discontinuities was counted on one channel. I think that can be ignored.

Then I started same test with 4 recordings at once. No discontinuities. Everething fine so HDD dosen't limit I think.
At last I cut all 4 recordings. No corruption found.

CPU usage ranged from 30 to 45%. There was also a short Peak of 80%.

Attached some Screens and logs from timeshifting.

Tomorrow I'll rerun testing with your patch. Just to be sure which one is the right for me?
From post 24,27 or 61?

 

[radical]

Here some Log's from yesterdays testing with your patch.
First recording from Sky Cinema HD is Little messed uo at 1:22:51. Could it be the Point were the second one was starting?

 

[mm1352000]

First recording from Sky Cinema HD is Little messed uo at 1:22:51. Could it be the Point were the second one was starting?

Your comment is not 100% clear to me so I can't answer the question.

First, please can you confirm that when you say "first recording from Sky Cinema HD" you mean this one:
[2014-04-18 20:12:00,181] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record Sky Cinema HD 20:12-22:00 Hangover

Second, when you say 1:22:51 do you mean real time 20:12:00 + 01:22:51 = 21:34:51 (9:34 PM), or do you actually mean 01:22:51 (1:22 AM on 19/04)?

Finally, when you ask "could it be the point where the second one was starting"... which recording do you mean?
There are a total of 9 recordings in the log file...

If I had to guess I think the answer is no.
None of the recordings start anywhere near 21:34:51 or 01:22:51.
There are also no indications of discontinuities in the stream anywhere near 21:34:51 or 01:22:51.
In short I can't see any explanation for the recording being messed up.