[mythtv-users] auto-expire after N days isn't expiring

[Jerome Yuzyk]

On Thursday, April 13, 2017 7:13:43 PM MDT Jerome Yuzyk wrote:
> On Thursday, April 13, 2017 6:18:04 PM MDT Michael T. Dean wrote:
> > On 04/13/2017 01:42 PM, Jerome Yuzyk wrote:
> > > On Thursday, April 13, 2017 11:17:52 AM MDT Jerome Yuzyk wrote:
> > >> [0.28.10 on Fedora 23]
> > >> 
> > >> I upgraded to 0.28.10 the other day and now my deleted recordings
> > >> aren't
> > >> expiring after 2 days like they used to. I've had this problem before
> > >> but
> > >> a
> > >> backend restart solved it. This time a restart doesn't solve it - I've
> > >> done
> > >> a couple and seen several "AutoExpire: CalcParams(): Max required Free
> > >> Space: 1.0 GB w/freq: 15 min" messages logged. I've checked my 
settings
> > >> and
> > >> they are as before.
> > >> 
> > >> What to check next?
> > > 
> > > I thought I'd try manually deleting one of the recordings queued for
> > > expiry
> > > and saw this logged:
> > > 
> > > Apr 13 11:36:23 tv mythbackend: 2017-04-13 11:36:23.692065 N
> > > DeleteRecordedFiles - recording id 138 filename /recording/tv/
> > > 2041_20170412090000.mpg
> > > Apr 13 11:36:23 tv mythbackend: 2017-04-13 11:36:23.694149 N 
> > > DoDeleteINDB
> > > - recording id 138 (chanid 2041 at 2017-04-12T09:00:00Z)
> > > Apr 13 11:36:28 tv mythbackend: 2017-04-13 11:36:27.976324 C
> > > ProgramInfo(): Failed to find recorded entry for 138.
> > > 
> > > The recording appears to have been deleted though, according to disk
> > > activity - reads and intermittent writes for slow-delete file
> > > truncation.
> > > But whatever controls expiry hasn't woken up.
> > 
> > Orphaned recording metadata for a ready-to-expire recording has been
> > known to cause problems with expiration (stopping it altogether in some
> > cases).  I suggest running find_orphans.py .
> > 
> > https://www.mythtv.org/wiki/Find_orphans.py
> > 
> > Mike
> 
> After all these years I may have a use for that script. I went and did the
> deletes manually, and nearly every one reported something like below, after
> the deletion was done, for some time after.
> 
> Apr 13 17:55:20 tv mythbackend: 2017-04-13 17:55:20.364197 C  
ProgramInfo():
> Failed to find recorded entry for 140.
> 
> I'll have to look at it more tomorrow.

I ran Find_orphans.py and all I got was a list of 2 backups it found, which 
indicates there are no orphans.

However, I just noticed an auto-expire started, the first since I noticed 
they weren't being done. It is actually deleting, with the same pattern of 
disk activity I've seen before.

Apr 15 21:45:45 tv mythbackend: 2017-04-15 21:45:45.073483 N  Expiring 22123 
MB for 2004 at 2017-04-13T23:00:00Z => "NHL Hockey":"Toronto Maple Leafs at 
Washington Capitals"
Apr 15 21:45:48 tv mythbackend: 2017-04-15 21:45:48.225899 N  
DeleteRecordedFiles - recording id 147 filename /recording/tv/
2004_20170413230000.ts
Apr 15 21:45:48 tv mythbackend: 2017-04-15 21:45:48.264264 N  DoDeleteINDB - 
recording id 147 (chanid 2004 at 2017-04-13T23:00:00Z)
Apr 15 21:45:59 tv mythbackend: 2017-04-15 21:45:59.213666 C  ProgramInfo(): 
Failed to find recorded entry for 147.

Note the "Failed to find" message though, like what I've had before, even 
while the deletion is ongoing.

-- 
A little of Jerome's MythTV World: http://mythtv.bss.ab.ca