HD playback breakup and auto-decrypt failures

Stuartb

New Member
Hi - I'm on 1.03.12/3.03 on my HDR. I have started experiencing:-

  • Picture breakup on HD playback
  • Some picture freeze/sound continues followed by crash/reboot shortly afterwards
  • Repeated failure to auto-decrypt recordings (which all appear to be in one folder)

Its on its original 1TB HDD.

SMART shows no issues (0 pending sectors, 0 reallocated)

I ran an extended disk test which created lost+found as it was not present and fixed some orphaned inodes, but otherwise seemed uneventful.

The autodecrypt keeps retrying and failing every few minutes. I don't know where the setting or package is to try disablig this - could this be causing issues?

Willing to get a new HDD and swap, but the behaviour and evidence so far doesn't firmly point to this being what's needed (apart from age).

Any advice?

Thanks

Stuart
 
This sounds like CPU overload. If you have webshell installed, start a command session from WebIF >> Diagnostics (or the same from a Telnet session) and report the output from the "top" command. Go to WebIF >> Settings >> General Settings and set Auto-processing log level = Actions, errors and scan information, then report the contents of auto.log (after it has had chance to accumulate some data).
 
  • Some picture freeze/sound continues followed by crash/reboot shortly afterwards
  • Repeated failure to auto-decrypt recordings (which all appear to be in one folder)
If you haven't already, I would reset the DLNA database (Diagnostics->DLNA).
Your box is occasionally crashing and coupled with the decryption failures, this could well be the cause.

Install the crashdiag package to gather more information from these crashes.
 
Output of TOP command. Will come back with auto.log when it has some info. Full of the decrypt errors at the moment, but not at the reporting level you asked for.

I plan to try the resetting the DLNA database after I've collected these diagnostics.

Thanks.

Stuart
Code:
  PID  PPID USER     STAT   VSZ %VSZ %CPU COMMAND
  186   176 root     S     339m 278%   8% /usr/bin/humaxtv
  291     1 root     SW       0   0%   0% [RtmpTimerTask]
2509  2488 root     R N   1352   1%   0% top
  954     1 root     S N   1252   1%   0% {editmonitor} /bin/sh /mod/sbin/editmonitor
  292     1 root     SW       0   0%   0% [RtmpMlmeTask]
  946     1 root     S N   3940   3%   0% /mod/bin/epg -f /mnt/hd1/dvbepg/epg.dat sqlitedumpd /mnt/hd1/epg.d
  811   808 root     S N   3696   3%   0% /mod/sbin/lighttpd -f /mod/etc/lighttpd/server.conf
  810   808 root     S N   3692   3%   0% /mod/sbin/lighttpd -f /mod/etc/lighttpd/server.conf
  808     1 root     S N   3448   3%   0% /mod/sbin/lighttpd -f /mod/etc/lighttpd/server.conf
  778     1 root     S N   1368   1%   0% /mod/sbin/crond
2054   913 root     S N   1340   1%   0% sleep 300
2533   954 root     S N   1340   1%   0% sleep 5
2437   141 root     S N   1268   1%   0% {tmenu} /bin/sh /bin/tmenu
  749     1 root     S     1248   1%   0% udhcpc -t 5 -T 10 -p /var/lib/humaxtv/udhcpc.wlan0.pid -i wlan0
    1     0 root     S     1244   1%   0% init
  176    26 root     S     1244   1%   0% {S90settop} /bin/sh /etc/init.d/S90settop start
2488  2437 root     S N   1240   1%   0% /bin/sh -l
  913     1 root     S N   1240   1%   0% {S55rs} /bin/sh /mod/etc/init.d/S55rs start
   26     1 root     S     1236   1%   0% {rcS} /bin/sh /etc/init.d/rcS
  905     1 root     S N   1024   1%   0% /mod/sbin/recmon -D /media/My Video
  135     1 nobody   S      936   1%   0% /usr/bin/dnsmasq
  312     1 root     S      840   1%   0% tinyftp -i HumaxFTP -p 0000 -c /media
  141     1 root     S N    816   1%   0% /sbin/utelnetd -l /bin/tmenu -p 23 -d -B
   24     1 root     SW       0   0%   0% [mtdblockd]
  497     9 root     SW<      0   0%   0% [kjournald]
   14     9 root     SW       0   0%   0% [pdflush]
   16     9 root     SW<      0   0%   0% [kswapd0]
   71     1 root     SWN      0   0%   0% [jffs2_gcd_mtd1]
  336     9 root     SW<      0   0%   0% [kjournald]
   10     9 root     SW<      0   0%   0% [kblockd/0]
    2     1 root     SW       0   0%   0% [migration/0]
    4     1 root     SW       0   0%   0% [migration/1]
   15     9 root     SW       0   0%   0% [pdflush]
   22     9 root     SW<      0   0%   0% [scsi_eh_0]
 
Last edited:
Last bit of auto log before setting scan option.

