[mythtv-users] mythtv+hdhomerun records wrong 2nd half of show

Sat Feb 19 02:11:26 UTC 2011

On Fri, Feb 18, 2011 at 1:32 PM, kanetse at gmail.com wrote:
> In the one case where you posted a log, I don't see any channel change
> messages that would cut off Glee prematurely.  Here are some
> suggestions:
I didn't provide the complete logs last time because they
were very verbose... I think I just grepped for started
and finished or something like that to show the sequence
of events.  I provided more log info this time.

>
> 1) Is it possible that something/someone else has taken control of
> HDHR from another PC?
Definitely not.  Only one mythtv system (frontend/backend)
was booted at the time and nobody was messing with it.

>
> 2) Have you tried just deleting all your capture cards in mythtv-setup
> using "Delete all capture cards" and re-adding them? I have found that
> resolves a lot of mysterious recording behaviour.
I have not yet tried that, but I will.  For now, I'll wait just
in case somebody asks me to try something to debug it
while it's in this state (in case you're right about that
fixing the problem).

>
> 3) Could you post the log during the time frame the most recent
> instance?  It would help see what mythtv was trying to do around 8:30
> when it first occurred.

See below.  I provided more complete logs than last time...
this time I only grepped out a bunch of mpeg2video errors
that I get at a rate of more than 10 per second.

>
> 4) I got stung by that HDHR channel changing bug mentioned by Raymond
> as well.  Your symptoms do seem very very similar to those caused by
> the bug.  But if you're sure you're addressing the HDHR by device ID,
> maybe the logs will tell us what's going on.

I used to address by IP address but then after a power outage,
the DHCP server re-assigned the IP address and I changed to
address by device ID after that.  I just double checked and it is still
addressed by device ID and has been for a long time.

Here are the logs:

