Tvheadend

Folks -

Just wondering if anyone else has seen this... I'll raise a bug if needed, but I'm not sure where to start to nail it down to make the bug specific.

A few times now, I've found that a recording is under-sized. On checking, I find that I've only got part of the programme - normally the start, but I'm sure I've had just the end once or twice. Now, I've always explained it retrospectively as "oh, I must have had something else recording that blocked the tuner". But I'm wrong.

This morning, I had a programme scheduled from 11:00 for 35 minutes. It started, it recorded, it stopped - apparently all well, but the file was too small. Checking the recording, I have something that's only 20:47 long instead of the 38:00 I'd expect (35 + 1 minute leading + 2 minutes trailing).

If I look in syslog, I find:

Oct 13 10:58:30 revo tvheadend[15139]: dvr: "Power Rangers Samurai" on "Channel 5+1" recorder starting
Oct 13 10:58:30 revo kernel: [496927.516351] tbsqboxs2: tbsqboxs2_set_voltage 1
Oct 13 10:58:30 revo tvheadend[15139]: subscription: "DVR: Power Rangers Samurai" subscribing on "Channel 5+1", weight: 300, adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 10,964,250 kHz Horizontal (No satconf)", provider: "BSkyB", service: "Channel 5+1", quality: 100
Oct 13 10:58:31 revo tvheadend[15139]: TS: Conexant CX24116/CX24118/ASTRA: 10,964,250 kHz Horizontal (No satconf)/Channel 5+1: MPEG2VIDEO @ #2321: Continuity counter error
Oct 13 10:58:31 revo tvheadend[15139]: TS: Conexant CX24116/CX24118/ASTRA: 10,964,250 kHz Horizontal (No satconf)/Channel 5+1: MPEG2AUDIO @ #2322: Continuity counter error
Oct 13 10:58:31 revo tvheadend[15139]: TS: Conexant CX24116/CX24118/ASTRA: 10,964,250 kHz Horizontal (No satconf)/Channel 5+1: TELETEXT @ #2324: Continuity counter error
Oct 13 10:58:31 revo tvheadend[15139]: dvr: /home/xbmc/Recordings/Power Rangers Samurai.2012-10-13.11-00.mkv from adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 10,964,250 kHz Horizontal (No satconf)", provider: "BSkyB", service: "Channel 5+1" 
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  # type                 lang resolution       samplerate channels
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  1 MPEG2VIDEO                544 x 576
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  2 MPEG2AUDIO           eng                   48000      2
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  3 MPEG2AUDIO           nar                   48000      2
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  4 TELETEXT             nar                                         <disabled, no valid input>
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  5 DVBSUB               eng         
Oct 13 10:58:31 revo tvheadend[15139]: dvr:  6 TEXTSUB              eng         
Oct 13 11:17:01 revo CRON[17892]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct 13 11:36:00 revo tvheadend[15139]: subscription: "DVR: Power Rangers Samurai" unsubscribing from "Channel 5+1" 
Oct 13 11:36:00 revo tvheadend[15139]: dvr: Recording completed: "/home/xbmc/Recordings/Power Rangers Samurai.2012-10-13.11-00.mkv" 
Oct 13 11:36:00 revo tvheadend[15139]: dvr: "Power Rangers Samurai" on "Channel 5+1": End of program: Completed OK

