Force DLNA Index, Auto Decrypt, Auto Shrink

I have (for the first time) dipped my toe into pre-indexing decryption (not that my boxes haven't been doing it, just that I have not tried to benefit from it so far).

I record the local bulletins on Breakfast at about 8 each weekday morning for Wales and West, using manual timers, which Sweeper then shovels into my [NEWS] folder and Auto-expire is set on it. If I want to view them, I usually do so remotely by virtual USB mount.

This morning, shortly after 8 (having watched the West bulletin live), I decided to see what pre-indexing decryption might have done for me. Previously I have had to wait for the DLNA index to catch up with the recordings being moved to [NEWS] before they were viewable remotely (by DLNA) or could be decrypted and viewable by remote file mount. The West recording played fine, but the Wales recording got the black screen typically associated with an encrypted file.

Here are edited highlights of the log file (the full version is available attached):
Code: 
23/04/2015 08:02:05 - autotrigger[16108]: Media scan starting, DLNA server status: 1
23/04/2015 08:02:05 - autotrigger[16108]: Scanning single directory '/media/My Video'
23/04/2015 08:02:05 - autotrigger[16108]:   /media/My Video/Breakfast_20150423_0755.ts - Not yet indexed, trying helper.
23/04/2015 08:02:06 - autotrigger[16108]:   DECRYPT: /media/My Video/Breakfast_20150423_0755
23/04/2015 08:02:06 - autotrigger[16108]:   DLNA: http://192.168.1.13:9000/web/media/11116.TS
23/04/2015 08:02:10 - autotrigger[16226]: will run for /media/My Video
23/04/2015 08:02:41 - autotrigger[16108]:   Removing/binning old copy.
23/04/2015 08:02:41 - autotrigger[16108]: Done... 211.71 MiB in 35.045 seconds - 6.04 MiB/s
~~~
23/04/2015 08:02:42 - autotrigger[16108]:   /media/My Video/Breakfast_20150423_0755(1).ts - Not yet indexed, trying helper.
23/04/2015 08:02:42 - autotrigger[16108]:   DECRYPT: /media/My Video/Breakfast_20150423_0755(1)
23/04/2015 08:02:42 - autotrigger[16108]:   DLNA: http://192.168.1.13:9000/web/media/11117.TS
23/04/2015 08:03:18 - autotrigger[16108]:   /media/My Video/Breakfast_20150423_0755(1).ts - In use.
~~~
23/04/2015 08:03:20 - autotrigger[16108]: move /media/My Video/Breakfast_20150423_0755.ts to [NEWS]
23/04/2015 08:03:20 - autotrigger[16108]: moveset(/media/My Video/Breakfast_20150423_0755.ts) -> /media/My Video/[NEWS]
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755.hmt
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755.nts
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755.ts
23/04/2015 08:03:20 - autotrigger[16108]: move /media/My Video/Breakfast_20150423_0755(1).ts to [NEWS]
23/04/2015 08:03:20 - autotrigger[16108]: moveset(/media/My Video/Breakfast_20150423_0755(1).ts) -> /media/My Video/[NEWS]
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755(1).hmt
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755(1).nts
23/04/2015 08:03:20 - autotrigger[16108]:  ....... /media/My Video/Breakfast_20150423_0755(1).ts
23/04/2015 08:03:20 - autotrigger[16108]: Resetting unwatched recording flag for /media/My Video/[NEWS]
23/04/2015 08:03:22 - autotrigger[16108]: Resetting unwatched recording flag for /media/My Video
23/04/2015 08:03:22 - autotrigger[16108]: decrypt scan completed in 76.815 seconds.
23/04/2015 08:05:02 - Media scan starting, DLNA server status: 1
23/04/2015 08:05:02 - decrypt scan starting.
23/04/2015 08:05:05 -   /media/My Video/[NEWS]/Breakfast_20150423_0755(1).ts - Not yet indexed, trying helper.
23/04/2015 08:05:06 -   DECRYPT: /media/My Video/[NEWS]/Breakfast_20150423_0755(1)
23/04/2015 08:05:06 -   DLNA: http://192.168.1.13:9000/web/media/11119.TS
23/04/2015 08:05:34 -   Removing/binning old copy.
23/04/2015 08:05:35 - Done... 200.13 MiB in 29.351 seconds - 6.82 MiB/s
~~~
23/04/2015 08:25:02 - Media scan starting, DLNA server status: 1
23/04/2015 08:25:02 - decrypt scan starting.
23/04/2015 08:25:05 -   /media/My Video/[NEWS]/Breakfast_20150423_0755(1).ts - already decrypted but the HMT flag is wrong.
23/04/2015 08:25:09 - decrypt scan completed in 6.868 seconds.

At 08:02:05 the system finds the West recording and decrypts it before it is moved to [NEWS]. At 08:02:42 it finds the Wales recording, but decryption aborts because the file is "in use". I'm not sure why that is - when I was trying to play these files, I was accessing them in the [NEWS] folder and at this point they have not yet been moved (according to the log).

At 08:03:20 sweeper moves the files to [NEWS], then the system has another go at decrypting the Wales recording pre-index. It still won't play remotely though, and at 08:25:02 the system discovered that the .hmt file is out of sync (and presumably corrects it, because the file plays after that).

So: why did the file appear to be in use, and why did the .hmt end up out of sync?
 

Attachments

  • auto.txt
    20.2 KB · Views: 3
Black Hole said:
So: why did the file appear to be in use...?
Click to expand...
I'm not sure. It wasn't in use very shortly afterwards when sweeper ran as it was able to move the file. It's possible that the Humax software was indexing it at that point.
There is a second auto-trigger (16226) for the second recording waiting in the wings at that point but it shouldn't have been holding the file open. (When that second one did get a chance to run, at 08:03:26, it found nothing to do as the previous auto-triggered run had already moved the file.)
why did the .hmt end up out of sync?
Click to expand...
I don't know the answer to this one either (yet!)

This sounds like a useful test case. I will make some changes to put more information in the logs and can you then see what happens tomorrow?

I thought it was possible to copy and paste the log from the new viewer but I can't test at the moment. A download button is a good idea too.
 
MymsMan said:
It is not directly relevant to live streaming but getting the bugs out of the dlna helper function is an important precursor to any progress on live streaming.

My, limited, experiments so far show that it is possible to access the current recording stream using the technique outlined by oatcakes but not the entire recording. If you start accessing the recording in VLC fifteen minutes after the start you will happily see the first 15 minutes but not the 15 minutes of additional recording whilst you were watching the start of the show - to see that you would need to restart and skip the first 15 minutes.

My interest is not streaming for network viewing per se but being able to access the decrypted stream so that ad breaks can be detected whilst the recording is in progress. I have ideas of how to handle the problem for detectads but not for network streaming in general.
Click to expand...
Thanks for the explanation.
 
@af123: with this pre-indexing decryption, would it be better to let flatten, sweeper, etc (ie the fast things) do their stuff before decryption, detectads, etc spend time trying to process them?
 
Black Hole said:
@af123: with this pre-indexing decryption, would it be better to let flatten, sweeper, etc (ie the fast things) do their stuff before decryption, detectads, etc spend time trying to process them?
Click to expand...

Possibly, but there are potential issues and it would be a visible change in behaviour as @MymsMan observed a few posts ago:

MymsMan said:
The reason Flatten and Sweeper were originally moved to be post-decryption scans was because moving/renaming recordings invalidated the dlna index and thus made the eventual running of decryption slow and unpredictable. Now with the new index helper function the index invalidation is no longer such an issue and there is no real reason that Flatten and Sweeper couldn't be run pre-decryption scan.

This would actually be quite a trivial change to make in the .hook files though it might be best to make it a Settings option since some users might not have the autodecrypt flag set for the target folders of the move/copy.

The fly in the ointment is that the autotrigger scans only look in the original folder and wouldn't find the moved files ;)
Click to expand...
 
af123 said:
I thought it was possible to copy and paste the log from the new viewer but I can't test at the moment. A download button is a good idea too.
Click to expand...

It is possible to copy and paste from the new viewer but while it is fine with small log files it is quite slow to load with larger files and 5000 lines only covers a few hours of the auto log with full tracing turned on so I have switched to viewing them with my full text editor via FTP.
 
MymsMan said:
Have there been any further thoughts on how to trigger a rescan?

My goal is to be able to watch Countdown without ads with our afternoon cup of teas at 3:30.
Click to expand...
A lot has happened since I reopened this thread less than a month ago!

My thanks to everyone who has contributed and especially to Oatcake for the idea of using helper files and af123 for the implementation.

I am pleased to report that today Countdown finished processing and was ad free by 15:23 well inside my original goal - I couldn't see any signs of errors in the logs.

However my new goal is to be able to start watching it ad free an hour earlier at 14:30 which I believe should now be feasible...
 
@Black Hole - new version of webif available which adds a bit of extra logging, will check a file which 'in-use' for 5 seconds in case it's transient and adds a button to the log viewer which will download the entire log.
 
It all worked fine today, possibly because I made certain not to try to play anything until it was decrypted:
Code: 
24/04/2015 07:45:19 - Media scan completed in 17.289 seconds.
24/04/2015 08:02:05 - autotrigger[24648]: /media/My Video/Breakfast_20150424_0755(1)
24/04/2015 08:02:05 - autotrigger[24648]: will run for /media/My Video
24/04/2015 08:02:05 - autotrigger[24648]: got lock
24/04/2015 08:02:05 - autotrigger[24648]: Registered do_arbookmarks for postdecrypt hook with priority 50.
24/04/2015 08:02:05 - autotrigger[24648]: Registered ::sweeper::scan for postdecryptscan hook with priority 50.
24/04/2015 08:02:05 - autotrigger[24648]: Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
24/04/2015 08:02:05 - autotrigger[24648]: -------------------------------------------------------
24/04/2015 08:02:05 - autotrigger[24648]: Media scan starting, DLNA server status: 1
24/04/2015 08:02:05 - autotrigger[24648]: Scanning single directory '/media/My Video'
24/04/2015 08:02:06 - autotrigger[24648]:   /media/My Video/Breakfast_20150424_0755(1).ts - has been indexed.
24/04/2015 08:02:06 - autotrigger[24648]:   DECRYPT: /media/My Video/Breakfast_20150424_0755(1)
24/04/2015 08:02:06 - autotrigger[24648]:   DLNA: http://127.0.0.1:9000/web/media/11133.TS
24/04/2015 08:02:11 - autotrigger[24761]: /media/My Video/Breakfast_20150424_0755
24/04/2015 08:02:11 - autotrigger[24761]: will run for /media/My Video
24/04/2015 08:02:41 - autotrigger[24648]:   Removing/binning old copy.
24/04/2015 08:02:41 - autotrigger[24648]: Done... 198.71 MiB in 35.088 seconds - 5.66 MiB/s
24/04/2015 08:02:41 - autotrigger[24648]:   ARBOOKMARK: /media/My Video/Breakfast_20150424_0755(1)
24/04/2015 08:02:41 - autotrigger[24648]: Recording was not padded, cannot process.
24/04/2015 08:02:41 - autotrigger[24648]: Processed in: 0.16s
24/04/2015 08:02:41 - autotrigger[24648]: Done...
24/04/2015 08:02:42 - autotrigger[24648]:   /media/My Video/Breakfast_20150424_0755.ts - Not yet indexed, trying helper.
24/04/2015 08:02:43 - autotrigger[24648]:   /media/My Video/Breakfast_20150424_0755.ts - database is locked
24/04/2015 08:02:43 - autotrigger[24648]:   /media/My Video/Breakfast_20150424_0755.ts - Can't use helper.
24/04/2015 08:02:43 - autotrigger[24648]: move /media/My Video/Breakfast_20150424_0755(1).ts to [NEWS]
24/04/2015 08:02:43 - autotrigger[24648]: moveset(/media/My Video/Breakfast_20150424_0755(1).ts) -> /media/My Video/[NEWS]
24/04/2015 08:02:43 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755(1).hmt
24/04/2015 08:02:43 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755(1).nts
24/04/2015 08:02:43 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755(1).ts
24/04/2015 08:02:43 - autotrigger[24648]: move /media/My Video/Breakfast_20150424_0755.ts to [NEWS]
24/04/2015 08:02:43 - autotrigger[24648]: moveset(/media/My Video/Breakfast_20150424_0755.ts) -> /media/My Video/[NEWS]
24/04/2015 08:02:43 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755.hmt
24/04/2015 08:02:44 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755.nts
24/04/2015 08:02:44 - autotrigger[24648]:  ....... /media/My Video/Breakfast_20150424_0755.ts
24/04/2015 08:02:44 - autotrigger[24648]: Resetting unwatched recording flag for /media/My Video/[NEWS]
24/04/2015 08:02:45 - autotrigger[24648]: Resetting unwatched recording flag for /media/My Video
24/04/2015 08:02:45 - autotrigger[24648]: decrypt scan completed in 39.446 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: dedup scan completed in 0.012 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: shrink scan completed in 0.021 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: mpg scan completed in 0.012 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: mp3 scan completed in 0.014 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: expire scan completed in 0.013 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: Media scan completed in 39.631 seconds.
24/04/2015 08:02:45 - autotrigger[24648]: done
24/04/2015 08:02:46 - autotrigger[24761]: got lock
24/04/2015 08:02:47 - autotrigger[24761]: Registered do_arbookmarks for postdecrypt hook with priority 50.
24/04/2015 08:02:47 - autotrigger[24761]: Registered ::sweeper::scan for postdecryptscan hook with priority 50.
24/04/2015 08:02:47 - autotrigger[24761]: Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
24/04/2015 08:02:47 - autotrigger[24761]: -------------------------------------------------------
24/04/2015 08:02:47 - autotrigger[24761]: Media scan starting, DLNA server status: 1
24/04/2015 08:02:47 - autotrigger[24761]: Scanning single directory '/media/My Video'
24/04/2015 08:02:47 - autotrigger[24761]: decrypt scan completed in 0.025 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: dedup scan completed in 0.013 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: shrink scan completed in 0.012 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: mpg scan completed in 0.015 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: mp3 scan completed in 0.013 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: expire scan completed in 0.015 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: Media scan completed in 0.19 seconds.
24/04/2015 08:02:47 - autotrigger[24761]: done
24/04/2015 08:05:02 - Registered do_arbookmarks for postdecrypt hook with priority 50.
24/04/2015 08:05:02 - Registered ::sweeper::scan for postdecryptscan hook with priority 50.
24/04/2015 08:05:02 - Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
24/04/2015 08:05:02 - -------------------------------------------------------
24/04/2015 08:05:02 - Media scan starting, DLNA server status: 1
24/04/2015 08:05:02 - decrypt scan starting.
24/04/2015 08:05:05 -   /media/My Video/[NEWS]/Breakfast_20150424_0755.ts - Not yet indexed, trying helper.
24/04/2015 08:05:05 -   DECRYPT: /media/My Video/[NEWS]/Breakfast_20150424_0755
24/04/2015 08:05:05 -   DLNA: http://192.168.1.13:9000/web/media/11135.TS
24/04/2015 08:05:35 -   Removing/binning old copy.
24/04/2015 08:05:35 - Done... 213.3 MiB in 30.292 seconds - 7.04 MiB/s
24/04/2015 08:05:35 -   ARBOOKMARK: /media/My Video/[NEWS]/Breakfast_20150424_0755
24/04/2015 08:05:35 - Recording was not padded, cannot process.
24/04/2015 08:05:35 - Processed in: 0.05s
24/04/2015 08:05:35 - Done...
24/04/2015 08:05:41 - decrypt scan completed in 39.046 seconds.

This time the Wales recording decrypted first, and it had been indexed (before it was moved). The West decryption was baulked first try, but I'm not sure what triggered the successful decryption at 08:05:02 - normal auto schedule?
 
Yes, that was the normal schedule (no leading autotrigger indicates scheduled scan).
Shame it couldn't decrypt in one pass due to locked database - will have to see if that can be overcome.
 
I noticed this in the auto log:
Code: 
26/04/2015 22:02:06 - autotrigger[3339]:   DECRYPT: /media/My Video/Vera/Vera_20150426_2002
26/04/2015 22:02:06 - autotrigger[3339]:   DLNA: http://192.168.0.9:9000/web/media/440.TS
26/04/2015 22:09:10 - autotrigger[3339]:   Removing/binning old copy.
26/04/2015 22:09:12 - autotrigger[3339]: Done... 3.38 GiB in 425.471 seconds - 8.14 MiB/s
26/04/2015 22:09:19 - autotrigger[3747]:   DECRYPT: /media/My Video/Indiana Jones and the Last Crusade_20150426_2003
26/04/2015 22:09:19 - autotrigger[3747]:   DLNA: http://127.0.0.1:9000/web/media/440.TS
26/04/2015 22:19:27 - autotrigger[3747]:   Removing/binning old copy.
26/04/2015 22:19:28 - autotrigger[3747]: Done... 5.33 GiB in 609.783 seconds - 8.96 MiB/s
Two programmes that finished at similar times were decrypted and appear to have been given the same DLNA index number (440). The second programme was actually given number 441, so it is either a logging error, or the system detected that the number had already been used and allocated another. Both were 'autotrigger' events but the URL of the first included the unit's actual IP address (192.168.0.9) while the second used '127.0.0.1'.
 
I presume these were decrypted using the helper files, which would have the same DLNA index. They would have been re-allocated index numbers when properly indexed (maybe re-using the first index because by then the helper files were deleted).
 
Black Hole said:
I presume these were decrypted using the helper files, which would have the same DLNA index. They would have been re-allocated index numbers when properly indexed (maybe re-using the first index because by then the helper files were deleted).
Click to expand...
Spot on!
 
Well, this morning the bulletins both failed to decrypt on the auto-trigger at 0802, sweeper moved and renamed them, then by the routine scan at 0805 they had been indexed! Explain that one :confused:
Code: 
28/04/2015 07:45:13 - Media scan completed in 11.859 seconds.

28/04/2015 08:02:04 - autotrigger[7160]: /media/My Video/Breakfast_20150428_0755(1)
28/04/2015 08:02:04 - autotrigger[7160]: will run for /media/My Video
28/04/2015 08:02:04 - autotrigger[7160]: got lock
28/04/2015 08:02:04 - autotrigger[7160]: Registered do_arbookmarks for postdecrypt hook with priority 50.
28/04/2015 08:02:04 - autotrigger[7160]: Registered ::sweeper::scan for postdecryptscan hook with priority 50.
28/04/2015 08:02:04 - autotrigger[7160]: Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
28/04/2015 08:02:04 - autotrigger[7160]: -------------------------------------------------------
28/04/2015 08:02:05 - autotrigger[7160]: Media scan starting, DLNA server status: 1
28/04/2015 08:02:05 - autotrigger[7160]: Scanning single directory '/media/My Video'
28/04/2015 08:02:05 - autotrigger[7160]:   /media/My Video/Breakfast_20150428_0755(1).ts - Not yet indexed, trying helper.
28/04/2015 08:02:05 - autotrigger[7160]:   /media/My Video/Breakfast_20150428_0755(1).ts - database is locked
28/04/2015 08:02:05 - autotrigger[7160]:   /media/My Video/Breakfast_20150428_0755(1).ts - Can't use helper.
28/04/2015 08:02:06 - autotrigger[7160]:   /media/My Video/Breakfast_20150428_0755.ts - Not yet indexed, trying helper.
28/04/2015 08:02:09 - autotrigger[7160]:   /media/My Video/Breakfast_20150428_0755.ts - Can't use helper.
28/04/2015 08:02:09 - autotrigger[7160]: Renaming /media/My Video/Breakfast_20150428_0755(1).ts to Breakfast_20150428_0755[801]
28/04/2015 08:02:09 - autotrigger[7160]: Setting title for /media/My Video/Breakfast_20150428_0755[801].ts to Breakfast (Wales)
28/04/2015 08:02:09 - autotrigger[7295]: /media/My Video/Breakfast_20150428_0755
28/04/2015 08:02:09 - autotrigger[7295]: will run for /media/My Video
28/04/2015 08:02:09 - autotrigger[7160]: move /media/My Video/Breakfast_20150428_0755[801].ts to [NEWS]
28/04/2015 08:02:09 - autotrigger[7160]: moveset(/media/My Video/Breakfast_20150428_0755[801].ts) -> /media/My Video/[NEWS]
28/04/2015 08:02:09 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[801].hmt
28/04/2015 08:02:09 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[801].nts
28/04/2015 08:02:09 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[801].ts
28/04/2015 08:02:10 - autotrigger[7160]: Renaming /media/My Video/Breakfast_20150428_0755.ts to Breakfast_20150428_0755[1]
28/04/2015 08:02:10 - autotrigger[7160]: Setting title for /media/My Video/Breakfast_20150428_0755[1].ts to Breakfast (West)
28/04/2015 08:02:10 - autotrigger[7160]: move /media/My Video/Breakfast_20150428_0755[1].ts to [NEWS]
28/04/2015 08:02:10 - autotrigger[7160]: moveset(/media/My Video/Breakfast_20150428_0755[1].ts) -> /media/My Video/[NEWS]
28/04/2015 08:02:10 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[1].hmt
28/04/2015 08:02:10 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[1].nts
28/04/2015 08:02:10 - autotrigger[7160]:  ....... /media/My Video/Breakfast_20150428_0755[1].ts
28/04/2015 08:02:10 - autotrigger[7160]: Resetting unwatched recording flag for /media/My Video/[NEWS]
28/04/2015 08:02:10 - autotrigger[7160]: Resetting unwatched recording flag for /media/My Video
28/04/2015 08:02:10 - autotrigger[7160]: decrypt scan completed in 5.457 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: dedup scan completed in 0.011 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: shrink scan completed in 0.013 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: mpg scan completed in 0.013 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: mp3 scan completed in 0.01 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: expire scan completed in 0.014 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: Media scan completed in 5.682 seconds.
28/04/2015 08:02:10 - autotrigger[7160]: done
28/04/2015 08:02:14 - autotrigger[7295]: got lock
28/04/2015 08:02:14 - autotrigger[7295]: Registered do_arbookmarks for postdecrypt hook with priority 50.
28/04/2015 08:02:14 - autotrigger[7295]: Registered ::sweeper::scan for postdecryptscan hook with priority 50.
28/04/2015 08:02:14 - autotrigger[7295]: Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
28/04/2015 08:02:14 - autotrigger[7295]: -------------------------------------------------------
28/04/2015 08:02:14 - autotrigger[7295]: Media scan starting, DLNA server status: 1
28/04/2015 08:02:14 - autotrigger[7295]: Scanning single directory '/media/My Video'
28/04/2015 08:02:15 - autotrigger[7295]: decrypt scan completed in 0.028 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: dedup scan completed in 0.013 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: shrink scan completed in 0.013 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: mpg scan completed in 0.011 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: mp3 scan completed in 0.014 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: expire scan completed in 0.011 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: Media scan completed in 0.177 seconds.
28/04/2015 08:02:15 - autotrigger[7295]: done
28/04/2015 08:05:02 - Registered do_arbookmarks for postdecrypt hook with priority 50.
28/04/2015 08:05:02 - Registered ::sweeper::scan for postdecryptscan hook with priority 50.
28/04/2015 08:05:02 - Registered ::sweeper::scansingledir for postdecryptsingledir hook with priority 50.
28/04/2015 08:05:02 - -------------------------------------------------------
28/04/2015 08:05:02 - Media scan starting, DLNA server status: 1
28/04/2015 08:05:02 - decrypt scan starting.
28/04/2015 08:05:04 -   /media/My Video/[NEWS]/Breakfast_20150428_0755[1].ts - has been indexed.
28/04/2015 08:05:04 -   DECRYPT: /media/My Video/[NEWS]/Breakfast_20150428_0755[1]
28/04/2015 08:05:04 -   DLNA: http://127.0.0.1:9000/web/media/11186.TS
28/04/2015 08:05:29 -   Removing/binning old copy.
28/04/2015 08:05:30 - Done... 207.76 MiB in 26.097 seconds - 7.96 MiB/s
28/04/2015 08:05:30 -   ARBOOKMARK: /media/My Video/[NEWS]/Breakfast_20150428_0755[1]
28/04/2015 08:05:30 - Recording was not padded, cannot process.
28/04/2015 08:05:30 - Processed in: 0.11s
28/04/2015 08:05:30 - Done...
28/04/2015 08:05:31 -   /media/My Video/[NEWS]/Breakfast_20150428_0755[801].ts - has been indexed.
28/04/2015 08:05:31 -   DECRYPT: /media/My Video/[NEWS]/Breakfast_20150428_0755[801]
28/04/2015 08:05:31 -   DLNA: http://127.0.0.1:9000/web/media/11187.TS
28/04/2015 08:05:57 -   Removing/binning old copy.
28/04/2015 08:05:57 - Done... 208.69 MiB in 26.508 seconds - 7.87 MiB/s
28/04/2015 08:05:57 -   ARBOOKMARK: /media/My Video/[NEWS]/Breakfast_20150428_0755[801]
28/04/2015 08:05:58 - Recording was not padded, cannot process.
28/04/2015 08:05:58 - Processed in: 0.18s
28/04/2015 08:05:58 - Done...
28/04/2015 08:06:03 - decrypt scan completed in 61.034 seconds.
 
Explain that one
Click to expand...
The explanation is fairly easy, the what (if anything) to do about it is less obvious.

Both recordings finished virtually simultaneously and were found by the first autotrigger 7160
The Decrypt of the first recording failed with 'database is locked' but there is no corresponding message for the second recording- somewhat strange.
The database could be locked because the Humax was in the process of indexing the recording itself.

Although the autotriggers failed the normal scheduled processing kicked in at 8:05 and decrypted both recordings within a minute by which time normal indexing had completed.

So you actually gained nothing from the new autotrigger mechanism but saved 5 minutes from the simple recheduling of the chron job to 5 minutes after the hour rather than 10 after the hour ;)

