• The forum software that supports hummy.tv will be upgraded to XenForo 2.3 on Wednesday the 20th of November 2024 starting at 7pm

    There will be some periods where the forum is unavailable, please bear with us. More details can be found in the upgrade thread.

Autodecrpyt problem - but only with 'Strictly'

peterworks

peterworks

Ye Olde Bowler
The problem has happened for the last two weekends. I get a warning message when opening WebIf showing that 'Strictly Come Dancing' has failed to decrypt. However it is subsequently decrypted successfully. Have had no problems with any other programs.
Herewith relevant parts of the Auto log.
Code: 
4320    25/10/2015 20:29:42 -   SHRINK: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913
4312    25/10/2015 20:25:02 -   DECRYPT: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913
4311    25/10/2015 20:25:02 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - has been indexed.
4299    25/10/2015 20:19:25 - autotrigger[20258]:   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - deferring shrink until decrypted.
4296    25/10/2015 20:19:17 - autotrigger[20258]:   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - File did not decrypt properly.
4294    25/10/2015 20:05:30 - autotrigger[20258]:   DECRYPT: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913
4293    25/10/2015 20:05:30 - autotrigger[20258]:   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - has been indexed.
4292    25/10/2015 20:05:30 - autotrigger[20258]: Scanning single directory '/media/My Video/Strictly Come Dancing'
4277    25/10/2015 20:05:19 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - deferring shrink until decrypted.
4272    25/10/2015 20:05:04 - autotrigger[20258]: will run for /media/My Video/Strictly Come Dancing
4271    25/10/2015 20:05:04 - autotrigger[20258]: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913
4257    25/10/2015 19:45:17 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - deferring shrink until decrypted.
4239    25/10/2015 19:25:16 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151025_1913.ts - deferring shrink until decrypted.
3497    24/10/2015 21:15:13 -   SHRINK: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833
3488    24/10/2015 21:05:08 -   DECRYPT: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833
3487    24/10/2015 21:05:08 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - has been indexed.
3467    24/10/2015 20:58:32 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.
3461    24/10/2015 20:57:56 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - File did not decrypt properly.
3458    24/10/2015 20:25:09 -   DECRYPT: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833
3457    24/10/2015 20:25:09 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - has been indexed.
3453    24/10/2015 20:25:05 - autotrigger[20901]: will run for /media/My Video/Strictly Come Dancing
3452    24/10/2015 20:25:05 - autotrigger[20901]: /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833
3435    24/10/2015 20:05:21 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.
3410    24/10/2015 19:45:16 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.
3392    24/10/2015 19:25:16 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.
3374    24/10/2015 19:05:16 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.
3356    24/10/2015 18:45:35 -   /media/My Video/Strictly Come Dancing/Strictly Come Dancing_20151024_1833.ts - deferring shrink until decrypted.

Any ideas please ?
 
Not much help, but here's my equivalent:
Code: 
24/10/2015 20:36:15 - autotrigger[32397]: Done... 5.97 GiB in 879.292 seconds - 6.96 MiB/s
24/10/2015 20:36:13 - autotrigger[32397]:   Removing/binning old copy.
24/10/2015 20:21:36 - autotrigger[32397]:   DLNA: http://192.168.1.11:9000/web/media/7873.TS
24/10/2015 20:21:36 - autotrigger[32397]:   DECRYPT: /media/My Video/Strictly 2015/Strictly Come Dancing_20151024_1835
 
I have seen file decryption problems when using the DLNA helper prior to the file being indexed (a problem for DetectAds) but in this case the recordings have been indexed so have no ideas what could cause transient decryption failures
 
I had a failed to decrypt message last week. The subsequent recording was flagged as decrypted, but whether it actually was or not, I don't know. (Just posted so as to indicate that peterworks occurrence was not a 'one off'
 
I don't know why it shows like that but surely it was just still recording until 8:25pm so something over-actively trying to decrypt it before file was released?
 
Thank you all for your input.
It is strange that it is only 'strictly'. Looking closer both episodes finish very close to the autotrigger kick off time. The first finished at 20:24:59 with autotrigger at 20:25:05.
The second finished at 20:04:58 with autotrigger at 20:05:04. Perhaps, although the log says it has been indexed, it has not, in fact, completed the indexing... Clutching at straws here !
 
dragon-it said:
I don't know why it shows like that but surely it was just still recording until 8:25pm so something over-actively trying to decrypt it before file was released?
Click to expand...
The detectads package is able to trigger chase-decryption, using AF's mechanism for creating a dummy DLNA index entry and initiate streaming even before the recording ends. It is supposed to be throttled so that the read rate does not exceed the record rate - but maybe if that doesn't work properly and the end of buffer is reached, a decryption fault occurs and has to be retried later?
 
Autotrigger is kicked of by recmon when the recording file is closed so it is no surprise that it is running close to the recording end, it is a coincidence that the regularly scheduled auto process has also started running at the same time.

What is surprising is that the Humax has already DLNA indexed the recording so soon after the recording end, it usually takes much longer (up to several hours in the worst case) hence the need for creating the DLNA helper mechanism, also surprising is the time taken for the decryption to run before the problem was detected - 32 minutes compared to 10 minutes for the later successful decryption.

