Tvheadend

Okay, I've been getting this on and off for a while, but I've got a debug log this time. There's a suspicion of descrambling issues - but this isn't an encrypted channel, so I've posted it here instead of the descrambling forum as more people are likely to see it here...

Dual USB tuners (TBS QBox S2 Conexant CX24116/CX24118 DVB-S and Hauppauge WinTV DiBcom 7000PC DVB-T) on an ATOM/ION system. XBMCBuntu, so Ubuntu 10.04 as a base; tvheadend version 3.2, although this was biting me on the betas as well (never on the old 2.12). I'm recording from DVB-S, which I normally do for the kids so probably the only place I've seen this happen.

Once every half-dozen or more recordings, I only get the very end of the file. I've watched the recording start on schedule - and the timestamp shows that it ended on schedule - but, somewhere in between, something would fail.

So, this is what I got the other day: 11m 11s of video and 160Mb of file instead of the 36:30/550Mb I was expecting.

Lightly-edited syslog:

Nov  1 17:28:30 revo tvheadend[1170]: dvr: "Power Rangers Mystic Force" on "Kix!" recorder starting
Nov  1 17:28:30 revo tvheadend[1170]: Service: Subscription "DVR: Power Rangers Mystic Force": Adding adapter "_dev_dvb_adapter1_Conexant_CX24116_CX2411811307000_V" for service "Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!" 
Nov  1 17:28:30 revo tvheadend[1170]: Service: Subscription "DVR: Power Rangers Mystic Force": Probing adapter "_dev_dvb_adapter1_Conexant_CX24116_CX2411811307000_V" without stealing for service "Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!" 
Nov  1 17:28:30 revo tvheadend[1170]: eit: processing cancelled
Nov  1 17:28:30 revo kernel: [64449.416309] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov  1 17:28:30 revo tvheadend[1170]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 11,307,000 kHz Vertical (No satconf)" (1557000, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Transport start
Nov  1 17:28:30 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:28:30 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:28:30 revo tvheadend[1170]: subscription: "DVR: Power Rangers Mystic Force" subscribing on "Kix!", weight: 300, adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 11,307,000 kHz Vertical (No satconf)", provider: "BSkyB", service: "Kix!", quality: 100
Nov  1 17:28:31 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input]
Nov  1 17:28:31 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service]
Nov  1 17:28:31 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service] [No available descrambler]
Nov  1 17:28:31 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service] [Demuxed packets] [No available descrambler]
Nov  1 17:28:31 revo tvheadend[1170]: eit: begin processing
Nov  1 17:28:31 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets] [No available descrambler]
Nov  1 17:28:33 revo tvheadend[1170]: Service: Subscription "DVR: Power Rangers Mystic Force": Adding adapter "_dev_dvb_adapter1_Conexant_CX24116_CX2411811307000_V" for service "Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!" 
Nov  1 17:28:33 revo tvheadend[1170]: dvr: Recording unable to start: "Power Rangers Mystic Force": No descrambler
Nov  1 17:28:35 revo tvheadend[1170]: Service: Subscription "DVR: Power Rangers Mystic Force": Adding adapter "_dev_dvb_adapter1_Conexant_CX24116_CX2411811307000_V" for service "Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!" 
Nov  1 17:28:35 revo tvheadend[1170]: Service: Subscription "DVR: Power Rangers Mystic Force": Probing adapter "_dev_dvb_adapter1_Conexant_CX24116_CX2411811307000_V" without stealing for service "Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!" 
Nov  1 17:28:35 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input]
Nov  1 17:28:35 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service]
Nov  1 17:28:35 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service] [Demuxed packets]
Nov  1 17:28:35 revo tvheadend[1170]: Service: Conexant CX24116/CX24118/ASTRA: 11,307,000 kHz Vertical (No satconf)/Kix!: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets]
Nov  1 17:28:36 revo tvheadend[1170]: dvr: File "/home/xbmc/Recordings/Power Rangers Mystic Force.2012-11-01.17-30.mkv" -- No such file or directory -- Using for recording
Nov  1 17:28:36 revo tvheadend[1170]: dvr: /home/xbmc/Recordings/Power Rangers Mystic Force.2012-11-01.17-30.mkv from adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 11,307,000 kHz Vertical (No satconf)", provider: "BSkyB", service: "Kix!" 
Nov  1 17:28:36 revo tvheadend[1170]: dvr:  # type                 lang resolution       samplerate channels
Nov  1 17:28:36 revo tvheadend[1170]: dvr:  1 MPEG2VIDEO                544 x 576
Nov  1 17:28:36 revo tvheadend[1170]: dvr:  2 MPEG2AUDIO           eng                   48000      2
Nov  1 17:29:06 revo tvheadend[1170]: eit: processing complete
Nov  1 17:29:06 revo tvheadend[1170]: uk_freesat: processing complete
Nov  1 17:29:06 revo tvheadend[1170]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 474,200 kHz" (Autoscan)
Nov  1 17:29:06 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:29:06 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:29:07 revo tvheadend[1170]: eit: begin processing
Nov  1 17:29:26 revo tvheadend[1170]: eit: processing cancelled
Nov  1 17:29:26 revo tvheadend[1170]: dvb: "/dev/dvb/adapter0" tuning to "ASTRA: 482,200 kHz" (Autoscan)
Nov  1 17:29:26 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:29:26 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:29:47 revo tvheadend[1170]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 474,200 kHz" (EPG scan)
Nov  1 17:29:47 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:29:47 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:29:47 revo tvheadend[1170]: eit: begin processing
Nov  1 17:30:00 revo ntpd[1561]: bind(21) AF_INET6 fe80::d2df:9aff:fe75:41f6%3#123 flags 0x11 failed: Cannot assign requested address
Nov  1 17:30:00 revo ntpd[1561]: unable to create socket on wlan0 (221) for fe80::d2df:9aff:fe75:41f6#123
Nov  1 17:30:00 revo ntpd[1561]: failed to init interface for address fe80::d2df:9aff:fe75:41f6
Nov  1 17:30:01 revo tvheadend[1170]: epg: expire event 653704 from CITV
Nov  1 17:30:01 revo tvheadend[1170]: epg: now/next 653705/653707 set on CITV
Nov  1 17:30:01 revo tvheadend[1170]: epg: arm channel timer @ 1351792200 for CITV
Nov  1 17:30:01 revo tvheadend[1170]: epg: inform HTSP of now event change on CITV
Nov  1 17:30:01 revo tvheadend[1170]: epg: expire event 675911 from NHK World HD
Nov  1 17:30:01 revo tvheadend[1170]: epg: now/next 675914/656431 set on NHK World HD
Nov  1 17:30:01 revo tvheadend[1170]: epg: arm channel timer @ 1351792800 for NHK World HD
Nov  1 17:30:01 revo tvheadend[1170]: epg: inform HTSP of now event change on NHK World HD

