search

catalinii / minisatip

minisatip is an SATIP server for linux using local DVB-S2, DVB-C, DVB-T or ATSC cards
https://minisatip.org
325 stars 78 forks source link

CA PID added and removed continuously during playback #1017

Closed Jalle19 closed 1 year ago

Jalle19 commented 1 year ago 
Oct 30 06:44:36 vladimir minisatip[5387]: [30/10 06:44:36.949 AD1]: Start streaming for stream sid 1, len 69892 to handle 25 => 10.110.4.13:55670
Oct 30 06:44:36 vladimir minisatip[5387]: [30/10 06:44:36.950 AD0]: Start streaming for stream sid 0, len 80452 to handle 5 => 10.110.4.13:55660
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.009 AD1]: CAT DDCI 6 len 5
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.009 AD1]: CAT pos 1 caid 0B00, pid 48
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.009 AD1]: CAT pid 48 already in use, skipping CAT
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.010 AD0]: CAT DDCI 6 len 5
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.010 AD0]: CAT pos 1 caid 0B00, pid 48
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.010 AD0]: CAT pid 48 already in use, skipping CAT
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.039 main]: Read RTSP (sock 5, handle 5) [10.110.4.13:55660] sid 0, len: 94
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: detect_dvb_parameters (S)-> addpids=2758
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: detect_dvb_parameters (E) -> src=-1, fe=-1, freq=-1, fec=-1, sr=-1, pol=-1, ro=-1, msys=-1, mtype=-1, plts=-1, bw=-1, inv=-1, pids=NULL - apids=2758 - dpids=NULL x_pmt=NULL
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: Setup stream sid 0 parameters, sock_id 5, handle 5
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: copy_dvb_param start -> src=1, fe=0, freq=250000, fec=10, sr=6875000, pol=0, ro=3, msys=1, mtype=5, plts=2, bw=8000000, inv=0, pids=NULL, apids=NULL, dpids=NULL x_pmt=NULL
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: copy_dvb_parameters -> src=1, fe=0, freq=250000, fec=10 sr=6875000, pol=0, ro=3, msys=1, mtype=5, plts=2, bw=8000000, inv=0, pids=NULL, apids=2758, dpids=NULL x_pmt=NULL
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: Play for stream sid 0, type 3, rsock 5, adapter 0, sock_id 5, rsock_id 5, handle 5
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: setting DVB parameters for adapter 0 - master_sid 0 sid 0 old f:250000
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: copy_dvb_param start -> src=1, fe=0, freq=250000, fec=10, sr=6875000, pol=0, ro=3, msys=1, mtype=5, plts=2, bw=8000000, inv=0, pids=NULL, apids=NULL, dpids=2758 x_pmt=NULL
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: copy_dvb_parameters -> src=1, fe=0, freq=250000, fec=10 sr=6875000, pol=0, ro=3, msys=1, mtype=5, plts=2, bw=8000000, inv=0, pids=NULL, apids=2758, dpids=NULL x_pmt=NULL
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: adding pids to adapter 0, sid 0, pids=2758
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: found already existing pid 2758 flags 1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: Dumping pids table for adapter 0, number of unknown pids: 0
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 450, fd 9, packets 333577, d/c errs 4903/0, flags 1, pmt 3, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 18, fd 15, packets 103957, d/c errs 0/0, flags 1, pmt -1, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 550, fd 10, packets 6689, d/c errs 98/0, flags 1, pmt 3, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 552, fd 11, packets 6689, d/c errs 98/0, flags 1, pmt 3, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 48, fd 24, packets 2800, d/c errs 0/0, flags 1, pmt -1, filter -1, sock -1, sids: 101 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 16, fd 14, packets 797, d/c errs 0/0, flags 1, pmt -1, filter -1, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 0, fd 8, packets 501, d/c errs 0/0, flags 1, pmt -1, filter 4, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 1464, fd 12, packets 501, d/c errs 0/0, flags 1, pmt -3, filter 9, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 1, fd 13, packets 501, d/c errs 0/0, flags 1, pmt -1, filter 11, sock -1, sids: 0 101 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 2758, fd 23, packets 499, d/c errs 0/0, flags 1, pmt -1, filter -1, sock -1, sids: 101 0 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: pid 17, fd 16, packets 101, d/c errs 0/0, flags 1, pmt -1, filter 5, sock -1, sids: 0 -1 -1 -1 -1 -1 -1 -1
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: not tuning for sid 0 (do_tune=0, master_sid=0)
Oct 30 06:44:37 vladimir minisatip[5387]: [30/10 06:44:37.040 main]: Reply (handle 5) [10.110.4.13:55660] content_len:0, sock 5

This sequence repeats multiple times per second as long as the channel is playing. It doesn't always happen, sometimes there's no output during playback other than the bandwidth stats from the signal thread.

What could be caused this? Is it just me or does this happen to others?

Jalle19 commented 1 year ago

Wondering if it's tvheadend that's doing this, I have to turn up the debugging on it to see what SAT>IP requests it makes.

Jalle19 commented 1 year ago

Yeah, it seems like it's tvheadend that's doing this:

Oct 30 12:35:40 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:40 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756'
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:41 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756'
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756'
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:42 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756'
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:43 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:44 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:45 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:45 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:45 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756'
Oct 30 12:35:45 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - delpids=2756
Oct 30 12:35:46 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17'
Oct 30 12:35:46 tvheadend tvheadend[6059]: satip: 0425: PLAY params[0] - addpids=2756
Oct 30 12:35:46 tvheadend tvheadend[6059]: satip: Status string: 'ver=1.2;tuner=2,240,1,9,266.00,8,dvbc,256qam,6875,0,,,0;pids=1329,18,4215,4218,6329,16,1474,0,1,17,2756

Will close this and debug further.

catalinii commented 1 year ago

this happens if the first channel is deleted then a new is one added to be decrypted by the DDCI.

If this happens outside of this, it's probably a bug.

Jalle19 commented 1 year ago

This happens when playing a channel, not while switching. I think this is just some corner case with tvheadend with oscam + minisatip with CAM and the same CAID 🤷 Will move all decryption to minisatip instead.