DetectAds not always succesful

[bottletop]

I think I may have a bug in the way I use or setup DetectAds. It seems to work fine most of the time, but occasionally it fails to perform the actual Ad Detection.
The settings I use are
Automatically process whilst recording in progress? (chaserun)
Start processing recording queue ASAP
Only Bookmark ends of ad breaks? No
Crop recording following ad detection? No
Delete (move to bin) original recording after processing? Yes
Write output recording to folder Same as input
Limit cpu usage to 0% (default)

The recordings that fail Ad Detect show up in the queue as
1968 30/10/2020 20:01:59 New_ The Gadget Show/New_ The Gadget Show_20201030_1901 detectads FAILED Plugin failure

The Ad Detect log also has this for the recordings it fails on
/mod/bin/chaseget:165: Error: child process exited abnormally
in procedure 'getfile' called at file "/mod/bin/chaseget", line 453
in procedure 'close' called at file "/mod/bin/chaseget", line 165

(I have kept chaseget settings to default)

I include part of the detectads.log.txt to help diagnose the problem

 

[Black Hole]

What happens if you manually queue the same recording for ad-detection?

 

[bottletop]

What happens if you manually queue the same recording for ad-detection?

That usually works. I've just tried it on one of the recordings and it completed Ad Detection ok. So I guess that it might be my HDR is struggling to cope with the processing demands I've placed on it.

 

[MymsMan]

Random failures during decryption are fairly common (though you do appear more than normal)
To protect against them when running in chaserun mode detectads puts an entry on the queue to retry detection after the programme has finished recording. If chaserun detection runs normally the queue entry is deleted.

Logging of processes run from the queue goes onto auto.log rather than detectads.log so I can't see why the Gadget Show failed to run from the queue, It can fail if sweeper or another process has moved or renamed the recording but that is usually a Not found error

 

[bottletop]

...Logging of processes run from the queue goes onto auto.log rather than detectads.log so I can't see why the Gadget Show failed to run from the queue, It can fail if sweeper or another process has moved or renamed the recording but that is usually a Not found error

Thanks for the explanation, and DetectAds itself which is excellent.
I attach the last 3 auto logs, which should cover similar days to the DetectAds log I posted.
One thing I notice in the auto log was this unfamiliar (to me) entry
31/10/2020 02:55:30 - decrypt:Wget error - --2020-10-31 01:50:05-- http://192.0.2.200:9000/web/media/1160.TS
I'll do a search on the forum with '/web/media' and have a read in case it's related.
I don't know why it uses IP 192.0.2.200, as I use fixed IP addresses
192.168.2.22 for the Wifi and
192.168.2.21 for the ethernet (which has a cable connected to the HDR, but usually nothing on the other end - I only attach trailing end to a switch or laptop when I wish to perform large data transfer).

Additional info I don't use sweeper or remote scheduling. I use Auto-shrink for most folders and have these set for
Auto Processing settings:
Log level - Actions, errors and scan information
auto processing run every 8 minutes
Suspend automatic processing whilst recording? Yes
Suspend automatic processing if will record soon? Yes
...how many minutes is soon? 10 minutes
Disable auto processing during 2100-2159, 2200-2259, 2300-2359
Create backup files in dustbin for decrypt and shrink? No

 

[Black Hole]

I don't know why it uses IP 192.0.2.200, as I use fixed IP addresses

The Humax default addresses are 192.0.2.100 (Ethernet) and 192.0.2.200 (WiFi), so if you see these come up you know the DHCP failed at boot.

31/10/2020 02:55:30 - decrypt:Wget error - --2020-10-31 01:50:05-- http://192.0.2.200:9000/web/media/1160.TS

That's an attempt to decrypt a recording which has failed because of (presumably) the IP address error. wget is the utility which fetches a file via HTTP. By using the recording's DLNA reference as the URL, this achieves hardware decryption - but it requires an active network link (or an Ethernet loopback plug). 192.0.2.100 might well work for a loopback plug, but I doubt 192.0.2.200 will work if the WiFi dongle has broken its connection to the router.

This is the smoking gun. It will become an open-and-shut case if you confirm 1160.TS resolves to the recording in question (which is in the WebIF media browser programme media details, if you scroll down far enough).

The question is: why is decryption trying to access 192.0.2.200? Is it because the HDR has forgotten its correct IP address; is it because the HDR has just booted and hasn't yet resolved (or can't resolve) its IP address; or could it be that the CF is somehow not using the correct IP address?

 

[bottletop]

That's an attempt to decrypt a recording which has failed because of (presumably) the IP address error. wget is the utility which fetches a file via HTTP. By using the recording's DLNA reference as the URL, this achieves hardware decryption - but it requires an active network link (or an Ethernet loopback plug). 192.0.2.100 might well work for a loopback plug, but I doubt 192.0.2.200 will work if the WiFi dongle has broken its connection to the router.
...

I think you may be right, but note that as far as I can remember, the HDR was booted up with WiFi enabled, so it should have an assigned static IP. Also I think that other DLNA decrypt entries on the auto.log seems to use the loopback device like decrypt: DLNA: http://127.0.0.1:9000/web/media/26148.TS

This is the smoking gun. It will become an open-and-shut case if you confirm 1160.TS resolves to the recording in question (which is in the WebIF media browser programme media details, if you scroll down far enough).

The question is: why is decryption trying to access 192.0.2.200? Is it because the HDR has forgotten its correct IP address; is it because the HDR has just booted and hasn't yet resolved (or can't resolve) its IP address; or could it be that the CF is somehow not using the correct IP address?

