[mythtv-users] Post upgrade 0.24 to 0.25 PVR-150/250/350 fail to record at some point
Kenan Ezal
SBMythTV at cox.net
Mon May 28 07:05:50 UTC 2012
On Wed, 2012-05-09 at 05:48 -0400, Kenan Ezal wrote:
> ---- Michael Harnden <mike at rochestervball.com> wrote:
> > On Tuesday, May 08, 2012 06:29:04 PM Michael Harnden wrote:
> > > On Tuesday, May 08, 2012 05:19:26 PM Kenan Ezal wrote:
> > > > ---- Michael Harnden <mike at rochestervball.com> wrote:
> > > > > On Tuesday, May 08, 2012 11:36:35 AM Michael T. Dean wrote:
> > > > > > On 05/08/2012 07:44 AM, Michael Harnden wrote:
> > > > > > > Quoting Kenan Ezal:
> > > > > > >> Summary of problem:
> > > > > > >>
> > > > > > >> After I reboot both my master backend and slave backend I schedule
> > > > > > >> recordings (that are currently on) to test my three tuners
> > > > > > >> (PVR-250/PVR-150 on master backend and PVR-350 on slave backend).
> > > > > > >> All
> > > > > > >> three tuners record their respective shows and I am able to play
> > > > > > >> back
> > > > > > >> during recording. I delete the shows and try again for a different
> > > > > > >> set of programs on different channels. Once again everything works
> > > > > > >> and I am pleased thinking my kids will be happy with the new Mickey
> > > > > > >> Mouse Clubhouse show that is scheduled to be recorded the next
> > > > > > >> morning.
> > > > > > >>
> > > > > > >> The following morning I wake up to find that the first show that
> > > > > > >> was
> > > > > > >> scheduled for recording at 2am (Phineas and Ferb) recorded fine
> > > > > > >> although the backend did report a database error (see below).
> > > > > > >> However, the second show (Doc McStuffins at 7:30am) and the third
> > > > > > >> show (Mickey Mouse Club House at 8am) did not record, although they
> > > > > > >> show up in grey on my list of recordings. All three shows were
> > > > > > >> scheduled to use Tuner 1 (PVR-250).
> > > > > > >>
> > > > > > >> I am puzzled so I sellect three other shows (such as the highly
> > > > > > >> provocative "Inside Edition: Butt Girl" and "Brazil Butt Lift") for
> > > > > > >> immediate recording. All three appear to be recording. However,
> > > > > > >> when
> > > > > > >> I check Tuner 1 I see that it is not. I stop the recording on Tuner
> > > > > > >> 1
> > > > > > >> (leaving the others recording) and try LiveTV and receive the
> > > > > > >> following error: "Error opening jump program buffer." The other two
> > > > > > >> tuners are in fact recording. However, I am able to recreate the
> > > > > > >> same
> > > > > > >> issue with any of the tuners. For example, the other night I
> > > > > > >> decided
> > > > > > >> to disable Tuner 1 so that Tuner 2 was the first in line to record.
> > > > > > >> The next morning same problem. I then disabled Tuners 1 and 2, and
> > > > > > >> the same problem occurred with Tuner 3 (on slave backend). They all
> > > > > > >> initially record fine, but fail during a later scheduled recording,
> > > > > > >> usually after successfully recording the first show.
> > > > > > >>
> > > > > > >> Extended Discussion:
> > > > > > >>
> > > > > > >> Unfortunately, this started about two weeks ago when I upgraded
> > > > > > >> from
> > > > > > >> 0.24 to 0.25 on Fedora 16. I use ATrpms to access the packages. At
> > > > > > >> first I thought it was a power supply problem because we had been
> > > > > > >> having some power problems in our area and I found my master
> > > > > > >> backend
> > > > > > >> completely off one morning. However, I believe that was a false
> > > > > > >> alarm
> > > > > > >> and now it appears to be a software problem. The system was very
> > > > > > >> stable and recording away happily before the upgrade.
> > > > > > >>
> > > > > > >> I have noted that other people have been reporting similar problems
> > > > > > >> with their PVRs although the descriptons vary a some and many seem
> > > > > > >> to
> > > > > > >> be focused on LiveTV. We never watch LiveTV, always recorded shows
> > > > > > >> so
> > > > > > >> I know it isn't a problem solely related to LiveTV.
> > > > > > >>
> > > > > > >> See for exampe:
> > > > > > >>
> > > > > > >> http://www.mythtv.org/pipermail/mythtv-users/2012-May/333121.html
> > > > > > >> https://bugs.archlinux.org/task/29627
> > > > > > >>
> > > > > > >> I did discover that there is a possible fix, but I"m not sure when
> > > > > > >> its going to get into the packages:
> > > > > > >>
> > > > > > >> https://github.com/MythTV/mythtv/commit/f81f712537b63502814d1f274c7
> > > > > > >> da
> > > > > > >> 1419
> > > > > > >> 6cedd8c
> > > > > > >>
> > > > > > >>
> > > > > > >> However, I'm not completely convinced that is the only problem on
> > > > > > >> my
> > > > > > >> system since I can't seem to make it fail on will. It's repeatable
> > > > > > >> in
> > > > > > >> that after a reboot, it will happen (probably overnight).
> > > > > > >>
> > > > > > >> 1. I'm curious if anyone else has had similar issues and was able
> > > > > > >> to
> > > > > > >> fix it without the above mentioned fix (I did try deleting all the
> > > > > > >> tuners and inputs and adding them back in and it did not help).
> > > > > > >>
> > > > > > >> snip
> > > > > > >
> > > > > > >
> > > > > > > I will dig into this a bit more when I get home from work tonight.
> > > > > >
> > > > > > Did you guys do a "Delete all capture cards" (not "Delete all capture
> > > > > > cards on <hostname>"), then re-create cards and re-connect inputs?
> > > > > > (Any
> > > > > > time you change cards or drivers, you should probably do that--and
> > > > > > should definitely do that if you have failures after the upgrade.) It
> > > > > > won't affect Video Sources or channels, so, it's a quick 30-second
> > > > > > process that allows MythTV to configure your cards for the current
> > > > > > drivers.
> > > > > >
> > > > > > Mike
> > > > > > _______________________________________________
> > > > > > mythtv-users mailing list
> > > > > > mythtv-users at mythtv.org
> > > > > > http://www.mythtv.org/mailman/listinfo/mythtv-users
> > > > >
> > > > > Hi Mike,
> > > > > I ran "Delete all capture cards" and had the same results (recording
> > > > > failure). After some more googling, I shut my server down (not just a
> > > > > reboot), waited a minute or so and restarted. So far I have been able to
> > > > > record 5 separate times on that tuner. So I think I am good. I'll
> > > > > observe
> > > > > for a couple of days and report back.
> > > > >
> > > > > I managed to break live TV in my Delete all cards process, so I am off
> > > > > to
> > > > > investigate that.
> > > > > Mike
> > > >
> > > > Mike,
> > > >
> > > > When you say you were able to record 5 seperate times, do you mean that
> > > > you
> > > > manually told the tuner to to record a show, stopped the recording, and
> > > > told it to record another show, possibly on another channel? [Or were
> > > > these
> > > > previously scheduled recordings?]
> > > >
> > > > If so, I was able to do the same thing, but after leaving the machine with
> > > > previously scheduled programs, the first scheduled program fails to
> > > > record.
> > > > For example, after a reboot, I went into Manage Recordings and selected a
> > > > currently running program for recording. It would successfully record. I
> > > > would stop the recording and go to another channel and do the same thing
> > > > with another program. Once again no problem. However, after thinking
> > > > everything is Ok I would come back the next morning to find an empty file
> > > > for a previously scheduled recording using that same tuner.
> > > >
> > > > I was wondering if there is something related to the scheduler going
> > > > on...?
> > > >
> > > > However, tonight I will try complete shutdown of both machines after I
> > > > remove my cards from setup. I will then re-select the cards after starting
> > > > the machine and see what happens. I may also shutdown after re-selecting.
> > > > I'll try anything now...
> > > >
> > > > -Kenan
> > > >
> > > > -Kenan
> > >
> > > Hi Kenan,
> > > Now you have me concerned, because that is exactly what I did. Told it to
> > > record a show, stopped it, picked another on a different channel, etc.
> > >
> > > I am using a PVR-350 and the interesting thing is that it is only the
> > > S-Video feed into the card that I was having problems with. I have the
> > > tuner portion of the card connected directly to my cable, and the S-Video
> > > input I am using to record from my cable box. The tuner portion has worked
> > > fine all along.
> > >
> > > I will schedule some shows on the S-Video feed overnight and report back.
> > > Mike
> > > _______________________________________________
> > > mythtv-users mailing list
> > > mythtv-users at mythtv.org
> > > http://www.mythtv.org/mailman/listinfo/mythtv-users
> >
> > Looks like I still have the problem. I was able to record a show at 11:00 pm, then the
> > card failed at the end of recording.
> >
> > May 8 22:59:29 mythtv-server mythbackend[1950]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(1): ASK_RECORDING 1 20 0 0
> > May 8 22:59:49 mythtv-server mythbackend[1950]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(1): Changing from None to RecordingOnly
> > May 8 22:59:49 mythtv-server mythbackend[1950]: I TVRecEvent tv_rec.cpp:3459 (TuningCheckForHWChange) TVRec(1): HW Tuner: 1->1
> > May 8 22:59:49 mythtv-server mythbackend[1950]: I TVRecEvent v4lchannel.cpp:661 (SetInputAndFormat) V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
> > May 8 22:59:50 mythtv-server mythbackend[1950]: N Scheduler autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
> > May 8 22:59:50 mythtv-server mythbackend[1950]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording: Pocoyo: channel 1519 on cardid 1, sourceid 1
> > May 8 22:59:50 mythtv-server mythbackend[1950]: E ProcessRequest programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(1519_20120508230000.mpg): GetPlaybackURL: '1519_20120508230000.mpg' should be local, but it can not be found.
> > May 8 22:59:50 mythtv-server mythbackend[1950]: E ProcessRequest programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(1519_20120508230000.mpg): GetPlaybackURL: '1519_20120508230000.mpg' should be local, but it can not be found.
> > May 8 22:59:51 mythtv-server mythbackend[1950]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Started recording: Pocoyo: channel 1519 on cardid 1, sourceid 1
> > May 8 22:59:51 mythtv-server mythbackend[1950]: I TVRecEvent tv_rec.cpp:3953 (TuningNewRecorder) TVRec(1): rec->GetPathname(): '/mnt/store/d4/video/1519_20120508230000.mpg'
> > May 8 23:00:00 mythtv-server mythbackend[1950]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> > May 8 23:00:00 mythtv-server mythbackend[1950]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-server.site as a client (events: 0)
> > May 8 23:00:00 mythtv-server mythbackend[1950]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> > May 8 23:00:00 mythtv-server mythbackend[1950]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-server.site as a client (events: 1)
> > May 8 23:02:50 mythtv-server mythbackend[1950]: N Expire autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
> > May 8 23:04:08 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:09:13 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:14:18 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:17:50 mythtv-server mythbackend[1950]: N Expire autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
> > May 8 23:19:24 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:24:24 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:29:25 mythtv-server mythbackend[1950]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> > May 8 23:30:10 mythtv-server mythbackend[1950]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(1): Changing from RecordingOnly to None
> > May 8 23:30:11 mythtv-server mythbackend[1950]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/video0): poll error
> > May 8 23:30:11 mythtv-server mythbackend[1950]: E RecThread mpegrecorder.cpp:1010 (run) MPEGRec(/dev/video0): Device error detected
> > May 8 23:30:13 mythtv-server mythbackend[1950]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/video0): poll error
> > May 8 23:30:13 mythtv-server mythbackend[1950]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Pocoyo on cardid 1 (Recording => Recorded)
> > May 8 23:30:13 mythtv-server mythbackend[1950]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording Pocoyo: channel 1519
> > May 8 23:30:13 mythtv-server mythbackend[1950]: E CoreContext mainserver.cpp:871 (customEvent) MainServer: PREVIEW_SUCCESS but no receivers.
>
> Darn. I was hoping your shutdown suggestion would work. I went home tonight and did exactly that.
>
> However, in your earlier message you stated that you were not having the same problem with your
> tuner, only your S-Video feed. That is different from my experience because I'm having the problem
> with my tuner. I don't use my S-Video feed.
>
> I'm convinced that there is a software problem, but because of how we are able to record
> on-demand, but not on-schedule, I think the problem has to do with the scheduler state and
> the PVR command requirements. The fact that your system is working with the tuner but not
> S-Video also seems to imply that the problem isn't tuner-related exactly.
>
> I may submit a bug report but I want to comb through my now volumous logs to see if I can
> spot a trend.
>
> Unfortunately my wife is getting a little worried that we won't be recording the end of the
> season episodes of her favorite shows... so the clock is ticking and I may have to revert
> to 0.24.
>
> -Kenan
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://www.mythtv.org/mailman/listinfo/mythtv-users
Unfortunately I have been unable to get my PVRs 150/250/350 to operate
consistently since upgrading to Myth 0.25 (Fedora 16). I have tried:
1. Deleting all tuners and then re-adding them back in (along with the
inputs).
2. Completely uninstalling 0.25 after removing the tuners, and then
re-installing 0.25 and adding back the tuners.
3. One-by-one removing one of the tuners from my master backend and
trying to get it to work with the other tuner alone.
4. Uninstalling and re-installing the ivtv-firmware.
5. Repairing mythconverg (just in case)
6. Different combinations of the above.
In all cases the PVRs record X number of shows successfully before
failing on X+1. X appears to be larger if I have a single tuner in the
master backend. X~1 when I have two tuners (PVR 150 & 250) in the master
backend.
However even when the recording is successful I get the following errors
in the log:
2012-05-26 14:00:16.119246 E [2716/2758] DeviceReadBuffer
DeviceReadBuffer.cpp:460 (Poll) - DevRdB(/dev/video0): poll error
2012-05-26 14:00:16.119379 E [2716/2756] RecThread mpegrecorder.cpp:1010
(run) - MPEGRec(/dev/video0): Device error detected
2012-05-26 14:00:18.586740 E [2716/2864] DeviceReadBuffer
DeviceReadBuffer.cpp:460 (Poll) - DevRdB(/dev/video0): poll error
and
2012-05-26 14:30:09.678806 E [2716/3004] Commflag_4195
previewgenerator.cpp:254 (Run) - Preview: Encountered problems running
'/usr/bin/mythpreviewgen --size 0x0 --chanid 1003 --starttime
20120526143000 --verbose general --logpath /var/log/mythtv --loglevel
info --quiet' (128)
2012-05-26 14:30:39.097627 E [2716/2966] DeviceReadBuffer
DeviceReadBuffer.cpp:513 (Poll) - DevRdB(/dev/video0): Poll giving up 2
2012-05-26 14:30:39.097755 E [2716/2965] RecThread mpegrecorder.cpp:1010
(run) - MPEGRec(/dev/video0): Device error detected
and sometimes the following:
2012-05-26 14:56:30.285663 E [2716/2965] RecThread mythdb.cpp:192
(DBError) - DB Error (Resolution insert):
Query was:
INSERT INTO recordedmarkup (chanid, starttime, mark, type, data)
VALUES ( ?, ?, ?, ?, ?);
Bindings were:
:CHANID=1003, :DATA=720, :MARK=46442, :STARTTIME=2012-05-26T14:30:00, :TYPE=30
Driver error was [2/1062]:
QMYSQL3: Unable to execute statement
Database error was:
Duplicate entry '1003-2012-05-26 14:30:00-30-46442' for key 'PRIMARY'
2012-05-26 14:56:30.286214 E [2716/2965] RecThread mythdb.cpp:192
(DBError) - DB Error (Resolution insert):
Query was:
INSERT INTO recordedmarkup (chanid, starttime, mark, type, data)
VALUES ( ?, ?, ?, ?, ?);
Bindings were:
:CHANID=1003, :DATA=480, :MARK=46442, :STARTTIME=2012-05-26T14:30:00, :TYPE=31
Driver error was [2/1062]:
QMYSQL3: Unable to execute statement
Database error was:
Duplicate entry '1003-2012-05-26 14:30:00-31-46442' for key 'PRIMARY'
2012-05-26 14:56:30.286807 E [2716/2965] RecThread mythdb.cpp:192
(DBError) - DB Error (Frame rate insert):
Query was:
INSERT INTO recordedmarkup (chanid, starttime, mark, type, data)
VALUES ( ?, ?, ?, ?, ?);
Bindings were:
:CHANID=1003, :DATA=29970, :MARK=46442, :STARTTIME=2012-05-26T14:30:00, :TYPE=32
Driver error was [2/1062]:
QMYSQL3: Unable to execute statement
Database error was:
Duplicate entry '1003-2012-05-26 14:30:00-32-46442' for key 'PRIMARY'
and
2012-05-26 15:00:18.714061 E [2716/2716] CoreContext mainserver.cpp:871
(customEvent) - MainServer: PREVIEW_SUCCESS but no receivers.
and
2012-05-26 15:30:27.368775 E [2716] ProcessRequest
fileringbuffer.cpp:289 (OpenFile) -
FileRingBuf(/data/recordings/1006_20120526153000.mpg): OpenFile(): File
too small (0B).
2012-05-26 15:30:38.958626 E [2716/3134] DeviceReadBuffer
DeviceReadBuffer.cpp:513 (Poll) - DevRdB(/dev/video0): Poll giving up 2
2012-05-26 15:30:38.959622 E [2716/3133] RecThread mpegrecorder.cpp:1010
(run) - MPEGRec(/dev/video0): Device error detected
and
2012-05-27 00:35:32.703992 W [2716/3532] ProcessRequest
mainserver.cpp:5801 (connectionClosed) - MainServer: Unknown socket
closing MythSocket(0x122e580)
2012-05-27 00:35:32.718470 E [2716/3532] ProcessRequest
mythsocket.cpp:358 (writeStringList) - MythSocket(122e580:-1):
writeStringList: Error, socket went unconnected.
We wrote 0 of 10 bytes with 1 errors
starts with: 2 ok
When it finally does fail:
2012-05-27 17:59:47.849584 I [2716/2724] TVRecEvent tv_rec.cpp:1014
(HandleStateChange) - TVRec(1): Changing from None to RecordingOnly
2012-05-27 17:59:47.849651 I [2716/2724] TVRecEvent mythdbcon.cpp:395
(PurgeIdleConnections) - New DB connection, total: 12
2012-05-27 17:59:47.850950 I [2716/2724] TVRecEvent tv_rec.cpp:3456
(TuningCheckForHWChange) - TVRec(1): HW Tuner: 1->1
2012-05-27 17:59:47.870471 I [2716/2724] TVRecEvent v4lchannel.cpp:661
(SetInputAndFormat) - V4LChannel(/dev/video0): SetInputAndFormat(1,
NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-27 17:59:48.033973 N [2716/2725] Scheduler autoexpire.cpp:263
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 2.0 GB
w/freq: 15 min
2012-05-27 17:59:48.043975 I [2716/2724] TVRecEvent tv_rec.cpp:3950
(TuningNewRecorder) - TVRec(1): rec->GetPathname():
'/data/recordings/1003_20120527180000.mpg'
2012-05-27 17:59:48.070399 I [2716/2725] Scheduler scheduler.cpp:2460
(HandleRecordingStatusChange) - Started recording: "KEY News at 6":
channel 1003 on cardid 1, sourceid 1
2012-05-27 17:59:50.991443 E [2716/7354] DeviceReadBuffer
DeviceReadBuffer.cpp:513 (Poll) - DevRdB(/dev/video0): Poll giving up 2
2012-05-27 17:59:50.991528 E [2716/7353] RecThread mpegrecorder.cpp:1010
(run) - MPEGRec(/dev/video0): Device error detected
2012-05-27 17:59:55.941410 E [2716/7355] DeviceReadBuffer
DeviceReadBuffer.cpp:513 (Poll) - DevRdB(/dev/video0): Poll giving up 2
The above repeats until the show is (supposedly) finished recording,
then:
2012-05-27 18:30:18.270742 E [2716/7805] DeviceReadBuffer
DeviceReadBuffer.cpp:460 (Poll) - DevRdB(/dev/video0): poll error
2012-05-27 18:30:18.270811 E [2716/7353] RecThread mpegrecorder.cpp:1010
(run) - MPEGRec(/dev/video0): Device error detected
2012-05-27 18:30:20.737730 E [2716/7806] DeviceReadBuffer
DeviceReadBuffer.cpp:460 (Poll) - DevRdB(/dev/video0): poll error
2012-05-27 18:30:20.763897 I [2716/2716] CoreContext scheduler.cpp:635
(UpdateRecStatus) - Updating status for "KEY News at 6" on cardid 1
(Recording => Recorded)
2012-05-27 18:30:20.772835 I [2716/2724] TVRecEvent
recordinginfo.cpp:1113 (FinishedRecording) - Finished recording KEY News
at 6: channel 1003
So, it thinks it recorded the show, but the file size is 0 and there is
no preview generated.
Occasionally, the show records, but in triplicate: I see three vertical
stripes of the same scene on one screen shot.
I don't think this is a hardware problem because I can make all three of
my PVRs fail eventually (and on two different machines: a master backend
and a slave backend). I'm worried it has some connection with the
database because of the database errors that I see. Also, there may be
some link with how long the tuner has been unused. There is a higher
likelihood of a successful follow-on recording (even with error
messages) if the tuner was used recently. The longer the pause
(overnight), then the higher likelihood that the next recording will
fail
Any help or suggestions would be very much appreciated.
-Kenan
More information about the mythtv-users
mailing list