Code:
17/04/2016 11:11:45 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - File did not decrypt properly.
17/04/2016 11:25:04 -   DECRYPT: /media/My Video/Top Gear/Best of Top Gear_20130317_2000
17/04/2016 11:25:04 -   DLNA: http://127.0.0.1:9000/web/media/2001.TS
17/04/2016 11:31:22 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - File did not decrypt properly.

Last entry in log (entries since setting scan option all look similar)

Code:
17/04/2016 15:25:01 - Media scan starting, DLNA server status: 0
17/04/2016 15:25:02 - decrypt scan starting.
17/04/2016 15:25:02 - decrypt scan completed in 0.917 seconds.
17/04/2016 15:25:02 - dedup scan starting.
17/04/2016 15:25:03 - dedup scan completed in 0.918 seconds.
17/04/2016 15:25:03 - shrink scan starting.
17/04/2016 15:25:04 - shrink scan completed in 0.916 seconds.
17/04/2016 15:25:04 - mpg scan starting.
17/04/2016 15:25:05 - mpg scan completed in 0.913 seconds.
17/04/2016 15:25:05 - mp3 scan starting.
17/04/2016 15:25:06 - mp3 scan completed in 0.964 seconds.
17/04/2016 15:25:06 - expire scan starting.
17/04/2016 15:25:07 - expire scan completed in 0.926 seconds.
17/04/2016 15:25:07 - Media scan completed in 5.621 seconds.
17/04/2016 15:35:05 - autotrigger[20306]: /media/My Video/F1_ Australian GP Highlights/F1_ Chinese GP Highlights_20160417_1330
17/04/2016 15:35:05 - autotrigger[20306]: will run for /media/My Video/F1_ Australian GP Highlights
17/04/2016 15:35:05 - autotrigger[20306]: got lock
17/04/2016 15:35:05 - autotrigger[20306]: -------------------------------------------------------
17/04/2016 15:35:05 - autotrigger[20306]: Media scan starting, DLNA server status: 0
17/04/2016 15:35:05 - autotrigger[20306]: Scanning single directory '/media/My Video/F1_ Australian GP Highlights'
17/04/2016 15:35:05 - autotrigger[20306]: decrypt scan completed in 0.02 seconds.
17/04/2016 15:35:05 - autotrigger[20306]: dedup scan completed in 0.015 seconds.
17/04/2016 15:35:05 - autotrigger[20306]: shrink scan completed in 0.014 seconds.
17/04/2016 15:35:05 - autotrigger[20306]: mpg scan completed in 0.019 seconds.
17/04/2016 15:35:06 - autotrigger[20306]: mp3 scan completed in 0.014 seconds.
17/04/2016 15:35:06 - autotrigger[20306]: expire scan completed in 0.013 seconds.
17/04/2016 15:35:06 - autotrigger[20306]: Media scan completed in 0.351 seconds.
17/04/2016 15:35:06 - autotrigger[20306]: done
 
Last edited:
Do you have the Auto-Decrypt flag set on your "F1_ Australian GP Highlights" folder or Recursive Auto-decrypt on "My Video"?

It appears that no attempt was made to decrypt the F1 today.

You mention all failure are in one folder, (Top Gear?), What are the flag settings for that folder?
We probably need to see the auto log for a recording in that folder.

Has the Top Gear decrypted successfully since the failures? (since it is not included in the later auto scans - decrypt failures are often transitory)
 
Last edited:
Hi. How do I check the auto-decrypt flags? I've never managed to find the settings for auto-decrypt.

Here is the latest auto.log which shows the failing decrypt on the Top Gear recordings...

This is repeating every 15 mins.

Thanks
Stuart

Code:
1544    17/04/2016 18:51:23 - Media scan completed in 381.587 seconds.
1543    17/04/2016 18:51:23 - expire scan completed in 1.061 seconds.
1542    17/04/2016 18:51:22 - expire scan starting.
1541    17/04/2016 18:51:22 - mp3 scan completed in 0.987 seconds.
1540    17/04/2016 18:51:21 - mp3 scan starting.
1539    17/04/2016 18:51:21 - mpg scan completed in 0.995 seconds.
1538    17/04/2016 18:51:20 - mpg scan starting.
1537    17/04/2016 18:51:20 - shrink scan completed in 0.978 seconds.
1536    17/04/2016 18:51:19 - shrink scan starting.
1535    17/04/2016 18:51:19 - dedup scan completed in 1.439 seconds.
1534    17/04/2016 18:51:17 - dedup scan starting.
1533    17/04/2016 18:51:17 - decrypt scan completed in 376.029 seconds.
1532    17/04/2016 18:51:04 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - File did not decrypt properly.
1531    17/04/2016 18:45:03 -   DLNA: http://127.0.0.1:9000/web/media/2001.TS
1530    17/04/2016 18:45:03 -   DECRYPT: /media/My Video/Top Gear/Best of Top Gear_20130317_2000
1529    17/04/2016 18:45:03 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - has been indexed.
1528    17/04/2016 18:45:01 - decrypt scan starting.
1527    17/04/2016 18:45:01 - Media scan starting, DLNA server status: 1
 
