Bug #1493: TVHeadend runs into a deadlock after receiving NOK from CS - Tvheadend

Bug #1493

TVHeadend runs into a deadlock after receiving NOK from CS

Added by B. J. almost 12 years ago. Updated almost 12 years ago.

Status:

Fixed

Priority:

Normal

Assignee:

Adam Sutton

Category:

Descrambling

Target version:

Start date:

2013-01-03

Due date:

% Done:

100%

Estimated time:

Found in version:

3.3.199~g759b5b1

Affected Versions:

3.3

Description

If I switch to a decrypted channel where access is denied, TVHeadend runs into a deadlock after unsubscribing from this channel (switching to an other channel).

Jan 03 09:34:29 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 37) PID 6157
Jan 03 09:34:30 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 37 Req delay: 1123 ms)
Jan 03 09:34:30 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 37 Req delay: 1123 ms)
Jan 03 09:34:30 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 03 09:34:30 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" unsubscribing from "Sky Sport HD Extra"

The "unsubscribing from ..." is the last message from debug-window, I have to restart TVHeadend.

History

Updated by Adam Sutton almost 12 years ago

Assignee set to Mariusz Białończyk
Affected Versions 3.3 added

Mariusz maybe you could take a look at this ?

Ta
Adam

Updated by Mariusz Białończyk almost 12 years ago

Hello. I just tested it on the recent tvh version and it works for me. I did similar test as you described: first i've got NOK then i switched to available channel and it all works. I did tests also on xbmc.

Updated by B. J. almost 12 years ago

Hmm, I can reproduce the deadlock. Here's a complete log:

