Auto-Expire not working

Pixel Eyes

Pixel Eyes

Member
I have scheduled the daily recording of two radio programmes. Auto-Expire is set on their respective folders (Remove recordings after 2 days, keep at least 2 recordings) but the recordings are accumulating and do not in fact get removed. 'Never delete unwatched recordings' is unchecked.

Any help would be appreciated.

Custom firmware version: 3.10 (build 2734)
 
Increase the log level for automatic processing to debugging (webif->settings->automatic processing settings) wait up to 20 minutes for it to run again then have a look in the auto.log log file (webif->Diagnostics). That should let us know what's going on.
 
OK done that. The auto.log loop starts with
Code: 
21/01/2017 11:45:02 - -------------------------------------------------------
21/01/2017 11:45:02 - DLNA Server is running.
21/01/2017 11:45:02 - Auto processing starting, DLNA server status: 1
21/01/2017 11:45:02 - Dustbin:
21/01/2017 11:45:02 - Root device: 2050
21/01/2017 11:45:02 - Processing queue...
21/01/2017 11:45:02 - decrypt scan starting.
21/01/2017 11:45:02 -   [/media/My Video]
21/01/2017 11:45:02 -     (R)
21/01/2017 11:45:02 - DECRYPT: [/media/My Video]
It finds that everything is already decrypted, and concludes with:
Code: 
21/01/2017 11:47:52 - decrypt scan completed in 169.843 seconds.
21/01/2017 11:47:52 - dedup scan starting.
21/01/2017 11:47:52 -   [/media/My Video]
21/01/2017 11:47:52 -     [/media/My Video/Last Tango in Halifax]
21/01/2017 11:47:52 -     [/media/My Video/Humans]
21/01/2017 11:47:52 -     [/media/My Video/The Fall]
21/01/2017 11:47:52 - DEDUP: [/media/My Video/The Fall]
21/01/2017 11:47:53 -       [/media/My Video/The Fall/Watched]
21/01/2017 11:47:53 - Running unwatched recalculation for /media/My Video/The Fall/Watched
21/01/2017 11:47:53 -     [/media/My Video/Coronation Street]
21/01/2017 11:47:53 - DEDUP: [/media/My Video/Coronation Street]
21/01/2017 12:05:02 - Registered ::newk::scan for postexpirescan hook with priority 50.

I am pretty sure it has behaved properly until recently; I presume this is an example:

Code: 
21/12/2016 13:00:12 - autotrigger[11353]:      EXPIRE: removed /media/My Video/Lauren Laverne/Mary Anne Hobbs_20161219_1000.ts

But then there are entries like this where it is deleting a recording which is has survived for 11 days:

Code: 
03/01/2017 16:08:21 - autotrigger[13025]:      EXPIRE: removed /media/My Video/The Radcliffe and Maconie Show/The Radcliffe and Maconie Show_20161223_1300.ts

I have been deleting some of the radio recordings manually, but right now for example there are four recordings in each of the two folders. The oldest was recorded 16 January, ie more than 2 days ago.

What's going on?
 
I'd be happy to give the webif beta a try. Sorry but I don't know how to install it. I have installed opkg-beta but not sure where to go from there.
 
It took a bit of head scratching before I realised it needed a reboot to make the beta WebIF available in Package Management!

My T2 is now running 1.4.0 but I can't see auto.log in the list of log files any more.
 
Right, I looked again this morning, and there is an auto.log file once more. Here is an extract

