Tvheadend

Also happens on BBC and Channel 4 (FTA).
Live TV and recordings. On Live TV you see "Buffering 0%" forever.

I got the same on ProSieben HD - observing the Buffering 0% . After a second attemp the live tv started.

If you can confirm this works by going back to previous version then please submit debug logs pre and post with the following debug (command line) options:

--trace mpegts,dvb,linuxdvb -l tvh.log

Adam

Applying the fixes from this morning (you are an active coder!) fixed the "Buffering 0%" issue for me. On encrypted and FTA. Thank you.

Still, it would have been good if Live streaming gave us a debug message like dvr does:

Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: subscription: "DVR: This Morning" subscribing on "ITV HD", weight: 300, adapter: "STV090x Multistandard : DVB-S #3", network: "28.2E", mux: "11097V", provider: "BSkyB", service: "ITV HD"
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: /data/3/tv_recordings/This Morning/ITV HD-This Morning.2014-04-23.12-30.ts from adapter: "STV090x Multistandard : DVB-S #3", network: "28.2E", mux: "11097V", provider: "BSkyB", service: "ITV HD"
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: # type lang resolution aspect ratio sample rate channels
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 1 H264 1920x1080 ?
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 2 MPEG2AUDIO nar ? ?
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 3 TELETEXT nar
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 4 DVBSUB eng
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 5 AC3 eng ? ?
Apr 23 12:24:39 sat tvheadend¹⁵³⁷⁹: dvr: 6 TEXTSUB eng

I may have spoken to soon... This afternoon I tested all 6 adapters, one by one (so disable all but one, test, move to the next, etc).
Left all 6 enabled.
Now I see in Status that 2 adapters are in use (adapter 4 and 5) one with live streaming and one with a recorder). But in syslog I see that epgscan cannot find a free adapter:

Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - tuning on STV090x Multistandard : DVB-S #0
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - failed to start, try another
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - starting for 'epggrab' (weight 1)
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - tuning on STV090x Multistandard : DVB-S #3
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - failed to start, try another
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - starting for 'epggrab' (weight 1)
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - tuning on STV090x Multistandard : DVB-S #1
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - failed to start, try another
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - starting for 'epggrab' (weight 1)
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - tuning on STV090x Multistandard : DVB-S #2
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - failed to start, try another
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - starting for 'epggrab' (weight 1)
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - tuning on STV090x Multistandard : DVB-S #0
Apr 23 16:17:29 sat tvheadend¹¹⁵⁸¹: mpegts: 12265H - failed to start, try another
Apr 23 16:17:30 sat tvheadend¹¹⁵⁸¹: subscription: "epggrab" unsubscribing
Apr 23 16:21:22 sat tvheadend¹¹⁵⁸¹: mpegts: 12187H - starting for 'epggrab' (weight 1)
Apr 23 16:21:22 sat tvheadend¹¹⁵⁸¹: mpegts: 12187H - tuning on STV090x Multistandard : DVB-S #5
Apr 23 16:21:23 sat tvheadend¹¹⁵⁸¹: subscription: 'epggrab' subscribing to mux, weight: 1, adapter: 'STV090x Multistandard : DVB-S #5', network: '23.5E', mux: '12187H'
Apr 23 16:23:03 sat tvheadend¹¹⁵⁸¹: subscription: "epggrab" unsubscribing
Apr 23 16:26:59 sat tvheadend¹¹⁵⁸¹: mpegts: 11552H - starting for 'epggrab' (weight 1)
Apr 23 16:26:59 sat tvheadend¹¹⁵⁸¹: mpegts: 11552H - tuning on STV090x Multistandard : DVB-S #5
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: subscription: 'epggrab' subscribing to mux, weight: 1, adapter: 'STV090x Multistandard : DVB-S #5', network: '19.2E', mux: '11552H'
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - starting for 'epggrab' (weight 1)
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - tuning on STV090x Multistandard : DVB-S #3
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - failed to start, try another
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - starting for 'epggrab' (weight 1)
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - tuning on STV090x Multistandard : DVB-S #1
Apr 23 16:27:02 sat tvheadend¹¹⁵⁸¹: mpegts: 11420H - failed to start, try another

