Page 1 of 1

Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Tue Sep 24, 2019 9:21 pm
by devnull
Hello all!

tl;dr recorder fails at some point after starting, logs don't show much, but truncated logs below.

I have MythTV set up with a Hauppauge 950Q USB tuner, hooked up to an antenna to capture local broadcasts. So far all is well except for recordings.

Occasionally, recordings will fail (around 80% of the time). I do not know why, and it doesn't seem related to a specific show. There's no specific place when it fails, but invariably, it just won't capture the entire episode, and MythTV marks the recording as failed.

Here are relevant logs from yesterday when I made a couple recordings:

The Good Doctor, recorded 9:52 out of 60 minutes

Code: Select all

Sep 23 22:00:05 media mythbackend: mythbackend[21652]: I Scheduler scheduler.cpp:2934 (HandleRecordingStatusChange) Tuning recording: "The Good Doctor":Disaster: channel 10901 on cardid [1], sourceid 1
Sep 23 22:00:06 media mythbackend: mythbackend[21652]: I CoreContext scheduler.cpp:729 (UpdateRecStatus) Updating status for "The Good Doctor":Disaster on cardid [1] (Tuning => Recording)
Sep 23 22:00:06 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:4231 (TuningNewRecorder) TVRec[1]: rec->GetPathname(): '/home/media/Recordings/10901_20190924020000.ts'
Sep 23 22:00:06 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:4263 (TuningNewRecorder) TVRec[1]: TuningNewRecorder - CreateRecorder()
Sep 23 22:02:32 media mythbackend: mythbackend[21652]: N Expire autoexpire.cpp:261 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
Sep 23 22:16:32 media mythbackend: mythbackend[21652]: N Expire autoexpire.cpp:261 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min

... truncated ...

Sep 23 23:00:00 media mythbackend: mythbackend[21652]: I CoreContext scheduler.cpp:729 (UpdateRecStatus) Updating status for "The Good Doctor":Disaster on cardid [1] (Recording => Recorder Failed)
Sep 23 23:00:00 media mythbackend: mythbackend[21652]: I Scheduler scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK -9 8 0 UpdateRecStatus2 | The Good Doctor | Disaster | Following what he believes was a disastrous first date with Carly, Dr. Shaun Murphy proposes a radical surgery to save a newlywed woman's life; Dr. Morgan Reznick and Dr. Alex Park compete for the chance to operate on an elderly patient. | EP026966280039
Unfortunately there doesn't seem to be anything logged at 22:09:52, which is when the recording failed, but something I did notice was that there are calls to autoexpire.cpp around that time period.

Because I noticed this pattern earlier, I had cleared out a bunch of junk from my hard drive and had over 80 GB free, but the episode still failed to record.

The Morning Show, recorded ~50 minutes out of 60

Code: Select all

Sep 24 09:00:00 media mythbackend: mythbackend[21652]: C CoreContext programinfo
.cpp:347 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
Sep 24 09:00:05 media mythbackend: mythbackend[21652]: I Scheduler scheduler.cpp
:2934 (HandleRecordingStatusChange) Tuning recording: "The Morning Show": channel 14101 on cardid [1], sourceid 1
Sep 24 09:00:05 media mythbackend: mythbackend[21652]: I CoreContext scheduler.cpp:729 (UpdateRecStatus) Updating status for "The Morning Show" on cardid [1] (Tuning => Recording)
Sep 24 09:00:05 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:4231 (TuningNewRecorder) TVRec[1]: rec->GetPathname(): '/home/media/Recordings/14101_20190924130000.ts'
Sep 24 09:00:05 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:4263 (TuningNewRecorder) TVRec[1]: TuningNewRecorder - CreateRecorder()

... truncated ...

