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

Have a MythTV related problem? Ask for help from other MythTV users here.

Moderator: Forum Moderators

Post Reply
devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Tue Sep 24, 2019 9:21 pm

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!

blm-ubunet
Senior
Posts: 125
Joined: Sun Jun 15, 2014 1:08 am
Cambodia

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

Post by blm-ubunet » Wed Sep 25, 2019 4:37 am

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.

devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Thu Sep 26, 2019 1:34 am

@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 🙂

MikeB2013
Senior
Posts: 519
Joined: Mon Jul 25, 2016 4:16 pm
Great Britain

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

Post by MikeB2013 » Thu Sep 26, 2019 9:01 am

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.

devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Thu Sep 26, 2019 6:29 pm

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 🙂

User avatar
bill6502
Developer
Posts: 1782
Joined: Fri Feb 07, 2014 5:28 pm
United States of America

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

Post by bill6502 » Thu Sep 26, 2019 7:54 pm

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.

devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Thu Sep 26, 2019 8:39 pm

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.

devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Fri Sep 27, 2019 7:34 pm

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.

devnull
Newcomer
Posts: 11
Joined: Tue Sep 24, 2019 9:08 pm
Canada

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

Post by devnull » Sun Sep 29, 2019 8:05 pm

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.

Post Reply