When I check each adapter, it is enabled and has the networks selected.
When I restart tvheadend, all 6 run (again). It is possible that an adapter "remembers" it has been disabled from the Configuration panel?

Hi, I confirm the issue on encrypted channel. I'm using tvheadend-trunk and showtime-trunk, but I found the same problem on tvheadend stable release (v3.6).

When I select an encrypted channel, subscription starts with state: Testing, but after 6 seconds the state becomes Bad (No input detected). So if I unsubscrive and subscribe more times on the same channel, the state becomes Running. I think the same thing happens during the streaming too, the video stops and resumes after 10-20 seconds even if the process continues to ask for valid keys for descrable.

I tried (with the same results):
- two DVB-T (DiBcom 7000PC, Afatech AF9033)
- one DVB-S (Technisat SkyStar USB HD)
- oscam-trunk-9705 with CWC and CAPMT

I'm available for further testing
Thanks for all

Any news on this bug? I can confirm that the same channels, with the same oscam installation, work well on VDR. I've also switched recently on SAT>IP and the problem is still there...

I've just discovered that tvheadend support oscam dvbapi network-mode: now all channels work! My previous configuration (working with VDR) used caid-specific newcamd connections.

it looks unreliable: sometimes, on the same channel, I get descrambler: channel-name-here: even stream key is not valid on the log...

I've solved my problems: this could help other people so I report the details. I've switched on the network-mode of dvbapi but in this mode some channels were not available ("...stream key is not valid" on logs). I've discovered that on these specific channels there are multiple PIDs with the same CAID of my card. I don't know why, but some of these PIDS can't correctly decoded by my card (oscam say decoded but tvheadend says the they are not valid...). In a OSCAM bug report ([[http://www.streamboard.tv/oscam/ticket/3762]]) I've found a way to force the use of a specific PID under some conditions.

For me, a file oscam.dvbapi with the following lines has solved my problems:
P: 09CD 3:3
I: 09CD 2

This trick could also help with dvbapi on local socket.

I'm noting that tvheadend has a per-service property "Preferred CA pid". It looks that using cwc I can force the correct PID and decode even using cwc. By the way, I should correct by-hand every channel and it looks ugly. What have changed in tvheadend. It looks that the choice in my case is incorrect.
For example, for "Cinema Classics" of sky-it on mux 12034V of Hotbird 13°, the info look like this:
@Index PID Type Language Details
0x00a5 / 165 PCR
0x0461 / 1121 PMT
1 0x00a5 / 165 MPEG2VIDEO
2 0x01a4 / 420 MPEG2AUDIO ita
3 0x01a5 / 421 MPEG2AUDIO und
4 0x01d9 / 473 TELETEXT
5 0x2309 / 8969 TEXTSUB ita
6 0x230a / 8970 TEXTSUB eng
7 0x0647 / 1607 CA CAIDS: 0919:000000
8 0x06ab / 1707 CA CAIDS: 093b:000000
9 0x070f / 1807 CA CAIDS: 09cd:000000
10 0x0672 / 1650 CA CAIDS: 0919:000000
11 0x06d6 / 1750 CA CAIDS: 093b:000000
12 0x073a / 1850 CA CAIDS: 09cd:000000

After filtering and reordering (without PCR and PMT)
Index PID Type Language Details
1 0x00a5 / 165 MPEG2VIDEO
2 0x01a4 / 420 MPEG2AUDIO ita
3 0x01a5 / 421 MPEG2AUDIO und
4 0x01d9 / 473 TELETEXT
5 0x2309 / 8969 TEXTSUB ita
6 0x230a / 8970 TEXTSUB eng
7 0x0647 / 1607 CA CAIDS: 0919:000000
8 0x06ab / 1707 CA CAIDS: 093b:000000
9 0x070f / 1807 CA CAIDS: 09cd:000000
10 0x0672 / 1650 CA CAIDS: 0919:000000
11 0x06d6 / 1750 CA CAIDS: 093b:000000
12 0x073a / 1850 CA CAIDS: 09cd:000000@

