[mythtv-users] 0.00MB recordings...

[Andrew Close]

On Wed, Dec 17, 2008 at 9:01 AM, Andrew Close <aclose at gmail.com> wrote:
> this is becoming more and more common for me :(  originally i was
> seeing this on a new/dev system that i'm setting up running MythBuntu
> 8.10 and recording with an HDHR.  i figured i had some settings that
> needed tweaking, and besides, it was only a play system.  but the
> problem is now happening (frequently) on my production MythBox running
> Myth .20 on a semi recent version of KnoppMyth.  my production box
> contains a PVR-250 and a PVR-500 and i'm recording analog (obviously)
> cable from Wide Open West in the western Chicago suburbs.  my signal
> strength is fairly good, as far as i can tell.  other recordings that
> actually record look good, or as good as analog over cable can look.
> :)  nothing has changed with my production setup (equipment, cabling,
> service) for at least 6 months.  as far as i've noticed, these 0MB
> recordings are occurring on all channels and in various timeslots.
> Monday night (i think it was Mon :) i noticed 'Chuck' and 'NCIS'
> recording simultaneously and things seemed to be fine.  Tuesday night
> my wife and i sat down to watch 'NCIS' and it wouldn't start up.
> viewing my programs in the 'Manage Recordings, Delete Recordings'
> screen i noticed that both recordings were 0MB; however, Monday night
> i know they recorded for at least 30 minutes because i noticed they
> were recording, watched a previously recorded program, and saw that
> they were still recording when my program was over.
>
> any thoughts on what to look for for possible diagnosis?  i have to
> admit i haven't checked the logs yet...  i'll do that when i get home
> tonight and report what i find.

ok, logs and stuff.

looks like my production box was last rebooted on Nov 23rd.

--- from /var/log/dmesg ---
ivtv:  Start initialization, version 1.1.0

no error messages in dmesg.  and it looks like all three tuners were
detected fine.

looking at the messages log for Dec 15th at 8PM (when 'Chuck' and
'NCIS' were being recorded) i see the following (over and over and
over...):

--- from /var/log/messages ---
Dec 15 20:09:19 MythBox -- MARK --
Dec 15 20:09:47 MythBox kernel: ivtv0: All encoder VBI stream buffers
are full. Dropping data.
Dec 15 20:09:48 MythBox kernel: ivtv0: Cause: the application is not
reading fast enough.

although, that says the application isn't reading fast enough, not writing...
ivtv0 would be my PVR-250 which registers as card #0.

--- from /var/log/messages ---
Dec 15 20:16:42 MythBox kernel: ivtv0: Cause: the application is not
reading fast enough.
Dec 15 20:29:19 MythBox -- MARK --
Dec 15 20:49:20 MythBox -- MARK --
Dec 15 21:09:20 MythBox -- MARK --
Dec 15 21:29:20 MythBox -- MARK --
Dec 15 21:49:20 MythBox -- MARK --
Dec 15 22:09:20 MythBox -- MARK --

so almost 30 minutes into the recording it looks like maybe it just died..?

--- from /var/log/messages ---
Dec 16 19:09:22 MythBox -- MARK --
Dec 16 19:15:25 MythBox kernel: hdc: command error: status=0x51 {
DriveReady SeekComplete Error }
Dec 16 19:15:25 MythBox kernel: hdc: command error: error=0x54 {
AbortedCommand LastFailedSense=0x05 }
Dec 16 19:15:25 MythBox kernel: ide: failed opcode was: unknown
Dec 16 19:15:25 MythBox kernel: ATAPI device hdc:
Dec 16 19:15:25 MythBox kernel:   Error: Illegal request -- (Sense key=0x05)
Dec 16 19:15:25 MythBox kernel:   "28 00 00 36 09 40 00 00 02 00 00 00
00 00 00 00 "
Dec 16 19:15:25 MythBox kernel: end_request: I/O error, dev hdc, sector 14165248
Dec 16 19:15:25 MythBox kernel: hdc: command error: status=0x51 {
DriveReady SeekComplete Error }
Dec 16 19:15:25 MythBox kernel: hdc: command error: error=0x54 {
AbortedCommand LastFailedSense=0x05 }

