VDR continuously initializing CAM

Message ID 47FFCF66.6080500@hot.ee
State New
Headers

Commit Message

Arthur Konovalov April 11, 2008, 8:51 p.m. UTC
  Klaus Schmidinger wrote:
> Since cCamSlot::Reset() is the only place where resetTime is set to
> a non-zero value, and you had lines like "resetTime1: 1207548401" in
> your syslog_1 file, apparently the tc[i]->Process() call in
> cCamSlot::Process() must have failed.
Yes, reset came from this procedure.
I added some printouts (look at attached diff).

How to see reason why this Reset() is called?

Arthur

Apr 11 23:40:31 akovdr2 vdr: [6914] cTimeMs: using monotonic clock (resolution is 4000250 ns)
Apr 11 23:40:31 akovdr2 vdr: [6914] VDR version 1.6.0 started
Apr 11 23:40:31 akovdr2 vdr: [6914] codeset is 'UTF-8' - known
Apr 11 23:40:31 akovdr2 vdr: [6914] found 23 locales in /usr/local/src/vdr-1.6.0/locale
Apr 11 23:40:31 akovdr2 vdr: [6914] loading plugin: /usr/local/vdr/PLUGINS/lib/libvdr-xine.so.1.6.0
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/setup.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/sources.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/diseqc.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/channels.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/timers.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/svdrphosts.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/remote.conf
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/keymacros.conf
Apr 11 23:40:31 akovdr2 vdr: [6915] video directory scanner thread started (pid=6914, tid=6915)
Apr 11 23:40:31 akovdr2 vdr: [6915] video directory scanner thread ended (pid=6914, tid=6915)
Apr 11 23:40:31 akovdr2 vdr: [6916] video directory scanner thread started (pid=6914, tid=6916)
Apr 11 23:40:31 akovdr2 vdr: [6916] video directory scanner thread ended (pid=6914, tid=6916)
Apr 11 23:40:31 akovdr2 vdr: [6914] reading EPG data from /usr/local/etc/vdr/epg.data
Apr 11 23:40:31 akovdr2 vdr: [6914] probing /dev/dvb/adapter0/frontend0
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: Reset called
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: Slot 1: reset...
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ok
Apr 11 23:40:31 akovdr2 vdr: [6918] CI adapter on device 0 thread started (pid=6914, tid=6918)
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 1207946431
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM 1: module present
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6919] tuner on device 1 thread started (pid=6914, tid=6919)
Apr 11 23:40:31 akovdr2 vdr: [6920] section handler thread started (pid=6914, tid=6920)
Apr 11 23:40:31 akovdr2 vdr: [6914] found 1 video device
Apr 11 23:40:31 akovdr2 vdr: [6914] initializing plugin: xine (0.8.2): Software based playback using xine
Apr 11 23:40:31 akovdr2 vdr: [6921] XineRemote control thread started (pid=6914, tid=6921)
Apr 11 23:40:31 akovdr2 vdr: [6921] Entering cXineRemote thread 
Apr 11 23:40:31 akovdr2 vdr: [6914] setting primary device to 2
Apr 11 23:40:31 akovdr2 vdr: [6914] assuming manual start of VDR
Apr 11 23:40:31 akovdr2 vdr: [6914] SVDRP listening on port 2001
Apr 11 23:40:31 akovdr2 vdr: [6914] setting current skin to "sttng"
Apr 11 23:40:31 akovdr2 vdr: [6914] loading /usr/local/etc/vdr/themes/sttng-default.theme
Apr 11 23:40:31 akovdr2 vdr: [6914] starting plugin: xine
Apr 11 23:40:31 akovdr2 vdr: [6924] KBD remote control thread started (pid=6914, tid=6924)
Apr 11 23:40:31 akovdr2 vdr: [6914] ERROR: remote control XineRemote not ready!
Apr 11 23:40:31 akovdr2 vdr: [6914] remote control KBD - keys known
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:31 akovdr2 kernel: dvb_ca adapter 0: DVB CAM detected and initialised successfully
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM 1: module ready
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:31 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:32 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:33 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: Reset calling i=1, tc[i]=136770992
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: Reset called
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: Slot 1: reset...
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ok
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 1207946434
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM 1: module present
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:34 akovdr2 kernel: dvb_ca adapter 0: DVB CAM detected and initialised successfully
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM 1: module ready
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:34 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:35 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:36 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: Reset calling i=1, tc[i]=136770992
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: Reset called
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: Slot 1: reset...
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ok
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 1207946437
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM 1: module present
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 2 resetTime: 0
Apr 11 23:40:37 akovdr2 kernel: dvb_ca adapter 0: DVB CAM detected and initialised successfully
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM 1: module ready
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6918] CAM DEBUG: ms: 3 resetTime: 0
Apr 11 23:40:37 akovdr2 vdr: [6914] CAM DEBUG: ms: 3 resetTime: 0
  

