Project

General

Profile

Bug #1670

Recordings fail with "time missed"

Added by Rob vh over 11 years ago. Updated over 11 years ago.

Status:
Invalid
Priority:
Normal
Assignee:
Mariusz Białończyk
Category:
Descrambling
Target version:
-
Start date:
2013-03-24
Due date:
% Done:

0%

Estimated time:
Found in version:
3.5.66~gbabe159-dirty
Affected Versions:
3.4

Description

On the same day I have several shows that record OK and one that fails with "time missed." It is the 2nd Castle (starting at 21:25) that fails. The others (despite tons of continuity errors) are stored:

Mar 21 21:19:32 sat tvheadend942: dvr: "Castle" on "SBS6" recorder starting
Mar 21 21:19:32 sat tvheadend942: Service: Subscription "DVR: Castle": Skipping "A4/ASTRA 1: 12,515,000 kHz Horizontal (Astra 1)/SBS6" -- not enabled
Mar 21 21:19:32 sat tvheadend942: subscription: "DVR: Castle" subscribing on "SBS6", weight: 300, adapter: "A2", network: "CANALDIGITAAL", mux: "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)", provider: "CANALDIGITAAL", service: "SBS6", quality: 100
Mar 21 21:19:55 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error indicator
Mar 21 21:19:55 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510: Continuity counter error
Mar 21 21:19:55 sat tvheadend[942]: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82: Continuity counter error
Mar 21 21:19:55 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: TELETEXT #41: Continuity counter error
Mar 21 21:22:54 sat tvheadend[942]: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510: Corrupted PES header
Mar 21 21:33:56 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error indicator
Mar 21 21:33:56 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510: Continuity counter error
Mar 21 21:33:56 sat tvheadend[942]: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82: Continuity counter error
Mar 21 21:34:38 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510: Continuity counter error
Mar 21 21:34:38 sat tvheadend[942]: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82: Continuity counter error
Mar 21 21:35:01 sat tvheadend942: subscription: "DVR: Castle" unsubscribing from "SBS6"
Mar 21 21:35:01 sat tvheadend942: dvr: Recording completed: "/data/2/tv_recordings/Castle/SBS6-Castle.2013-03-21.20-30.mkv"
Mar 21 21:35:01 sat tvheadend942: dvr: "Castle" on "SBS6": End of program: Completed OK
Mar 21 21:35:20 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error indicator
......
Mar 21 22:40:02 sat tvheadend942: subscription: "DVR: Castle" unsubscribing from "SBS6"
Mar 21 22:40:02 sat tvheadend942: capmt: Removing CAPMT Server from service
Mar 21 22:40:02 sat tvheadend942: dvr: "Castle" on "SBS6": End of program: Time missed

