Tvheadend

I'd be dangerous to myself if I ever stopped to think...

I'm going the wrong way here. I checked the file (kind of obvious, perhaps...) and it is, indeed, the beginning of the file I recorded, not the end - just as I've had before. But the "work backwards 11:11 from the end of the log" is the wrong way, I need to look 11:11 into the log. But the "no descrambler" could be a total red herring.

Still nothing really relevant, though... if the recording started at 17:28:30, I'd expect something at around 17:39:41, plus or minus a bit - and all I have is this:

Nov  1 17:35:01 revo tvheadend[1170]: epg: now/next 675950/1725812 set on mta-muslim tv
Nov  1 17:35:01 revo tvheadend[1170]: epg: arm channel timer @ 1351792800 for mta-muslim tv
Nov  1 17:35:01 revo tvheadend[1170]: epg: inform HTSP of now event change on mta-muslim tv
Nov  1 17:35:01 revo tvheadend[1170]: epg: expire event 699477 from 3e
Nov  1 17:35:01 revo tvheadend[1170]: epg: now/next 699479/662290 set on 3e
Nov  1 17:35:01 revo tvheadend[1170]: epg: arm channel timer @ 1351792800 for 3e
Nov  1 17:35:01 revo tvheadend[1170]: epg: inform HTSP of now event change on 3e
Nov  1 17:39:47 revo tvheadend[1170]: eit: processing complete
Nov  1 17:39:47 revo tvheadend[1170]: uk_freesat: processing complete
Nov  1 17:39:47 revo tvheadend[1170]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 522,000 kHz" (Autoscan)
Nov  1 17:39:47 revo tvheadend[1170]: uk_freesat: install table handlers
Nov  1 17:39:47 revo tvheadend[1170]: eit: install table handlers
Nov  1 17:39:48 revo tvheadend[1170]: eit: begin processing
Nov  1 17:40: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:40:00 revo ntpd[1561]: unable to create socket on wlan0 (223) for fe80::d2df:9aff:fe75:41f6#123
Nov  1 17:40:00 revo ntpd[1561]: failed to init interface for address fe80::d2df:9aff:fe75:41f6
Nov  1 17:40:00 revo tvheadend[1170]: epg: expire event 674250 from CommunityChnl
Nov  1 17:40:00 revo tvheadend[1170]: epg: now/next 674252/694205 set on CommunityChnl
Nov  1 17:40:00 revo tvheadend[1170]: epg: arm channel timer @ 1351792800 for CommunityChnl
Nov  1 17:40:00 revo tvheadend[1170]: epg: inform HTSP of now event change on CommunityChnl

Sooo... unless the uk_freesat message means that tvheadend interrupted itself? I can suspect that I never had this problem using XMLTV as the EPG, and only have had it since I switched to OTA with the later versions, but I'd be guessing at that...

Still worth noting that the timestamp on the file and the log both suggest that the file wasn't closed until the end of the recording - it's just that nothing was written to it after the first 11 minutes.

I've just updated everything that moves - kernel, TBS drivers, NVidia drivers (yeah, I know they're hardly related, but you know what updating them is like...), so let's see.

But any thoughts, anyone? ... anyone ... Bueller ... anyone ...?

I very much doubt the OTA stuff is related, this should be fairly well protected from the recording/DVB stream code. The only possible link might be if the scheduling appeared to change, but I doubt that's the case.

However it would be useful to know if this is 3.2 or master? ANd if its master are you using full mux RX?

How regularly is this happening? The only time I've seen anything like this is I enabled full mux dump debug option (as I needed to capture a full stream for testing) and I noticed that on a couple of occasions my card appeared to stop streaming data. Restarting TVH appeared to fix the problem in this case, so that could have been a TVH issue I'm not sure.

Adam

3.2 - but it's been apparent since around 2.99 - it certainly never happened on 2.12 with basically the same setup.