Comments

Klaus Schmidinger April 11, 2008, 9:01 p.m. UTC | #1
On 04/11/08 22:51, Arthur Konovalov wrote:
> Klaus Schmidinger wrote:
>> Since cCamSlot::Reset() is the only place where resetTime is set to
>> a non-zero value, and you had lines like "resetTime1: 1207548401" in
>> your syslog_1 file, apparently the tc[i]->Process() call in
>> cCamSlot::Process() must have failed.
> Yes, reset came from this procedure.
> I added some printouts (look at attached diff).
> 
> How to see reason why this Reset() is called?

The tc[i]->Process() call failed.

Further debug info could be gathered by adding output at the "return false"
lines in cCiTransportConnection::Process().

Well, actually it's only one place there where false is returned,
and that's when the "alive" timer times out, which is apparently
after the 2 seconds between the resets you're observing, see

#define TC_ALIVE_TIMEOUT 2000

One possible test would be to increase this time and see whether
this increases the distance between resets - or makes them go away
at all.

Depending on the result of this test we'll see how to continue.

Klaus
  
Arthur Konovalov April 11, 2008, 9:10 p.m. UTC | #2
Klaus Schmidinger wrote:
> Well, actually it's only one place there where false is returned,
> and that's when the "alive" timer times out, which is apparently
> after the 2 seconds between the resets you're observing, see
> 
> #define TC_ALIVE_TIMEOUT 2000
> 
> One possible test would be to increase this time and see whether
> this increases the distance between resets - or makes them go away
> at all.
> 
> Depending on the result of this test we'll see how to continue.

Meanwhile I increased constant

MODULE_CHECK_INTERVAL to 300 ms

and now syslog looks much better.

Currently I have not display (ssh session only) and can't verify final 
result.

Is it possible that is OK now?