I have since rebooted the HDR, so http://192.168.2.22:9000/web/media/1160.TS doesn't show anything, just error 404
I've since spotted another entry 01/11/2020 00:52:04 - decrypt: DLNA: http://192.168.2.22:9000/web/media/1160.
Should that not use 127.0.0.1 instead of the actual IP?

 

[Black Hole]

I have since rebooted the HDR, so http://192.168.2.22:9000/web/media/1160.TS doesn't show anything, just error 404

If you chase-decrypt (or I think even post-recording decryption uses the same mechanism), a fake DLNA index entry is generated so that hardware decryption can take place even though the "real" DLNA index entry would normally only be created some time later or during the shutdown process. This used to be a major inconvenience.

Thus 1160.TS was likely just a proxy.

the HDR was booted up with WiFi enabled, so it should have an assigned static IP.

There are definitely "issues" with WiFi, mine occasionally changes IP address for no apparent reason. See https://hummy.tv/forum/threads/hdr-lan-wi-fi-settings-mysteriously-corrupted.9511/post-136810

Should that not use 127.0.0.1 instead of the actual IP?

I don't know. I seem to recall something about decryption not working using the loopback address, but I guess that can't be right if there are log entries showing it happening. What we know for sure is that 192.0.2.200 isn't right.

 

[/df]

192.0.2.200 is the settop program's built-in default IP address for WiFi. It's meant to be replaced by the configured address, but there may be a lag at start-up while this happens: in the worst case, the default may persist until you manually Apply the WLAN settings in the TV UI, or restart the machine.

Queued, manual and chaseget decryption try to use 127.0.0.1 for the DLNA URL. However there is a code path that can lead to this:

01/11/2020 00:52:02 - De-queuing 1986 - decrypt - /mnt/hd2/My Video/Match of the Day/Match of the Day_20201031_2250.ts
01/11/2020 00:52:03 - decrypt:  /mnt/hd2/My Video/Match of the Day/Match of the Day_20201031_2250.ts - Not yet indexed, trying helper.
01/11/2020 00:52:04 - decrypt:  DECRYPT: /mnt/hd2/My Video/Match of the Day/Match of the Day_20201031_2250
01/11/2020 00:52:04 - decrypt:  DLNA: http://192.168.2.22:9000/web/media/1160.TS

In this case, Match of the Day_20201031_2250.ts hadn't yet been indexed. This falls back to a procedure which also handles the case where the recording is not in a directory indexed by DLNA: a dummy recording is created as a symlink to the recording and the dummy recording is manually added to the DLNA index if necessary. In this one case, the DLNA URL is retrieved without specifying the default host/IP (/mod/webif/lib/auto/plugin/decrypt/queue.hook l.79ff):

			    lassign [system dlnahelper [\
				    file normalize $file]] url
# instead of
			    lassign [system dlnahelper [\
				    file normalize $file] "127.0.0.1"] url

The existing code inserts the IP address from the second line of /etc/hosts as the host/IP part of the URL (perhaps [os.gethostname] would be better now). In the case shown in the log extract above, that is the expected address; in post #5, the WLAN addressing hadn't (yet) been properly set up and the system default address was used.

 

[Black Hole]

...so... that's a bug then?

 

[/df]

Seems so, but an easy fix.

 

[MymsMan]

chaseget called by detectads also uses the dlna helper to assign a URL for a recording that hasn't yet been indexed by the system,

The fact that you have been seeing errors during normal decryption matches the errors you are seeing during detectads,.
Although there is no use of the external network connection during decryption the network has to be stable for decryption to take place. Unplugging the LAN cable on a wired connection is sufficient to interrupt an in progress decryption.

...so... that's a bug then?

Only if making @/df's proposed change fixes the issues
Under normal circumstances it works so not a problem, my suspicion is the networking code is fairly simple minded and that any disruption to the network will cause issues regardless of the ip address being used

However it is a simple change and worth a few experiments

 

[Black Hole]

Well, it strikes me that if there is a different result according to which route gets there, it's a bug. All routes should end up using the loop-back address, if one does.

 

[MymsMan]

The existing code inserts the IP address from the second line of /etc/hosts as the host/IP part of the URL. In the case shown in the log extract above, that is the expected address; in post #5, the WLAN addressing hadn't (yet) been properly set up and the system default address is used.

Should the change be made inside dlnahelper rather than in the callers?
That way chaseget would get the benefit automatically without a code change.
Under what circumstances would passing the URL paramater to dlnahelper normally be needed?

 

[/df]

I suppose it's possible that in a case like post #5 the DLNA URL could have 127.0.0.1 as its host/IP part and still be inaccessible, but 127.0.0.1 is associated with the lo network interface, so it should function separately from any reconfiguration of real physical interfaces.

 

[/df]

Should the change be made inside dlnahelper rather than in the callers?
...

Yes, one could just make the change proc {system dlnahelper} {file {urlbase "127.0.0.1"}} { in system.class, which would handle chaseget, manual and queued decryption, and apparently those are the only callers of {system dlnahelper} (are there packages that use it, though?).

The other cases where 127.0.0.1 is passed into DLNA-related functions should probably be left alone, as the default to [system ip] is needed for other callers.

 

[MymsMan]

are there packages that use it, though?).

I don't think so - detectads and chasedecrypt both use chaseget to perform decryption

 

[/df]

https://git.hpkg.tv/hummypkg/webif/pulls/23