Project

General

Profile

Bug #2805

CAPMT: TVH is not able to start stream to Kodi after stop of Kodi and then starting it again - switching channels back and forth starts stream again

Added by Crazy Fin over 9 years ago. Updated over 9 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
John Törnblom
Category:
Descrambling
Target version:
-
Start date:
2015-04-26
Due date:
% Done:

0%

Estimated time:
Found in version:
3.9.2747~g3049486~trusty
Affected Versions:

Description

Running on latest TVH 3.9.2747~g3049486~trusty.

When I start Kodi the live-TV stream does not start, it stays on "Buffering... 0%".
If I switch channels back and forth the streaming starts properly.
If I disable one of my tuners in TVH and then stop Kodi and start Kodi again the channel works fine. If I now stop Kodi again and then start a second time I get the buffering issue again with no live-tv stream starting unless I either:

1. Switch channels back and forth
or
2. disable the current tuner in TVH

I see the following in the TVH-log when the buffering happens:

2015-04-26 13:11:50.743 htsp: Got connection from 127.0.0.1
2015-04-26 13:11:50.743 htsp: 127.0.0.1: Welcomed client software: XBMC Media Center (HTSPv8)
2015-04-26 13:11:50.749 htsp: 127.0.0.1 [ XBMC Media Center ]: Identified as user xbmc-tvserver
2015-04-26 13:11:50.749 htsp: 127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]: Privileges raised
2015-04-26 13:11:51.745 mpegts: 10903V in THOR - tuning on TUNER 8
2015-04-26 13:11:51.745 capmt: tvheadend: Starting CAPMT server for service "SVT2 HD" on adapter 7 seq 0x0007
2015-04-26 13:11:51.745 subscription: 0007: "127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]" subscribing on channel "SVT2 HD", weight: 150, adapter: "TUNER 8", network: "THOR", mux: "10903V", provider: "Telenor", service: "SVT2 HD", profile="htsp", hostname="127.0.0.1", username="xbmc-tvserver", client="XBMC Media Center"
2015-04-26 13:11:54.267 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 1)
2015-04-26 13:12:05.244 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 21)
2015-04-26 13:12:16.039 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 41)
2015-04-26 13:12:27.307 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 56)

I havent seen these continuity errors for a looong time.
If I now stop Kodi and then disable for example tuner 8 (adapter 7) that was used above and then start Kodi again it works fine and Kodi starts streaming the channel properly and the log looks clean without any continuity counter errors:

2015-04-26 13:20:28.173 htsp: Got connection from 127.0.0.1
2015-04-26 13:20:28.173 htsp: 127.0.0.1: Welcomed client software: XBMC Media Center (HTSPv8)
2015-04-26 13:20:28.180 htsp: 127.0.0.1 [ XBMC Media Center ]: Identified as user xbmc-tvserver
2015-04-26 13:20:28.180 htsp: 127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]: Privileges raised
2015-04-26 13:20:29.157 mpegts: 10903V in THOR - tuning on TUNER 6
2015-04-26 13:20:29.410 capmt: tvheadend: Starting CAPMT server for service "SVT2 HD" on adapter 5 seq 0x0008
2015-04-26 13:20:29.410 subscription: 0008: "127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]" subscribing on channel "SVT2 HD", weight: 150, adapter: "TUNER 6", network: "THOR",

Exiting Kodi now and restarting it again causes the buffering stop to start again and no live stream until I switch channel back and forth.

Exiting Kodi and starting it again the log starts to show the continuity errors again:

2015-04-26 13:22:57.224 mpegts: 10903V in THOR - tuning on TUNER 6
2015-04-26 13:22:57.224 capmt: tvheadend: Starting CAPMT server for service "SVT2 HD" on adapter 5 seq 0x0009
2015-04-26 13:22:57.224 subscription: 0009: "127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]" subscribing on channel "SVT2 HD", weight: 150, adapter: "TUNER 6", network: "THOR", mux: "10903V", provider: "Telenor", service: "SVT2 HD", profile="htsp", hostname="127.0.0.1", username="xbmc-tvserver", client="XBMC Media Center"
2015-04-26 13:22:59.093 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 1)
2015-04-26 13:23:10.705 TS: THOR/10903V/SVT2 HD: H264 #1175 Continuity counter error (total 30)