Loglevel debug: enabled
Jan 04 11:44:10 htsp: Got connection from 127.0.0.1
Jan 04 11:44:10 htsp: 127.0.0.1: Welcomed client software: XBMC Media Center (HTSPv7)
Jan 04 11:44:10 htsp: 127.0.0.1 [ XBMC Media Center ]: Identified as user xbmc
Jan 04 11:44:10 htsp: 127.0.0.1 [ xbmc | XBMC Media Center ]: Privileges raised
Jan 04 11:44:10 htsp: using timeshift buffer (60 mins)
Jan 04 11:44:11 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C626000000" for service "Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1" 
Jan 04 11:44:11 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C626000000" for service "Philips TDA10023 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1" 
Jan 04 11:44:11 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C626000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1" 
Jan 04 11:44:11 cwc: Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1 using CWC 192.168.178.1:24109
Jan 04 11:44:11 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" subscribing on "Sky Sport HD 1", weight: 150, adapter: "Philips TDA10021 DVB-C", network: "BetaDigital", mux: "BetaDigital: 626,000 kHz", provider: "SKY", service: "Sky Sport HD 1", quality: 100
Jan 04 11:44:11 Service: Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1: Status changed to [Hardware input] 
Jan 04 11:44:11 Service: Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1: Status changed to [Hardware input] [Input on service] 
Jan 04 11:44:11 Service: Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 04 11:44:11 cwc: Insert new ECM channel 6330
Jan 04 11:44:11 cwc: Sending ECM (channel 6330) section=0/0, for service Sky Sport HD 1 (seqno: 45) PID 6330
Jan 04 11:44:11 cwc: Insert new ECM channel 7354
Jan 04 11:44:11 cwc: Insert new ECM channel 6586
Jan 04 11:44:11 cwc: Insert new ECM channel 6842
Jan 04 11:44:11 cwc: Insert new ECM channel 8122
Jan 04 11:44:11 cwc: Insert new ECM channel 7098
Jan 04 11:44:11 cwc: Insert new ECM channel 7610
Jan 04 11:44:12 cwc: es->es_nok 0      t->tht_prefcapid 0
Jan 04 11:44:12 cwc: Received ECM reply (channel 6330) for service "Sky Sport HD 1" even: 36.9d.1c.ef.65.b5.a1.bb odd: e4.07.26.11.3c.fd.50.89 (seqno: 45 Req delay: 763 ms)
Jan 04 11:44:12 cwc: Obtained key for service "Sky Sport HD 1" in 763 ms, from 192.168.178.1:24109
Jan 04 11:44:12 cwc: Delete ECMpid 7610
Jan 04 11:44:12 cwc: Delete ECMpid 7098
Jan 04 11:44:12 cwc: Delete ECMpid 8122
Jan 04 11:44:12 cwc: Delete ECMpid 6842
Jan 04 11:44:12 cwc: Delete ECMpid 6586
Jan 04 11:44:12 cwc: Delete ECMpid 7354
Jan 04 11:44:12 Service: Philips TDA10021 DVB-C/BetaDigital: 626,000 kHz/Sky Sport HD 1: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets] 
Jan 04 11:44:16 cwc: Sending ECM (channel 6330) section=0/0, for service Sky Sport HD 1 (seqno: 46) PID 6330
Jan 04 11:44:16 cwc: es->es_nok 0      t->tht_prefcapid 6330
Jan 04 11:44:16 cwc: Received ECM reply (channel 6330) for service "Sky Sport HD 1" even: 36.9d.1c.ef.65.b5.a1.bb odd: 16.9e.b5.69.92.1d.43.f2 (seqno: 46 Req delay: 671 ms)
Jan 04 11:44:23 cwc: Sending ECM (channel 6330) section=0/0, for service Sky Sport HD 1 (seqno: 47) PID 6330
Jan 04 11:44:23 cwc: es->es_nok 0      t->tht_prefcapid 6330
Jan 04 11:44:23 cwc: Received ECM reply (channel 6330) for service "Sky Sport HD 1" even: d4.2e.17.19.36.bb.da.cb odd: 16.9e.b5.69.92.1d.43.f2 (seqno: 47 Req delay: 663 ms)
Jan 04 11:44:30 cwc: Sending ECM (channel 6330) section=0/0, for service Sky Sport HD 1 (seqno: 48) PID 6330
Jan 04 11:44:30 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" unsubscribing from "Sky Sport HD 1" 
Jan 04 11:44:30 htsp: using timeshift buffer (60 mins)
Jan 04 11:44:30 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:30 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:30 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:30 eit: processing cancelled
Jan 04 11:44:30 dvb: "/dev/dvb/adapter1" tuning to "BetaDigital: 658,000 kHz" (Transport start)
Jan 04 11:44:30 eit: install table handlers
Jan 04 11:44:30 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 04 11:44:30 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" subscribing on "Sky Sport HD Extra", weight: 150, adapter: "Philips TDA10021 DVB-C", network: "BetaDigital", mux: "BetaDigital: 658,000 kHz", provider: "SKY", service: "Sky Sport HD Extra", quality: 100
Jan 04 11:44:30 eit: begin processing
Jan 04 11:44:30 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 04 11:44:30 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 04 11:44:30 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 04 11:44:30 TS: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Transport error indicator
Jan 04 11:44:30 cwc: Insert new ECM channel 6157
Jan 04 11:44:30 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 49) PID 6157
Jan 04 11:44:30 cwc: Insert new ECM channel 7181
Jan 04 11:44:30 cwc: Insert new ECM channel 6413
Jan 04 11:44:30 cwc: Insert new ECM channel 7949
Jan 04 11:44:30 cwc: Insert new ECM channel 6925
Jan 04 11:44:30 cwc: Insert new ECM channel 7437
Jan 04 11:44:30 cwc: Insert new ECM channel 6669
Jan 04 11:44:30 cwc: Got unexpected ECM reply (seqno: 48)
Jan 04 11:44:30 cwc: After got unexpected (ct->cs_okchannel: -3)
Jan 04 11:44:31 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 49 Req delay: 1303 ms)
Jan 04 11:44:33 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 50) PID 6157
Jan 04 11:44:34 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 50 Req delay: 1119 ms)
Jan 04 11:44:34 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 50 Req delay: 1119 ms)
Jan 04 11:44:34 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 04 11:44:36 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:36 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:38 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:38 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:38 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:38 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 04 11:44:38 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 04 11:44:38 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 04 11:44:39 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 04 11:44:39 cwc: Insert new ECM channel 6157
Jan 04 11:44:39 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 51) PID 6157
Jan 04 11:44:39 cwc: Insert new ECM channel 7181
Jan 04 11:44:39 cwc: Insert new ECM channel 6413
Jan 04 11:44:39 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 51 Req delay: 39 ms)
Jan 04 11:44:39 cwc: Insert new ECM channel 7949
Jan 04 11:44:39 cwc: Insert new ECM channel 6925
Jan 04 11:44:39 cwc: Insert new ECM channel 7437
Jan 04 11:44:39 cwc: Insert new ECM channel 6669
Jan 04 11:44:40 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 52) PID 6157
Jan 04 11:44:40 eit: processing complete
Jan 04 11:44:41 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 52 Req delay: 1123 ms)
Jan 04 11:44:41 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 52 Req delay: 1123 ms)
Jan 04 11:44:41 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 04 11:44:43 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:43 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:45 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:45 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:45 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 04 11:44:45 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 04 11:44:45 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 04 11:44:45 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 04 11:44:45 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 04 11:44:45 cwc: Insert new ECM channel 6157
Jan 04 11:44:45 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 53) PID 6157
Jan 04 11:44:45 cwc: Insert new ECM channel 7181
Jan 04 11:44:45 cwc: Insert new ECM channel 6413
Jan 04 11:44:45 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 53 Req delay: 31 ms)
Jan 04 11:44:45 cwc: Insert new ECM channel 7949
Jan 04 11:44:45 cwc: Insert new ECM channel 6925
Jan 04 11:44:45 cwc: Insert new ECM channel 7437
Jan 04 11:44:45 cwc: Insert new ECM channel 6669
Jan 04 11:44:47 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 54) PID 6157
Jan 04 11:44:48 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 54 Req delay: 1119 ms)
Jan 04 11:44:48 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 54 Req delay: 1119 ms)
Jan 04 11:44:48 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 04 11:44:49 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" unsubscribing from "Sky Sport HD Extra"