2011-02-17 20:00:03.577 ProgramInfo(1192_20100917070000.mpg), Error:
GetPlaybackURL: '1192_20100917070000.mpg' should be local, but it can
not be found.
2011-02-17 20:00:03.626 ProgramInfo(1012_20100917170000.mpg), Error:
GetPlaybackURL: '1012_20100917170000.mpg' should be local, but it can
not be found.
2011-02-17 20:00:03.662 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 7 min
2011-02-17 20:00:03.685 ProgramInfo(1192_20100921070000.mpg), Error:
GetPlaybackURL: '1192_20100921070000.mpg' should be local, but it can
not be found.
2011-02-17 20:00:03.708 Started recording: The Vampire Diaries "The
Dinner Party": channel 1012 on cardid 7, sourceid 1
2011-02-17 20:00:03.735 ProgramInfo(1192_20100922070000.mpg), Error:
GetPlaybackURL: '1192_20100922070000.mpg' should be local, but it can
not be found.
2011-02-17 20:00:03.802 ProgramInfo(1192_20100923070000.mpg), Error:
GetPlaybackURL: '1192_20100923070000.mpg' should be local, but it can
not be found.
2011-02-17 20:00:03.834 TVRec(8): rec->GetFileName():
'/var/lib/mythtv/recordings/1033_20110217200000.mpg'
<snip>
2011-02-17 20:26:47.169 ProgramInfo(1012_20110216170000.mpg), Error:
GetPlaybackURL: '1012_20110216170000.mpg' should be local, but it can
not be found.
2011-02-17 20:26:49.025 Reschedule requested for id 0.
2011-02-17 20:26:51.758 Scheduled 702 items in 2.7 = 0.04 match + 2.66 place
2011-02-17 20:28:17.216 ProgramInfo(): Updated pathname '':'' ->
'1007_20110215200000.mpg'
2011-02-17 20:29:00.848 Reschedule requested for id 0.
2011-02-17 20:29:03.558 Scheduled 702 items in 2.7 = 0.04 match + 2.65 place
2011-02-17 20:29:29.909 TVRec(8): ASK_RECORDING 8 29 0 0
2011-02-17 20:29:30.497 TVRec(9): ASK_RECORDING 9 29 0 0
2011-02-17 20:30:00.975 TVRec(8): Changing from RecordingOnly to None
2011-02-17 20:30:01.023 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217200000.mpg'
2011-02-17 20:30:01.055 Finished recording Scrubs "My No Good Reason":
channel 1033
2011-02-17 20:30:01.106 ProgramInfo(1033_20110217200000.mpg), Error:
Unknown type, recording width was 528
2011-02-17 20:30:01.198 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217200000.mpg'
2011-02-17 20:30:01.299 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217200000.mpg'
2011-02-17 20:30:01.347 Finished recording Scrubs "My No Good Reason":
channel 1033
2011-02-17 20:30:01.426 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217200000.mpg'
2011-02-17 20:30:01.433 mythbackend version:
branches/release-0-23-fixes [26437] www.mythtv.org
2011-02-17 20:30:01.488 Using runtime prefix = /usr
2011-02-17 20:30:01.512 Using configuration directory = /home/mythtv/.mythtv
2011-02-17 20:30:01.538 Empty LocalHostName.
2011-02-17 20:30:01.562 Using localhost value of dgl-desktop
2011-02-17 20:30:01.603 New DB connection, total: 1
2011-02-17 20:30:01.636 Connected to database 'mythconverg' at host: localhost
2011-02-17 20:30:01.696 Closing DB connection named 'DBManager0'
2011-02-17 20:30:01.722 Connected to database 'mythconverg' at host: localhost
2011-02-17 20:30:01.750 Current MythTV Schema Version (DBSchemaVer): 1254
2011-02-17 20:30:01.774 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217200000.mpg'
2011-02-17 20:30:02.752 ProgramInfo(): Updated pathname '':'' ->
'1192_20110217203000.mpg'
2011-02-17 20:30:02.753 TVRec(9): Changing from None to RecordingOnly
2011-02-17 20:30:02.815 TVRec(9): HW Tuner: 9->9
2011-02-17 20:30:02.950 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 4 min
2011-02-17 20:30:02.990 Started recording: Maya & Miguel "Abuela
Upmanship": channel 1192 on cardid 9, sourceid 1
2011-02-17 20:30:03.099 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217203000.mpg'
2011-02-17 20:30:03.376 TVRec(8): Changing from None to RecordingOnly
2011-02-17 20:30:03.415 TVRec(8): HW Tuner: 8->8
2011-02-17 20:30:03.501 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 4 min
2011-02-17 20:30:03.540 Started recording: Scrubs "My Long Goodbye":
channel 1033 on cardid 8, sourceid 1
2011-02-17 20:30:03.581 TVRec(9): rec->GetFileName():
'/var/lib/mythtv/recordings/1192_20110217203000.mpg'
2011-02-17 20:30:03.697 ProgramInfo(1063_20100502120000.mpg), Error:
GetPlaybackURL: '1063_20100502120000.mpg' should be local, but it can
not be found.
2011-02-17 20:30:03.732 ProgramInfo(1063_20100502130000.mpg), Error:
GetPlaybackURL: '1063_20100502130000.mpg' should be local, but it can
not be found.
2011-02-17 20:30:03.762 ProgramInfo(1063_20100515153000.mpg), Error:
GetPlaybackURL: '1063_20100515153000.mpg' should be local, but it can
not be found.
<snip>
2011-02-17 20:59:00.823 Reschedule requested for id 0.
2011-02-17 20:59:03.798 Scheduled 700 items in 3.0 = 0.30 match + 2.66 place
2011-02-17 20:59:30.016 TVRec(8): ASK_RECORDING 8 29 0 0
2011-02-17 20:59:30.272 TVRec(7): ASK_RECORDING 7 29 0 0
2011-02-17 20:59:30.413 TVRec(10): ASK_RECORDING 10 29 0 0
2011-02-17 20:59:30.561 TVRec(9): ASK_RECORDING 9 29 0 0
2011-02-17 21:00:00.122 TVRec(8): Changing from RecordingOnly to None
2011-02-17 21:00:00.364 TVRec(7): Changing from RecordingOnly to None
2011-02-17 21:00:00.379 ProgramInfo(): Updated pathname '':'' ->
'1033_20110217203000.mpg'
2011-02-17 21:00:00.496 ProgramInfo(): Updated pathname '':'' ->
'1012_20110217200000.mpg'
2011-02-17 21:00:00.520 Finished recording Scrubs "My Long Goodbye":
channel 1033
2011-02-17 21:00:00.545 Finished recording The Vampire Diaries "The
Dinner Party": channel 1012

Thanks,

      Dave