Black Hole said:
The detectads package is able to trigger chase-decryption, using AF's mechanism for creating a dummy DLNA index entry and initiate streaming even before the recording ends. It is supposed to be throttled so that the read rate does not exceed the record rate - but maybe if that doesn't work properly and the end of buffer is reached, a decryption fault occurs and has to be retried later?
Click to expand...

ChaseGet does not use throttling to control read rate - I did experiment with it in early (not released) versions but it proved to be too unreliable to be useful so instead it uses time slicing. ChaseGet reads to the current end of file and then sleeps for 30 seconds (shorter near end of recording) before reading the next segment of the recording so I know that hitting the end of file is not a cause for the decryption failures.
A decryption failure is actually detected as a file length mismatch between the encrypted and decrypted versions of the recording - there is no knowing where in the recording the problem first occurs and potentially some errors could go undetected if they didn't cause a length mismatch.

In numerous experiments during the development of the new DetectAds it appears that decryption is very reliable if performed before the recording is DLNA indexed or after it has been fully indexed but there is a period around the indexing when it becomes unreliable. Usually, due to the time slicing, DetectAds is able to complete before the recording is indexed or any error occurs during the final adverts where nobody cares but occasionally it can cause more significant problems and poor Trev suffers abuse from his other half!

I don't know what the Humax is doing whilst it is preforming indexing, it is obviously something more significant than just creating a database entry, if we knew what it was up to and could detect when it started/ended we might be able to avoid attempting decryption in that window and prevent these decryption failures.

Failure symptoms that I have seen have include the program not being indexed yet but not being able to retrieve the full program length using the DLNA helper, or getting more than the full program length - on at least one occasion I received part of a totally different program!
 
How about moving the recording somewhere so that the indexer can't find it by itself (presuming the indexer only looks for the completed recording on those occasions rather than a complete scan). Maybe even out of My Video. Should only need a directory tweak, no actual data movement.
 
Black Hole said:
How about moving the recording somewhere so that the indexer can't find it by itself (presuming the indexer only looks for the completed recording on those occasions rather than a complete scan). Maybe even out of My Video. Should only need a directory tweak, no actual data movement.
Click to expand...
That sounds worth a try. Thanks for the idea.

DeteactAds already creates the decrypt file in /mod/tmp with a link to the original nts file so that nicesplice can read it so it would be quite simple to create links for all of the recording files.

Whether it would work for auto-decrypt would need some experimentation since in the original Strictly example the indexer has already found the recording and started doing its stuff so it may be too late to hide the recording but it could be useful for the normal case where indexing hasn't yet occurred.
 
I have had this twice now, image below of warning I received.

2015 12 23 - Humax HDR Fox T2 - Failed Decrypt.png

Both times it was for the same series; Perry and Croft: Made in Britain, yesterdays episode and today.
 
I have had that several times on BBC (only) recordings whilst running detectads although BBC is excluded from DA
 
ian_j said:
I don't have detectads installed, I wondered if it was something to do with the : in the filename.
Click to expand...
Usually decryption succeeds on the next attempt 20 minutes later so it unlikely to be related to the filename.

Can you post the auto.log extracts for the relevant period - previous occurrences have shown a very long failed decryption attempt followed by much shorter successful decryption and that the recording has already been DLNA indexed.
 
ian_j said:
This is the one for todays warning:

View attachment 2093


This is the one from yesterday:

View attachment 2094
Click to expand...

Very similar to the pattern I predicted though yesterday's recording also failed with a length error on the second attempt before succeeding at the third attempt.

The Diners, Drive-ins, Dives episode worked first time both days so it remains a mystery why certain programs repeatedly fail on the first attempt while most work fine.
 
Not a problem really it's mainly the shock of opening up the WebIF and getting a LARGE red warning.

I thought something terminal had happened to the Humax.
 
I too have had this happen again for Strictly and for another prog (cant remember what now). Am wondering as most recordings finish on the hour or half hour (plus in my case 5 mins padding) if it might be worth tweaking the times autotrigger kicks off to an odd time (say 09, 29 and 49 past the hour) ? Unfortunately, as this problem cannot be reproduced it would be almost impossible to know if this would work...
 
peterworks said:
I too have had this happen again for Strictly and for another prog (cant remember what now). Am wondering as most recordings finish on the hour or half hour (plus in my case 5 mins padding) if it might be worth tweaking the times autotrigger kicks off to an odd time (say 09, 29 and 49 past the hour) ? Unfortunately, as this problem cannot be reproduced it would be almost impossible to know if this would work...
Click to expand...

There are two variations of auto processing:
  1. Autotrigger - processes a single recording and is triggered by end of recording so will always start within seconds of the the recording finishing
  2. Auto - runs on a timed basis at 5, 25, 45 minutes past the hour (can be adjusted by editing chrontabs) and processes all recording that autotrigger failed to handle
The problem seems to be related to the DLNA indexer and it is difficult to predict when that will run, it varies from a few seconds to hours and even when indexed it is not clear when the index is safe to use.

Using a link and the DLNA helper (as suggested by BH in post #10) seems to have reduced the problem for detectads, only one user has reported DetectAds decryption length error problems since I introduced the change but retrying later works for Auto so perhaps the easiest fix is just to remove the alert message and only generate the log message.

edit: clarify lack of problems is for DetectDs only
 
Last edited:
You must log in or register to reply here.
Back
Top