Sep 24 09:27:30 media mythbackend: mythbackend[21652]: N Expire autoexpire.cpp:2
61 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq
: 14 min
Sep 24 09:41:30 media mythbackend: mythbackend[21652]: N Expire autoexpire.cpp:2
61 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq
: 14 min
Sep 24 09:49:06 media mythbackend: mythbackend[21652]: I MythSocketThread(89) ma
inserver.cpp:7928 (connectionClosed) Playback sock(55ccb62e2ef0) 'media' disconn
ected
Sep 24 09:49:27 media mythbackend: mythbackend[21652]: I MythSocketThread(79) ba
ckendcontext.cpp:97 (SetFrontendDisconnected) BackendContext: Frontend 'media' d
isconnected.
Sep 24 09:49:27 media mythbackend: mythbackend[21652]: I MythSocketThread(79) ma
inserver.cpp:7928 (connectionClosed) Playback sock(55ccb6241db0) 'media' disconn
ected
Sep 24 09:49:27 media mythbackend: mythbackend[21652]: I MythSocketThread(75) ma
inserver.cpp:7928 (connectionClosed) Monitor sock(55ccb6242300) 'media' disconnected
Sep 24 09:55:30 media mythbackend: mythbackend[21652]: N Expire autoexpire.cpp:261 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
Sep 24 10:00:01 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:1091 (HandleStateChange) TVRec[1]: Changing from RecordingOnly to None
Sep 24 10:00:01 media mythbackend: mythbackend[21652]: N RecThread recorders/recorderbase.cpp:507 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (1920x1080 A/R: 3 29.97fps) Audio Codec: ac3
Sep 24 10:00:01 media mythbackend: mythbackend[21652]: I TVRecEvent tv_rec.cpp:864 (FinishedRecording) TVRec[1]: FinishedRecording(14101_2019-09-24T13:00:00Z) damaged recq:<RecordingQuality overall_score="0" key="14101_2019-09-24T13:00:00Z" countinuity_error_count="0" packet_count="38577695">#012    <Gap start="2019-09-24T13:50:43Z" end="2019-09-24T14:00:00Z" duration="556" />#012</RecordingQuality>
Sep 24 10:00:01 media mythbackend: mythbackend[21652]: E CoreContext mainserver.cpp:1199 (customEvent) MainServer: PREVIEW_SUCCESS but no receivers.
Sep 24 10:00:01 media mythbackend: mythbackend[21652]: I CoreContext scheduler.cpp:729 (UpdateRecStatus) Updating status for "The Morning Show" on cardid [1] (Recording => Recorder Failed)
For this show, it was also a scheduled recording, but my wife tuned in to watch it while it was recording. She closed the frontend seemingly around the same time the recording failed as well. Very odd.

Anybody have thoughts on what I should do to debug? The logs don't seem to show enough information (or any at all, really) for the time period when recordings fail.

Thanks in advance!

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Wed Sep 25, 2019 4:37 am
by blm-ubunet
Is it possible that LiveTV was the problem in both cases?

AIUI the H 950Q is only a single tuner (USB stick) & I imagine you have multiple multiplexes (dvb parlance).. if your LiveTV priority is higher than recordings then they get bumped when LiveTV switches to another frequency channel/slot (multiplex).
The new Haupauge quad tuners (T2) are very good in DVB land so long as you have a recent kernel.

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Thu Sep 26, 2019 1:34 am
by devnull
@blm-ubunet thanks for the response! I see you're quite active on this board, the world needs more people like you :D

My setup is a single frontend and backend on the same machine, so I doubt additional requests to the tuner were the issue. I can also confirm no live TV was playing at the time nor were there conflicting scheduled recordings.

However that said, my 950Q is really old! I bought it years and years ago to play with Mythbuntu and when I was done I bounced around the bottom of my junk box for the following years.

A quad tuner sounds like overkill but I'm not as financially strapped as I was back then, so perhaps a new tuner card is the solution 🙂

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Thu Sep 26, 2019 9:01 am
by MikeB2013
What is your version of mythtv ?
For Ubuntu based systems, in a terminal session run :

Code: Select all

mythbackend --version
The reason for asking is to see if your mythtv version is relatively up to date.

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Thu Sep 26, 2019 6:29 pm
by devnull
Hello, thanks for replying. I am using 0.30-fixes, as provided by the MythTV PPA. I was thinking I could update the systemd (or was it an init script) with arguments to enable verbose logging, but am not sure if that would actually provide something to pinpoint the problem, or if it'd just introduce more noise 🙂

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Thu Sep 26, 2019 7:54 pm
by bill6502
I can help with logging. Try: systemctl cat mythtv-backend and you'll see a line
like this: EnvironmentFile=-/etc/mythtv/additional.args. Edit/create that file and add
a line like: ADDITIONAL_ARGS="-v record". Restart the backend for it to take affect.
(the leading minus sign means it's OK if the file doesn't exist)

Or, with the backend running, type: mythbackend --setverbose record. That will
go away if the backend is restarted.

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Thu Sep 26, 2019 8:39 pm
by devnull
Thanks @bill6502, I also see you're very active on the boards, really shows the developers' commitment to the project!

I've enabled verbose logging now, I'll definitely report back if it fails again... or if my quad tuner comes. That's also noteworthy, I suppose.

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Fri Sep 27, 2019 7:34 pm
by devnull
Unsure of whether it was something I did or sheer luck, but in the past day, none of my recordings have failed.

The only change I made was to increase swap (/swapfile) from 2GB to 10.

Re: Recorder fails halfway through recording, but cannot discern reason. Help me debug? :)

Posted: Sun Sep 29, 2019 8:05 pm
by devnull
The quad tuner arrived. As expected, Linux picked it up immediately on boot and I haven't had a failed recording since.

For those interested, summary of changes I made between OP and now.

* Upgraded from Hauppauge WinTV-HVR-950Q to Hauppauge WinTV-quadHD
* Increased swap from 2GB to 10GB
* Installed separate 1TB hard drive and moved recordings directory over to that drive (originally was on system drive)

Unsure which step actually fixed things.