This happens a lot :-(

Files

syslog.txt (94.5 KB) syslog.txt Rob vh, 2013-03-24 17:11
syslog.27 (56.3 MB) syslog.27 Rob vh, 2013-03-28 20:27
syslog.28 (20.2 MB) syslog.28 Rob vh, 2013-03-28 20:27
time missed.bmp (3.99 MB) time missed.bmp Rob vh, 2013-03-28 20:27
recordings.bmp (3.99 MB) recordings.bmp Rob vh, 2013-03-28 20:28
syslog.zip (598 KB) syslog.zip Rob vh, 2013-03-28 23:54
recordings.bmp (3.99 MB) recordings.bmp Rob vh, 2013-03-28 23:54
time missed.bmp (3.99 MB) time missed.bmp Rob vh, 2013-03-28 23:54
syslog.zip (244 KB) syslog.zip Rob vh, 2013-04-19 10:08

History

#1

Updated by Adam Sutton over 11 years ago

See my notes on #1666, it might be related. And can you attach the full debug log.

Adam

#2

Updated by Rob vh over 11 years ago

At other times I have no issue with recording 5 simultaneous shows. Do you think it is a race condition that fails the mutex lock?
I have attached the normal log from syslog, but will figure out how to activate full debug.
Thx.

#3

Updated by Rob vh over 11 years ago

When I signed on to the web interface, the display only showed the EPG tab, with no entries at all. The other tabs (DVR, Configuration, Status) did not show. Restarting the URL didn't help.
Syslog showed that CAs were being scanned.

So I did service tvheadend restart and checked the failed recordings. After a set of successful recordings on March 27, evening, the first failure occurred around midnight. Around that time I added a few Muxes to Adapter 5. From then on all scheduled recordings (on Adapters 0 - 3) failed.

PS. I switched to 3.5.70 in the afternoon of Mar 27.

#5

Updated by Rob vh over 11 years ago

Maybe this one is a little easier to diagnose.
I restarted tvheadend at 19:40.
It started to record Castle at 20:25. This file recorded for 45 minutes and stops in the middle of the episode. Even though "finished recordings" claims it is 1 hour, it stops after 45 minutes.
The 2nd episode (starting at 21:25) isn't recorded.
This time I didn't fool with the GUI ;-)

#6

Updated by Adam Sutton over 11 years ago

  • Category changed from General to Descrambling
  • Status changed from New to Need feedback
  • Assignee set to Mariusz Białończyk
  • Affected Versions 3.4 added

This looks, and I've not looked too hard yet, like a problem with capmt. The recording lengths etc... are simply from the EPG data they don't reflect how much was actually recorded (yes there are improvements to be made there).

I'd guess that your descrambling system is breaking down and thus the recording stops receiving any new data and subsequent ones fail. Why this is happening I don't know as I've not much experience with the capmt stuff.

Adam

#7

Updated by Rob vh over 11 years ago

When I look at the EPG data, and the way it is presented in the Upcoming recordings list, the start time and expected duration are reasonable. Never noticed "zero length" values. The OSCAM I'm using has been stable with subsequent tvheadends that I'm testing, which suggests that OSCAM services that used to work OK (with stable recording) some months ago, now result in more "time missed" events. True, that may be due to the changes in capmt (I haven't looked at the source code of capmt ;-) ).

#8

Updated by Mariusz Białończyk over 11 years ago

Hi,
Capmt code was not updated recently. According to your logs it seems that the stream is really broken, then capmt disconnect. Cannot tell you more. If it is not an oscam problem (keys reach tvh on time), then the only thing which comes to my mind is - that you could try to switch from FFdecsa to libdvbcsa or vice versa.

#9

Updated by Rob vh over 11 years ago

I also have seen occasional "time missed" status on FTA channels.

#10

Updated by Adam Sutton over 11 years ago

Sorry guys,

I didn't read this properly. Been away a few days and scanning through a
whole bunch of problems.

This is actually more likely to be related to the generally broken DVB
input system between ddc466c1bfa7405563a68a662114f5a3659d7cb5 (one commit
before the one mentioned) and e9ce02138e81d0dd94a2b155e57fda282063c008
(current master I think).

I'd suggest updating and if the problem goes away I'll close this.

Adam

On 3 April 2013 11:52, wrote:

Issue #1670 has been updated by Mariusz Białończyk.

Hi,
Capmt code was not updated recently. According to your logs it seems that
the stream is really broken, then capmt disconnect. Cannot tell you more.
If it is not an oscam problem (keys reach tvh on time), then the only thing
which comes to my mind is - that you could try to switch from FFdecsa to
libdvbcsa or vice versa.
------------------------------
Bug #1670: Recordings fail with "time missed"

- Author: Rob vh
- Status: Need feedback
- Priority: Normal
- Assignee: Mariusz Białończyk
- Category: Descrambling
- Target version:
- Found in version: 3.5.66~gbabe159-dirty
- Affected Versions: 3.4

On the same day I have several shows that record OK and one that fails
with "time missed." It is the 2nd Castle (starting at 21:25) that fails.
The others (despite tons of continuity errors) are stored:

Mar 21 21:19:32 sat tvheadend942 : dvr: "Castle"
on "SBS6" recorder starting
Mar 21 21:19:32 sat tvheadend942 : Service:
Subscription "DVR: Castle": Skipping "A4/ASTRA 1: 12,515,000 kHz Horizontal
(Astra 1)/SBS6" -- not enabled
Mar 21 21:19:32 sat tvheadend942 : subscription:
"DVR: Castle" subscribing on "SBS6", weight: 300, adapter: "A2", network:
"CANALDIGITAAL", mux: "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)",
provider: "CANALDIGITAAL", service: "SBS6", quality: 100
Mar 21 21:19:55 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error
indicator
Mar 21 21:19:55 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510:
Continuity counter error
Mar 21 21:19:55 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz
Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82:
Continuity counter error
Mar 21 21:19:55 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: TELETEXT #41:
Continuity counter error
Mar 21 21:22:54 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz
Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510:
Corrupted PES header
Mar 21 21:33:56 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error
indicator
Mar 21 21:33:56 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510:
Continuity counter error
Mar 21 21:33:56 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz
Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82:
Continuity counter error
Mar 21 21:34:38 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510:
Continuity counter error
Mar 21 21:34:38 sat tvheadend942: TS: A2/CANALDIGITAAL: 12,515,000 kHz
Horizontal (Astra 1)/SBS6: MPEG2AUDIO #82:
Continuity counter error
Mar 21 21:35:01 sat tvheadend942 : subscription:
"DVR: Castle" unsubscribing from "SBS6"
Mar 21 21:35:01 sat tvheadend942 : dvr:
Recording completed:
"/data/2/tv_recordings/Castle/SBS6-Castle.2013-03-21.20-30.mkv"
Mar 21 21:35:01 sat tvheadend942 : dvr: "Castle"
on "SBS6": End of program: Completed OK
Mar 21 21:35:20 sat tvheadend942 : TS:
A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error
indicator
......
Mar 21 22:40:02 sat tvheadend942 : subscription:
"DVR: Castle" unsubscribing from "SBS6"
Mar 21 22:40:02 sat tvheadend942 : capmt:
Removing CAPMT Server from service
Mar 21 22:40:02 sat tvheadend942 : dvr: "Castle"
on "SBS6": End of program: Time missed

This happens a lot :-(
------------------------------

You have received this notification because you have either subscribed to
it, or are involved in it.
To change your notification preferences, please click here:
https://tvheadend.org/my/account

#11

Updated by Rob vh over 11 years ago

the current GIT build crashes my server (i2c timeout) so it does not have time to actually make many recordings. I will update this issue when there's a fix to the timeouts.

#12

Updated by Koen Kooi over 11 years ago

I still get "time missed" with e9ce02138e81d0dd94a2b155e57fda282063c008 from time to time, restarting tvh helps, but not always.

#13

Updated by Koen Kooi over 11 years ago

Since live TV does work pretty much all the time I did an experiment with a few recordings: Stream the TV channel live using TVHguide just before the recording starts and the "time missed" errors are gone! It seems to me that I'm hitting some kind of timeout in tvh when my tbs6618 is slow to tune to a channel. If there's such a timeout, can it be increased?

#14

Updated by Adam Sutton over 11 years ago

There is a per adapter grace period, I think its 10s by default. I guess its possible that if the tuner really takes longer than that to lock it could somehow enter some strange loop whereby it fails/timeout, re-tunes, fails/timeout, etc... Also I wouldn't expect that behaviour from a tuner on subsequent re-tune (to same settings).

However, that would be the same for ALL reception (doesn't matter if its DVR/HTSP/HTTP).

#15

Updated by Rob vh over 11 years ago

Koen, are these FTA transmissions, or does it involve captm?

#16

Updated by Koen Kooi over 11 years ago

CWC using OSCAM and a USB card reader, I can't get the builtin CAM slot working on the tbs6618. A setup similar to https://tvheadend.org/projects/tvheadend/wiki/Tvheadend_oscam_ziggo

#17

Updated by Rob vh over 11 years ago

On Thursday I installed http://linuxtv.org/hg/~endriss/media_build_experimental/ on my Mythbuntu 12.04 server (3.2.0-40). When this proved stable, I upgraded to the Friday version of tvheadend. No timeouts and no "time missed" for 2 days (I exercised the dvr). See also https://tvheadend.org/issues/1678

#18

Updated by Koen Kooi over 11 years ago

I have one of those GPL violating TBS6618 with binary only drivers :(

#19

Updated by Adam Sutton over 11 years ago

  • Status changed from Need feedback to Invalid

Just to clarify, the TBS drivers are not GPL violating (that would be a serious offence). They simply have modules with proprietary licenses (for which no source code is available) that "taints" the kernel.

Based on Rob's recent input, I'm closing this issue.

Adam

#20

Updated by Koen Kooi over 11 years ago

I still get 'time missed' and 'no input detected' with latest git (46704009e12c40ddc54792a99b0a912f2aa3c12c).

As for the GPL issues: tainting the kernel is OK, but these module link to external linux-media GPL code, which is not allowed.

#21

Updated by Adam Sutton over 11 years ago

No, they provide patched linux-media code, to allow loading of their modules. They're not breaching the GPL as far as I'm aware. If they were I'd definitely be kicking them (as I did to ensure the MOI kernel code was released).

But back to the issue at hand. Does this happen randomly or reliably? Can you try disabling an then re-enabling (from the UI) the adapters to see if that changes performance. I've had some weird issues in past with my TBS cards starting up oddly (when TVH first connects) and this only going away when TVH re-attempts access.

Adam

#22

Updated by Rob vh over 11 years ago

For the first time in a week, I got the dreaded "time missed" event again. And again for the TV show Castle. The 20:30 show seemed to record fine, the 21:25 show went to the end and at 22:40 complained "time missed."

root@sat:/home/hts/.hts/tvheadend/dvr/log# cat 673 {
"channel": "SBS6",
"start": 1366309800,
"stop": 1366313400,
"start_extra": 5,
"stop_extra": 10,
"config_name": "",
"creator": "Auto recording",
"filename": "/data/2/tv_recordings/Castle/SBS6-Castle.2013-04-18.20-30.mkv",
"title": {
"dut": "Castle"
},
"dvb_eid": 205,
"pri": "normal",
"noresched": 0,
"autorec": "41",
"contenttype": 17,
"broadcast": 1821,
"container": 1
}
root@sat:/home/hts/.hts/tvheadend/dvr/log# cat 674 {
"channel": "SBS6",
"start": 1366313400,
"stop": 1366317000,
"start_extra": 5,
"stop_extra": 10,
"config_name": "",
"creator": "Auto recording",
"title": {
"dut": "Castle"
},
"dvb_eid": 206,
"pri": "normal",
"noresched": 0,
"autorec": "41",
"contenttype": 17,
"broadcast": 1823,
"container": 1
}

Oh, but this is worse... I notice that the first recording only took about 45 minutes of the show, not the whole hour. Because at the same time (20:25) another recording started on the same tuner for NGC, for a 30 minutes show.

root@sat:/home/hts/.hts/tvheadend/dvr/log# cat 671 {
"channel": "National Geographic Channel",
"start": 1366309800,
"stop": 1366311600,
"start_extra": 5,
"stop_extra": 10,
"config_name": "",
"creator": "Auto recording by: 10.29.1.62",
"filename": "/data/2/tv_recordings/Behind the Science/National Geographic Channel-Behind the Science.2013-04-18.20-30.mkv",
"title": {
"dut": "Behind the Science"
},
"dvb_eid": 326,
"description": {
"dut": ""
},
"pri": "normal",
"noresched": 0,
"autorec": "38",
"contenttype": 128,
"broadcast": 16561,
"container": 1
}

Apr 18 20:24:31 sat tvheadend11180: dvr: "Behind the Science" on "National Geographic Channel" recorder starting
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Adding adapter "_dev_dvb_adapter4_STV090x_Multistandard12515000_H_satconf_5" for service "A4/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Adding adapter "_dev_dvb_adapter3_STV090x_Multistandard12515000_H_satconf_4" for service "A3/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Adding adapter "_dev_dvb_adapter2_STV090x_Multistandard12515000_H_satconf_3" for service "A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Adding adapter "_dev_dvb_adapter1_STV090x_Multistandard12515000_H_satconf_2" for service "A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Adding adapter "_dev_dvb_adapter0_STV090x_Multistandard12515000_H_satconf_1" for service "A0/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Behind the Science": Probing adapter "_dev_dvb_adapter1_STV090x_Multistandard12515000_H_satconf_2" without stealing for service "A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: Starting capmt server for service "NGC" on tuner 1
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x1817 for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x0100 for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x1818 for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x0100 for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x0500 for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: subscription: "DVR: Behind the Science" subscribing on "National Geographic Channel", weight: 300, adapter: "A1", network: "CANALDIGITAAL", mux: "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)", provider: "CANALDIGITAAL", service: "NGC", quality: 32
Apr 18 20:24:31 sat tvheadend11180: dvr: "Castle" on "SBS6" recorder starting
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Adding adapter "_dev_dvb_adapter4_STV090x_Multistandard12515000_H_satconf_5" for service "A4/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Adding adapter "_dev_dvb_adapter3_STV090x_Multistandard12515000_H_satconf_4" for service "A3/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Adding adapter "_dev_dvb_adapter2_STV090x_Multistandard12515000_H_satconf_3" for service "A2/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Adding adapter "_dev_dvb_adapter1_STV090x_Multistandard12515000_H_satconf_2" for service "A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Adding adapter "_dev_dvb_adapter0_STV090x_Multistandard12515000_H_satconf_1" for service "A0/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: Service: Subscription "DVR: Castle": Probing adapter "_dev_dvb_adapter1_STV090x_Multistandard12515000_H_satconf_2" without stealing for service "A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6"
Apr 18 20:24:31 sat tvheadend11180: capmt: Starting capmt server for service "SBS6" on tuner 1
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x1817 for service "SBS6"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x0100 for service "SBS6"
Apr 18 20:24:31 sat tvheadend11180: capmt: New caid 0x0100 for service "SBS6"
Apr 18 20:24:31 sat tvheadend11180: subscription: "DVR: Castle" subscribing on "SBS6", weight: 300, adapter: "A1", network: "CANALDIGITAAL", mux: "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)", provider: "CANALDIGITAAL", service: "SBS6", quality: 32
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Status changed to [Hardware input]
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC: Status changed to [Hardware input]
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Status changed to [Hardware input] [Input on service]
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC: Status changed to [Hardware input] [Input on service]
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/NGC: Status changed to [Hardware input] [Input on service] [Demuxed packets]
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x583 (1411), CAID=0x500 (1280) PROVID=0x42500 (271616)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x727 (1831), CAID=0x100 (256) PROVID=0x6C (108)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x727 (1831), CAID=0x1818 (6168) PROVID=0x0 (0)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x713 (1811), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x713 (1811), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 20:24:31 sat tvheadend11180: capmt: Trying to obtain key for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=0 socket=19
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: added: i=0
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x583 (1411), CAID=0x500 (1280) PROVID=0x42500 (271616)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x727 (1831), CAID=0x100 (256) PROVID=0x6C (108)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x727 (1831), CAID=0x1818 (6168) PROVID=0x0 (0)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x713 (1811), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x713 (1811), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 20:24:31 sat tvheadend11180: capmt: Trying to obtain key for service "NGC"
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=4015 socket=19
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: found sid, reusing socket, i=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: added: i=0
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Status changed to [Hardware input] [Input on service] [Demuxed packets]
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x641 (1601), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 20:24:31 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 20:24:31 sat tvheadend11180: capmt: Trying to obtain key for service "SBS6"
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=4015 socket=19
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 20:24:31 sat tvheadend11180: capmt: capmt_send_msg: added: i=1
Apr 18 20:24:31 sat tvheadend11180: capmt: created socket with socket_fd=43
Apr 18 20:24:31 sat tvheadend11180: capmt: CA_SET_PID cai 1 req 1074294663 (0 0001)
Apr 18 20:24:31 sat tvheadend11180: capmt: CA_SET_DESCR cai 1 req 1074818950 par 0 idx 0 821317ac65ff68cc
Apr 18 20:24:31 sat tvheadend11180: capmt: Obtained key for service "SBS6"
Apr 18 20:24:31 sat tvheadend11180: capmt: CA_SET_DESCR cai 1 req 1074818950 par 1 idx 0 c4847cc4f9a1ed87
Apr 18 20:24:31 sat tvheadend11180: Service: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets]

and stops at 21:10 (as expected)

Apr 18 21:10:00 sat tvheadend11180: dvb: "/dev/dvb/adapter0" tuning via s2api to "ASTRA: 10,847,000 kHz Vertical (Astra 2)" (1097000, 23000000 Baud, 5/6, SYS_DVBS2, PSK_8) for Autoscan
Apr 18 21:10:00 sat tvheadend11180: dvb: /dev/dvb/adapter2 stopping thread
Apr 18 21:10:00 sat tvheadend11180: dvb: /dev/dvb/adapter2 stopped thread
Apr 18 21:10:00 sat tvheadend11180: dvb: "/dev/dvb/adapter2" tuning via s2api to "ASTRA: 10,832,000 kHz Horizontal (Astra 2)" (1082000, 22000000 Baud, 5/6, SYS_DVBS, QPSK) for Autoscan
Apr 18 21:10:00 sat tvheadend11180: dvb: "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1" on adapter "A4", status changed to Constant FEC
Apr 18 21:10:00 sat tvheadend11180: epg: expire event 15905 (Twee voor Twaalf) from NED2
Apr 18 21:10:00 sat tvheadend11180: epg: now/next 15907/15909 set on NED2
Apr 18 21:10:00 sat tvheadend11180: epg: arm channel timer 1366315200 for NED2
Apr 18 21:10:00 sat tvheadend[11180]: epg: inform HTSP of now event change on NED2
Apr 18 21:10:00 sat tvheadend[11180]: subscription: "DVR: Behind the Science" unsubscribing from "National Geographic Channel"
Apr 18 21:10:00 sat tvheadend[11180]: capmt: Removing CAPMT Server from service
Apr 18 21:10:00 sat tvheadend[11180]: capmt: capmt_send_stop: closing socket i=0, socket_fd=19
Apr 18 21:10:00 sat tvheadend[11180]: dvr: Recording completed: "/data/2/tv_recordings/Behind the Science/National Geographic Channel-Behind the Science.2013-04-18.20-30.mkv"
Apr 18 21:10:01 sat tvheadend[11180]: dvr: "Behind the Science" on "National Geographic Channel": End of program: Completed OK
Apr 18 21:10:01 sat tvheadend[11180]: dvb: /dev/dvb/adapter0 started dvr thread
Apr 18 21:10:01 sat tvheadend[11180]: uk_freesat: install table handlers
Apr 18 21:10:01 sat tvheadend[11180]: eit: install table handlers
Apr 18 21:10:01 sat tvheadend[11180]: capmt: CA_SET_PID cai 1 req 1074294663 (-1 0000)
Apr 18 21:10:01 sat tvheadend[11180]: capmt: adding ECMPID=0x641 (1601), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:01 sat tvheadend[11180]: capmt: adding ECMPID=0x709 (1801), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:01 sat tvheadend[11180]: capmt: adding ECMPID=0x709 (1801), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=4002 socket=43
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: found sid, reusing socket, i=1
Apr 18 21:10:01 sat tvheadend[11180]: capmt: capmt_send_msg: added: i=1
Apr 18 21:10:01 sat tvheadend[11180]: dvb: /dev/dvb/adapter2 started dvr thread
Apr 18 21:10:01 sat tvheadend[11180]: uk_freesat: install table handlers
Apr 18 21:10:01 sat tvheadend[11180]: eit: install table handlers
Apr 18 21:10:02 sat tvheadend[11180]: eit: begin processing
Apr 18 21:10:04 sat tvheadend[11180]: capmt: CA_SET_DESCR cai 1 req 1074818950 par 0 idx 0 1f1899d08a4afcd0
Apr 18 21:10:06 sat tvheadend[11180]: dvb: /dev/dvb/adapter5 stopping thread
Apr 18 21:10:06 sat tvheadend[11180]: dvb: /dev/dvb/adapter5 stopped thread
Apr 18 21:10:06 sat tvheadend[11180]: TS: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error indicator
Apr 18 21:10:06 sat tvheadend[11180]: TS: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO #510: Continuity counter error
Apr 18 21:10:06 sat tvheadend11180: dvb: "/dev/dvb/adapter5" tuning via s2api to "ASTRA: 11,953,500 kHz Horizontal (Astra 2)" (1353500, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Apr 18 21:10:11 sat tvheadend11180: dvb: /dev/dvb/adapter4 stopping thread
Apr 18 21:10:11 sat tvheadend11180: dvb: /dev/dvb/adapter4 stopped thread
Apr 18 21:10:11 sat tvheadend11180: eit: processing cancelled
Apr 18 21:10:11 sat tvheadend11180: capmt: adding ECMPID=0x641 (1601), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:11 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:11 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=4002 socket=43
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: found sid, reusing socket, i=1
Apr 18 21:10:11 sat tvheadend11180: capmt: capmt_send_msg: added: i=1
Apr 18 21:10:11 sat tvheadend11180: dvb: "/dev/dvb/adapter4" tuning via s2api to "ASTRA: 10,729,000 kHz Vertical (Astra 2)" (979000, 22000000 Baud, 5/6, SYS_DVBS, QPSK) for EPG scan
Apr 18 21:10:11 sat tvheadend11180: eit: begin processing
Apr 18 21:10:13 sat tvheadend11180: dvb: /dev/dvb/adapter4 started dvr thread
Apr 18 21:10:13 sat tvheadend11180: uk_freesat: install table handlers
Apr 18 21:10:13 sat tvheadend11180: eit: install table handlers
Apr 18 21:10:14 sat tvheadend11180: capmt: CA_SET_DESCR cai 1 req 1074818950 par 1 idx 0 be1df4cf7af0147e
Apr 18 21:10:17 sat tvheadend11180: uk_freesat: processing complete
Apr 18 21:10:17 sat tvheadend11180: dvb: /dev/dvb/adapter3 stopping thread
Apr 18 21:10:17 sat tvheadend11180: dvb: /dev/dvb/adapter3 stopped thread
Apr 18 21:10:18 sat tvheadend11180: dvb: "/dev/dvb/adapter3" tuning via s2api to "CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)" (1915000, 22000000 Baud, 5/6, SYS_DVBS, QPSK) for Autoscan
Apr 18 21:10:18 sat tvheadend11180: eit: begin processing
Apr 18 21:10:18 sat tvheadend11180: dvb: /dev/dvb/adapter3 started dvr thread
Apr 18 21:10:18 sat tvheadend11180: uk_freesat: install table handlers
Apr 18 21:10:18 sat tvheadend11180: eit: install table handlers
Apr 18 21:10:21 sat tvheadend11180: capmt: adding ECMPID=0x641 (1601), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:21 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:21 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=4002 socket=43
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: found sid, reusing socket, i=1
Apr 18 21:10:21 sat tvheadend11180: capmt: capmt_send_msg: added: i=1
Apr 18 21:10:22 sat tvheadend11180: eit: begin processing
Apr 18 21:10:22 sat tvheadend11180: eit: processing complete
Apr 18 21:10:24 sat tvheadend11180: capmt: CA_SET_DESCR cai 1 req 1074818950 par 0 idx 0 aca44b9b33728b30
Apr 18 21:10:25 sat tvheadend11180: dvb: "ASTRA: 11,953,500 kHz Horizontal (Astra 2)" on adapter "A5", status changed to Bad signal
Apr 18 21:10:27 sat tvheadend11180: dvb: "/dev/dvb/adapter5" tuning via s2api to "ASTRA: 10,876,500 kHz Vertical (Astra 2)" (1126500, 22000000 Baud, 5/6, SYS_DVBS, QPSK) for Autoscan
Apr 18 21:10:28 sat tvheadend11180: dvb: /dev/dvb/adapter5 started dvr thread
Apr 18 21:10:28 sat tvheadend11180: uk_freesat: install table handlers
Apr 18 21:10:28 sat tvheadend11180: eit: install table handlers
Apr 18 21:10:31 sat tvheadend11180: eit: processing complete
Apr 18 21:10:31 sat tvheadend11180: uk_freesat: processing complete
Apr 18 21:10:31 sat tvheadend11180: dvb: /dev/dvb/adapter4 stopping thread
Apr 18 21:10:31 sat tvheadend11180: dvb: /dev/dvb/adapter4 stopped thread
Apr 18 21:10:31 sat tvheadend11180: TS: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: Transport error indicator
Apr 18 21:10:31 sat tvheadend11180: TS: A1/CANALDIGITAAL: 12,515,000 kHz Horizontal (Astra 1)/SBS6: MPEG2VIDEO @ #510: Continuity counter error
Apr 18 21:10:31 sat tvheadend11180: dvb: "/dev/dvb/adapter4" tuning via s2api to "ASTRA: 11,023,000 kHz Horizontal (Astra 2)" (1273000, 23000000 Baud, 2/3, SYS_DVBS2, PSK_8) for Autoscan
Apr 18 21:10:31 sat tvheadend11180: capmt: adding ECMPID=0x641 (1601), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:31 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x100 (256) PROVID=0x6A (106)
Apr 18 21:10:31 sat tvheadend11180: capmt: adding ECMPID=0x709 (1801), CAID=0x1817 (6167) PROVID=0x0 (0)
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [0]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [1]: sid=4002 socket=43
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [2]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [3]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [4]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [5]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [6]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [7]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [8]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [9]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [10]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [11]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [12]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [13]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [14]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: SOCKETS TABLE DUMP [15]: sid=0 socket=0
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: found sid, reusing socket, i=1
Apr 18 21:10:31 sat tvheadend11180: capmt: capmt_send_msg: added: i=1

This happened with 35.97~G4570400.

#23

Updated by Koen Kooi over 11 years ago

Another failure mode is that the recording starts, but the webui says the status is 'testing'. 'killall tvheadend' and have systemd auto restart it makes it record.

#24

Updated by Anonymous over 11 years ago

I have several "time missed" in failed recordings every day.
I have 4 tuners (Dual Nova T-500) and I usually don't record more then 2 programs at the same time.
Full mux reception set to off.

#25

Updated by Anonymous over 11 years ago

I use Code Word Client for some channels.

#26

Updated by Rob vh over 11 years ago

Try to change the media container from Matroska into stream (pass through). That's an option in the recording configuration. Since I made that change, recording has been flawless. Someone in the dev team doesn't like mkv ;-).

#27

Updated by Koen Kooi over 11 years ago

I changed it to TS yesterday and the 2 recordings since then seem to have succeeded. Too soon to say it's a complete success though.

Also available in: Atom PDF