OSCAM-log looks like this when the stream starts properly:
2015/04/26 13:27:42 B87450 c [NEW ECMPID #0] CAID: 0B00 ECM_PID: 1BB6 PROVID: 000000
2015/04/26 13:27:42 B87450 c Found 1 ECMpids and 0 STREAMpids in PMT
2015/04/26 13:27:42 B87450 c [DVBAPI] Receiver wants to demux srvid 0581 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/26 13:27:42 B87450 c New program number: 0581 (0B00:0581 unknown) [pmt_list_management 3]
2015/04/26 13:27:42 B87450 c [DVBAPI] Found channel in cache -> start descrambling ecmpid #0
2015/04/26 13:27:42 B87450 c [DVBAPI] Demuxer #0 trying to descramble PID #0 CAID 0B00 PROVID 000000 ECMPID 1BB6 ANY CHID PMTPID 0000 VPID 000A
2015/04/26 13:27:42 B87450 c tvheadend (0B00&000000/0000/0581/88:9DB8705AA2FD62D73A0368C5D668B219): found (331 ms) by SerialReader

and when the stream does not start properly OSCAM log looks like this:

2015/04/26 13:29:45 B87450 c [DVBAPI] Demuxer #0 continue decoding of SRVID 0581
2015/04/26 13:29:45 B87450 c [SKIP STREAM] CAID: 0B00 ECM_PID: 1BB6 PROVID: 000000 (Same as ECMPID #0)
2015/04/26 13:29:45 B87450 c Found 1 ECMpids and 0 STREAMpids in PMT
2015/04/26 13:29:45 B87450 c [DVBAPI] Receiver wants to demux srvid 0581 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/26 13:29:45 B87450 c New program number: 0581 (0B00:0581 unknown) [pmt_list_management 3]

and when switching channel in Kodi to another one and then back to the first one stream starts properly and OSCAM-log looks like this then:

2015/04/26 13:32:23 B87450 c [NEW ECMPID #0] CAID: 0B00 ECM_PID: 1BB6 PROVID: 000000
2015/04/26 13:32:23 B87450 c Found 1 ECMpids and 0 STREAMpids in PMT
2015/04/26 13:32:23 B87450 c [DVBAPI] Receiver wants to demux srvid 0581 on adapter 0007 camask 0080 index 0000 pmtpid 0000
2015/04/26 13:32:23 B87450 c New program number: 0581 (0B00:0581 unknown) [pmt_list_management 3]
2015/04/26 13:32:23 B87450 c [DVBAPI] Found channel in cache -> start descrambling ecmpid #0
2015/04/26 13:32:23 B87450 c [DVBAPI] Demuxer #0 trying to descramble PID #0 CAID 0B00 PROVID 000000 ECMPID 1BB6 ANY CHID PMTPID 0000 VPID 0011
2015/04/26 13:32:24 B87450 c tvheadend (0B00&000000/0000/0581/88:EFF56937BC3907C8A23467E4602F070B): found (321 ms) by SerialReader

Switching channel back and forth starts the stream again. This happens for all my tuners so it is not tuner dependent and I haven't upgraded Oscam or Kodi when these issues started (as far as I recall). I miiiight have updated TVH by mistake when updating other Ubuntu components through the Ubuntu update center.
I have now updated Kodi to 14.2 (from 14.1) and TVH to the latest as well as Oscam to revision r1422 but still the same issue.

It "feels" like TVH is not releasing tuner properly or re-tuning to it properly when re-starting Kodi? Or is this only OSCAM or Kodi-related issue?

Let me know what kind of logs you might need to dig into this issue.

Files

Oscam log (31.8 KB) Oscam log Crazy Fin, 2015-04-29 19:25

History

#1

Updated by Crazy Fin over 9 years ago

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.

#2

Updated by Jaroslav Kysela over 9 years ago

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

#3

Updated by Crazy Fin over 9 years ago

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.

#4

Updated by Crazy Fin over 9 years ago

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.

#5

Updated by Crazy Fin over 9 years ago

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.

#6

Updated by Jaroslav Kysela over 9 years ago

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

#7

Updated by Crazy Fin over 9 years ago

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.

#8

Updated by Crazy Fin over 9 years ago

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.

#9

Updated by Jaroslav Kysela over 9 years ago

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

#10

Updated by Crazy Fin over 9 years ago

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?

#11

Updated by Crazy Fin over 9 years ago

Ok here is the log when I start the second Kodi (first one is already running and is running on the same machine as TVH) and this second starts ok:

2015-04-29 19:05:07.770 htsp: Got connection from 192.168.10.10
2015-04-29 19:05:07.770 htsp: 192.168.10.10: Welcomed client software: XBMC Media Center (HTSPv8)
2015-04-29 19:05:07.771 htsp: 192.168.10.10 [ XBMC Media Center ]: Identified as user xbmc-lab
2015-04-29 19:05:07.771 htsp: 192.168.10.10 [ xbmc-lab | XBMC Media Center ]: Privileges raised
2015-04-29 19:05:09.136 mpegts: 10903V in THOR - tuning on TUNER 7
2015-04-29 19:05:09.369 capmt: tvheadend: Starting CAPMT server for service "SVT1 HD" on adapter 6 seq 0x0013
2015-04-29 19:05:09.369 capmt: tvheadend: New caid 0x0B00 for service "SVT1 HD"
2015-04-29 19:05:09.369 capmt: tvheadend: adding ECMPID=0x1BB5 (7093), CAID=0xB00 (2816) PROVID=0x0 (0), SID=3801, ADAPTER=6
2015-04-29 19:05:09.369 capmt: tvheadend: Trying to obtain key for service "SVT1 HD"
2015-04-29 19:05:09.369 capmt: tvheadend: adding ECMPID=0x1BD0 (7120), CAID=0xB00 (2816) PROVID=0x0 (0), SID=1405, ADAPTER=7
2015-04-29 19:05:09.369 subscription: 0032: "192.168.10.10 [ xbmc-lab | XBMC Media Center ]" subscribing on channel "SVT1 HD", weight: 150, adapter: "TUNER 7", network: "THOR", mux: "10903V", provider: "Telenor", service: "SVT1 HD", profile="htsp", hostname="192.168.10.10", username="xbmc-lab", client="XBMC Media Center"
2015-04-29 19:05:09.369 http: 192.168.10.10: HTTP/1.1 HEAD /imagecache/8 -- 404
2015-04-29 19:05:09.369 http: 192.168.10.10: HTTP/1.1 HEAD /imagecache/37 -- 404
2015-04-29 19:05:09.722 capmt: tvheadend, CA_SET_DESCR adapter 7 par 0 idx 1 a8bc69cd44a76c57
2015-04-29 19:05:10.069 capmt: tvheadend: CA_SET_PID adapter 6 index 2 seq 0x0013
2015-04-29 19:05:10.069 capmt: tvheadend, CA_SET_DESCR adapter 6 par 0 idx 2 704aefa99b0ac76c
2015-04-29 19:05:10.069 descrambler: Obtained keys from capmt-127.0.0.1-11000 for service "SVT1 HD"
2015-04-29 19:05:10.069 capmt: tvheadend, CA_SET_DESCR adapter 6 par 1 idx 2 defbb0891bc0f4cf
2015-04-29 19:05:10.221 http: 192.168.10.10: HTTP/1.1 HEAD /imagecache/37 -- 404
2015-04-29 19:05:10.221 http: 192.168.10.10: HTTP/1.1 HEAD /imagecache/8 -- 404
2015-04-29 19:05:17.905 capmt: tvheadend, CA_SET_DESCR adapter 6 par 0 idx 2 fbc47c3bd460fc30
2015-04-29 19:05:19.884 capmt: tvheadend, CA_SET_DESCR adapter 7 par 1 idx 1 c48de7386d6faa86

and here I close the first Kodi:

2015-04-29 19:05:21.717 subscription: 0031: "127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]" unsubscribing from "TV4 HD", hostname="127.0.0.1", username="xbmc-tvserver", username="XBMC Media Center"
2015-04-29 19:05:21.717 capmt: tvheadend: Removing CAPMT Server from service "TV4 HD" on adapter 7
2015-04-29 19:05:21.717 capmt: tvheadend: adding ECMPID=0x1BB5 (7093), CAID=0xB00 (2816) PROVID=0x0 (0), SID=3801, ADAPTER=6
2015-04-29 19:05:21.823 htsp: 127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]: Disconnected

and now I start the first Kodi again and the buffering starts and look at 2 seconds later when you see the first continuity counter error in log. (I do not see these continuity errors when I start a single Kodi session and the buffering does not appear):

2015-04-29 19:05:28.147 capmt: tvheadend, CA_SET_DESCR adapter 6 par 1 idx 2 77166efbe467b601
2015-04-29 19:05:30.819 htsp: Got connection from 127.0.0.1
2015-04-29 19:05:30.820 htsp: 127.0.0.1: Welcomed client software: XBMC Media Center (HTSPv8)
2015-04-29 19:05:30.831 htsp: 127.0.0.1 [ XBMC Media Center ]: Identified as user xbmc-tvserver
2015-04-29 19:05:30.831 htsp: 127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]: Privileges raised
2015-04-29 19:05:31.871 mpegts: 10934H in THOR - tuning on TUNER 8
2015-04-29 19:05:31.871 capmt: tvheadend: Starting CAPMT server for service "TV4 HD" on adapter 7 seq 0x0014
2015-04-29 19:05:31.871 capmt: tvheadend: New caid 0x0B00 for service "TV4 HD"
2015-04-29 19:05:31.871 capmt: tvheadend: adding ECMPID=0x1BD0 (7120), CAID=0xB00 (2816) PROVID=0x0 (0), SID=1405, ADAPTER=7
2015-04-29 19:05:31.871 capmt: tvheadend: Trying to obtain key for service "TV4 HD"
2015-04-29 19:05:31.871 capmt: tvheadend: adding ECMPID=0x1BB5 (7093), CAID=0xB00 (2816) PROVID=0x0 (0), SID=3801, ADAPTER=6
2015-04-29 19:05:31.871 subscription: 0033: "127.0.0.1 [ xbmc-tvserver | XBMC Media Center ]" subscribing on channel "TV4 HD", weight: 150, adapter: "TUNER 8", network: "THOR", mux: "10934H", provider: "Telenor", service: "TV4 HD", profile="htsp", hostname="127.0.0.1", username="xbmc-tvserver", client="XBMC Media Center"
2015-04-29 19:05:31.910 capmt: tvheadend: CA_SET_PID adapter 7 index -1 seq 0x0012
2015-04-29 19:05:33.573 TS: THOR/10934H/TV4 HD: H264 @ #1047 Continuity counter error (total 1)
2015-04-29 19:05:38.570 capmt: tvheadend, CA_SET_DESCR adapter 6 par 0 idx 2 9019751e0e355295

I have attached the Oscam-log for the same time period.

Let me know if you need a better log (i.e. the full log for same time period and not just my cutouts from the log).

#12

Updated by Jaroslav Kysela over 9 years ago

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..
#13

Updated by Jaroslav Kysela over 9 years ago

  • Subject changed from TVH is not able to start stream to Kodi after stop of Kodi and then starting it again - switching channels back and forth starts stream again to CAPMT: TVH is not able to start stream to Kodi after stop of Kodi and then starting it again - switching channels back and forth starts stream again
  • Category changed from Streaming to Descrambling
#14

Updated by Mariusz Białończyk over 9 years ago

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.

#15

Updated by Crazy Fin over 9 years ago

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?

#16

Updated by B C over 9 years ago

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

#17

Updated by Crazy Fin over 9 years ago

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. :-)

#18

Updated by Mariusz Białończyk over 9 years ago

  • Status changed from New to Fixed

crazy XXX Fin
Thank you for the info - in this case indeed please continue discussion on the OSCam trac/streamboard. Closing as requested. Thank you :)

#19

Updated by Mariusz Białończyk over 9 years ago

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

#20

Updated by B C over 9 years ago

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

#21

Updated by Crazy Fin over 9 years ago

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.

Also available in: Atom PDF