As you see:

- I have two adapters (TDA10021/10023)
- I use the timeshift branch

#  ps -ef | grep tvh
xbmc      1118     1  4 11:22 ?        00:01:32 tvheadend -f -u xbmc -g video
xbmc      2624  2355  0 11:56 pts/0    00:00:00 grep --color=auto tvh

Updated by B. J. almost 12 years ago

I have made two compiles from git today:

- master has'nt the issue, all is working ok
- timeshift branch runs into the deadlock

So it's an isssue with the timeshift branch indeed.

Updated by Mariusz Białończyk almost 12 years ago

Assignee changed from Mariusz Białończyk to Adam Sutton

Maybe you could bisect the problem and let Adam know which commit broke it...

Updated by Adam Sutton almost 12 years ago

Status changed from New to Need feedback

Can you please try the latest master (timeshift has now been merged). And can you test it with timeshift enabled (runtime) and disabled.

Adam

Updated by B. J. almost 12 years ago

Hello Adam,

I'll check this today in the evening of course.

Updated by B. J. almost 12 years ago

Autobuild gives me an error:

        dpkg-deb --build debian/tvheadend ..
dpkg-deb: error: parsing file 'debian/tvheadend/DEBIAN/control' near line 16 package 'tvheadend':
 empty value for version
dh_builddeb: dpkg-deb --build debian/tvheadend .. returned exit code 2
        dpkg-deb --build debian/tvheadend-dbg ..
dpkg-deb: error: parsing file 'debian/tvheadend-dbg/DEBIAN/control' near line 12 package 'tvheadend-dbg':
 empty value for version
dh_builddeb: dpkg-deb --build debian/tvheadend-dbg .. returned exit code 2
make: *** [binary] Error 1
dpkg-buildpackage: error: debian/rules binary gave error exit status 2

Updated by B. J. almost 12 years ago

