Bug #2728
capmt fails when descrambling on multiple adapters
100%
Description
I don't know if tvh or oscam is "guilty". Oscam running on local host, only local real cards involved. In the following example adapter 0 and 2 are tuned to Sky Germany channels and decoding fine, log starts with tune request on adapter3 to ORF III which should be ok by adding ECMPID=0x9C7 (2503), CAID=0xD95 (3477) PROVID=0x0 (0). If only capmt is enabled it won't start decoding, but it will if I enable a newcamd connection with the same user to the same oscam instance or if it's the only channel being decoded. So capmt is working fine as long as only one channel needs to be decoded at the same time. I currently have added newcamd clients for every caid of my cards but that should work with a single capmt connection without problems. It also makes no differnce weather ca system, ecm pid is locked or not etc....
2015-03-22 22:36:31.799 [ INFO]:subscription: 01EF: "192.168.0.6 [ TV-Schlafzimmer | Kodi Media Center ]" unsubscribing from "ORF1 HD", hostname="192.168.0.6", username="TV-Schlafzimmer", client="Kodi Media Center"
2015-03-22 22:36:31.803 [ TRACE]:descrambler: mux 0x3d94850 - flush tables
2015-03-22 22:36:31.803 [ INFO]:capmt: OSCAM Spaz (local): Removing CAPMT Server from service "ORF1 HD" on adapter 0
2015-03-22 22:36:31.803 [ DEBUG]:capmt: OSCAM Spaz (local): adding ECMPID=0x1817 (6167), CAID=0x1833 (6195) PROVID=0x0 (0)
2015-03-22 22:36:31.803 [ DEBUG]:capmt: OSCAM Spaz (local): adding ECMPID=0x1854 (6228), CAID=0x1833 (6195) PROVID=0x0 (0)
2015-03-22 22:36:31.803 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 123)
2015-03-22 22:36:31.803 [ TRACE]:capmt: 9F 80 32 82 00 24 01 00 7B 18 00 19 01 82 02 00 ..2..$..{.......
2015-03-22 22:36:31.803 [ TRACE]:capmt: 03 81 08 00 00 00 00 00 0B 00 85 84 02 00 60 09 ..............`.
2015-03-22 22:36:31.803 [ TRACE]:capmt: 04 18 33 F8 17 01 00 0D 00 06 ..3.......
2015-03-22 22:36:31.803 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 127)
2015-03-22 22:36:31.803 [ TRACE]:capmt: 9F 80 32 82 00 24 02 00 7F 19 00 19 01 82 02 00 ..2..$..........
2015-03-22 22:36:31.803 [ TRACE]:capmt: 02 81 08 00 00 00 00 00 0D 00 85 84 02 00 62 09 ..............b.
2015-03-22 22:36:31.803 [ TRACE]:capmt: 04 18 33 F8 54 01 00 09 00 06 ..3.T.....
2015-03-22 22:36:31.816 [ INFO]:mpegts: 11273.25H in Astra 1 19.2 - tuning on STV090x Multistandard : DVB-S #0
2015-03-22 22:36:31.816 [ INFO]:capmt: OSCAM Spaz (local): Starting CAPMT server for service "ORF III HD" on adapter 0 seq 0x0013
2015-03-22 22:36:31.816 [ DEBUG]:capmt: OSCAM Spaz (local): New caid 0x0D95 for service "ORF III HD"
2015-03-22 22:36:31.816 [ DEBUG]:capmt: OSCAM Spaz (local): adding ECMPID=0x9C7 (2503), CAID=0xD95 (3477) PROVID=0x0 (0)
2015-03-22 22:36:31.816 [ DEBUG]:capmt: OSCAM Spaz (local): Trying to obtain key for service "ORF III HD"
2015-03-22 22:36:31.817 [ DEBUG]:capmt: OSCAM Spaz (local): adding ECMPID=0x1817 (6167), CAID=0x1833 (6195) PROVID=0x0 (0)
2015-03-22 22:36:31.817 [ DEBUG]:capmt: OSCAM Spaz (local): adding ECMPID=0x1854 (6228), CAID=0x1833 (6195) PROVID=0x0 (0)
2015-03-22 22:36:31.817 [ INFO]:subscription: 01FF: "192.168.0.6 [ TV-Schlafzimmer | Kodi Media Center ]" subscribing on "ORF III HD", weight: 150, adapter: "STV090x Multistandard : DVB-S #0", network: "Astra 1 19.2", mux: "11273.25H", provider: "ORF", service: "ORF III HD", profile="htsp", hostname="192.168.0.6", username="TV-Schlafzimmer", client="Kodi Media Center"
2015-03-22 22:36:31.817 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 13308)
2015-03-22 22:36:31.817 [ TRACE]:capmt: 9F 80 32 82 00 24 01 33 FC 1A 00 19 01 82 02 00 ..2..$.3........
2015-03-22 22:36:31.817 [ TRACE]:capmt: 00 81 08 00 00 00 00 03 ED 00 01 84 02 01 34 09 ..............4.
2015-03-22 22:36:31.817 [ TRACE]:capmt: 04 0D 95 E9 C7 01 00 13 00 06 ..........
2015-03-22 22:36:31.817 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 123)
2015-03-22 22:36:31.817 [ TRACE]:capmt: 9F 80 32 82 00 24 00 00 7B 1B 00 19 01 82 02 00 ..2..$..{.......
2015-03-22 22:36:31.817 [ TRACE]:capmt: 03 81 08 00 00 00 00 00 0B 00 85 84 02 00 60 09 ..............`.
2015-03-22 22:36:31.817 [ TRACE]:capmt: 04 18 33 F8 17 01 00 0D 00 06 ..3.......
2015-03-22 22:36:31.817 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 127)
2015-03-22 22:36:31.817 [ TRACE]:capmt: 9F 80 32 82 00 24 02 00 7F 1C 00 19 01 82 02 00 ..2..$..........
2015-03-22 22:36:31.817 [ TRACE]:capmt: 02 81 08 00 00 00 00 00 0D 00 85 84 02 00 62 09 ..............b.
2015-03-22 22:36:31.817 [ TRACE]:capmt: 04 18 33 F8 54 01 00 09 00 06 ..3.T.....
2015-03-22 22:36:32.199 [ TRACE]:descrambler: CAT data (len 42)
2015-03-22 22:36:32.199 [ TRACE]:descrambler: 09 04 06 48 E2 58 09 04 06 50 E2 59 09 04 17 02 ...H.X...P.Y....
2015-03-22 22:36:32.199 [ TRACE]:descrambler: E2 63 09 04 0D 95 E2 BD 09 04 0D 98 E2 BE 09 04 .c..............
2015-03-22 22:36:32.199 [ TRACE]:descrambler: 18 33 E3 2B 09 04 09 C4 E3 3E .3.+.....>
2015-03-22 22:36:32.925 [ TRACE]:descrambler: stream key changed to odd for service "TNT Serie HD"
2015-03-22 22:36:32.926 [ TRACE]:descrambler: EMM message (len 137, pid 6167)
2015-03-22 22:36:32.926 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:32.926 [ TRACE]:capmt: FF FF 00 00 0A 00 80 30 86 07 84 00 F3 6E 6B A1 .......0.....nk.
2015-03-22 22:36:32.926 [ TRACE]:capmt: 22 4C 17 63 A3 CE 2E 9F A7 E7 26 E2 97 15 3D C6 "L.c......&...=.
2015-03-22 22:36:32.926 [ TRACE]:capmt: 8D 98 3F 7B 5D 07 5D 44 AF ED 1D FD 2E 7C A9 9A ..?{].]D.....|..
2015-03-22 22:36:32.926 [ TRACE]:capmt: 30 08 2B FD 60 CF B8 FA CD D1 14 28 5A F7 CA 65 0.+.`......(Z..e
2015-03-22 22:36:32.926 [ TRACE]:capmt: 81 B7 C3 55 C3 CA 7C DB 56 1B 90 8D 90 3E 45 C7 ...U..|.V....>E.
2015-03-22 22:36:32.926 [ TRACE]:capmt: C7 79 6F 61 20 FD 6D C1 5A C1 33 0E 0A 43 98 66 .yoa .m.Z.3..C.f
2015-03-22 22:36:32.926 [ TRACE]:capmt: BA 80 B1 9E 2D 08 76 F4 54 8D 1E 8D 48 73 27 82 ....-.v.T...Hs'.
2015-03-22 22:36:32.926 [ TRACE]:capmt: 5C B0 6C AA 82 7B D1 AD 21 60 A3 26 E4 54 E4 F4 \.l..{..!`.&.T..
2015-03-22 22:36:32.926 [ TRACE]:capmt: FD 8D D6 BC C6 4E 0D 3C F0 D2 09 B2 92 7E AD .....N.<.....~.
2015-03-22 22:36:32.926 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:32.926 [ TRACE]:capmt: 40 3C 6F 2B 03 0A 00 18 17 81 00 00 00 00 00 00 <o+............ #3081 Continuity counter error (total 1)
2015-03-22 22:36:32.926 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 ................
2015-03-22 22:36:32.926 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:32.926 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:32.926 [ TRACE]:capmt: 04 .
2015-03-22 22:36:32.926 [ TRACE]:capmt: OSCAM Spaz (local): setting filter: adapter=3, demux=10, filter=0, pid=6167
2015-03-22 22:36:32.926 [ TRACE]:capmt: 81 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:32.926 [ TRACE]:capmt: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:32.926 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:33.070 [WARNING]:TS: Astra 1 19.2/11273.25H/ORF III HD: AC3
2015-03-22 22:36:33.070 [WARNING]:TS: Astra 1 19.2/11273.25H/ORF III HD: AC3 #3082 Continuity counter error (total 1).o............!
2015-03-22 22:36:33.561 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:33.561 [ TRACE]:capmt: 40 10 6F 86 03 00 00 00 0A 00 00 00 00 7F AB 21
2015-03-22 22:36:33.561 [ TRACE]:capmt: 4B 3F 7F E2 A0 K?...
2015-03-22 22:36:33.561 [ DEBUG]:capmt: OSCAM Spaz (local), CA_SET_DESCR adapter 3 par 0 idx 10 7fab214b3f7fe2a0
2015-03-22 22:36:33.561 [ TRACE]:descrambler: Obtained keys 7FAB214B3F7FE2A0:0000000000000000 from capmt-192.168.0.245-9000 for service "TNT Serie HD"
2015-03-22 22:36:35.532 [ TRACE]:descrambler: stream key changed to even for service "13th Street HD"
2015-03-22 22:36:35.532 [ TRACE]:descrambler: EMM message (len 137, pid 6228)
2015-03-22 22:36:35.532 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:35.532 [ TRACE]:capmt: FF FF 00 00 07 00 81 30 86 07 84 00 22 68 3D 16 .......0...."h=.
2015-03-22 22:36:35.532 [ TRACE]:capmt: 31 5C 3F FA 76 07 8F 63 39 A5 FF 27 1A 82 98 0F 1\?.v..c9..'....
2015-03-22 22:36:35.532 [ TRACE]:capmt: A8 4D BA 56 39 0C B1 A3 39 8E F8 2F 9B 5C E9 23 .M.V9...9../.\.#
2015-03-22 22:36:35.532 [ TRACE]:capmt: 2C 25 8D 26 FD BE C6 51 56 69 49 FD C1 52 B4 A4 ,%.&...QViI..R..
2015-03-22 22:36:35.532 [ TRACE]:capmt: 9D 39 1C F3 DF ED 60 8A C8 FF 16 16 2A 61 A3 6D .9....`.....*a.m
2015-03-22 22:36:35.532 [ TRACE]:capmt: C8 23 3D 05 65 20 7E 13 E0 28 83 C2 3F 19 DA 4E .#=.e ~..(..?..N
2015-03-22 22:36:35.532 [ TRACE]:capmt: 15 7A 37 18 CA 85 3A F2 83 58 BB 07 9C 60 E3 D4 .z7...:..X...`..
2015-03-22 22:36:35.532 [ TRACE]:capmt: C5 72 94 4D 98 AB DD 2E 7B E4 62 D3 06 00 FF B2 .r.M....{.b.....
2015-03-22 22:36:35.532 [ TRACE]:capmt: A8 E1 D1 FD 71 3F CD 43 3E 3F B3 FF 78 0B 9D ....q?.C>?..x..
2015-03-22 22:36:35.533 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:35.533 [ TRACE]:capmt: 40 3C 6F 2B 02 07 00 18 54 80 00 00 00 00 00 00 <o+....T........o............f
2015-03-22 22:36:35.533 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 ................
2015-03-22 22:36:35.533 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:35.533 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:35.533 [ TRACE]:capmt: 04 .
2015-03-22 22:36:35.533 [ TRACE]:capmt: OSCAM Spaz (local): setting filter: adapter=2, demux=7, filter=0, pid=6228
2015-03-22 22:36:35.533 [ TRACE]:capmt: 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:35.533 [ TRACE]:capmt: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:35.533 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:36.106 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:36.106 [ TRACE]:capmt: 40 10 6F 86 02 00 00 00 07 00 00 00 01 DD A1 66
2015-03-22 22:36:36.106 [ TRACE]:capmt: E4 88 6F FC F3 ..o..
2015-03-22 22:36:36.106 [ DEBUG]:capmt: OSCAM Spaz (local), CA_SET_DESCR adapter 2 par 1 idx 7 dda166e4886ffcf3
2015-03-22 22:36:36.106 [ TRACE]:descrambler: Obtained keys 0000000000000000:DDA166E4886FFCF3 from capmt-192.168.0.245-9000 for service "13th Street HD"
2015-03-22 22:36:39.957 [ TRACE]:descrambler: stream key changed to even for service "TNT Serie HD"
2015-03-22 22:36:40.061 [ TRACE]:descrambler: EMM message (len 137, pid 6167)
2015-03-22 22:36:40.061 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:40.061 [ TRACE]:capmt: FF FF 00 00 0A 00 81 30 86 07 84 00 C2 66 B7 0B .......0.....f..
2015-03-22 22:36:40.061 [ TRACE]:capmt: FA 8F FD 4C 35 50 E5 A7 29 FF EB EA A4 07 25 37 ...L5P..).....%7
2015-03-22 22:36:40.061 [ TRACE]:capmt: 50 AB F8 F2 0E 0D 61 92 B8 BC ED A9 A1 FA 2F 3D P.....a......./=
2015-03-22 22:36:40.061 [ TRACE]:capmt: C3 23 E9 B7 81 BF EB 0C 44 05 28 63 88 36 73 FC .#......D.(c.6s.
2015-03-22 22:36:40.061 [ TRACE]:capmt: FF AD 62 2A 1B 32 04 29 24 A8 0F F6 D2 85 2C 45 ..b*.2.)$.....,E
2015-03-22 22:36:40.061 [ TRACE]:capmt: A0 FF A8 F8 DA 4E F5 64 D4 17 82 FB C3 8B 9B CB .....N.d........
2015-03-22 22:36:40.061 [ TRACE]:capmt: 58 97 42 44 18 31 33 E1 7D 68 1F 39 7C 2F 9F FD X.BD.13.}h.9|/..
2015-03-22 22:36:40.061 [ TRACE]:capmt: 6E DB 1E 29 FA 3B C7 4A EF C4 C4 F0 9B 98 DB AC n..).;.J........
2015-03-22 22:36:40.061 [ TRACE]:capmt: E4 14 B3 CA A4 F0 DD 5A BA 1C 4F 6E DF 4A EF .......Z..On.J.
2015-03-22 22:36:40.061 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:40.061 [ TRACE]:capmt: 40 3C 6F 2B 03 0A 00 18 17 80 00 00 00 00 00 00 <o+.............o..........U.f
2015-03-22 22:36:40.061 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 ................
2015-03-22 22:36:40.061 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:40.061 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:40.061 [ TRACE]:capmt: 04 .
2015-03-22 22:36:40.061 [ TRACE]:capmt: OSCAM Spaz (local): setting filter: adapter=3, demux=10, filter=0, pid=6167
2015-03-22 22:36:40.061 [ TRACE]:capmt: 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:40.061 [ TRACE]:capmt: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:40.061 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:40.725 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:40.725 [ TRACE]:capmt: 40 10 6F 86 03 00 00 00 0A 00 00 00 01 55 17 66
2015-03-22 22:36:40.725 [ TRACE]:capmt: D2 32 FB CD FA .2...
2015-03-22 22:36:40.725 [ DEBUG]:capmt: OSCAM Spaz (local), CA_SET_DESCR adapter 3 par 1 idx 10 551766d232fbcdfa
2015-03-22 22:36:40.725 [ TRACE]:descrambler: Obtained keys 0000000000000000:551766D232FBCDFA from capmt-192.168.0.245-9000 for service "TNT Serie HD"
2015-03-22 22:36:41.358 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:41.358 [ TRACE]:descrambler: EMM message (len 142, pid 4098)
2015-03-22 22:36:41.358 [ TRACE]:capmt: FF FF 00 00 0A 01 82 70 8B 00 00 00 00 00 04 84 .......p........
2015-03-22 22:36:41.358 [ TRACE]:capmt: 00 46 1E FF 81 1A A3 91 1C D1 4C 08 ED DA 44 E4 .F........L...D.
2015-03-22 22:36:41.358 [ TRACE]:capmt: 1A F7 45 85 CB 48 4D 60 EE 41 C7 B9 31 8B BA 5E ..E..HM`.A..1..^
2015-03-22 22:36:41.359 [ TRACE]:capmt: 6E 99 A8 D3 DE 47 91 78 CE 9E B9 7F 41 E2 F2 E6 n....G.x....A...
2015-03-22 22:36:41.359 [ TRACE]:capmt: 0E 67 7D 00 67 E7 F2 3A 16 E3 2E F7 93 A0 12 A1 .g}.g..:........
2015-03-22 22:36:41.359 [ TRACE]:capmt: D8 38 B9 C6 74 9B 96 7D D2 42 AE 11 55 58 41 FD .8..t..}.B..UXA.
2015-03-22 22:36:41.359 [ TRACE]:capmt: CD E1 91 15 AD 03 F4 BB B4 C7 88 AD 76 02 F9 1D ............v...
2015-03-22 22:36:41.359 [ TRACE]:capmt: 23 90 7C 3C 08 33 C9 56 1E 75 B9 63 F6 D4 13 57 #.|<.3.V.u.c...W
2015-03-22 22:36:41.359 [ TRACE]:capmt: 0E 98 0A 96 3C 21 84 3B CA B3 7B 8F 35 EE 69 26 ....<!.;..{.5.i&
2015-03-22 22:36:41.359 [ TRACE]:capmt: 58 E7 A6 75 X..u
2015-03-22 22:36:42.538 [ TRACE]:descrambler: stream key changed to odd for service "13th Street HD"
2015-03-22 22:36:42.539 [ TRACE]:descrambler: EMM message (len 137, pid 6228)
2015-03-22 22:36:42.539 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:42.539 [ TRACE]:capmt: FF FF 00 00 07 00 80 30 86 07 84 00 F9 96 A6 99 .......0........
2015-03-22 22:36:42.539 [ TRACE]:capmt: B3 10 22 59 D0 DB 5B 55 40 2F 93 72 E9 BC E1 52 .."Y..[U@/.r...R
2015-03-22 22:36:42.539 [ TRACE]:capmt: 55 56 B3 80 32 C0 A8 D8 F3 C9 F8 D2 E6 32 F0 F9 UV..2........2..
2015-03-22 22:36:42.539 [ TRACE]:capmt: 33 D1 17 6F 49 AE 59 B6 9B CE F4 A1 18 7C B2 8E 3..oI.Y......|..
2015-03-22 22:36:42.539 [ TRACE]:capmt: 55 01 4C 84 AF A8 34 ED D4 3D 06 83 AA 0A 25 B5 U.L...4..=....%.
2015-03-22 22:36:42.539 [ TRACE]:capmt: F0 45 A4 B7 5E 8F CD 57 D4 52 34 0D 32 AD 40 D0 .E..^..W.R4.2..<o+....T.......
2015-03-22 22:36:42.539 [ TRACE]:capmt: B7 E9 BA 2A 82 C5 0D 03 82 FF DA 92 19 A3 96 5B ...*...........[
2015-03-22 22:36:42.539 [ TRACE]:capmt: 28 1F CA 35 99 66 F1 03 97 DD 16 DD 9E BE DF 39 (..5.f.........9
2015-03-22 22:36:42.539 [ TRACE]:capmt: 18 37 CC FC F7 CA 1E C7 BD B9 AE E6 11 62 A2 .7...........b.
2015-03-22 22:36:42.540 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:42.540 [ TRACE]:capmt: 40 3C 6F 2B 02 07 00 18 54 81 00 00 00 00 00 00
2015-03-22 22:36:42.540 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 ................
2015-03-22 22:36:42.540 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:42.540 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:42.540 [ TRACE]:capmt: 04 .
2015-03-22 22:36:42.540 [ TRACE]:capmt: OSCAM Spaz (local): setting filter: adapter=2, demux=7, filter=0, pid=6228
2015-03-22 22:36:42.540 [ TRACE]:capmt: 81 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:42.540 [ TRACE]:capmt: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:42.540 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:43.123 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:43.123 [ TRACE]:capmt: 40 10 6F 86 02 00 00 00 07 00 00 00 00 98 9E 1A .o.............<o+............
2015-03-22 22:36:43.123 [ TRACE]:capmt: 50 19 26 CA 09 P.&..
2015-03-22 22:36:43.123 [ DEBUG]:capmt: OSCAM Spaz (local), CA_SET_DESCR adapter 2 par 0 idx 7 989e1a501926ca09
2015-03-22 22:36:43.123 [ TRACE]:descrambler: Obtained keys 989E1A501926CA09:0000000000000000 from capmt-192.168.0.245-9000 for service "13th Street HD"
2015-03-22 22:36:46.957 [ TRACE]:descrambler: stream key changed to odd for service "TNT Serie HD"
2015-03-22 22:36:47.103 [ TRACE]:capmt: OSCAM Spaz (local): Sending message to socket 35 (sid 0)
2015-03-22 22:36:47.103 [ TRACE]:capmt: FF FF 00 00 0A 00 80 30 86 07 84 00 67 17 E4 6C .......0....g..l
2015-03-22 22:36:47.103 [ TRACE]:capmt: 71 8E AC 31 D9 7C FE D1 D5 B6 B1 F6 F0 B9 21 9A q..1.|........!.
2015-03-22 22:36:47.103 [ TRACE]:capmt: 2F 0B 29 B4 23 74 2D 87 98 50 07 FB EE 75 D9 8B /.).#t-..P...u..
2015-03-22 22:36:47.103 [ TRACE]:capmt: 8E 35 DF 99 B8 CC 5C 60 41 CA DF F4 F7 B1 25 45 .5....\`A.....%E
2015-03-22 22:36:47.103 [ TRACE]:capmt: CB DC F7 C0 42 F9 B2 3C 1F 17 29 D5 E8 86 7A C2 ....B..<..)...z.
2015-03-22 22:36:47.103 [ TRACE]:capmt: B4 0B EF 91 AC B2 3A 9C CF 92 2D D4 AC 75 21 58 ......:...-..u!X
2015-03-22 22:36:47.103 [ TRACE]:capmt: C5 76 72 8A BD C2 42 1C 0D 39 DC 35 D0 79 14 A6 .vr...B..9.5.y..
2015-03-22 22:36:47.103 [ TRACE]:capmt: 93 CF DA 53 8B C5 2A A8 D7 3A 28 2B D7 97 E3 3E ...S..*..:(+...>
2015-03-22 22:36:47.103 [ TRACE]:capmt: 4D 69 C5 69 0F 0E 78 94 D0 B4 C3 A8 20 E8 5F Mi.i..x..... ._
2015-03-22 22:36:47.103 [ TRACE]:capmt: OSCAM Spaz (local): Received message from socket 35
2015-03-22 22:36:47.103 [ TRACE]:capmt: 40 3C 6F 2B 03 0A 00 18 17 81 00 00 00 00 00 00
2015-03-22 22:36:47.103 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 ................
2015-03-22 22:36:47.103 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:47.103 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:47.103 [ TRACE]:capmt: 04 .
2015-03-22 22:36:47.103 [ TRACE]:capmt: OSCAM Spaz (local): setting filter: adapter=3, demux=10, filter=0, pid=6167
2015-03-22 22:36:47.103 [ TRACE]:capmt: 81 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:47.103 [ TRACE]:capmt: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
2015-03-22 22:36:47.103 [ TRACE]:capmt: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
Files
Subtasks
History
Updated by B C over 9 years ago
Updated by this was with oscam net protocol, but it also happens with eg tcp
Updated by B C over 9 years ago
funny thing, not reporting it for a long time and now build 10640 of oscam makeing things a lot better, but still not perfect, so maybe let's watch on oscam's front for a while
Updated by Jaroslav Kysela over 9 years ago
Updated by I extended the logging in v3.9-2626-gc54f9b0 . Also, attach both tvheadend and oscam logs for the same session (for oscam enable debug flag 128 - it's dvbapi debugging).
Updated by B C over 9 years ago
it seems you already fixed it with c54f9b0c. Let my family find out till tomorrow :-)
Updated by B C over 9 years ago
one more thing. If it's not the intended behavior, I will do some more logging if necessary. When changing channels, oscam logs that it will continue to decode the service id that is beeing handled for another adapter (exmaple demuxer 1, SRVID 007f) but it will also log that it adds the corresponding pid again as new ecm pid. It does this twice while changing channels.
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 continue decoding of SRVID 007F
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 1833 ECM_PID: 1854 PROVID: 000000
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 receiver wants to demux srvid 007F on adapter 0003 camask 0008 index 0000 pmtpid 0000
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 new program number: 007F (13th Street HD) [pmt_list_management 3]
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 added new ecmpid 0 CAID: 0500 ECM_PID: 1FE1 PROVID: 050810
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 added new ecmpid 1 CAID: 0500 ECM_PID: 1FE0 PROVID: 040820
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 found 2 ECMpids and 1 STREAMpids in PMT
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 receiver wants to demux srvid 1260 on adapter 0000 camask 0001 index 0000 pmtpid 0000
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 new program number: 1260 (0500:1260 unknown) [pmt_list_management 1]
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 trying to descramble PID 0 CAID 0500 PROVID 050810 ECMPID 1FE1 ANY CHID PMTPID 0000 VPID 0027
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 trying to descramble PID 1 CAID 0500 PROVID 040820 ECMPID 1FE0 ANY CHID PMTPID 0000 VPID 0027
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 continue decoding of SRVID 007F
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 1833 ECM_PID: 1854 PROVID: 000000
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 found 1 ECMpids and 1 STREAMpids in PMT
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 receiver wants to demux srvid 007F on adapter 0003 camask 0008 index 0000 pmtpid 0000
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 1 new program number: 007F (13th Street HD) [pmt_list_management 2]
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 found channel in cache and matching prio -> start descrambling ecmpid 1
2015/03/23 11:11:36 1D2ED40 c (dvbapi) Demuxer 0 trying to descramble PID 1 CAID 0500 PROVID 040820 ECMPID 1FE0 ANY CHID PMTPID 0000 VPID 0027
Updated by B C over 9 years ago
With the latest version of tvh it's not working. I have attached logs from tvh 2641 and oscam 10641. It alternatively decodes on each adapter, either ATV HD or ORF1 HD is being descrambled, but neither channel is working continously. With the help of CWC client both work fine simultaniously.
Updated by Jaroslav Kysela over 9 years ago
This looks like an oscam bug, the ECM filters seems to be malformed:
OK: 2015/03/23 22:47:45 90C5E0 c (dvbapi) Demuxer 1 Filter 2 fetched ECM data (ecmlength = 09C) 2015/03/23 22:47:45 90C5E0 c (dvbapi) Demuxer 1 ECMTYPE 80 CAID 0D05 PROVID 000004 ECMPID 00DC FAKECHID 0000 (unique part in ecm) 2015/03/23 22:47:45 90C5E0 c (dvbapi) Demuxer 1 Filter 2 set ecmtable to ODD (CAID 0D05 PROVID 000004 FD 65535) 2015/03/23 22:47:45 90C5E0 c (dvbapi) Demuxer 1 Filter 2 set chid to ANY CHID on fd 65535 PMT change: 2015/03/23 22:47:50 90C5E0 c (dvbapi) Marked demuxer 1/16 (srvid = 132F fd = 19) to stop decoding 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 continue decoding of SRVID 132F 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 found pmt type: 81 length: 8 (assuming enigma private descriptor: namespace 0000 tsid 3ef onid 01) 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0650 ECM_PID: 007A PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 1 CAID: 0D98 ECM_PID: 0110 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 2 CAID: 098C ECM_PID: 01EA PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 3 CAID: 09C4 ECM_PID: 01E0 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 4 CAID: 1833 ECM_PID: 01A4 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 5 CAID: 1702 ECM_PID: 0140 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 6 CAID: 0648 ECM_PID: 0078 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 7 CAID: 0D95 ECM_PID: 010E PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 8 CAID: 0D05 ECM_PID: 00DC PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new stream (type: 01 pid: 002e length: 6) 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 found 9 ECMpids and 1 STREAMpids in PMT 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 receiver wants to demux srvid 132F on adapter 0000 camask 0001 index 0000 pmtpid 0000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 new program number: 132F (0650:132F unknown) [pmt_list_management 3] 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 demux_index: 0 ca_mask: 01 program_info_length: 73 ca_pmt_list_management 03 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 handles 0 emm filters 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 continue decoding of SRVID 132F 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 found pmt type: 81 length: 8 (assuming enigma private descriptor: namespace 0000 tsid 3ef onid 01) 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 0 CAID: 0650 ECM_PID: 007A PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 1 CAID: 0D98 ECM_PID: 0110 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 2 CAID: 098C ECM_PID: 01EA PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 3 CAID: 09C4 ECM_PID: 01E0 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 4 CAID: 1833 ECM_PID: 01A4 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 5 CAID: 1702 ECM_PID: 0140 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 6 CAID: 0648 ECM_PID: 0078 PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 7 CAID: 0D95 ECM_PID: 010E PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new ecmpid 8 CAID: 0D05 ECM_PID: 00DC PROVID: 000000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 added new stream (type: 01 pid: 002e length: 6) 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 found 9 ECMpids and 1 STREAMpids in PMT 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 receiver wants to demux srvid 132F on adapter 0000 camask 0001 index 0000 pmtpid 0000 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 new program number: 132F (0650:132F unknown) [pmt_list_management 2] 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 demux_index: 0 ca_mask: 01 program_info_length: 73 ca_pmt_list_management 02 2015/03/23 22:47:50 90C5E0 c (dvbapi) Demuxer 1 handles 0 emm filters Wrong: 2015/03/23 22:47:55 90C5E0 c (dvbapi) Demuxer 1 Filter 2 fetched ECM data (ecmlength = 09C) 2015/03/23 22:47:55 90C5E0 c (dvbapi) Demuxer 1 ECMTYPE 81 CAID 0D05 PROVID 000000 ECMPID 00DC FAKECHID 0000 (unique part in ecm) 2015/03/23 22:47:55 90C5E0 c (dvbapi) Demuxer 1 not requesting cw -> ecm filter was killed!
I don't see any "Demuxer 1 stop Filter 2" or "Demuxer 1 disable stream" messages which kills filter.
Could you try to downgrade oscam (for example to 10087) ? It seems that there are many changes in the dvbapi recently.. Anyway, report this issue also to oscam developers.
Updated by B C over 9 years ago
10087 is working rock solid. I've opened a ticket on trac.
Thanks
Updated by Jaroslav Kysela over 9 years ago
- Status changed from New to Rejected
Closing, it seems like an issue for the recent oscam. I can re-open it if it's a tvh bug.
Updated by B C over 9 years ago
so finally we got some updates for oscam and now it's working better. Still I have an issue which theparasol means now is on tvheadends side (see http://www.streamboard.tv/oscam/ticket/4149#comment:13) I just made some logs with latest tvheadend (2808) and oscam (10656). I did the following
1. Start ORF1 HD on client #1
2. Start ORF2 HD on client #2
3. Start ORF III HD on client #3
so far everything is fine
4. Switch to Pulse4 on client #3
now ORF2 HD on client #2 gets an ECM timeout, according to theparasol tvheadend no longer sends ecm requests to oscam
Updated by B C over 9 years ago
- File tvh-10656.log tvh-10656.log added
- File oscam-r10656.log oscam-r10656.log added
Updated by B C over 9 years ago
I think I found the problem. In my test case ORF2 HD and ORF III HD do use the same ECM pid. So if both channels are tuned in and I switch away from one of them the ecm filter gets closed and the running program dies. I have no idea if this is tvheadends or oscams fault. Jaroslav could you have a look?
Thanks
Updated by B C over 9 years ago
I think tvheadend is not taking the demux index into account when opening and closing filters, at least the index is in oscams message for opening and closing. (just guessing as I only looked at the payload without knowing the protocol :-) )
2015/05/05 16:21:05 1375010 c (dvbapi) Demuxer 1 try to start new filter for caid: 0D95, provid: 000000, pid: 09C7
2015/05/05 16:21:05 1375010 c (dvbapi) Sending packet to dvbapi client (fd=8):
2015/05/05 16:21:05 1375010 c (dvbapi) 40 3C 6F 2B 01 01 02 09 C7 80 00 00 00 00 00 00
2015/05/05 16:21:05 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 F0 00 00 00 00 00 00
2015/05/05 16:21:05 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/05/05 16:21:05 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 0B B8 00 00 00
2015/05/05 16:21:05 1375010 c (dvbapi) 04
2015/05/05 16:21:40 1375010 c (dvbapi) Demuxer 2 try to start new filter for caid: 0D95, provid: 000000, pid: 09C7
2015/05/05 16:21:40 1375010 c (dvbapi) Sending packet to dvbapi client (fd=8):
2015/05/05 16:21:40 1375010 c (dvbapi) 40 3C 6F 2B 01 02 00 09 C7 80 00 00 00 00 00 00
2015/05/05 16:21:40 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 F0 00 00 00 00 00 00
2015/05/05 16:21:40 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2015/05/05 16:21:40 1375010 c (dvbapi) 00 00 00 00 00 00 00 00 00 00 00 0B B8 00 00 00
2015/05/05 16:21:40 1375010 c (dvbapi) 04
2015/05/05 16:22:15 1375010 c (dvbapi) Demuxer 2 stop Filter 1 (fd: 65535 api: 0, caid: 0D95, provid: 000004, ecmpid: 09C7)
2015/05/05 16:22:15 1375010 c (dvbapi) Sending packet to dvbapi client (fd=8):
2015/05/05 16:22:15 1375010 c (dvbapi) 00 00 6F 2A 01 02 00 09 C7
2015/05/05 16:24:00 0 s (dvbapi) Demuxer 1 stop Filter 3 (fd: 65535 api: 0, caid: 0D95, provid: 000004, ecmpid: 09C7)
2015/05/05 16:24:00 0 s (dvbapi) Sending packet to dvbapi client (fd=8):
2015/05/05 16:24:00 0 s (dvbapi) 00 00 6F 2A 01 01 02 09 C7
Updated by B C over 9 years ago
yes, this fixed it, great. I think this ticket can be closed now.
Thanks