hmm, that's Tues evening.  that doesn't look good either.  (turns out
that hdc is my dvd drive and we were watching Toy Story 2 with my son
at this time)  :)  the above message repeats for roughly 2 minutes and
then goes back to -- MARK -- every 20 minutes.

ok.  the Mythbackend.log looks like it has better info and i'm seeing
issues back as far as my logs go: Dec 10th:

--- from /var/log/mythtv/mythbackend.log.7 ---
2008-12-10 11:30:01.609 TVRec(9): Changing from None to RecordingOnly
2008-12-10 11:30:01.617 TVRec(9): HW Tuner: 9->9
2008-12-10 11:30:01.735 Started recording: WordWorld "The Christmas
Star; A Christmas Present for Dog": channel 1011 on cardid 9, sourceid
1
2008-12-10 11:30:07.336 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-10 11:30:12.884 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-10 11:30:16.014 JobQueue: Commercial Flagging Starting for
WordWorld "The Christmas Star; A Christmas Present for Dog" recorded
from channel 1011 at Wed Dec 10 11:30:00 2008
2008-12-10 11:30:16.481 Using runtime prefix = /usr
2008-12-10 11:30:16.548 New DB connection, total: 1
2008-12-10 11:30:16.560 Connected to database 'mythconverg' at host: localhost
2008-12-10 11:30:16.579 New DB connection, total: 2
2008-12-10 11:30:16.581 Connected to database 'mythconverg' at host: localhost
2008-12-10 11:30:18.428 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-10 11:30:23.086 RingBuf(/myth/tv/1011_20081210113000.mpg):
Invalid file (fd -1) when opening '/myth/tv/1011_20081210113000.mpg'.

so it looks like the ivtv driver bombed out and Myth keeps working as
usual, but the capture card can't do its thing.  in the most recent
backend log i'm seeing the same thing:

--- from /var/log/mythtv/mythbackend.log ---
2008-12-17 15:03:14.452 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 15:03:19.998 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 15:03:20.029 TVRec(9): Changing from RecordingOnly to None
2008-12-17 15:03:20.042 Finished recording This Old House "Weston
Project": channel 1056
2008-12-17 15:03:20.050 Reschedule requested for id 0.
2008-12-17 15:03:20.968 Finished recording This Old House "Weston
Project": channel 1056
2008-12-17 15:03:21.453 Scheduled 139 items in 1.4 = 0.00 match + 1.40 place
2008-12-17 15:03:21.464 Preview Error: Previewer file
'/myth/tv/1056_20081217142800.mpg' is not valid.
2008-12-17 18:53:02.065 TVRec(9): Changing from None to RecordingOnly
2008-12-17 18:53:02.229 TVRec(9): HW Tuner: 9->9
2008-12-17 18:53:02.524 Started recording: Pushing Daisies "The
Norwegians": channel 1007 on cardid 9, sourceid 1
2008-12-17 18:53:07.963 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:13.525 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:19.089 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:19.365 JobQueue: Commercial Flagging Starting for
Pushing Daisies "The Norwegians" recorded from channel 1007 at Wed Dec
17 18:53:00 2008
2008-12-17 18:53:21.136 Using runtime prefix = /usr
2008-12-17 18:53:21.360 New DB connection, total: 1
2008-12-17 18:53:21.418 Connected to database 'mythconverg' at host: localhost
2008-12-17 18:53:21.448 New DB connection, total: 2
2008-12-17 18:53:21.450 Connected to database 'mythconverg' at host: localhost
2008-12-17 18:53:24.673 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:27.955 RingBuf(/myth/tv/1007_20081217185300.mpg):
Invalid file (fd -1) when opening '/myth/tv/1007_20081217185300.mpg'.
2008-12-17 18:53:28.025 Connecting to backend server:
192.168.1.148:6543 (try 1 of 5)
2008-12-17 18:53:28.035 Using protocol version 31
2008-12-17 18:53:28.036 MainServer::HandleAnnounce Monitor
2008-12-17 18:53:28.038 adding: MythBox as a client (events: 0)
2008-12-17 18:53:28.040 MainServer::HandleAnnounce Monitor
2008-12-17 18:53:28.041 adding: MythBox as a client (events: 1)
2008-12-17 18:53:30.088 NVP::OpenFile(): Error, file not found:
/myth/tv/1007_20081217185300.mpg
2008-12-17 18:53:30.241 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:30.370 JobQueue: Commercial Flagging Finished, 0
break(s) found.
2008-12-17 18:53:30.379 Preview Error: Previewer file
'/myth/tv/1007_20081217185300.mpg' is not valid.
2008-12-17 18:53:35.861 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding
2008-12-17 18:53:41.439 MPEGRec(/dev/video2) Error: select timeout -
ivtv driver has stopped responding