How often... once every six to eight recordings, perhaps? Enough to not really trust it - I wouldn't leave it for a week and expect it to work for everything scheduled, for example. I've seen it on a couple of channels (Kix!, More 4, perhaps 5 as well), which is why I originally started trying to record normal and timeshifted, to give myself two bites of the cherry...

I must admit I really don't get it, certainly I record a lot of stuff now using 3.2 (all my series links are done via TVH). Admittedly this is limited to a few channels (mostly BBC One HD and BBC HD) but I've not missed anything yet and there isn't a mass deluge of posts saying recordings are broken.

Therefore I thikn there is something specific about your system (though I'm not saying TVH isn't to blame). I'll try and think of some tests we can perform.

Adam

Thanks - I can blow away the whole lot if need be, it won't take long to rebuild. It's infuriating that there's just no relevant information... could we perhaps add some more debugging, and I'll switch to master as my main install accordingly? I'd need to install it over 3.2 (I've only run it independently so far), but I presume a simple make install would sort that out.

Trust me, I've been using tvh for a long time (having already died at the altar of Myth, VDR and yaVDR beforehand ), I've played with 4TR and Windows, and I really have no desire to fight again with any other backend - especially on Windows, the whole package is just far too heavy for a simple ION system. You've been doing fabulous work to resurrect Andreas' original project, and many people are very grateful - tvheadend remains the simplest, most elegant by far - so I'll gladly wrestle with this further.

Don't use make install, please (or you'll suffer my wrath!). Better to run it locally ./build.linux/tvheadend etc.. if your testing and to build a deb (or other package) if you need to install it permanently (./Autobuild.sh t precise[amd64|i386]). See Packaging for details.

I'm sure we can find a solution to this and maybe it relates to some of the stuff I'm about to fix, though I'm not sure as this looks slightly different.

Adam

Just to let you know that I've updated everything that moves (plus some things that don't) - NVidia drivers, kernel, TBS drivers, and tvheadend (to 3.2.18~g40a8920~oneiric). So far, the whole system seems more stable, but I've lined up a whole host of repeat recordings just to give it a work out... let's see.

Well, the system is undoubtedly more stable since the updates (I had terrible problems with system lockups/crashes), but I just missed half a recording last night. No worries, I'm padding the schedule with things I really don't want, so life goes on for this one.

Just to keep a record - this was 22:00-00:05, +1 start/+5 end, recorded 1:16:19 (so died around 23:15:19). First half only recorded. Log entries at this point only point to normal activity:

Nov  8 23:14:49 revo tvheadend[2045]: dvb: "/dev/dvb/adapter0" tuning to "ASTRA: 482,200 kHz" (Autoscan)
Nov  8 23:14:49 revo tvheadend[2045]: uk_freesat: install table handlers
Nov  8 23:14:49 revo tvheadend[2045]: eit: install table handlers
Nov  8 23:15:01 revo tvheadend[2045]: epg: expire event 2165302 from theDealchannel
Nov  8 23:15:01 revo tvheadend[2045]: epg: now/next 2165304/2165306 set on theDealchannel
Nov  8 23:15:01 revo tvheadend[2045]: epg: arm channel timer @ 1352417400 for theDealchannel
Nov  8 23:15:01 revo tvheadend[2045]: epg: inform HTSP of now event change on theDealchannel
Nov  8 23:15:01 revo tvheadend[2045]: epg: expire event 1752802 from Argos TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: now/next 1752804/1752806 set on Argos TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: arm channel timer @ 1352417400 for Argos TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: inform HTSP of now event change on Argos TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: expire event 2183196 from Sikh Channel
Nov  8 23:15:01 revo tvheadend[2045]: epg: now/next 2183198/2189144 set on Sikh Channel
Nov  8 23:15:01 revo tvheadend[2045]: epg: arm channel timer @ 1352420100 for Sikh Channel
Nov  8 23:15:01 revo tvheadend[2045]: epg: inform HTSP of now event change on Sikh Channel
Nov  8 23:15:01 revo tvheadend[2045]: epg: expire event 2155415 from Pick TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: now/next 2155418/2155421 set on Pick TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: arm channel timer @ 1352418600 for Pick TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: inform HTSP of now event change on Pick TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: expire event 1790616 from PICK TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: now/next 1790618/1790620 set on PICK TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: arm channel timer @ 1352418600 for PICK TV
Nov  8 23:15:01 revo tvheadend[2045]: epg: inform HTSP of now event change on PICK TV
Nov  8 23:15:09 revo tvheadend[2045]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 498,000 kHz" (Autoscan)
Nov  8 23:15:09 revo tvheadend[2045]: uk_freesat: install table handlers
Nov  8 23:15:09 revo tvheadend[2045]: eit: install table handlers
Nov  8 23:15:10 revo tvheadend[2045]: eit: begin processing
Nov  8 23:15:30 revo tvheadend[2045]: eit: processing cancelled
Nov  8 23:15:30 revo tvheadend[2045]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 522,000 kHz" (Autoscan)
Nov  8 23:15:30 revo tvheadend[2045]: uk_freesat: install table handlers
Nov  8 23:15:30 revo tvheadend[2045]: eit: install table handlers
Nov  8 23:15:30 revo tvheadend[2045]: eit: begin processing
Nov  8 23:15:50 revo tvheadend[2045]: eit: processing cancelled
Nov  8 23:15:50 revo tvheadend[2045]: dvb: "/dev/dvb/adapter0" tuning to "Gloucestershire: 530,000 kHz" (Autoscan)
Nov  8 23:15:50 revo tvheadend[2045]: uk_freesat: install table handlers
Nov  8 23:15:50 revo tvheadend[2045]: eit: install table handlers
Nov  8 23:15:50 revo tvheadend[2045]: eit: begin processing
Nov  8 23:16:10 revo tvheadend[2045]: eit: processing cancelled

The autoscan messages relate to my DVB-T tuner.

The recording (such as it was!) was my TBS QBox 2 DVB-S2 running drivers v121021. Kernel 3.0.0-26 on XBMCBuntu (11.10/oneiric). Ample disc space.

Channel was Channel 4+1. Log file reports correct end-of-file at 00:10 as predicted.

I'll now try to actively record things on different tuners to see if that makes any difference.

Some observations after some saturation testing over the last 24 hours...

1. I reduced the priority of my tuners - I had the DVB-S as higher priority, i.e. I'd added 50 to the DVB-T priority to make it lower). I made them equal.

I thought that this had perhaps fixed the problem, but I still got one failure - which is perhaps less than I'd expect, though.

2. I had one failure yesterday.