... so tvheadend thinks that it ran for the full duration (albeit ending a minute earlier than I'd expect, which is a different issue!) - but nearly half of the file is missing.

• The PC was still on, otherwise it couldn't have written to the log file.

• The tuner is still live - I've just recorded something else as a test, plus there's nothing in the logs about any kind of disconnect or reconnect.

• There's plenty of disc space (47Gb free at the moment).

• There were no other recordings scheduled, so it wasn't a tuner clash.

• Nothing else untoward happened to my knowledge - the only oddity is CRON kicking in at about the right time (though not quite, it's about 2 minutes before the recoding borked).

• There's nothing in /etc/cron.hourly anyway, plus /var/spool/cron/crontabs is blank, plus crontab -l and sudo crontab -l confirm that nothing is scheduled - so there shouldn't be anything interrupting that I can see.

• The system clock is fine and accurate (and agrees with the radio-controlled clock I just checked it against).

• There's nothing in any log file I can see to suggest that anything went wrong - no errors about writing to disc, for example, or complaints about the weather.

• The same recording on another channel an hour earlier worked perfectly - still with the cron job kicking in, with pretty-much identical log entries.

Oct 13 09:58:31 revo tvheadend[15139]: dvr: "Power Rangers Samurai" on "Channel 5" recorder starting
Oct 13 09:58:31 revo kernel: [493328.840813] tbsqboxs2: tbsqboxs2_set_voltage 1
Oct 13 09:58:32 revo tvheadend[15139]: subscription: "DVR: Power Rangers Samurai" subscribing on "Channel 5", weight: 300, adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 10,964,250 kHz Horizontal (No satconf)", provider: "BSkyB", service: "Channel 5", quality: 100
Oct 13 09:58:32 revo tvheadend[15139]: TS: Conexant CX24116/CX24118/ASTRA: 10,964,250 kHz Horizontal (No satconf)/Channel 5: MPEG2AUDIO @ #2306: Continuity counter error
Oct 13 09:58:38 revo tvheadend[15139]: dvr: /home/xbmc/Recordings/Power Rangers Samurai.2012-10-13.10-00.mkv from adapter: "Conexant CX24116/CX24118", network: "ASTRA", mux: "ASTRA: 10,964,250 kHz Horizontal (No satconf)", provider: "BSkyB", service: "Channel 5" 
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  # type                 lang resolution       samplerate channels
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  1 MPEG2VIDEO                544 x 576
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  2 MPEG2AUDIO           eng                   96000      0          <disabled, no valid input>
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  3 MPEG2AUDIO           nar                   48000      2
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  4 TELETEXT             nar                                         <disabled, no valid input>
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  5 DVBSUB               eng         
Oct 13 09:58:38 revo tvheadend[15139]: dvr:  6 TEXTSUB              eng         
Oct 13 10:17:01 revo CRON[17347]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct 13 10:36:01 revo tvheadend[15139]: subscription: "DVR: Power Rangers Samurai" unsubscribing from "Channel 5" 
Oct 13 10:36:01 revo tvheadend[15139]: dvr: Recording completed: "/home/xbmc/Recordings/Power Rangers Samurai.2012-10-13.10-00.mkv" 
Oct 13 10:36:01 revo tvheadend[15139]: dvr: "Power Rangers Samurai" on "Channel 5": End of program: Completed OK

System details (it's an upgraded XBMCBuntu installation on an Acer Revo R3600 with a Samsung SSD):

• uname -a: Linux revo 3.0.0-24-generic #40-Ubuntu SMP Tue Jul 24 15:36:59 UTC 2012 i686 i686 i386 GNU/Linux

• tvheadend: 3.1.769~g4303374~oneiric

• xbmc (FWIW - unrelated more than likely): is reporting as "unknown", but it's the latest Pulse8 version, and the web page declares this as 11.0-pvr build 100, git rev. a6df109.

It's random, so it's hard to even nail it down to a particular tuner (I have DVB-T and DVB-S - this happened on the latter, but I can't say if that's always the case).

Thoughts? Any clues or suggestions? Any way of enabling more detailed debugging to see what's going on, perhaps? I've taken to recording things multiple times (on the original and the +1 channel, for example, as you see here), just to be sure, which clearly isn't good...

EDIT ** *

Okay, a bit more... I've just watched it do it again. I had a programme on More4 scheduled from 21:00-22:05.

Again, it was on my DVB-S (TBS) card - although this is my preferred card, so it's what I'd expect.

What I noticed is that I was unable to schedule a new recording... I was actually just trying to schedule the +1 version before 22:00 because of my post above! Anyway, I tried, but I could click whatever I liked in the web interface, and nothing would get scheduled. Turning debugging on in the web interface, and nothing appeared - almost like the mouse click never happened.

Switching to ssh, I could see that the file timestamp of the current recording had stopped at 21:49 - as the minutes passed, it didn't update, nor did it get any bigger (it stopped at 942,504,923).

Finally, I had the log messages that the programme had ended and the recording stopped - only then did the timestamp update to 22:06 (so one minute after the programme end - again, I have +2 set in preferences, but at least it was after the scheduled end! NOTE found this issue, raised bug 1327) and the file size changed ever so slightly (to 942,974,269 - so 458Kb larger - except I'd expect another 300Mb for the missing 15 minutes).

Checking the file immediately, I did indeed have a 50ish minute file instead of the 65-to-68 minutes expected.

Interestingly, I still couldn't schedule a new recording - until I stopped and restarted tvheadend, and then all was well again...

EDIT 2 ** *

I give up. This is just too frustrating.

The programme is on again at 01:40 tomorrow morning. I've scheduled that to record.

However, it's also on again now - on More4+1. Unfortunately, the moment I try to record what's showing now, tvheadend deletes the 01:40 recording from the schedule.

Restarting the system, and starting it recording now... okay, seems to be working... except I can't now schedule the 01:40 version, tvh is ignoring that one again! So I need to wait for the current programme to end, then schedule the one that's later... perhaps...

I'm now desperately trying to find where tvh stores the schedule to see if I can enter it manually, but this is just too frustrating for words...