so i guess i see what the problem was, the ivtv driver wasn't driving
:)  but i don't know why it stopped.  and even though the log snippets
look as though they may be for the same card, there were a couple
instances where more than one recording was going on at a time so the
MythBox had to be using two different tuners.  but i guess they could
have been the two tuners on the PVR-500 :)

so now i'm rebooting.  i guess that will reinitialize the ivtv driver
and things should start working again.  if i start seeing 0MB
recordings again i'll know to look in the logs sooner and hopefully
find more info as to why ivtv (if that's the culprit) stops working.
rebooting forced an fsck which hadn't happened in 203 days. :)

--- from /var/log/dmesg  ---
Linux version 2.6.18-chw-13 (root at mythtv) (gcc version 4.1.2 20061115
(prerelease) (Debian 4.1.1-21)) #1 SMP PREEMPT Sat Jun 2 21:06:06 PDT
2007
<snip>
Linux video capture interface: v2.00
ivtv:  Start initialization, version 1.1.0
ivtv0: Initializing card #0
ivtv0: Autodetected Hauppauge card (cx23416 based)
ACPI: PCI Interrupt Link [LNK3] enabled at IRQ 9
ACPI: PCI Interrupt 0000:01:08.0[A] -> Link [LNK3] -> GSI 9 (level,
low) -> IRQ 9
ivtv0: Unreasonably low latency timer, setting to 64 (was 32)
tuner 2-0061: chip found @ 0xc2 (ivtv i2c driver #0)
msp3400 2-0040: MSP3445G-B8 found @ 0x80 (ivtv i2c driver #0)
msp3400 2-0040: MSP3445G-B8 supports radio, mode is autodetect and autoselect
saa7115 2-0021: saa7115 found (1f7115d0e100000) @ 0x42 (ivtv i2c driver #0)
tveeprom 2-0050: Hauppauge model 32062, rev B185, serial# 7368771
tveeprom 2-0050: tuner model is TCL 2002N 6A (idx 85, type 50)
tveeprom 2-0050: TV standards NTSC(M) (eeprom 0x08)
tveeprom 2-0050: audio processor is MSP3445 (idx 12)
tveeprom 2-0050: decoder processor is SAA7115 (idx 19)
tveeprom 2-0050: has no radio, has IR receiver, has no IR transmitter
ivtv0: Autodetected Hauppauge WinTV PVR-250
tuner-simple 2-0061: type set to 50 (TCL 2002N)
tuner 2-0061: type set to TCL 2002N
ivtv0: Registered device video0 for encoder MPG (4096 kB)
ivtv0: Registered device video32 for encoder YUV (2048 kB)
ivtv0: Registered device vbi0 for encoder VBI (1024 kB)
ivtv0: Registered device video24 for encoder PCM (320 kB)
ivtv0: Initialized card #0: Hauppauge WinTV PVR-250
ivtv1: Initializing card #1
ivtv1: Autodetected Hauppauge card (cx23416 based)
ACPI: PCI Interrupt Link [LNK1] enabled at IRQ 5
ACPI: PCI Interrupt 0000:02:08.0[A] -> Link [LNK1] -> GSI 5 (level,
low) -> IRQ 5
ivtv1: Unreasonably low latency timer, setting to 64 (was 32)
tuner 3-0043: chip found @ 0x86 (ivtv i2c driver #1)
tda9887 3-0043: tda988[5/6/7] found @ 0x43 (tuner)
tuner 3-0043: type set to tda9887
TEA5767 detected.
tuner 3-0060: chip found @ 0xc0 (ivtv i2c driver #1)
tea5767 3-0060: type set to Philips TEA5767HN FM Radio
tuner 3-0060: type set to tea5767
tuner 3-0061: chip found @ 0xc2 (ivtv i2c driver #1)
tveeprom 3-0050: Hauppauge model 23552, rev D492, serial# 8024066
tveeprom 3-0050: tuner model is Philips FQ1236A MK4 (idx 92, type 57)
tveeprom 3-0050: TV standards NTSC(M) (eeprom 0x08)
tveeprom 3-0050: second tuner model is Philips TEA5768HL FM Radio (idx
101, type 62)
tveeprom 3-0050: audio processor is CX25843 (idx 37)
tveeprom 3-0050: decoder processor is CX25843 (idx 30)
tveeprom 3-0050: has radio, has no IR receiver, has no IR transmitter
ivtv1: Autodetected WinTV PVR 500 (unit #1)
cx25840 3-0044: cx25843-23 found @ 0x88 (ivtv i2c driver #1)
wm8775 3-001b: chip found @ 0x36 (ivtv i2c driver #1)
tuner-simple 3-0061: type set to 57 (Philips FQ1236A MK4)
tuner 3-0061: type set to Philips FQ1236A MK4
ivtv1: Registered device video1 for encoder MPG (4096 kB)
ivtv1: Registered device video33 for encoder YUV (2048 kB)
ivtv1: Registered device vbi1 for encoder VBI (1024 kB)
ivtv1: Registered device video25 for encoder PCM (320 kB)
ivtv1: Registered device radio1 for encoder radio
ivtv1: Initialized card #1: WinTV PVR 500 (unit #1)
ivtv2: Initializing card #2
ivtv2: Autodetected Hauppauge card (cx23416 based)
ACPI: PCI Interrupt Link [LNK2] enabled at IRQ 11
ACPI: PCI Interrupt 0000:02:09.0[A] -> Link [LNK2] -> GSI 11 (level,
low) -> IRQ 11
ivtv2: Unreasonably low latency timer, setting to 64 (was 32)
tuner 4-0043: chip found @ 0x86 (ivtv i2c driver #2)
tda9887 4-0043: tda988[5/6/7] found @ 0x43 (tuner)
tuner 4-0043: type set to tda9887
tuner 4-0061: chip found @ 0xc2 (ivtv i2c driver #2)
cx25840 4-0044: cx25843-23 found @ 0x88 (ivtv i2c driver #2)
wm8775 4-001b: chip found @ 0x36 (ivtv i2c driver #2)
tveeprom 4-0050: Hauppauge model 23552, rev D492, serial# 8024066
tveeprom 4-0050: tuner model is Philips FQ1236A MK4 (idx 92, type 57)
tveeprom 4-0050: TV standards NTSC(M) (eeprom 0x08)
tveeprom 4-0050: second tuner model is Philips TEA5768HL FM Radio (idx
101, type 62)
tveeprom 4-0050: audio processor is CX25843 (idx 37)
tveeprom 4-0050: decoder processor is CX25843 (idx 30)
tveeprom 4-0050: has radio, has no IR receiver, has no IR transmitter
ivtv2: Correcting tveeprom data: no radio present on second unit
ivtv2: Autodetected WinTV PVR 500 (unit #2)
tuner-simple 4-0061: type set to 57 (Philips FQ1236A MK4)
tuner 4-0061: type set to Philips FQ1236A MK4
ivtv2: Registered device video2 for encoder MPG (4096 kB)
ivtv2: Registered device video34 for encoder YUV (2048 kB)
ivtv2: Registered device vbi2 for encoder VBI (1024 kB)
ivtv2: Registered device video26 for encoder PCM (320 kB)
ivtv2: Initialized card #2: WinTV PVR 500 (unit #2)
ivtv:  End initialization
Adding 1092412k swap on /dev/hda2.  Priority:-1 extents:1 across:1092412k
EXT3 FS on hda1, internal journal
bttv: driver version 0.9.17 loaded
bttv: using 8 buffers with 2080k (520 pages) each for capture
bt878: AUDIO driver version 0.0.0 loaded

no errors or warnings in dmesg...

nothing outstanding in mythbackend.log after the reboot.  and it
appears that a recording that was recording (not really) before the
reboot picked up and actually began recording after the reboot.  so i
guess i'm all fixed for the moment.  :)

next time i'll try to remember to jump into the logs before asking for help. ;)

any more thoughts/comments on why ivtv just stopped?

thanks again

-- 
Andrew Close