Opened 9 years ago

Closed 9 years ago

#4149 closed defect (fixed)

dvb net api with tvheadend and multiple adapters "resets" all the time

Reported by: lsd Owned by: theparasol
Priority: minor Component: DVBApi
Severity: low Keywords: multiple adapters, tvheadend
Cc: Sensitive: no

Description

Revision

10641

Issue Description

I have attached logs of oscam and tvh where I am on two different encrypted channels at a time. Demux0 and demux1 always restart just like after a channel change, result is that after each restart, the other channel fails to decode.
I have opend a ticked for tvheadend and got the following response from perexg here: https://tvheadend.org/issues/2728#note-7 I don't see any "Demuxer 1 stop Filter 2" or "Demuxer 1 disable stream" messages which kills filter.

When the issue occurs

more than 1 adapter accessing dvbapi

How the issue is reproducable

latest version of tvh from git (2641), stream two encrypted channels, eg ORF III HD & ATV HD. When only one channel needs to be decrypte, everything is fine

Attachments (5)

oscam.log (111.5 KB ) - added by lsd 9 years ago.
tvh.log (116.0 KB ) - added by lsd 9 years ago.
r10619.log (94.0 KB ) - added by lsd 9 years ago.
r10620.log (99.9 KB ) - added by lsd 9 years ago.
r10655.log (214.4 KB ) - added by lsd 9 years ago.

Download all attachments as: .zip

Change History (21)

by lsd, 9 years ago

Attachment: oscam.log added

by lsd, 9 years ago

Attachment: tvh.log added

comment:1 by lsd, 9 years ago

I just made some tests with 10087 and everything is rock solid. I also tried tcp mode instead of net api.... same story

comment:2 by Jeroen , 9 years ago

Same problem here, oscam r10646 not working with 2 encrypted channels , oscam svn-10087 works fine

Last edited 9 years ago by Jeroen (previous) (diff)

comment:3 by manio, 9 years ago

I think it would be much easier if you can tell which commit exactly broke it. From r10087 to r10646 is a big gap and a lot of dvbapi module changes...

comment:4 by manio, 9 years ago

Ok guys, I think i was able to bisect the problem. According to my bisecting the first bad commit is r10620. Could you please confirm? (please test on r10619 and r10620).

comment:5 by lsd, 9 years ago

well yes and no :-), r10620 definitely makes it worse, but while testing r10619 with >= 3 adapters it seems that I am still able to kill one decrypting channel from time to time. Nether the less, r10620 does something wrong and I think we should fix this first and later focus on my problem as it might as well come from tvheadends side as I can reproduce this even with r9574. As in general only two adapters are active at the same time in my setup I did not realize this until I tried to biscet this as well with all my 4 adapters and failed to find the revision as it fail with every version I could try.

comment:6 by manio, 9 years ago

Owner: set to theparasol

Hello
To be able to easier bisect the problem I was doing streaming from tvh using mplayer (http).
My testing pattern was the following:

  1. Start streaming channel A
  2. Start streaming channel B
  3. Stop streaming channel B
  4. Restart streaming channel B

If it plays fine in step 4 - then I marked the revision as good, bad otherwise.

My results seems to be reproducible and was also confirmed by other guy (r10620 as the first bad rev).

Maybe theparasol could shed some light on this as the commit is big (I would call it bulk). IMHO every single change should be done in one single commit, so we could easier track which change starts the problem (git is very helpful with this, as we could make more commits and push it once), but that is quite another story :)

comment:7 by theparasol, 9 years ago

Why is it sending PMT with LIST_ONLY for channel A
Then directly PMT with LIST_FIRST for channel B
Then directly PMT with LIST_LAST for channel A

If you want me to assist I need -d128 logging for R10619 and R10620.
For both revisions to exact the same zapping actions, that makes comparing the logs a lot easier!

Since Enigma and stapi boxes are not affected I presume the CA_PMT handling is not completly correct implemented in tvheadend, but without proper logs to compare thats just a guess.

comment:8 by lsd, 9 years ago

I originally started the bug report on tvheadends bug tracker as it was unclear to me if it's a tvh or oscam issue, so let's find out if we can fix this with the help of both sides. My test setup for the following logs was:
oscam with just one cccam reader to my home oscam instance with my locals. I just allowed 0d95 as the only ca id as I first experienced this with ORF channels. tvh <--> oscam in tcp mode. All fancy pmt stuff like lock ecm pid, lock caid etc disabled in tvh.
Each log starts with starting tvh. First I switch to ORF1 HD on client # 1, let it process a few ECMs and then switch to ORF2 HD on client # 2, wait a bit, stop it and restart ORF2 HD on client # 2.
This is working fine with r10619 but fails on r10620. In my case ORF1 HD stops as soon as I start ORF2 HD on client # 2
If we need more logs let me know