Code: 
23/01/2017 00:05:19 - autotrigger[7861]: got lock
23/01/2017 00:05:19 - autotrigger[7861]: Auto processing starting
23/01/2017 00:05:19 - autotrigger[7861]: Registered decrypt with priority 600 (::decrypt::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered dedup with priority 800 (::dedup::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered expire with priority 900 (::expire::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered mp3 with priority 300 (::mp3::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered mpg with priority 300 (::mpg::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered shrink with priority 400 (::shrink::run)
23/01/2017 00:05:19 - autotrigger[7861]: Registered newk with priority 850 (::newk::scan)
23/01/2017 00:05:19 - autotrigger[7861]: Legacy plugins in use - newk
23/01/2017 00:05:19 - autotrigger[7861]: Scanning media for flags...
23/01/2017 00:05:20 - autotrigger[7861]: Scan completed (0.463 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: Active flags: decryptr dedup expire mp3
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video                                                                  - decryptr
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/The Fall                                                         - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Coronation Street                                                - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/American Restoration                                             - expire
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Aircraft Stories                                                 - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Mighty Planes                                                    - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/How We Got to Now with Steven Johnson                            - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Ordinary Lies                                                    - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Lauren Laverne                                                   - mp3 expire
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Kim Philby - His Most Intimate Betrayal                          - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/How It's Made                                                    - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/University Challenge                                             - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Later with Jools Holland                                         - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Later Live with Jools Holland                                    - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Justified                                                        - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/The Hollow Crown_ Richard II                                     - dedup
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/The Radcliffe and Maconie Show                                   - expire
23/01/2017 00:05:20 - autotrigger[7861]: /media/My Video/Cuffs                                                            - dedup
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::expire::rundir (Priority 900)
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::expire::rundir (0.004 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::dedup::rundir (Priority 800)
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::dedup::rundir (0.001 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::decrypt::rundir (Priority 600)
23/01/2017 00:05:20 - autotrigger[7861]: No decrypt flags in filesystem, suppressing scan.
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::decrypt::rundir (0.002 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::shrink::rundir (Priority 400)
23/01/2017 00:05:20 - autotrigger[7861]: No shrink flags in filesystem, suppressing scan.
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::shrink::rundir (0.002 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::mp3::rundir (Priority 300)
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::mp3::rundir (0.001 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: ********************************************************
23/01/2017 00:05:20 - autotrigger[7861]: *********> ::mpg::rundir (Priority 300)
23/01/2017 00:05:20 - autotrigger[7861]: No mpg flags in filesystem, suppressing scan.
23/01/2017 00:05:20 - autotrigger[7861]: <********* ::mpg::rundir (0.003 seconds)
23/01/2017 00:05:20 - autotrigger[7861]: Auto processing completed in 0.646 seconds.
23/01/2017 00:05:20 - autotrigger[7861]: done
The two folders still contain recordings which should have been automatically deleted.
 
That's an extract from a triggered run which only looks at a specific directory. Can you find an extract from one of the scheduled runs (every 10 minutes unless you've changed the default and without the 'autotrigger' bit)?
 
Every line in my auto.log says 'autotrigger'.

I have just noticed that in the last hour the files in the Lauren Laverne folder have expired correctly
Code: 
23/01/2017 13:00:11 - autotrigger[6422]: ********************************************************
23/01/2017 13:00:11 - autotrigger[6422]: *********> ::expire::rundir (Priority 900)
23/01/2017 13:00:11 - autotrigger[6422]: EXPIRE: [/media/My Video/Lauren Laverne]
23/01/2017 13:00:11 - autotrigger[6422]:   type 0 keep 2 days 2 keepnew 0
23/01/2017 13:00:11 - autotrigger[6422]:       Entries: 5
23/01/2017 13:00:11 - autotrigger[6422]:         Lauren Laverne_20170117_0959.ts
23/01/2017 13:00:11 - autotrigger[6422]:         Lauren Laverne_20170118_0959.ts
23/01/2017 13:00:11 - autotrigger[6422]:         Lauren Laverne_20170119_0959.ts
23/01/2017 13:00:11 - autotrigger[6422]:         Lauren Laverne_20170120_0959.ts
23/01/2017 13:00:11 - autotrigger[6422]:         Lauren Laverne_20170123_0959.ts
23/01/2017 13:00:11 - autotrigger[6422]:       Lauren Laverne_20170117_0959.ts
23/01/2017 13:00:12 - autotrigger[6422]:         6.00013888889 days (cf. 2)
23/01/2017 13:00:12 - autotrigger[6422]:         Removing.
23/01/2017 13:00:15 - autotrigger[6422]:      EXPIRE: removed /media/My Video/Lauren Laverne/Lauren Laverne_20170117_0959.ts
23/01/2017 13:00:15 - autotrigger[6422]:       Lauren Laverne_20170118_0959.ts
23/01/2017 13:00:15 - autotrigger[6422]:         5.00015046296 days (cf. 2)
23/01/2017 13:00:15 - autotrigger[6422]:         Removing.
23/01/2017 13:00:21 - autotrigger[6422]:      EXPIRE: removed /media/My Video/Lauren Laverne/Lauren Laverne_20170118_0959.ts
23/01/2017 13:00:21 - autotrigger[6422]:       Lauren Laverne_20170119_0959.ts
23/01/2017 13:00:22 - autotrigger[6422]:         4.00013888889 days (cf. 2)
23/01/2017 13:00:22 - autotrigger[6422]:         Removing.
23/01/2017 13:00:27 - autotrigger[6422]:      EXPIRE: removed /media/My Video/Lauren Laverne/Lauren Laverne_20170119_0959.ts
23/01/2017 13:00:27 - autotrigger[6422]:     Remaining (2) <= keep (2)
23/01/2017 13:00:27 - autotrigger[6422]: <********* ::expire::rundir (16.303 seconds)
23/01/2017 13:00:27 - autotrigger[6422]: ********************************************************
However, the Radcliffe and Maconie folder has not been processed.
 
Pixel Eyes said:
Every line in my auto.log says 'autotrigger'.
Click to expand...
That's unusual, it should be doing an entire media scan every 10 minutes (or whatever interval you've set in the settings page).
In the log you just posted, I'd guess that it had just finished recording an episode of LL - that's what triggered the expire run on that specific folder.

My best guess is that the cron service is not running on your machine, could you post the output of the crontab diagnostic? (Run it via web interface->Diagnostics, then enter crontab in the box (where the word 'general' is) and click 'Run Diagnostic')
 
af123 said:
I'd guess that it had just finished recording an episode of LL
Click to expand...

You are right because the Radcliffe and Maconie folder was processed at 16:05 when today's recording finished.

Here is the crontab output
Code: 
>>> Beginning diagnostic crontab

Running: crontab
1136 crond
=================
0 2 * * * /mod/sbin/anacron -s -d
10-59/20 * * * * /mod/bin/chaseget -standby>/dev/null 2>&1
* * * * * /mod/monitor/run
8-59/20 * * * * /mod/webif/plugin/detectads/detectads -pq>/dev/null 2>&1
5,25,45 * * * * /mod/webif/lib/bin/auto >/dev/null 2>&1
=================


>>> Ending diagnostic crontab
 
Yep, you're missing a line or two.. strange.
I'm about to upload a new beta package so can you upgrade webif and check the crontab diagnostic again to see if it changes?
 
Upgraded to web interface version 1.4.0-1.

Here's the crontab output now
Code: 
>>> Beginning diagnostic crontab

Running: crontab
1254 crond
=================
0 2 * * * /mod/sbin/anacron -s -d
10-59/20 * * * * /mod/bin/chaseget -standby>/dev/null 2>&1
* * * * * /mod/monitor/run
8-59/20 * * * * /mod/webif/plugin/detectads/detectads -pq>/dev/null 2>&1
5,25,45 * * * * /mod/webif/lib/bin/auto >/dev/null 2>&1
=================


>>> Ending diagnostic crontab
 
No change!
Can you try doing a force-reinstall of the cron-daemon package followed by webif?
You can do this from the Diagnostics web page by putting the package name in the box near the top.
 
Both reinstalled. However, crontab output and auto.log still look the same to me. At least now expire runs after each recording finishes.

(By the way, this may be a red herring but whenever I install a package I have to manually restart lighttpd using Telnet.)
 
Pixel Eyes said:
By the way, this may be a red herring but whenever I install a package I have to manually restart lighttpd using Telnet.
Click to expand...
Why didn't you say that to start with? No it's not a red herring. It's the cause of packages not installing properly.
Run "opkg update" and "opkg upgrade" from the command prompt and then force reinstall Webif.
 
Pixel Eyes said:
(By the way, this may be a red herring but whenever I install a package I have to manually restart lighttpd using Telnet.)
Click to expand...
Aha! That will explain it.
Get onto the command line via telnet and type:

opkg upgrade webif

or actually, just opkg upgrade if you want to upgrade everything. That should allow the web server to finish upgrading and then everything else should follow.
 
prpr said:
Run "opkg update" and "opkg upgrade" from the command prompt and then force reinstall Webif.
Click to expand...
I have done that and my crontab now looks like this
Code: 
>>> Beginning diagnostic crontab

Running: crontab
1176 crond
2063 crond
=================
0 2 * * * /mod/sbin/anacron -s -d
* * * * * /mod/monitor/run
10-59/20 * * * * /mod/bin/chaseget -standby>/dev/null 2>&1
8 * * * * /mod/webif/plugin/detectads/detectads -pq>/dev/null 2>&1
* * * * * /mod/webif/lib/auto/scan >/dev/null 2>&1
* * * * * /mod/webif/lib/auto/deq >/dev/null 2>&1
=================


>>> Ending diagnostic crontab
Plus the auto.log now looks very different.

I did get a warning that the disk pending sector count is 1 and the disc offline sector count is 1, but everything is performing well.

I'm a happy bunny now so thanks very much for the expert guidance!
 
You must log in or register to reply here.
Back
Top