Tvheadend

I have made the following discovery about this problem:

If I have another Kodi running somewhere else against same TVH-server then I am able to start a Kodi session, stop it, start it again without any problems.

If I only have one Kodi running I will encounter these problems when exiting Kodi and then starting it again.

Could you retry with oscam revision 10087 ? There are some changes in dvbapi (oscam) which introduced some bugs.

Ok running on Oscam rev 10087 now:

2015-04-26 19:32:51.000 capmt: tvheadend: mode 5 connected to 127.0.0.1:11000 (single)
2015-04-26 19:32:51.000 capmt: tvheadend: connected to OSCam v1.20-unstable_svn, build r10087 (x86_64-linux-gnu), using network protocol_version = 1

but still the same buffering error in Kodi when restarting Kodi and having only one Kodi running.

Restarting Oscam and/or TVH removes the error until Kodi is restarted next time.

2015-04-26 20:06:48.000 capmt: tvheadend: mode 5 connected to 127.0.0.1:11000 (single)
2015-04-26 20:06:48.000 capmt: tvheadend: connected to OSCam v1.20-unstable_svn, build r10652 (x86_64-linux-gnu), using network protocol_version = 2

Ok tested with revision 10652 now and I have not been able to reproduce these problems anymore. I'll keep testing for a few days more. Meanwhile, please mark this ticket as resolved by using Oscam r10652.