The more significant question is why are we seeing 'database is locked' on the helper file access?
For normal URL retrievals the system class retries the request up to 5 times with a second gap, there is no evidence of a 5 second delay so presumably it is related to attempting to add an index entry to the database for the helper file for which there is (currently) no retry mechanism.

But why is it trying to index the helper file?
This should have been a one-time procedure performed the first time the helper file was needed and then remained indexed for all future use.
My suspicion, without hard evidence, is that because the recordings are being moved or deleted after decryption the symbolic link from the helper becomes invalid and that a periodic task in the Humax process is cleaning up the DLNA database removing the entries for moved/deleted recordings and is deleting the entry for the helper because of the invalid link.

My suggestions would be that the dnlahelper Release operation should delete the symbolic links and recreate the dummy helper files to hopefully elimate / reduce the need for reindexation of the helper and secondly the index creation should retry the operation a few times on the 'database is locked' error.

I don't remember seeing an answer to this question by Oatcake and wonder the same:
Oatcake said:
now that you can force an entry into the DLNA database why not bypass the symbolic link idea and just force the actual video into the database?
Click to expand...
 
I can't see that your explanation holds water. The recordings get renamed and moved after the indexing you indicate, either of which will break the index, and yet they remain indexed at 0805!
 
This continues. Both my Breakfast bulletins were decrypted, relocated, and renamed by 8.03 this morning (although not DLNA-indexed, obviously).
 
You must log in or register to reply here.
Back
Top