[mythtv-users] Recording failed, but the backend didn't figure that out...

[Phil Bridges]

On Mon, Jul 30, 2012 at 8:51 PM, Jason Gillis <spuppet at comcast.net> wrote:
> Hi all,
>
> I've been trying to record as much of the Olympics coverage that NBC decides that I'm able to handle.  This has been up to four simultaneous recordings, and has put some pretty good strain on my storage array at certain times of day when I'm doing other things with it.
>
> I noticed this morning that when a schedule file system consistency check kicked off on the array at 7:00am (normally a fine time to do that), I got the following in the backend logs:
>
> Jul 30 07:00:41 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): write(61288) cnt 1081 total 62404344 -- took a long time, 29848 ms
> Jul 30 07:00:41 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2733_20120730040000.mpg:146): write(57528) cnt 827 total 47683192 -- took a long time, 29265 ms
> Jul 30 07:00:42 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1031 total 59474552 -- took a long time, 29347 ms
> Jul 30 07:00:42 mythbackend mythbackend[2638]: N Expire autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
> Jul 30 07:00:52 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): write(57528) cnt 1350 total 77955704 -- took a long time, 9530 ms
> Jul 30 07:00:52 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2733_20120730040000.mpg:146): write(57904) cnt 1132 total 65291836 -- took a long time, 9608 ms
> Jul 30 07:00:52 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1339 total 77214608 -- took a long time, 9748 ms
> Jul 30 07:01:14 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1748 total 100809172 -- took a long time, 17458 ms
> Jul 30 07:01:14 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2733_20120730040000.mpg:146): write(57528) cnt 1650 total 95157328 -- took a long time, 17968 ms
> Jul 30 07:01:14 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): write(57528) cnt 1988 total 114757832 -- took a long time, 17887 ms
> Jul 30 07:01:22 mythbackend mythbackend[2638]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> Jul 30 07:01:43 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): write(57152) cnt 2315 total 133614984 -- took a long time, 15320 ms
> Jul 30 07:01:43 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1861 total 107371124 -- took a long time, 15057 ms
> Jul 30 07:01:44 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2733_20120730040000.mpg:146): write(57716) cnt 1920 total 110695152 -- took a long time, 15054 ms
> Jul 30 07:01:55 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2733_20120730040000.mpg:146): write(57716) cnt 1859 total 107214332 -- took a long time, 3520 ms
> Jul 30 07:01:55 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1768 total 102001844 -- took a long time, 3464 ms
> Jul 30 07:01:55 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): write(57528) cnt 2249 total 129763992 -- took a long time, 3155 ms
> Jul 30 07:01:56 mythbackend mythbackend[2638]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/nas/mythtv/recordings/2787_20120730060000.mpg:107): write(57528) cnt 1782 total 102771704 -- took a long time, 1099 ms
> Jul 30 07:02:00 mythbackend mythbackend[2638]: E HDHRStreamHandler ThreadedFileWriter.cpp:216 (Write) TFW(/nas/mythtv/recordings/2723_20120730060000.mpg:110): Maximum buffer size exceeded.#012#011#011#011file will be truncated, no further writing will be done.#012#011#011#011This generally indicates your disk performance #012#011#011#011is insufficient to deal with the number of on-going #012#011#011#011recordings, or you have a disk failure.
>
> Obviously, this was just too much for the array to handle and that was it for that recording...  What's strange is that in the GUI or in mythweb, I see no indication that there was a problem with this recording.  Both tell me the recording is 76GB, but if I look at the file in the recordings directory, it's 7.4GB and the last modified date is 7:02 AM as expected.  I've noticed similar conditions on Saturday and Sunday where I believe the recordings failed due to bad signal from the cable provider.  In some of those instances, the result was similar, failed recordings but the backend didn't seem to realize it.  I don't have the files for those recordings anymore, so I can't accurately pull together details as I can for the 7:02 occurrence today.
>
> My backend (mythbuntu) was updated on Saturday:
>
> Please attach all output as a file in bug reports.
> MythTV Version : v0.25.2-8-g3256849
> MythTV Branch : fixes/0.25
> Network Protocol : 72
> Library API : 0.25.20120506-1
> QT Version : 4.6.2
> Options compiled in:
>  linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_crystalhd using_dvb using_firewire using_frontend using_hdhomerun using_ceton using_hdpvr using_iptv using_ivtv using_joystick_menu using_libcec using_libcrypto using_libdns_sd using_libxml2 using_lirc using_mheg using_opengl_video using_qtwebkit using_qtscript using_qtdbus using_v4l2 using_v4l1 using_x11 using_xrandr using_xv using_bindings_perl using_bindings_python using_bindings_php using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads using_live using_mheg using_libxml2
>
> This is talking to an HDHR and a HDHR Prime.  The recording that failed this morning was the on the prime.
>
> So, I'm curious about why the backend didn't detect that the recording had failed at this point?  Obviously, the problem is the storage, but it would be nice if the system knew it had given up on itself.  :)
>
> Most infuriating is that it seems to be impossible to restart a recording of a show that myth thinks has been recorded.  On Saturday when I noticed this, my first thought was "oh, I'll just tell it to record that program that still in progress" because it was the middle of an 11 hour program.  I was not able to convince myth to restart recording those showings that had failed, as it seemed to think they were OK.  I tried deleting the programs with delete+rerecord, forgetting the old via mythweb, deleting the entries from the oldrecorded table in the DB (I know, a bad idea...).  None worked.  I finally had to delete the schedule for the entire olympics and then re-add it.  This was finally successful in getting things restarted.
>

I'm having a similar thing happen.  I was recording NBC's Olympics
coverage tonight, along with two other channels.  All three were
recording on my master backend, but it determined to record all three
files to my slave backend's drives.  Althought I'm running a gigabit
network, the two 9 o'clock programs errored out about 9:20.  The
frontend didn't indicate the recordings were incomplete - they said
they were x GB (7 or so).