Sorry, problem still exists... :-(

I will have to post a bug ticket at the OSCAM forum I guess.

It happens only if I stop and restart Kodi during the same session. Restarting OSCAM and/or restarting TVH helps.

Provide also debug log 128 from oscam to see all dvbapi signalling.. Not sure if it's oscam's fault or tvh's one.

Alright, quite difficult/messy to reproduce now. Only way I have been able to reproduce currently is to have two or more Kodi up and running (version 14.2 compiled March 26th) and then stop/restart one of them to trigger this bugg.

This is what I see in the OSCAM-log when set to debug level 128:

Here I have the first Kodi client up and running properly:

2015/04/27 22:59:39 25F8460 c (dvbapi) PMT Update on socket 18.
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 Filter 1 fetched ECM data (ecmlength = 088)
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 ECMTYPE 81 CAID 0B00 PROVID 000000 ECMPID 1BB5 FAKECHID 0000 (unique part in ecm)
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 Filter 1 set ecmtable to EVEN (CAID 0B00 PROVID 000000 FD 65535)
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 Filter 1 set chid to ANY CHID on fd 65535
2015/04/27 22:59:39 25F8460 c (dvbapi) Sending packet to dvbapi client (fd=18):
2015/04/27 22:59:39 25F8460 c (dvbapi) 40 3C 6F 2B 06 01 00 1B B5 80 00 00 00 00 00 00
2015/04/27 22:59:39 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00
2015/04/27 22:59:39 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/04/27 22:59:39 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/04/27 22:59:39 25F8460 c (dvbapi) 04
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 get controlword!
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 request controlword for ecm 0B00&000000/0000/0ED9/88:2C96BAB868CD977BA069083147E7DBC1
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 controlword received for PID 0 CAID 0B00 PROVID 000000 ECMPID 1BB5 CHID 0000 VPID 0042
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 requested controlword for ecm 2C96BAB868CD977BA069083147E7DBC1 on fd 65535
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 ca6 is using index 1 for streampid 0042 -> write!
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 writing odd part (E8E1E8B11D8D0CB6) of controlword, replacing expired (5B13F15FC0EA41EB)
2015/04/27 22:59:39 25F8460 c (dvbapi) Demuxer 1 write cw0 index: 1 (ca6)
2015/04/27 22:59:39 25F8460 c (dvbapi) Sending packet to dvbapi client (fd=18):
2015/04/27 22:59:39 25F8460 c (dvbapi) 40 10 6F 86 06 00 00 00 01 00 00 00 00 E8 E1 E8
2015/04/27 22:59:39 25F8460 c (dvbapi) B1 1D 8D 0C B6
2015/04/27 22:59:39 25F8460 c (ecm) tvheadend* (0B00&000000/0000/0ED9/88:2C96BAB868CD977BA069083147E7DBC1): found (321 ms) by SerialReader

And I thiiiink this is were the second Kodi logs in and then stops with "Buffering...." in the Kodi status window:

2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 matching reader SerialReader against available emmpids -> START!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 reader SerialReader emmfilter 2/3 type match -> ENABLE!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 duplicate emm filter type SHARED, emmpid: 0x0030, emmcaid: 0B00, emmprovid: 000000 -> SKIPPED!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 reader SerialReader emmfilter 3/3 type match -> ENABLE!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 duplicate emm filter type UNIQUE, emmpid: 0x0030, emmcaid: 0B00, emmprovid: 000000 -> SKIPPED!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 matching reader SerialReader against available emmpids -> DONE!
2015/04/27 22:59:47 25F8460 c (dvbapi) Demuxer 1 handles 0 emm filters
2015/04/27 22:59:49 25F8460 c (dvbapi) PMT Update on socket 18.
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 Filter 1 fetched ECM data (ecmlength = 088)
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 ECMTYPE 80 CAID 0B00 PROVID 000000 ECMPID 1BB5 FAKECHID 0000 (unique part in ecm)
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 Filter 1 set ecmtable to ODD (CAID 0B00 PROVID 000000 FD 65535)
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 Filter 1 set chid to ANY CHID on fd 65535
2015/04/27 22:59:49 25F8460 c (dvbapi) Sending packet to dvbapi client (fd=18):
2015/04/27 22:59:49 25F8460 c (dvbapi) 40 3C 6F 2B 06 01 00 1B B5 81 00 00 00 00 00 00
2015/04/27 22:59:49 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00
2015/04/27 22:59:49 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/04/27 22:59:49 25F8460 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/04/27 22:59:49 25F8460 c (dvbapi) 04
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 get controlword!
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 request controlword for ecm 0B00&000000/0000/0ED9/88:D5BA8A07F450C8A51077564549430982
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 controlword received for PID 0 CAID 0B00 PROVID 000000 ECMPID 1BB5 CHID 0000 VPID 0042
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 requested controlword for ecm D5BA8A07F450C8A51077564549430982 on fd 65535
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 ca6 is using index 1 for streampid 0042 -> write!
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 writing even part (365BFF900E3D6AB5) of controlword, replacing expired (B70EE4A9691DC248)
2015/04/27 22:59:49 25F8460 c (dvbapi) Demuxer 1 write cw1 index: 1 (ca6)
2015/04/27 22:59:49 25F8460 c (dvbapi) Sending packet to dvbapi client (fd=18):
2015/04/27 22:59:49 25F8460 c (dvbapi) 40 10 6F 86 06 00 00 00 01 00 00 00 01 36 5B FF
2015/04/27 22:59:49 25F8460 c (dvbapi) 90 0E 3D 6A B5
2015/04/27 22:59:49 25F8460 c (ecm) tvheadend (0B00&000000/0000/0ED9/88:D5BA8A07F450C8A51077564549430982): found (321 ms) by SerialReader

If I now stop the first Kodi that was up and running properly and then restart the 2nd Kodi that was still showing "Buffering" then the 2nd Kodi starts fine.

This is how the Oscam-log looks like when I start the first Kodi:
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0B00 ECM_PID: 1BD0 PROVID: 000000
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 receiver wants to demux srvid 057D on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 new program number: 057D (0B00:057D unknown) [pmt_list_management 3]
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 found channel in cache and matching prio -> start descrambling ecmpid 0
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 trying to descramble PID 0 CAID 0B00 PROVID 000000 ECMPID 1BD0 ANY CHID PMTPID 0000 VPID 0002
2015/04/28 22:23:11 1FA0D40 c (ecm) tvheadend (0B00&000000/0000/057D/88:33AFF8989CF54267F6C82168D6C49110): found (325 ms) by SerialReader

And this is how the log looks like when I restart a 2nd Kodi. Note that now the Oscam log does NOT say:
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 found channel in cache and matching prio -> start descrambling ecmpid 0
which can be seen on successful start of Kodi as in the log example above.

2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 1 continue decoding of SRVID 057D
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0B00 ECM_PID: 1BD0 PROVID: 000000
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 1 receiver wants to demux srvid 057D on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 1 new program number: 057D (0B00:057D unknown) [pmt_list_management 1]
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 2 continue decoding of SRVID 0ED9
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 2 added new ecmpid 0 CAID: 0B00 ECM_PID: 1BB5 PROVID: 000000
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 2 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 2 receiver wants to demux srvid 0ED9 on adapter 0006 camask 0040 index 0000 pmtpid 0000
2015/04/28 22:24:52 1FA0D40 c (dvbapi) Demuxer 2 new program number: 0ED9 (0B00:0ED9 unknown) [pmt_list_management 2]

I would expect to see
2015/04/28 22:23:10 1FA0D40 c (dvbapi) Demuxer 1 found channel in cache and matching prio -> start descrambling ecmpid 0
after the last log line above.

Hmmm, I am not sure if this is a Oscam or TVH issue or a combo of the two when using the DVBAPI-protocol. This worked perfectly fine until a few weeks ago and I suspect that the only part in this setup that I might have upgraded accidentaly was TVH since I have upgraded TVH accidentally previously before when using the Ubuntu software updater.

I don't see much from this. Could you do "--trace descrambler,capmt" for tvh and debug 128 on oscam to compare both sides ?

Jaroslav Kysela wrote:

I don't see much from this. Could you do "--trace descrambler,capmt" for tvh and debug 128 on oscam to compare both sides ?

Ok, will do. If I enable the tracing from the TVH webgui, is it the field "Debug subsystems:" or the field "Trace subsystems:" that I put in "--trace descrambler,capmt" and when doing this from the webgui do I skip the initial "--trace" and just enter "descrambler,capmt" in either debug field or trace field?

OK. It seems like oscam fault.

2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Receiver wants to demux srvid 057D on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 continue decoding of SRVID 057D
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 found pmt type: 81 length: 8 (assuming enigma private descriptor: namespace 0000 tsid 0e onid 46)
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0B00 ECM_PID: 1BD0 PROVID: 000000
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 added new stream (type: 01 pid: 0014 length: 6)
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 receiver wants to demux srvid 057D on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 new program number: 057D (0B00:057D unknown) [pmt_list_management 1]

... remove the old ecmpid 0x0012

2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Remove streampid 0012 using indexer 1 from ca7
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Removed last indexer of streampid 0012 from ca7
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Demuxer 1 disable stream 2 pid=0x0012 index=-1 on ca7
2015/04/29 19:05:31  1FA0D40 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2015/04/29 19:05:31  1FA0D40 c   (dvbapi)   40 08 6F 87 07 00 00 00 12 FF FF FF FF

... no futher ECM requests for demuxer 1 adapter 7 ecmpid 0x0014 .. oscam should set the ecm filter here..

@crazy XXX Fin
To make sure that the problem is not my latest ECMINFO changes please try OSCam r10651 and let us know if everything is correct.

Mariusz Białończyk wrote:

@crazy XXX Fin
To make sure that the problem is not my latest ECMINFO changes please try OSCam r10651 and let us know if everything is correct.

I tested with r10651 and still the same problem. Have tested latest r10653 as well but no success.

When I start my first Kodi the Oscam-log looks fine:
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 0ED9 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 new program number: 0ED9 (0B00:0ED9 unknown) [pmt_list_management 3]
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 found channel in cache and matching prio -> start descrambling ecmpid 0
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 trying to descramble PID 0 CAID 0B00 PROVID 000000 ECMPID 1BB5 ANY CHID PMTPID 0000 VPID 0016
2015/04/30 16:13:13 18FB8E0 c (ecm) tvheadend (0B00&000000/0000/0ED9/88:CA682E057DE6573D848D0CF39468422D): found (330 ms) by SerialReader

Starting the 2nd Kodi on a different channel:

2015/04/30 16:13:46 18FB8E0 c (ecm) tvheadend (0B00&000000/0000/0ED9/88:B24167024B5995DFEC590E316F1BAC47): found (320 ms) by SerialReader
2015/04/30 16:13:49 18FB8E0 c (dvbapi) Demuxer 0 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/30 16:13:49 18FB8E0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 0ED9 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/30 16:13:49 18FB8E0 c (dvbapi) Demuxer 0 new program number: 0ED9 (0B00:0ED9 unknown) [pmt_list_management 2]
2015/04/30 16:13:49 18FB8E0 c (dvbapi) Demuxer 1 found channel in cache and matching prio -> start descrambling ecmpid 0
2015/04/30 16:13:49 18FB8E0 c (dvbapi) Demuxer 1 trying to descramble PID 0 CAID 0B00 PROVID 000000 ECMPID 1B76 ANY CHID PMTPID 0000 VPID 0017
2015/04/30 16:13:49 18FB8E0 c (ecm) tvheadend (0B00&000000/0000/115E/75:3DEAA91F857478ACE66A2C1B29EBC6B7): found (290 ms) by SerialReader
2015/04/30 16:13:53 18FB8E0 c (reader) SerialReader [conax] tvheadend emmtype=shared, len=180, cnt=3: skipped (0 ms)
2015/04/30 16:13:53 18FB8E0 c (reader) SerialReader [conax] Successfully added EMM to /var/log/oscam/emm/SerialReader_shared_emm.log
2015/04/30 16:13:53 18FB8E0 c (reader) SerialReader [conax] tvheadend emmtype=shared, len=180, cnt=3: skipped (0 ms)
2015/04/30 16:13:53 18FB8E0 c (reader) SerialReader [conax] Successfully added EMM to /var/log/oscam/emm/SerialReader_shared_emm.log
2015/04/30 16:13:54 18FB8E0 c (ecm) tvheadend (0B00&000000/0000/115E/75:F2D4B94A8B0CB9AEAA667C061CE0E584): found (290 ms) by SerialReader
2015/04/30 16:13:56 18FB8E0 c (ecm) tvheadend (0B00&000000/0000/0ED9/88:4EDA2377D7253696D8E3D6F28625BF02): found (320 ms) by SerialReader

After I have stopped the first Kodi and then starting it again I see this in the OSCAM log:

2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 0ED9 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 0 new program number: 0ED9 (0B00:0ED9 unknown) [pmt_list_management 1]
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 1 continue decoding of SRVID 115E
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0B00 ECM_PID: 1B76 PROVID: 000000
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 1 receiver wants to demux srvid 115E on adapter 0006 camask 0040 index 0000 pmtpid 0000
2015/04/30 16:16:41 18FB8E0 c (dvbapi) Demuxer 1 new program number: 115E (0B00:115E unknown) [pmt_list_management 2]

Biggest difference is that I do not see the log line saying:
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 found channel in cache and matching prio -> start descrambling ecmpid 0
2015/04/30 16:13:12 18FB8E0 c (dvbapi) Demuxer 0 trying to descramble PID 0 CAID 0B00 PROVID 000000 ECMPID 1BB5 ANY CHID PMTPID 0000 VPID 0016
which I see on every successful start of Kodi

I have no problem to descramble all channels as long as I run only one Kodi. If I restart OSCAM I can runt two or more Kodis without problems but as soon as I restart any of the Kodis running the problems starts again and sometimes it helps by switching channels back and forth and sometimes I need to either restart OSCAM or TVH.

Let me know if I can do some more detailed logging and maybe what OSCAM forum would be best to post logs and questions?

we also have still Problems with multiple adapters with current svn version, see http://www.streamboard.tv/oscam/ticket/4149
allthough crazy fin also has problems with 10087

Gentlemen, we can close this ticket now. Definately an issue with OSCAM.

I do not know what happened when I "thought" that I had downgraded my OSCAM to r10087 as suggested to check if it helped and I reported back that the issue still existed.

I just tested with r9890 and I couldn't reproduce the problems anymore so I decided to test r10087 again and as B C talked about in the referred link to the Streamboard forum the r10087 of OSCAM is rock solid.

I have now been running on r10087 for about an hour and stopped, restarted several Kodis from 3-4 different machines and have not been able to reproduce the Kodi buffering startup error.

Thanks all involved for helping me out with trying to find the issues with this problem. We'll move over to the OSCAM forum now for further debugging. :-)

FYI: I think the problem starts with r10620:
http://www.streamboard.tv/oscam/ticket/4149#comment:4

can you guys test r10654? First quick test seems to be ok for me, although you two have a slight different problem than me

Alright, cool! I am now on OSCAM r10656 together with TVH 3.9.2789 and I have not been able to reproduce the problems anymore.

Have tested with up to 4 Kodis from 4 different machines using different muxes so that TVH needs to utilize 4 of my 8 tuners. I have also tested with stopping and restarting the Kodis back and forth and seems pretty stable now.