In my case, my card is a type 09cd and it looks that my pid is always the third. tvheadend automatically select pid 1850 and the decoding doesn't work. If I correct such value in 1807, it works well.

The prefcapid selection looks broken with my card. On the above example channel there are 2 possible PIDS with 09cd (1807, 1850), and tvheadend try to request two ECMs. My oscam is, maybe wrongly, reporting answers that are both accepted by tvheadend. It looks that the first reply cancels the other request and it is chosen as prefcapid. A log starting with precapid=0 is below reported: at time 17:45:33.502 the working pid 1807 is selected as prefcapid (just because it arrives first!), but later at time 17:45:36.914 it is overwritten (!?!) by the broken pid 1850.

I hope this is not just noise by me. I would try to help you developers to improve the project.


2014-07-21 17:45:09.000 [ TRACE]:cwc: sending message sid 0 len 26 enq 0
2014-07-21 17:45:09.000 [ TRACE]:cwc: 00 00 39 5F 10 98 DD BE 41 9A E2 58 22 64 50 6C ..9_....A..X"dPl
2014-07-21 17:45:09.000 [ TRACE]:cwc: 0D 03 CD 7C E8 BA 58 1B AB D7 ...|..X...
2014-07-21 17:45:32.643 [ INFO]:mpegts: 12034V in Hotbird 13° - tuning on SAT>IP DVB-S Tuner #1 (192.168.200.10)
2014-07-21 17:45:32.643 [ TRACE]:descrambler: mux 0x7f2a8806ded0 open pid 070F (1807) (flags 0x0040)
2014-07-21 17:45:32.643 [ TRACE]:descrambler: mux 0x7f2a8806ded0 open pid 073A (1850) (flags 0x0040)
2014-07-21 17:45:32.643 [ DEBUG]:cwc: 12034V/Cinema Classics using CWC sam:65327
2014-07-21 17:45:32.643 [ INFO]:subscription: "HTTP" subscribing on "none", weight: 100, adapter: "SAT>IP DVB-S Tuner #1 (192.168.200.10)", network: "Hotbird 13°", mux: "12034V", provider: "SkyItalia", service: "Cinema Classics", hostname: "192.168.200.200", username: "<N/A>", client: "VLC/2.1.5 LibVLC/2.1.5"
2014-07-21 17:45:33.182 [WARNING]:TS: 12034V/Cinema Classics: Transport error indicator
2014-07-21 17:45:33.236 [ DEBUG]:cwc: ECM state 0
2014-07-21 17:45:33.236 [ DEBUG]:cwc: Insert new ECM (PID 1807) for service "Cinema Classics"
2014-07-21 17:45:33.236 [ TRACE]:cwc: sending message sid 11109 len 210 enq 1
2014-07-21 17:45:33.236 [ TRACE]:cwc: 00 00 A1 04 92 B5 5C 6D 8D 39 94 D7 E5 37 DF FA ......\m.9...7..
2014-07-21 17:45:33.236 [ TRACE]:cwc: 93 99 0F B5 6D 60 F0 70 63 6B 4E ED 0E A9 8E AA ....m`.pckN.....
2014-07-21 17:45:33.236 [ TRACE]:cwc: 76 CD 61 6F B7 87 0E DD DE B6 39 7F BE 4A 45 59 v.ao......9..JEY
2014-07-21 17:45:33.236 [ TRACE]:cwc: B2 F6 60 5A 5D 94 80 CB D9 32 E0 8F D3 27 BC 22 ..`Z]....2...'."
2014-07-21 17:45:33.236 [ TRACE]:cwc: 79 45 0E 3C 3D 96 33 9B E2 34 06 DC 55 3F 7E B8 yE.<=.3..4..U?~.
2014-07-21 17:45:33.236 [ TRACE]:cwc: F5 6A E6 05 1E 94 05 48 DA 57 77 28 8E 5B D4 E4 .j.....H.Ww(.[..
2014-07-21 17:45:33.237 [ TRACE]:cwc: 88 79 1B 05 F9 07 DA 07 71 DE C6 54 68 A1 32 A4 .y......q..Th.2.
2014-07-21 17:45:33.237 [ TRACE]:cwc: F6 C0 9F D7 02 F3 0A BE B2 B9 BE 3E 55 31 19 19 ...........>U1..
2014-07-21 17:45:33.237 [ TRACE]:cwc: F5 7C 36 23 DD 10 6B 7C F1 65 39 DD CF 40 61 50 .|6#..k|.e9..@aP
2014-07-21 17:45:33.237 [ TRACE]:cwc: F5 79 91 1B E2 98 81 02 A6 6B 09 69 0F 10 57 4C .y.......k.i..WL
2014-07-21 17:45:33.237 [ TRACE]:cwc: 33 BD B6 51 86 86 29 DB E5 C0 FF 74 C9 FE F7 02 3..Q..)....t....
2014-07-21 17:45:33.237 [ TRACE]:cwc: C8 07 20 3B A0 B0 5D 55 EA 19 42 6A 0D 96 6F A8 .. ;..]U..Bj..o.
2014-07-21 17:45:33.237 [ TRACE]:cwc: 51 23 A2 81 60 A5 01 50 7D 4F E3 A9 E2 46 E1 45 Q#..`..P}O...F.E
2014-07-21 17:45:33.237 [ TRACE]:cwc: 7C 00 |.
2014-07-21 17:45:33.237 [ DEBUG]:cwc: Sending ECM (PID 1807) section=0/0, for service "Cinema Classics" (seqno: 3)
2014-07-21 17:45:33.237 [ TRACE]:descrambler: ECM message (len 183, pid 1807) for service "Cinema Classics"
2014-07-21 17:45:33.237 [ TRACE]:descrambler: initial stream key set to even for service "Cinema Classics"
2014-07-21 17:45:33.288 [ DEBUG]:cwc: ECM state 0
2014-07-21 17:45:33.288 [ DEBUG]:cwc: Insert new ECM (PID 1850) for service "Cinema Classics"
2014-07-21 17:45:33.288 [ TRACE]:cwc: sending message sid 11109 len 210 enq 1
2014-07-21 17:45:33.288 [ TRACE]:cwc: 00 00 19 75 21 82 DE BC D2 1D 52 6B 19 76 E7 AA ...u!.....Rk.v..
2014-07-21 17:45:33.288 [ TRACE]:cwc: E6 2F 0C 8E BD 95 F3 30 9B 53 82 B9 6D 7E 20 93 ./.....0.S..m~ .
2014-07-21 17:45:33.288 [ TRACE]:cwc: F5 56 67 67 DB AB C1 DD E9 B2 61 AE 69 7A 69 B2 .Vgg......a.izi.
2014-07-21 17:45:33.288 [ TRACE]:cwc: 69 6B 0C E3 09 E4 69 F7 19 EC 45 19 67 0E E3 5F ik....i...E.g.._
2014-07-21 17:45:33.288 [ TRACE]:cwc: FD 5C 6C 0E DA FB E2 04 01 C3 DD 42 1B 6A 37 80 .\l........B.j7.
2014-07-21 17:45:33.288 [ TRACE]:cwc: 56 3C 63 55 1B 1A F0 19 4F EF FD 1E 2D B6 1D C7 V<cU....O...-...
2014-07-21 17:45:33.288 [ TRACE]:cwc: 8E AC C6 2B F8 CF 49 0C AF A2 67 2B D0 A0 81 49 ...+..I...g+...I
2014-07-21 17:45:33.288 [ TRACE]:cwc: 3D A8 66 BB 6A 51 C2 8C 9F 49 3C 14 B6 0D AF E5 =.f.jQ...I<.....
2014-07-21 17:45:33.288 [ TRACE]:cwc: 81 01 BC DE CF 21 E6 09 C8 6D D5 84 4D 4B 10 04 .....!...m..MK..
2014-07-21 17:45:33.288 [ TRACE]:cwc: 40 BE 6E CB 02 C1 06 DB 97 EB 2B B2 FE B4 2D DE .n.......+...-.
2014-07-21 17:45:33.289 [ TRACE]:cwc: C5 FC C8 4C 17 F2 02 91 AD 37 77 17 F9 41 9D 91 ...L.....7w..A..
2014-07-21 17:45:33.289 [ TRACE]:cwc: C8 9C 70 94 DA 6C 50 68 E1 6E 84 11 4C 66 EC B8 ..p..lPh.n..Lf..
2014-07-21 17:45:33.289 [ TRACE]:cwc: FE ED ED 9F B7 56 97 B4 DE 60 F8 27 B1 1B 23 16 .....V...`.'..#.
2014-07-21 17:45:33.289 [ TRACE]:cwc: E8 E9 ..
2014-07-21 17:45:33.289 [ DEBUG]:cwc: Sending ECM (PID 1850) section=0/0, for service "Cinema Classics" (seqno: 4)
2014-07-21 17:45:33.289 [ TRACE]:descrambler: ECM message (len 183, pid 1850) for service "Cinema Classics"
2014-07-21 17:45:33.289 [ TRACE]:descrambler: CAT data (len 18)
2014-07-21 17:45:33.289 [ TRACE]:descrambler: 09 04 09 19 E1 2D 09 04 09 3B E1 2D 09 04 09 CD .....-...;.-....
2014-07-21 17:45:33.289 [ TRACE]:descrambler: E1 2D .-
2014-07-21 17:45:33.289 [ TRACE]:cwc: caid update event - mux 0x7f2a8806ded0 caid 0919 (2329) pid 012d (301) valid 1
2014-07-21 17:45:33.289 [ TRACE]:cwc: caid update event - mux 0x7f2a8806ded0 caid 093b (2363) pid 012d (301) valid 1
2014-07-21 17:45:33.289 [ TRACE]:cwc: caid update event - mux 0x7f2a8806ded0 caid 09cd (2509) pid 012d (301) valid 1
2014-07-21 17:45:33.289 [ TRACE]:descrambler: attach emm caid 09CD (2509) pid 012D (301)
2014-07-21 17:45:33.289 [ TRACE]:descrambler: mux 0x7f2a8806ded0 open pid 012D (301) (flags 0x0000)
2014-07-21 17:45:33.502 [ DEBUG]:cwc: Saving prefered PID 1807 for cwc-sam-65327
2014-07-21 17:45:33.502 [ DEBUG]:cwc: Received ECM reply (PID 1807) for service "Cinema Classics" even: 43.03.dd.23.03.92.6e.03 odd: 00.00.00.00.00.00.00.00 (seqno: 3 Req delay: 168 ms)
2014-07-21 17:45:33.502 [ DEBUG]:cwc: Obtained key for service "Cinema Classics" in 268 ms, from cwc-sam-65327
2014-07-21 17:45:33.502 [ DEBUG]:descrambler: Obtained keys from cwc-sam-65327 for service "Cinema Classics"
2014-07-21 17:45:33.502 [ TRACE]:descrambler: Obtained keys 4303DD2303926E03:0000000000000000 from cwc-sam-65327 for service "Cinema Classics"
2014-07-21 17:45:33.502 [WARNING]:cwc: Delete ECM (PID 1850) for service "Cinema Classics" from cwc-sam-65327
2014-07-21 17:45:33.952 [WARNING]:cwc: Got unexpected ECM reply (seqno: 4)
2014-07-21 17:45:35.660 [ DEBUG]:cwc: ECM state 2
2014-07-21 17:45:35.660 [ DEBUG]:cwc: Reset after unexpected or no reply for service "Cinema Classics"
2014-07-21 17:45:35.660 [ DEBUG]:cwc: Insert new ECM (PID 1850) for service "Cinema Classics"
2014-07-21 17:45:35.660 [ TRACE]:cwc: sending message sid 11109 len 210 enq 1
2014-07-21 17:45:35.660 [ TRACE]:cwc: 00 00 E1 EE CA 74 18 CF F6 FF E0 35 A7 2C 62 A6 .....t.....5.,b.
2014-07-21 17:45:35.660 [ TRACE]:cwc: 69 F6 C4 B6 CA 00 F0 C7 63 F7 C6 CA C3 B2 CC F9 i.......c.......
2014-07-21 17:45:35.660 [ TRACE]:cwc: E6 CB DB 8C 2B 79 A5 CC 3C F3 E1 C7 8F B5 3B 41 ....+y..<.....;A
2014-07-21 17:45:35.660 [ TRACE]:cwc: DC 11 6A 0C 39 9E 49 B5 AF C5 B3 E0 15 FA 84 11 ..j.9.I.........
2014-07-21 17:45:35.660 [ TRACE]:cwc: 13 7C 4A 27 7B 28 09 6F 37 1C AF 94 4B 30 C6 6A .|J'{(.o7...K0.j
2014-07-21 17:45:35.660 [ TRACE]:cwc: 95 85 78 6D B1 80 79 9F B1 1F 52 9A 32 9B F3 0F ..xm..y...R.2...
2014-07-21 17:45:35.660 [ TRACE]:cwc: EB E5 32 7F AC C7 64 F2 87 B9 B6 44 E8 91 47 88 ..2...d....D..G.
2014-07-21 17:45:35.660 [ TRACE]:cwc: 68 E7 37 AF 9D 14 F0 53 57 DE 24 39 B6 02 A3 F4 h.7....SW.$9....
2014-07-21 17:45:35.660 [ TRACE]:cwc: 94 12 13 77 7A DC CF D6 E3 A7 F5 A8 01 6D 0D C2 ...wz........m..
2014-07-21 17:45:35.660 [ TRACE]:cwc: 78 DB CA 13 CB 87 DA 2E A0 10 D3 0D 6D 19 3A 19 x...........m.:.
2014-07-21 17:45:35.660 [ TRACE]:cwc: E6 C7 4E 48 C2 01 5E 6A 8A A4 D1 0B 2F 17 8D 46 ..NH..^j..../..F
2014-07-21 17:45:35.660 [ TRACE]:cwc: F8 11 34 50 31 9A D4 C3 F0 74 BD 29 57 83 78 76 ..4P1....t.)W.xv
2014-07-21 17:45:35.660 [ TRACE]:cwc: 4C B1 28 EE FC C0 66 FF 0D DC 76 0F 0E 5A 25 52 L.(...f...v..Z%R
2014-07-21 17:45:35.660 [ TRACE]:cwc: 2E F9 ..
2014-07-21 17:45:35.660 [ DEBUG]:cwc: Sending ECM (PID 1850) section=0/0, for service "Cinema Classics" (seqno: 5)
2014-07-21 17:45:35.660 [ TRACE]:descrambler: ECM message (len 183, pid 1850) for service "Cinema Classics"
2014-07-21 17:45:36.914 [ DEBUG]:cwc: Saving prefered PID 1850 for cwc-sam-65327
2014-07-21 17:45:36.914 [ DEBUG]:cwc: Received ECM reply (PID 1850) for service "Cinema Classics" even: 00.00.00.00.00.00.00.00 odd: 9d.78.49.5e.39.9b.bd.91 (seqno: 5 Req delay: 152 ms)
2014-07-21 17:45:36.914 [ TRACE]:descrambler: Obtained keys 0000000000000000:9D78495E399BBD91 from cwc-sam-65327 for service "Cinema Classics"
2014-07-21 17:45:36.914 [WARNING]:cwc: Delete ECM (PID 1807) for service "Cinema Classics" from cwc-sam-65327
2014-07-21 17:45:42.655 [ DEBUG]:cwc: ECM state 1
2014-07-21 17:45:42.655 [ TRACE]:descrambler: ECM message (len 183, pid 1807) for service "Cinema Classics"
2014-07-21 17:45:43.215 [ TRACE]:descrambler: stream key changed to odd for service "Cinema Classics"
2014-07-21 17:45:45.640 [ TRACE]:cwc: sending message sid 11109 len 210 enq 1
2014-07-21 17:45:45.640 [ TRACE]:cwc: 00 00 27 22 C4 BA 32 C5 BE 23 B1 53 78 F6 CD 4F ..'"..2..#.Sx..O
2014-07-21 17:45:45.640 [ TRACE]:cwc: A3 99 60 99 65 03 F6 00 03 3B B5 FE 36 19 33 53 ..`.e....;..6.3S
2014-07-21 17:45:45.640 [ TRACE]:cwc: F4 82 99 7B 29 6D 93 8F 83 00 BC A9 35 09 C6 DD ...{)m......5...
2014-07-21 17:45:45.640 [ TRACE]:cwc: DD C5 10 00 95 7B C1 EA A4 FD 3E 2D 5E B1 4A 0F .....{....>-^.J.
2014-07-21 17:45:45.640 [ TRACE]:cwc: FE 55 F4 DA D4 98 CE 4B B6 2E 86 6F 63 AA 74 BB .U.....K...oc.t.
2014-07-21 17:45:45.640 [ TRACE]:cwc: 16 41 CD A4 3E EA E8 98 BF 4A 33 56 CF 9E 6D A1 .A..>....J3V..m.
2014-07-21 17:45:45.640 [ TRACE]:cwc: 1D E6 BE 71 E7 E9 85 E6 A6 ED 59 D2 D9 D1 E4 D7 ...q......Y.....
2014-07-21 17:45:45.640 [ TRACE]:cwc: AE 97 C0 D8 FE 0A 38 F3 1B B6 EF A7 7B 20 25 95 ......8.....{ %.
2014-07-21 17:45:45.640 [ TRACE]:cwc: CE C5 E7 F9 BF B7 7C CC 5A 7B 1B E3 6F EE 09 BD ......|.Z{..o...
2014-07-21 17:45:45.640 [ TRACE]:cwc: 4D 44 9F CC DC AF 53 F7 27 07 D7 66 60 AD 50 1C MD....S.'..f`.P.
2014-07-21 17:45:45.640 [ TRACE]:cwc: 46 2F F6 E6 80 0A 51 45 0F C4 10 AB A8 94 DC C5 F/....QE........
2014-07-21 17:45:45.640 [ TRACE]:cwc: 57 5D 51 24 90 11 B2 AA F6 A2 4D 24 4F E7 4E B1 W]Q$......M$O.N.
2014-07-21 17:45:45.640 [ TRACE]:cwc: 2B 43 0A 53 0F 29 A4 FC 91 68 9F D7 EF C9 C4 A7 +C.S.)...h......
2014-07-21 17:45:45.640 [ TRACE]:cwc: 9A 07 ..
2014-07-21 17:45:45.641 [ DEBUG]:cwc: Sending ECM (PID 1850) section=0/0, for service "Cinema Classics" (seqno: 6)
2014-07-21 17:45:45.641 [ TRACE]:descrambler: ECM message (len 183, pid 1850) for service "Cinema Classics"
2014-07-21 17:45:46.274 [ DEBUG]:cwc: Received ECM reply (PID 1850) for service "Cinema Classics" even: 4f.09.8c.e4.c9.ae.82.f9 odd: 00.00.00.00.00.00.00.00 (seqno: 6 Req delay: 136 ms)
2014-07-21 17:45:46.274 [ TRACE]:descrambler: Obtained keys 4F098CE4C9AE82F9:0000000000000000 from cwc-sam-65327 for service "Cinema Classics"
2014-07-21 17:45:52.639 [ DEBUG]:cwc: ECM state 1
2014-07-21 17:45:52.639 [ TRACE]:descrambler: ECM message (len 183, pid 1807) for service "Cinema Classics"@

I have not seen this issue in several months. using both FTA (SD and HD) and Oscam (pc-nodmx).