At least I could compile but: deadlock ;(

Jan 10 21:31:23 cwc: Received ECM reply (channel 6145) for service "Sky Sport HD 2" even: 1e.20.6e.ac.bc.e2.60.fe odd: 02.9f.89.2a.23.75.cf.67 (seqno: 19 Req delay: 748 ms)
Jan 10 21:31:26 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" unsubscribing from "Sky Sport HD 2" 
Jan 10 21:31:26 htsp: using timeshift buffer (unlimited)
Jan 10 21:31:26 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:26 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:26 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:26 eit: processing cancelled
Jan 10 21:31:26 dvb: "/dev/dvb/adapter1" tuning to "BetaDigital: 658,000 kHz" (Transport start)
Jan 10 21:31:26 eit: install table handlers
Jan 10 21:31:26 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 10 21:31:26 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" subscribing on "Sky Sport HD Extra", weight: 150, adapter: "Philips TDA10021 DVB-C", network: "BetaDigital", mux: "BetaDigital: 658,000 kHz", provider: "SKY", service: "Sky Sport HD Extra", quality: 100
Jan 10 21:31:26 eit: begin processing
Jan 10 21:31:26 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 10 21:31:26 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 10 21:31:26 TS: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Transport error indicator
Jan 10 21:31:26 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 10 21:31:26 cwc: Insert new ECM channel 6157
Jan 10 21:31:26 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 20) PID 6157
Jan 10 21:31:26 cwc: Insert new ECM channel 7181
Jan 10 21:31:26 cwc: Insert new ECM channel 6413
Jan 10 21:31:26 cwc: Insert new ECM channel 7949
Jan 10 21:31:26 cwc: Insert new ECM channel 6925
Jan 10 21:31:26 cwc: Insert new ECM channel 7437
Jan 10 21:31:26 cwc: Insert new ECM channel 6669
Jan 10 21:31:27 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 20 Req delay: 1208 ms)
Jan 10 21:31:28 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 21) PID 6157
Jan 10 21:31:30 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 21 Req delay: 1120 ms)
Jan 10 21:31:30 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 21 Req delay: 1120 ms)
Jan 10 21:31:30 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 10 21:31:30 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:30 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:31 eit: processing cancelled
Jan 10 21:31:31 dvb: "/dev/dvb/adapter0" tuning to "REMOTE CABLE NETWORK          : 386,000 kHz" (EPG scan)
Jan 10 21:31:31 eit: install table handlers
Jan 10 21:31:31 eit: begin processing
Jan 10 21:31:32 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:32 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:32 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:32 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 10 21:31:32 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 10 21:31:32 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 10 21:31:32 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 10 21:31:32 cwc: Insert new ECM channel 6157
Jan 10 21:31:32 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 22) PID 6157
Jan 10 21:31:32 cwc: Insert new ECM channel 7181
Jan 10 21:31:32 cwc: Insert new ECM channel 6413
Jan 10 21:31:32 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 22 Req delay: 32 ms)
Jan 10 21:31:32 cwc: Insert new ECM channel 7949
Jan 10 21:31:32 cwc: Insert new ECM channel 6925
Jan 10 21:31:32 cwc: Insert new ECM channel 7437
Jan 10 21:31:32 cwc: Insert new ECM channel 6669
Jan 10 21:31:35 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 23) PID 6157
Jan 10 21:31:37 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 23 Req delay: 1180 ms)
Jan 10 21:31:37 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 23 Req delay: 1180 ms)
Jan 10 21:31:37 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 10 21:31:39 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:39 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:41 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:41 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:41 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:41 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 10 21:31:41 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 10 21:31:41 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 10 21:31:41 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 10 21:31:41 cwc: Insert new ECM channel 7949
Jan 10 21:31:41 cwc: Insert new ECM channel 6925
Jan 10 21:31:41 cwc: Insert new ECM channel 7437
Jan 10 21:31:41 cwc: Insert new ECM channel 6669
Jan 10 21:31:41 cwc: Insert new ECM channel 6157
Jan 10 21:31:41 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 24) PID 6157
Jan 10 21:31:41 cwc: Insert new ECM channel 7181
Jan 10 21:31:41 cwc: Insert new ECM channel 6413
Jan 10 21:31:41 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 24 Req delay: 36 ms)
Jan 10 21:31:42 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 25) PID 6157
Jan 10 21:31:44 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 25 Req delay: 1180 ms)
Jan 10 21:31:44 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 25 Req delay: 1180 ms)
Jan 10 21:31:44 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 10 21:31:45 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:45 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:47 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:47 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:47 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:47 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 10 21:31:47 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 10 21:31:47 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 10 21:31:47 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 10 21:31:47 cwc: Insert new ECM channel 6157
Jan 10 21:31:47 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 26) PID 6157
Jan 10 21:31:47 cwc: Insert new ECM channel 7181
Jan 10 21:31:47 cwc: Insert new ECM channel 6413
Jan 10 21:31:47 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 26 Req delay: 32 ms)
Jan 10 21:31:47 cwc: Insert new ECM channel 7949
Jan 10 21:31:47 cwc: Insert new ECM channel 6925
Jan 10 21:31:47 cwc: Insert new ECM channel 7437
Jan 10 21:31:47 cwc: Insert new ECM channel 6669
Jan 10 21:31:49 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 27) PID 6157
Jan 10 21:31:51 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 27 Req delay: 1184 ms)
Jan 10 21:31:51 cwc: Can not descramble service "Sky Sport HD Extra", access denied (seqno: 27 Req delay: 1184 ms)
Jan 10 21:31:51 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No access] 
Jan 10 21:31:51 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:51 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:53 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:53 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Adding adapter "_dev_dvb_adapter0_Philips_TDA10023_DVB_C658000000" for service "Philips TDA10023 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:53 Service: Subscription "127.0.0.1 [ xbmc | XBMC Media Center ]": Probing adapter "_dev_dvb_adapter1_Philips_TDA10021_DVB_C658000000" without stealing for service "Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra" 
Jan 10 21:31:53 cwc: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra using CWC 192.168.178.1:24109
Jan 10 21:31:53 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] 
Jan 10 21:31:53 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] 
Jan 10 21:31:53 Service: Philips TDA10021 DVB-C/BetaDigital: 658,000 kHz/Sky Sport HD Extra: Status changed to [Hardware input] [Input on service] [Demuxed packets] 
Jan 10 21:31:53 cwc: Insert new ECM channel 6157
Jan 10 21:31:53 cwc: Sending ECM (channel 6157) section=0/0, for service Sky Sport HD Extra (seqno: 28) PID 6157
Jan 10 21:31:53 cwc: Insert new ECM channel 7181
Jan 10 21:31:53 cwc: Insert new ECM channel 6413
Jan 10 21:31:53 cwc: Received NOK for service "Sky Sport HD Extra" (channel 6157) (seqno: 28 Req delay: 32 ms)
Jan 10 21:31:53 cwc: Insert new ECM channel 7949
Jan 10 21:31:53 cwc: Insert new ECM channel 6925
Jan 10 21:31:53 cwc: Insert new ECM channel 7437
Jan 10 21:31:53 cwc: Insert new ECM channel 6669
Jan 10 21:31:54 subscription: "127.0.0.1 [ xbmc | XBMC Media Center ]" unsubscribing from "Sky Sport HD Extra"