Arthur
Apr 12 00:00:03 akovdr2 vdr: [7372] cTimeMs: using monotonic clock (resolution is 4000250 ns)
Apr 12 00:00:03 akovdr2 vdr: [7372] VDR version 1.6.0 started
Apr 12 00:00:03 akovdr2 vdr: [7372] codeset is 'UTF-8' - known
Apr 12 00:00:03 akovdr2 vdr: [7372] found 23 locales in /usr/local/src/vdr-1.6.0/locale
Apr 12 00:00:03 akovdr2 vdr: [7372] loading plugin: /usr/local/vdr/PLUGINS/lib/libvdr-xine.so.1.6.0
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/setup.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/sources.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/diseqc.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/channels.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/timers.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/svdrphosts.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/remote.conf
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/keymacros.conf
Apr 12 00:00:03 akovdr2 vdr: [7373] video directory scanner thread started (pid=7372, tid=7373)
Apr 12 00:00:03 akovdr2 vdr: [7373] video directory scanner thread ended (pid=7372, tid=7373)
Apr 12 00:00:03 akovdr2 vdr: [7374] video directory scanner thread started (pid=7372, tid=7374)
Apr 12 00:00:03 akovdr2 vdr: [7374] video directory scanner thread ended (pid=7372, tid=7374)
Apr 12 00:00:03 akovdr2 vdr: [7372] reading EPG data from /usr/local/etc/vdr/epg.data
Apr 12 00:00:03 akovdr2 vdr: [7372] probing /dev/dvb/adapter0/frontend0
Apr 12 00:00:03 akovdr2 vdr: [7372] CAM DEBUG: Reset called
Apr 12 00:00:03 akovdr2 vdr: [7372] CAM DEBUG: Slot 1: reset...
Apr 12 00:00:03 akovdr2 vdr: [7372] CAM DEBUG: ok
Apr 12 00:00:03 akovdr2 vdr: [7376] CI adapter on device 0 thread started (pid=7372, tid=7376)
Apr 12 00:00:03 akovdr2 vdr: [7376] CAM 1: module present
Apr 12 00:00:03 akovdr2 vdr: [7377] tuner on device 1 thread started (pid=7372, tid=7377)
Apr 12 00:00:03 akovdr2 vdr: [7378] section handler thread started (pid=7372, tid=7378)
Apr 12 00:00:03 akovdr2 vdr: [7372] found 1 video device
Apr 12 00:00:03 akovdr2 vdr: [7372] initializing plugin: xine (0.8.2): Software based playback using xine
Apr 12 00:00:03 akovdr2 vdr: [7379] XineRemote control thread started (pid=7372, tid=7379)
Apr 12 00:00:03 akovdr2 vdr: [7379] Entering cXineRemote thread 
Apr 12 00:00:03 akovdr2 vdr: [7372] setting primary device to 2
Apr 12 00:00:03 akovdr2 vdr: [7372] assuming manual start of VDR
Apr 12 00:00:03 akovdr2 vdr: [7372] SVDRP listening on port 2001
Apr 12 00:00:03 akovdr2 vdr: [7372] setting current skin to "sttng"
Apr 12 00:00:03 akovdr2 vdr: [7372] loading /usr/local/etc/vdr/themes/sttng-default.theme
Apr 12 00:00:03 akovdr2 vdr: [7372] starting plugin: xine
Apr 12 00:00:03 akovdr2 vdr: [7382] KBD remote control thread started (pid=7372, tid=7382)
Apr 12 00:00:03 akovdr2 vdr: [7372] ERROR: remote control XineRemote not ready!
Apr 12 00:00:03 akovdr2 vdr: [7372] remote control KBD - keys known
Apr 12 00:00:03 akovdr2 kernel: dvb_ca adapter 0: DVB CAM detected and initialised successfully
Apr 12 00:00:03 akovdr2 vdr: [7376] CAM 1: module ready
Apr 12 00:00:05 akovdr2 vdr: [7376] CAM 1: TSD Crypt Conax, 01, 0000, 033D
Apr 12 00:00:11 akovdr2 vdr: [7376] CAM 1: doesn't reply to QUERY - only a single channel can be decrypted
Apr 12 00:00:11 akovdr2 vdr: [7372] setting watchdog timer to 30 seconds
Apr 12 00:00:11 akovdr2 vdr: [7372] switching to channel 1
Apr 12 00:00:11 akovdr2 vdr: [7383] transfer thread started (pid=7372, tid=7383)
Apr 12 00:00:11 akovdr2 vdr: [7384] receiver on device 1 thread started (pid=7372, tid=7384)
Apr 12 00:00:11 akovdr2 vdr: [7385] TS buffer on device 1 thread started (pid=7372, tid=7385)
Apr 12 00:00:17 akovdr2 vdr: [7372] max. latency time 1 seconds
Apr 12 00:00:20 akovdr2 vdr: [7377] frontend 0 timed out while tuning to channel 1, tp 112187
  
Arthur Konovalov April 11, 2008, 9:31 p.m. UTC | #3
Now I have next question/problem.
 From Technisat support I have the following answer:

Our CAM TechniCrypt CW is able to do multiple parallel decryptions since 
the software version  26.1.5.0.11

I have this firmware:
Conax CA
About
0. Quit menu
1. Software version: 26.1.5.0.11
2. Interface version: 0x40
3. Smart card number: 014 6900 0921 - 3
4. Number of sessions: 5
5. Language: 44
6. CA_SYS_ID: 0x0B00
SE

But line from syslog says:

CAM 1: doesn't reply to QUERY - only a single channel can be decrypted

Is it possible to verify is it true or is there misunderstanding somewhere?

Arthur
  
Klaus Schmidinger April 12, 2008, 9:11 a.m. UTC | #4
On 04/11/08 23:10, Arthur Konovalov wrote:
> Klaus Schmidinger wrote:
>> Well, actually it's only one place there where false is returned,
>> and that's when the "alive" timer times out, which is apparently
>> after the 2 seconds between the resets you're observing, see
>>
>> #define TC_ALIVE_TIMEOUT 2000
>>
>> One possible test would be to increase this time and see whether
>> this increases the distance between resets - or makes them go away
>> at all.
>>
>> Depending on the result of this test we'll see how to continue.
> 
> Meanwhile I increased constant
> 
> MODULE_CHECK_INTERVAL to 300 ms
> 
> and now syslog looks much better.
> 
> Currently I have not display (ssh session only) and can't verify final 
> result.
> 
> Is it possible that is OK now?