This was on Dave (a channel I hadn't had issues with before). So it's not strictly channel-dependent.

3. Dave is only on Freeview, so that rules out the DVB-S tuner

... and thus rules out the TBS hardware and drivers to my mind.

4. As normal, I've got a whole host of EIT update messages at around the time the file stopped recording. That said, there are always a lot of EIT messages, so I can't say that's relevant.

5. As normal, the log file reports that tvheadend think that the recording ran its course - so I have the "Completed OK" at 15:05, even though the file had stopped at around 14:45.

6. I had another programme scheduled to record on the same channel - so same tuner - immediately afterwards (starting at 15:00). This failed, and reports as "time missed".

I don't know if this is behaviour as intended... I'd presumed that the second recording would happily start while the first was still running, as there's no channel change let alone a mux change. But it's possible that this is irrelevant if back-to-back recordings aren't meant to/able to work normally.. I'll test this by recording something else back-to-back to see.

7. The log file shows that this second recording started on time ("recorder starting", "subscribing on...")... it's only when I get to the end of that programme (16:05) that the log file shows "time missed". Otherwise, the machine thinks it recorded okay, although no file was created, and there's no log message to suggest it tried (i.e. no "... Using for recording" message).

Random thoughts:

• Could something have locked that tuner so the second recording thread couldn't pick it up? Certainly the "nothing can talk to the tuner" would explain the disappearance of the first recorded stream and the failure of the second.

• Could this be the EIT update, since that goes off and tries to scan other channels? I may revert to XMLTV to see if that changes anything.

• I'm happy that I've eliminated the tuners themselves. It's possible that it's a USB issue, though, since they're both on USB connections. To eliminate further, I'd need to try (a) a different backend to see if I get anything like the same behaviour (too much change, likely to be inconclusive) and (b) a different connection method (only practical to try a different port, so again likely to be inconclusive).

Thoughts continue...

Nope, back-to-back recordings on the same channel appear to work fine. So the fact that the second recording above couldn't start is almost certainly related to the loss of transport signal/whatever for the first recording.

Nothing in kern.log or syslog about USB devices, though, so the system thinks they've stayed connected throughout (which they have). Nothing else on this system that should be trying to access the tuners - no other backend software, for example.

Another random thought: power saving, even if the devices were in use? Any kind of power saving log other than pm-powersave.log, which says nothing about anything from what I can see?

lsusb tells me nothing, even in verbose mode... any way of seeing if these devices have been "disconnected" in some way?

Okay, switched off OTA EPG and went back to XMLTV... recorded something like eight programmes back-to-back on the same channel - hopes well up - and then the next failed, same issue as before: it apparently made no effort to even create the file (nothing in the log, nothing in the target directory). So I have a hard disk full of Red Dwarf and Top Gear reruns for now reason :).

It's now moved on to the next programme but, again, I've nothing in the log to say that it's actually created the file, so I expect this one to fail as well. This is the first failure beginning - note nothing about creating the file, nothing about the streams being recorded. Programme scheduled for 18:00 with 1 minute lead time:

Nov 11 17:58:31 revo tvheadend[2045]: dvr: "Red Dwarf II" on "Dave" recorder starting
Nov 11 17:58:31 revo tvheadend[2045]: Service: Subscription "DVR: Red Dwarf II": Adding adapter "_dev_dvb_adapter0_DiBcom_7000PC498000000" for service "DiBcom 7000PC/Gloucestershire: 498,000 kHz/Dave" 
Nov 11 17:58:31 revo tvheadend[2045]: subscription: "DVR: Red Dwarf II" subscribing on "Dave", weight: 300, adapter: "DiBcom 7000PC", network: "Gloucestershire", mux: "Gloucestershire: 498,000 kHz", provider: "", service: "Dave", quality: 100
Nov 11 17:58:43 revo kernel: [607578.612466] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov 11 17:58:43 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "12,596,000 kHz Vertical (No satconf)" (1996000, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Nov 11 17:58:49 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Bad signal
Nov 11 17:58:50 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Faint signal
Nov 11 17:58:51 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Bad signal
Nov 11 17:58:52 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Faint signal
Nov 11 17:58:53 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Bad signal
Nov 11 17:58:54 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Faint signal
Nov 11 17:58:58 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Bad signal
Nov 11 17:58:59 revo tvheadend[2045]: dvb: "12,596,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Faint signal
Nov 11 17:59:00 revo tvheadend[2045]: epg: expire event 2088576 from ?TV
Nov 11 17:59:00 revo tvheadend[2045]: epg: now/next 2134506/2179991 set on ?TV
Nov 11 17:59:00 revo tvheadend[2045]: epg: arm channel timer @ 1352678340 for ?TV
Nov 11 17:59:00 revo tvheadend[2045]: epg: inform HTSP of now event change on ?TV
Nov 11 17:59:03 revo kernel: [607599.160827] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov 11 17:59:04 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 11,343,000 kHz Vertical (No satconf)" (1593000, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Nov 11 17:59:23 revo kernel: [607618.792536] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov 11 17:59:23 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "12,629,000 kHz Vertical (No satconf)" (2029000, 6111000 Baud, 3/4, SYS_DVBS, QPSK) for Autoscan
Nov 11 17:59:40 revo tvheadend[2045]: dvb: "12,629,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Bad signal
Nov 11 17:59:41 revo tvheadend[2045]: dvb: "12,629,000 kHz Vertical (No satconf)" on adapter "Conexant CX24116/CX24118", status changed to Faint signal
Nov 11 17:59:44 revo kernel: [607639.404499] tbsqboxs2: tbsqboxs2_set_voltage 1
Nov 11 17:59:44 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 12,606,650 kHz Horizontal (No satconf)" (2006650, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Nov 11 18:00:01 revo tvheadend[2045]: epg: expire event 2153053 from Premier Radio
Nov 11 18:00:01 revo tvheadend[2045]: epg: now/next 2153131/2153133 set on Premier Radio
Nov 11 18:00:01 revo tvheadend[2045]: epg: arm channel timer @ 1352660400 for Premier Radio
Nov 11 18:00:01 revo tvheadend[2045]: epg: inform HTSP of now event change on Premier Radio

... this is where the next one kicks off - again, no mention of the file being created or of the streams - 18:40, same 1 minute lead time:

Nov 11 18:38:30 revo tvheadend[2045]: dvr: "Red Dwarf II" on "Dave" recorder starting
Nov 11 18:38:30 revo tvheadend[2045]: Service: Subscription "DVR: Red Dwarf II": Adding adapter "_dev_dvb_adapter0_DiBcom_7000PC498000000" for service "DiBcom 7000PC/Gloucestershire: 498,000 kHz/Dave" 
Nov 11 18:38:30 revo tvheadend[2045]: subscription: "DVR: Red Dwarf II" subscribing on "Dave", weight: 300, adapter: "DiBcom 7000PC", network: "Gloucestershire", mux: "Gloucestershire: 498,000 kHz", provider: "", service: "Dave", quality: 100
Nov 11 18:38:42 revo kernel: [609977.837000] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov 11 18:38:43 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 11,426,000 kHz Vertical (No satconf)" (1676000, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Nov 11 18:39:03 revo kernel: [609998.637393] tbsqboxs2: tbsqboxs2_set_voltage 1
Nov 11 18:39:03 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "11,023,250 kHz Horizontal (No satconf)" (1273250, 23000000 Baud, 2/3, SYS_DVBS2, QPSK) for Autoscan
Nov 11 18:39:23 revo kernel: [610018.648795] tbsqboxs2: tbsqboxs2_set_voltage 1
Nov 11 18:39:23 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 11,584,620 kHz Horizontal (No satconf)" (1834620, 27500000 Baud, 2/3, SYS_DVBS, QPSK) for Autoscan
Nov 11 18:39:44 revo kernel: [610039.341391] tbsqboxs2: tbsqboxs2_set_voltage 0
Nov 11 18:39:44 revo tvheadend[2045]: dvb: "/dev/dvb/adapter1" tuning via s2api to "ASTRA: 12,363,000 kHz Vertical (No satconf)" (1763000, 29500000 Baud, 3/4, SYS_DVBS2, QPSK) for Autoscan
Nov 11 18:40:01 revo tvheadend[2045]: epg: expire event 1993792 from POP
Nov 11 18:40:01 revo tvheadend[2045]: epg: now/next 1993794/1993796 set on POP
Nov 11 18:40:01 revo tvheadend[2045]: epg: arm channel timer @ 1352659800 for POP
Nov 11 18:40:01 revo tvheadend[2045]: epg: inform HTSP of now event change on POP

... and this is the end of the first one, five minutes after programme completion as scheduled (so 18:40 + 5 minutes):

Nov 11 18:45:00 revo tvheadend[2045]: subscription: "DVR: Red Dwarf II" unsubscribing from "Dave" 
Nov 11 18:45:00 revo tvheadend[2045]: dvr: "Red Dwarf II" on "Dave": End of program: Time missed

Compare that to a successful recording earlier:

Nov 11 13:58:30 revo tvheadend[2045]: dvr: "Red Dwarf II" on "Dave" recorder starting
Nov 11 13:58:30 revo tvheadend[2045]: Service: Subscription "DVR: Red Dwarf II": Adding adapter "_dev_dvb_adapter0_DiBcom_7000PC498000000" for service "DiBcom 7000PC/Gloucestershire: 498,000 kHz/Dave" 
Nov 11 13:58:30 revo tvheadend[2045]: subscription: "DVR: Red Dwarf II" subscribing on "Dave", weight: 300, adapter: "DiBcom 7000PC", network: "Gloucestershire", mux: "Gloucestershire: 498,000 kHz", provider: "", service: "Dave", quality: 100
Nov 11 13:58:35 revo tvheadend[2045]: dvr: File "/home/xbmc/Recordings/Red Dwarf II.2012-11-11.14-00.mkv" -- No such file or directory -- Using for recording
Nov 11 13:58:35 revo tvheadend[2045]: dvr: /home/xbmc/Recordings/Red Dwarf II.2012-11-11.14-00.mkv from adapter: "DiBcom 7000PC", network: "Gloucestershire", mux: "Gloucestershire: 498,000 kHz", provider: "", service: "Dave" 
Nov 11 13:58:35 revo tvheadend[2045]: dvr:  # type                 lang resolution       samplerate channels
Nov 11 13:58:35 revo tvheadend[2045]: dvr:  1 MPEG2VIDEO                544 x 576
Nov 11 13:58:35 revo tvheadend[2045]: dvr:  2 MPEG2AUDIO           eng                   48000      2
Nov 11 13:58:35 revo tvheadend[2045]: dvr:  3 MPEG2AUDIO           eng                   48000      1
Nov 11 13:58:35 revo tvheadend[2045]: dvr:  4 DVBSUB               eng

... and it seems that either the streams just disappear or the file-writing routine doesn't kick off. Could it be that this is what's happening while writing to the file, it just fails to get a stream or just gives up writing until it closes the file??

Are these two faults even related - a programme stopping halfway through, and a programme not even starting in the first place when scheduled back-to-back?

Do you have debug enabled? It looks like you don't to me, but I might be wrong.

I think the fact that it suddenly stops recording and then fails to record from that point on is interesting. Do you know if you ever manage to get anything again from that tuner without restarting TVH?

Also do you have close FDs enabled?

This all sounds very much like the old TBS bug, except there is now an error message should the DVR thread exit, so I think this must be something different. Though the outward symptons seems similar.

Can you attach full debug logs when you get problems, they are more useful for the purpose of debugging etc.. Though annotated snippets can help to show where the points of failure are etc...

Adam

Thanks, Adam... I'm going to beat this to death if it's the last thing I do ...

I think I have debug enabled - humour me and tell me how, just to make sure. I've certainly got TVH_DEBUG=1 in /etc/default/tvheadend, so is there anything more? Or do you mean a gdb trace?

Re: do I get anything more... yes, I have in the past, but only after "a rest". I'm going to keep plugging this tuner for a while, then let it pause, then start recording again, just to see what happens.

Re: close FDs... lost me there... file descriptors? Isn't that something that the code would be doing? Or do you suspect that I'm running out in some way? I'll Google it, but any hints appreciated here...

Re: TBS... except that this isn't a TBS card I'm using here, I'm relying on built-in kernel support. So unless the very presence of a TBS card somehow upsets things...

Re: full debug logs - sure, I know I'm just annotating, but until I get some consistency I thought I'd save the pastebin space! All I have is syslogs at the moment, unless tvh is creating a separate debug log elsewhere?

No, if you have TVH_DEBUG=1 then its most probably on and I'm just not paying attention. I've been busy for a few days so my INBOX is overflowing!

hmm, I was hoping you were gonna say no signal completely disappears

Close FDs - if you don't know what I'm talking about you don't have it enabled The only reason I ask is this causes the DVB input thread to terminate and get restarted (potentially) on each re-tune. Which "could" allow the above to still happen but eventually recover. But I think this is probably a dead-end.

TBS - no sure, the BUG wasn't actually TBS specific (just TBS drivers seemed particularly prone). And again if it recovers likelihood is that particular issue is not what you're experiencing.

Attach the logs straight here or pastebin doesn't really matter. But full logs are always better as there might be something that to you is unrelated/innocuous and to me (or someone else) means something. TVH doesn't create its own log so only syslog (or pipe to file). If you're worried about posting a full syslog, just "grep tvheadend" out of it.

Adam

Yeah, I'm aware you get copied on every one of these mindless posts of mine and everyone else's, so I thank you again for the attention.

Let me monitor it tonight to see if it resurrects itself... the last programme failed again, although it died after 5 minutes this time. The tuner is idle for now, so let's see as the next scheduled event kicks in.

Close FDs... okay, that makes sense. No, I'm not forcing anything shut, that'd be rude to a poor process that's just going about its business.

Full grep'ed syslog... not that it's secret, it just makes the following a little shorter...

• EDIT

Doesn't look this forum can cope with the full paste, and pastebin is complaining of the length as well, so I'll borrow XBM Clogs... I'm sure they won't mind.

• EDIT 2

Nope, xbmclogs can't cope with it either! It's only 19,000 lines, I don't know why they're stuggling, I've seen worse... I might have to email it to you.

Yeah better to attach full logs rather than post in line But I'll forgive you this tiem since I asked for it :p

Adam

Yes, you did

http://xbmclogs.com/show.php?id=14272

Last one for tonight... the full log for today.

http://xbmclogs.com/show.php?id=14281

Let me monitor it tonight to see if it resurrects itself... the last programme failed again, although it died after 5 minutes this time. The tuner is idle for now, so let's see as the next scheduled event kicks in.

And yes, after a bit of a rest, the tuner carried on recording correctly without a restart. The last two recordings worked fine.

FYI, I am seeing the same effect. The difference is that all of my recordings are too short. They seem to stop recording after just a few minutes. My system is very basic and very underpowered. The linux box is a Pogoplug with an ARM processor. The tuner is a single tuner HDHOMERUN. Therefore, I can never record more than one show at a time. Thus far, I have not been able to record a full show, so the linux box is only doing one task, aka recording. (It is not recording and streaming back at the same time.) Below are some of the output from the system. The tuner is configured and is working OK. There are no bad tuner events. The recording starts and then after a couple of minutes the mkv file on the hd quits growing. After the recording completes, then the time stamp of the mkv file updates also.

If I record using the "Add Entry" of the Recorder Schedule, then I also often get the "cannot write meta data" message. On the data below, you can see that I did not get that message and there appears to be nothing abnormal. Since it happens very frequently for me, if you tell me what debug you want enabled and what logs you would like to see, I can run some experiments.

I am running version 3.2.18.
Thanks.
---- Steve

Nov 14 21:22:35 [INFO]:dvr: "Nashville" on "1511 KVUEDT (ABC)" starting at 2012-11-14 20:55:00, scheduled for recording by "steve"
Nov 14 21:22:36 [INFO]:dvr: "Nashville" on "1511 KVUEDT (ABC)" recorder starting
Nov 14 21:22:36 [INFO]:subscription: "DVR: Nashville" subscribing on "1511 KVUEDT (ABC)", weight: 300, adapter: "HDHomeRun ATSC", network: "<N/A>", mux: "219,000 kHz", provider: "<N/A>", service: "<N/A>", quality: 100
Nov 14 21:22:37 [INFO]:dvr: /mnt/myhd1/Pogo_stuff/Recordings/Nashville.mkv from adapter: "HDHomeRun ATSC", network: "<N/A>", mux: "219,000 kHz", provider: "<N/A>", service: "<N/A>"
Nov 14 21:22:37 [INFO]:dvr: # type lang resolution samplerate channels
Nov 14 21:22:37 [INFO]:dvr: 1 MPEG2VIDEO 1920 x 1080
Nov 14 21:22:37 [INFO]:dvr: 2 AC3 eng 48000 5.1
Nov 14 22:05:00 [INFO]:subscription: "DVR: Nashville" unsubscribing from "1511 KVUEDT (ABC)"
Nov 14 22:05:00 [INFO]:dvr: Recording completed: "/mnt/myhd1/Pogo_stuff/Recordings/Nashville.mkv"
Nov 14 22:05:00 [INFO]:dvr: "Nashville" on "1511 KVUEDT (ABC)": End of program: Completed OK

[root@alarm Recordings]# date
Wed Nov 14 21:38:26 CST 2012
[root@alarm Recordings]# ls -l
total 173664
-rwxr-xr-x 1 root root 177830104 Nov 14 21:24 Nashville.mkv
[root@alarm Recordings]# ls -l
total 173664
-rwxr-xr-x 1 root root 177830104 Nov 14 21:24 Nashville.mkv
[root@alarm Recordings]# ls -l
total 173664
-rwxr-xr-x 1 root root 177830104 Nov 14 21:24 Nashville.mkv
[root@alarm Recordings]# ls -l
total 173664
-rwxr-xr-x 1 root root 177830104 Nov 14 21:24 Nashville.mkv
[root@alarm Recordings]# date
Wed Nov 14 22:07:33 CST 2012
[root@alarm Recordings]# ls -l
total 173952
-rwxr-xr-x 1 root root 178124581 Nov 14 22:05 Nashville.mkv
[root@alarm Recordings]#

OK, somehow I got the debug enabled. I ran a short timer recordings. Attached is a text file of the log data and the directory list on the storage location. Notice a couple of things.

1. I got the "Unable to write meta data".

2. However, the file was being written. About 30 seconds later the writing to the HD stopped.

3. At the same time the writing to the HD stopped, I got a message of " expire event 783 from 1531 KEYEDT (CBS)" This is the channel I am recording.

----- Steve

I ran two more tests this morning. Attached is the same log file and directory listing that I showed earlier. The log seem funny. Even though I have debug enabled, the level of printouts seem to vary. Sometimes I lots of stuff and other times nothing but the normal messages. When I did not get the expected chatter, I toggle the debug "gear" briefly to make sure it was enabled. These were 10 minute time recordings. There is 5 minutes of padding on each end. The tuner is turned on 5 minutes and 30 seconds early. (I guess the extra 30 seconds is to allow it to find the network.)
Note that the directory listing has three 10 minute time recordings from the same channel source. All three are too short, but have significantly different lengths. Therefore, it seems to stop writing to the disk at varying times.

----- Steve

I set the pre and post extra time from 5 minutes to 0 minutes as a test. On the first recording that I attempted, it failed to start creating the output file. The tuner was properly configured, it just forgot to start saving data. Then at the end of the recording, it complained that it was too late to record anything. I tried it again, and the next time, I got a partial file with only the very beginning of the recording. Attached is the log of these events.

Adam Bark and team - any ideas where we take this next? Is there something more specific we can be looking for, any code to maybe see what's happening in the file create/write-to-file routines? I'll see if I can make any sense of the code, but I fear I'll be floundering...

Thanks,

Ian

I suspect that we've got more information on the following thread, so let's switch to that one and save running things in parallel:

http://www.lonelycoder.com/redmine/boards/5/topics/6540

Looks like Mr Miller is already well into poking around in the code.

Hi - I can't get the link to the "parallel" thread to work, so find it by searching... I expect after five years, things may have migrated and broken.

I know this is SOOO old a thread (sorry to post on it) but I've been reading it, hoping it might give some clues to a similar problem I'm having.

Is there a chance someone could point me to the other "really old" thread please, so I can continue reading the story (in the hope it might help)?

Thanks!