This is the last message and then I have to restart tvheadend. XBMC reports "disconnected from hts tvheadend". BTW same behaviour occurs if I disable (!) timeshift in the WebUI.

#10

Updated by Dimitris Kazakos almost 12 years ago

Same thing here, it's definitely the timeshift code.
I had this problem with previous timeshift builds (this is the reason I had it disabled until it was solved).
Got it again as soon as I compiled the master branch today with timeshift code merged.

#11

Updated by Dimitris Kazakos almost 12 years ago

Update: it still happens if timeshift is disabled from the ui timeshift tab, so it must be something related to the codes changes due to timeshift (not the timeshift operation itself).

#12

Updated by Dimitris Kazakos almost 12 years ago

Another update: just compiled with --disable-timeshift and the problem is gone.

#13

Updated by Adam Sutton almost 12 years ago

Can you just confirm its always when unsubscribing via htsp (i.e. from xbmc)? What about streaming via http?

Also does it only happen if the sub, descrambling fails? Is it ok if channel streams ok?

I think i can at least explain why disabling timeshift has no effect.

Adam

#14

Updated by B. J. almost 12 years ago

This happens always when unsubscribing from a channel via xbmc that can't decrypt. In this case tvheadend is still running but is no more responsible and is disconnected from xbmc after a few seconds. It's not happen when descrambling is ok so switching decrypted channels (where descrambling is successfull) has the normal behaviour.

#15

Updated by Adam Sutton almost 12 years ago

Status changed from Need feedback to Fixed
% Done changed from 0 to 100

Applied in changeset commit:979c9d5c7e0551a69a41a2bc2691e87746b49eba.

#16

Updated by B. J. almost 12 years ago

Can confirm this. It's fixed! Thank you Adam!

#17

Updated by Dimitris Kazakos almost 12 years ago

I am sorry to say that this is not completely fixed; though the fix from Adam does make things right when service cannot be descrambled, TVHeadend still hangs/crashes (not sure) when trying to play a channel and the adapter is already in use (if timeshift is enabled).
Should I create a new issue or is this enough?

#18

Updated by Adam Sutton almost 12 years ago

Sounds like a different, though probably related, issue. Stick in a new report.

Ta
Adam

Also available in: Atom PDF

Project

General

Profile

Tvheadend

Issues

Custom queries

Bug #1493

TVHeadend runs into a deadlock after receiving NOK from CS

History

Updated by Adam Sutton almost 12 years ago

Updated by Mariusz Białończyk almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by Mariusz Białończyk almost 12 years ago

Updated by Adam Sutton almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by Dimitris Kazakos almost 12 years ago

Updated by Dimitris Kazakos almost 12 years ago

Updated by Dimitris Kazakos almost 12 years ago

Updated by Adam Sutton almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by Adam Sutton almost 12 years ago

Updated by B. J. almost 12 years ago

Updated by Dimitris Kazakos almost 12 years ago

Updated by Adam Sutton almost 12 years ago