by lsd, 9 years ago

Attachment: r10619.log added

by lsd, 9 years ago

Attachment: r10620.log added

comment:9 by lsd, 9 years ago

first quick test of 10654 is looking good. My test case from the logs is working and I can also restart channels like manio faild with r10620. I will update after more testing
a big thank you

comment:10 by manio, 9 years ago

For me the r10654 doesn't solve the problem (at least the above testing scenario).

comment:11 by lsd, 9 years ago

The folling with r10655 faild (log attached)
Start ORF1 HD on # 1
Start ORF2 HD on # 2
Start ORF III HD on # 3
until now everything ok
now switch on # 3 from ORF III HD to Pulse4
Client # 2 with ORF2 HD stops working, tvh log says:
2015-05-05 16:22:34.354 descrambler: ECM late (20 seconds) for service "ORF2O HD"

still my own local with backup serving ecms, and I can reproduce this several times

Version 0, edited 9 years ago by lsd (next)

by lsd, 9 years ago

Attachment: r10655.log added

comment:12 by lsd, 9 years ago

r10656 is working better but still I get ECM late after a few more switches, log comming 2morrow as currently some guys would kill me for testing :-)

comment:13 by theparasol, 9 years ago

From your own log:
2015/05/05 16:21:14 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:C9E89344F8A8E58579A72D4D0F37E52B): found (126 ms) by Spaz - ORF2 OOE HD (cwc LEARN)
2015/05/05 16:21:24 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:C9E89344F8A8E585651AE56402040006): found (129 ms) by Spaz - ORF2 OOE HD (cwc LEARN)
2015/05/05 16:21:34 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:191AF02362704618651AE56402040006): found (128 ms) by Spaz - ORF2 OOE HD (cwc LEARN)
2015/05/05 16:21:44 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:191AF023627046187406DB5512A228DC): cache2 (130 ms) by Spaz - ORF2 OOE HD (cwc LEARN)
2015/05/05 16:21:54 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:0470EA5EB57AE7167406DB5512A228DC): cache2 (128 ms) by Spaz - ORF2 OOE HD (cwc LEARN)
2015/05/05 16:22:04 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:0470EA5EB57AE716AE523C3C4E939F80): cache2 (130 ms) by Spaz - ORF2 OOE HD (cwc OK)
2015/05/05 16:22:14 1375010 c (ecm) tvheadend (0D95&000004/0000/09C7/33F8/B8:2A7A25C9B0068B41AE523C3C4E939F80): cache2 (145 ms) by Spaz - ORF2 OOE HD (cwc OK)
2015/05/05 16:22:14 1375010 c (dvbapi) Demuxer 1 Filter 3 fetched ECM data (ecmlength = 0B8)
2015/05/05 16:22:14 1375010 c (dvbapi) Demuxer 1 ECMTYPE 81 CAID 0D95 PROVID 000004 ECMPID 09C7 FAKECHID 0000 (unique part in ecm)
2015/05/05 16:22:14 1375010 c (dvbapi) Demuxer 1 Filter 3 set ecmtable to EVEN (CAID 0D95 PROVID 000004 FD 65535)
2015/05/05 16:22:14 1375010 c (dvbapi) Demuxer 1 Filter 3 set chid to ANY CHID on fd 65535

Thats it... no more ecms for ORF2 HD, and I tell you this oscam has not given a command to kill the last ecmfilter for this demuxer. TV-headend decided to stop sending ecms we asked for, hence no controlword reply from oscam and no more decoding.

at the end of your log oscam gives a command to stop the last ecmfilter for this demuxer:

(dvbapi) Demuxer 1 stop Filter 3 (fd: 65535 api: 0, caid: 0D95, provid: 000004, ecmpid: 09C7)

Plz provide your log and my findings to the tvheadend coder so this can be fixed!

Last edited 9 years ago by theparasol (previous) (diff)

comment:14 by lsd, 9 years ago

i have updated my ticket on the other side. BTW, according to http://www.streamboard.tv/wbb2/thread.php?threadid=43237&page=3 also Octagon receivers have a similar problem.....

comment:15 by manio, 9 years ago

I was just testing r10656 - and it seems that now it is working fine. I was not able to reproduce the problem any more. Thanks, theparasol :)

cheers!

comment:16 by lsd, 9 years ago

Resolution: fixed
Status: newclosed

While manios problem was fixed with r10656 mine was fixed in tvheadend v3.9-2814-g128f3a3. Root cause was that in my special case two different channels used the same ecm pid and the filter was closed while it should have been left open for the other channel
thanks @theparasol and @perexg

Note: See TracTickets for help on using tickets.