What you're achieving with this longer timeout is that the module status
is checked less often. If this leads to an improvement, I guess it means
that getting the module status is somehow broken, because it really should
be allowed to get te module status at any time (or does anybody know of
some specs that say otherwise?).

This might be the reason why you don't have trouble with other apps,
because maybe they don't check the module status (or at least not that
often).

At any rate, if this really fixes the problem for you (please let us
know whether it actually work in the long run) I guess it shouldn't
be wrong to generally set this timeout to 300ms - or maybe even more?
Like 1000ms or so?

Klaus
  
Klaus Schmidinger April 12, 2008, 9:16 a.m. UTC | #5
On 04/11/08 23:31, Arthur Konovalov wrote:
> Now I have next question/problem.

Please start a new thread for a new topic ( I've at least changed the subject).

>  From Technisat support I have the following answer:
> 
> Our CAM TechniCrypt CW is able to do multiple parallel decryptions since 
> the software version  26.1.5.0.11
> 
> I have this firmware:
> Conax CA
> About
> 0. Quit menu
> 1. Software version: 26.1.5.0.11
> 2. Interface version: 0x40
> 3. Smart card number: 014 6900 0921 - 3
> 4. Number of sessions: 5
> 5. Language: 44
> 6. CA_SYS_ID: 0x0B00
> SE
> 
> But line from syslog says:
> 
> CAM 1: doesn't reply to QUERY - only a single channel can be decrypted
> 
> Is it possible to verify is it true or is there misunderstanding somewhere?

Please activate the DumpTPDUDataTransfer and DebugProtocol switches in ci.c
and check whether VDR receives a reply to its QUERY.

Klaus
  
Arthur Konovalov April 13, 2008, 1:18 p.m. UTC | #6
Klaus Schmidinger wrote:
>> Meanwhile I increased constant
>>
>> MODULE_CHECK_INTERVAL to 300 ms
>>
>> and now syslog looks much better.
>>
> 
> At any rate, if this really fixes the problem for you (please let us
> know whether it actually work in the long run) I guess it shouldn't
> be wrong to generally set this timeout to 300ms - or maybe even more?

It seems stable with 300ms with my CAM, but for reliability reason I set 
it to 500ms.

Arthur
  

Patch

--- ci.c.orig	2008-04-11 21:20:00.000000000 +0300
+++ ci.c	2008-04-11 23:37:16.000000000 +0300
@@ -1625,6 +1625,7 @@ 
   for (int i = 1; i <= MAX_CONNECTIONS_PER_CAM_SLOT; i++) {
       if (tc[i]) {
          if (!tc[i]->Process()) {
+	   isyslog("CAM DEBUG: Reset calling i=%d, tc[i]=%d", i, tc[i]); //AK
            Reset();
            return;
            }
@@ -1681,16 +1682,20 @@ 
 
 bool cCamSlot::Reset(void)
 {
+  isyslog("CAM DEBUG: Reset called"); //AK
   cMutexLock MutexLock(&mutex);
   ChannelCamRelations.Reset(slotNumber);
   DeleteAllConnections();
   if (ciAdapter) {
      dbgprotocol("Slot %d: reset...", slotNumber);
+     isyslog("CAM DEBUG: Slot %d: reset...", slotNumber); //AK
      if (ciAdapter->Reset(slotIndex)) {
         resetTime = time(NULL);
         dbgprotocol("ok.\n");
+        isyslog("CAM DEBUG: ok"); //AK
         return true;
         }
+     isyslog("CAM DEBUG: failed"); //AK
      dbgprotocol("failed!\n");
      }
   return false;
@@ -1700,11 +1705,15 @@ 
 {
   cMutexLock MutexLock(&mutex);
   eModuleStatus ms = ciAdapter ? ciAdapter->ModuleStatus(slotIndex) : msNone;
+  isyslog("CAM DEBUG: ms: %d resetTime: %d", ms, resetTime); //AK
   if (resetTime) {
      if (ms <= msReset) {
-        if (time(NULL) - resetTime < MODULE_RESET_TIMEOUT)
+	isyslog("CAM DEBUG: ms le msReset"); //AK
+        if (time(NULL) - resetTime < MODULE_RESET_TIMEOUT) {
+	   isyslog("CAM DEBUG: return msReset"); //AK
            return msReset;
         }
+    }
      resetTime = 0;
      }
   return ms;