In the Browse menu you should see a small padlock icon
decrypt.png
on folders that have the auto-decrypt setting and padlock with arrow
decryptr.png
for recursive, the setting can be changed with the Opt+ button menu. Go to parent folder to set options for the My Video folder itself.

Have you reset DLNA database yet as suggested earlier.
 
Hi. How do I check the auto-decrypt flags? I've never managed to find the settings for auto-decrypt.

Illustrating the description in the previous post; but you don't need to do this for ad detection (detectads decrypts for you):

image.jpeg
 
Last edited:
Auto-decrypt is not set on the MyVideo folder. It is only set on two folders within that. One of those is Top Gear. In that folder, all recordings are flagged as decrypted except for the one appearing in the logs. I have previously deleted some recordings in this folder which were also failing on decrypt.

I had not reset the DLNA database yet because I thought it might cloud diagnosing the cause, but it seems as though that's the next logical step.

I'll give that a whirl.

Thanks
Stuart
 
I'm guessing I need to wait for the DLNA server to reindex the recordings before I can set decrypt flags again. Once that's done, I'll try to decrypt that recording to close the loop and report back. Thanks for all the help.
 
This has some similarities to problems that I have had
https://hummy.tv/forum/threads/record-replay-detect-ads-overload.7012/
I was recording 2 HD programmes, chase playing another and running detect-ads in the background. The net result was that the 2 recording exhibited picture breakup etc.
Attempts were made to to reduce cpu load (MymsMan added a cpu limit to detectads, but that had little effect), suggesting that may be disk bandwidth overload that was causing the live record channels to drop data.

It seems that 2HD recordings + 1 chase play (3 real-time writes + 1 real time read) is OK (Humax will have designed their hardware to accomodate this). Adding the faster-than-real-time cpu read & write associated with detectads seems to create the problem. This may be a limitation of the hard disk or more likely the way the Humax hardware manages sharing the disk between record/replay and the cpu.

In your case, a faulty recording may be causing the crash when it is played, so what was going on when that recording was made?
 
Just for information, IIRC I have had seven real-time HiDef streams running (as a test).
How did you manage that?
In the scenario I describe, there are 6 channels, so it should be OK (based on your test). However, only 4 are real-time, the other 2 would be significantly faster and even if cpulimit brought their average down to real-time, there could be bursts that cause problems.

I would like to get to the bottom of my problem, I don't dare turn on automatic running of detectads because of the damage that I had to a number of recordings just from running it manually when the system was otherwise busy. The wife was NOT pleased (and we still have a few damaged recordings left to watch, for which I am still getting flack).
(I know... I need to find some time when there are no recordings to run some tests, just not very easy to slot in at the present).
 
Record two, timeshift one (that's two streams), playback three more from various computing devices over the network.
Have you achieved that whilst using detectads on the recordings or was that prior to the introduction of chaserun.

I have too many problems with HD recordings to know which breakups are attributable to poor signal and which might be due to system overloads.
 
I have not tested that recently, it was ages ago when we were assessing the performance of the hardware.
 
After resetting the DLNA database, the issue persisted. This auto.log entry coincides with picture breakup on playback. I've now deleted that file and will hope that fixes it. Thanks again for all the assistance, education and whilst I'm here - thanks for the the custom firmware and packages. I'm late using it, but amazed by what you have all achieved.

Code:
2059    18/04/2016 21:51:41 - Media scan completed in 400.527 seconds.
2058    18/04/2016 21:51:41 - expire scan completed in 1.024 seconds.
2057    18/04/2016 21:51:40 - expire scan starting.
2056    18/04/2016 21:51:40 - mp3 scan completed in 0.992 seconds.
2055    18/04/2016 21:51:39 - mp3 scan starting.
2054    18/04/2016 21:51:39 - mpg scan completed in 1.012 seconds.
2053    18/04/2016 21:51:38 - mpg scan starting.
2052    18/04/2016 21:51:38 - shrink scan completed in 1.019 seconds.
2051    18/04/2016 21:51:37 - shrink scan starting.
2050    18/04/2016 21:51:37 - dedup scan completed in 1.749 seconds.
2049    18/04/2016 21:51:36 - dedup scan starting.
2048    18/04/2016 21:51:36 - decrypt scan completed in 394.652 seconds.
2047    18/04/2016 21:51:22 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - File did not decrypt properly.
2046    18/04/2016 21:45:03 -   DLNA: http://127.0.0.1:9000/web/media/242.TS
2045    18/04/2016 21:45:03 -   DECRYPT: /media/My Video/Top Gear/Best of Top Gear_20130317_2000
2044    18/04/2016 21:45:03 -   /media/My Video/Top Gear/Best of Top Gear_20130317_2000.ts - has been indexed.
2043    18/04/2016 21:45:01 - decrypt scan starting.
2042    18/04/2016 21:45:01 - Media scan starting, DLNA server status: 1
2041    18/04/2016 21:45:01 - -------------------------------------------------------
 
Back
Top