... loads more epg messages ...

Nov  1 17:30:01 revo rsyslogd-2177: imuxsock begins to drop messages from pid 1170 due to rate-limiting
Nov  1 17:31:30 revo rsyslogd-2177: imuxsock lost 220 messages from pid 1170 due to rate-limiting

... more epg and a couple of ntpd messages as above ...

Nov  1 18:00:00 revo rsyslogd-2177: imuxsock begins to drop messages from pid 1170 due to rate-limiting
Nov  1 18:00:18 revo rsyslogd-2177: imuxsock lost 872 messages from pid 1170 due to rate-limiting

obviously, syslog just got fed up of being spammed at this point!

... then more of the same ... until ...

Nov  1 18:05:00 revo tvheadend[1170]: epg: expire event 653546 from BBC ALBA
Nov  1 18:05:00 revo tvheadend[1170]: epg: now/next 654364/654365 set on BBC ALBA
Nov  1 18:05:00 revo tvheadend[1170]: epg: arm channel timer @ 1351793700 for BBC ALBA
Nov  1 18:05:00 revo tvheadend[1170]: epg: inform HTSP of now event change on BBC ALBA
Nov  1 18:05:00 revo tvheadend[1170]: subscription: "DVR: Power Rangers Mystic Force" unsubscribing from "Kix!" 
Nov  1 18:05:00 revo tvheadend[1170]: dvr: Recording completed: "/home/xbmc/Recordings/Power Rangers Mystic Force.2012-11-01.17-30.mkv" 
Nov  1 18:05:00 revo tvheadend[1170]: dvr: "Power Rangers Mystic Force" on "Kix!": End of program: Completed OK

Early on in the log file, there are a couple of messages about no available descrambler and then No such file or directory as it tries to create the output file, so that's clearly where it's most likely to be going wrong. Interestingly, though, I'd expect some entries around 17:53:49 as the programme finally started recording (to give me the 11m 11s by 18:05:00), but all I have is these entries around that time:

Nov  1 17:51:08 revo tvheadend[1170]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 498,000 kHz" (EPG scan)
Nov  1 17:51:08 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:51:08 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:51:09 revo tvheadend[1170]: eit: begin processing
Nov  1 17:54:01 revo tvheadend[1170]: epg: expire event 653457 from 10382
Nov  1 17:54:01 revo tvheadend[1170]: epg: now/next 653459/654282 set on 10382
Nov  1 17:54:01 revo tvheadend[1170]: epg: arm channel timer @ 1351792800 for 10382
Nov  1 17:54:01 revo tvheadend[1170]: epg: inform HTSP of now event change on 10382
Nov  1 17:55:00 revo ntpd[1561]: bind(21) AF_INET6 fe80::d2df:9aff:fe75:41f6%3#123 flags 0x11 failed: Cannot assign requested address
Nov  1 17:55:00 revo ntpd[1561]: unable to create socket on wlan0 (226) for fe80::d2df:9aff:fe75:41f6#123
Nov  1 17:55:00 revo ntpd[1561]: failed to init interface for address fe80::d2df:9aff:fe75:41f6
Nov  1 17:55:00 revo tvheadend[1170]: epg: expire event 653707 from CITV

... which are unrelated.

Any thoughts, anyone? It's making tvheadend very unreliable for me, which isn't good at all, but I don't know if it's my hardware, the firmware/drivers, or the tvheadend code - it's all changed too much recently (except the hardware, which used to work fine).

And yes, I'm getting so many problems recording Power Rangers for the kids, I might just buy the DVDs... :)