Multimode and Manual Timer Recording - Detectads or system issue?

[MontysEvilTwin]

By default my units are set up for accurate recording, but I use the Multimode package to pad recordings on selected channels. I also use Detectads for chaserun processing of non-BBC TV channels. This works fine for both AR and padded channels when the recordings are set up from the TV guide. However, while manual timer recordings work, they are only processed by Detectads if they are on a channel with AR recording (default setting), if the channel is flagged for padding in Multimode, it is not processed by Detectads: the recording is not even checked by Detectads for channel exclusion.
The problem may be be deeper than Detectads: it might be caused by an interaction between Multimode and the system autoprocessing. If the unit is brought out of standby during the recording, at the end of the recording, rather than being decrypted immediately as the result of an autotrigger process, it is not processed until the next scheduled scan.
I tested this earlier by setting a manual timer recording to run from 10:56 AM until noon (CBS Action - a channel I set for padding). The system booted at 10:53:41 (according to activity.log), the recording started at 10:56:01 and finished at 11:59:59 (according to redring.log: I could not find the event logged anywhere else). It was not processed by Detectads and was decrypted when the next autoscan ran at 12:05. Oddly the filename was 'CBS Action_20160418_1054' (recording actually started at 10:56). I also noticed while the recording was running that the start time was set in the hmt file as 10:54 and the end time was 12:02 (68 minutes rather than the actual duration of 64 minutes). When the recording finished at noon (as scheduled in the manual timer), the end time in the hmt file was amended to 11:58 (incorrect) with a duration of 64 minutes (correct). It seems that while the recording happened correctly as defined by the timer, some of the system settings were as if padding had also been applied to the manual timer. This behaviour is incorrect, but I don't know if it is responsible for the failure of Detectads to process the recording.

 

[MymsMan]

detectads chaserun is dependent on being trigggered by recmon when the recording files are initially created - recmon (and detectads) has no knowledge whether the recording was started by a manual recording, padded recording, AR or by the record button on the remote. All methods are absolutely identical.

However occasionally the recmon process can fail and no notifications are generated (did you see auto-trigger entries in the auto.log?), I don't know why it fails and wonder if we could use a chron job to check whether it is alive a restart it if needed

when setting up a manual recording you can choose the title - the default is the channel name

 

[MontysEvilTwin]

I've done a bit more testing. I set up two manual timer recordings, the first on an AR channel (Channel 4), the second two minutes later on a padded channel (CBS Action). See below:

In this case, Detectads worked on both recordings:

18/04/2016 18:02:01 RM(5622)-   DETECTADS: Checking /media/My Video/Channel 4_20160418_1802.ts (Channel 4) for channel exclusion
18/04/2016 18:02:01 RM(5622)-   DETECTADS: Started /media/My Video/Channel 4_20160418_1802.ts for chaserun advert detection
18/04/2016 18:02:01 DA(5629)- ==DETECTADS Chase Run: /media/My Video/Channel 4_20160418_1802.ts
18/04/2016 18:04:06 RM(7765)-   DETECTADS: Checking /media/My Video/CBS Action_20160418_1802.ts (CBS Action) for channel exclusion
18/04/2016 18:04:06 RM(7765)-   DETECTADS: Started /media/My Video/CBS Action_20160418_1802.ts for chaserun advert detection
18/04/2016 18:04:06 DA(7771)- ==DETECTADS Chase Run: /media/My Video/CBS Action_20160418_1802.ts
18/04/2016 18:05:00 - CG(8662)- System power on attempted
18/04/2016 18:05:01 - CG(8680)- System power on attempted
18/04/2016 18:07:34 DA(5629)-   ad break found 0:00-0:41 (0 - 41) Frames: 1 - 1037
18/04/2016 18:13:39 DA(7771)-   ad break found 3:49-7:53 (229 - 473) Frames: 5733 - 11833
18/04/2016 18:14:49 DA(5629)-   ad break found 7:05-11:10 (425 - 670) Frames: 10633 - 16739
Process 8682 found
18/04/2016 18:17:22 DA(5629)- Final bookmarks: 41 425 670
18/04/2016 18:17:23 DA(5629)- /media/My Video/Channel 4_20160418_1802.ts deleted
18/04/2016 18:17:25 DA(5629)- done...processed /media/My Video/Channel 4_20160418_1802.ts in 745.145s 00:12:25 - 2 ad breaks detected
Removed /mod/tmp/Channel 4_20160418_1802-inp.ts<br>
Removed /mod/tmp/Channel 4_20160418_1802-inp.nts<br>
Removed /mod/tmp/Channel 4_20160418_1802-inp.hmt<br>
Process 8665 found
18/04/2016 18:20:02 DA(7771)- Final bookmarks: 0 229 473
18/04/2016 18:20:03 DA(7771)- /media/My Video/CBS Action_20160418_1802.ts deleted
18/04/2016 18:20:05 DA(7771)- done...processed /media/My Video/CBS Action_20160418_1802.ts in 905.039s 00:15:05 - 1 ad breaks detected
Removed /mod/tmp/CBS Action_20160418_1802-inp.ts<br>
Removed /mod/tmp/CBS Action_20160418_1802-inp.nts<br>
Removed /mod/tmp/CBS Action_20160418_1802-inp.hmt<br>

As before, the time in the filename and start time in the hmt file are wrong for the recording on the padded channel. From the log at 18:05:00 and 18:05:01 there are two entries for system power on; I don't know if this is significant but it does look like the problem is elsewhere, not in Detectads.

From activity.log:

18/04/2016 18:17:05 - Recorded: /Channel 4 (14 minutes - Channel 4)

but no mention of the other recording.

From redring.log:

[RR] Mon Apr 18 18:02:00 2016: Recording start 25:'/mnt/hd2/My Video/Channel 4_20160418_1802.nts'
[RR] Mon Apr 18 18:02:00 2016:    Recording 1
[RR] Mon Apr 18 18:02:00 2016: REC icon on.
[RR] Mon Apr 18 18:02:00 2016:    System is in standby.
[RR] Mon Apr 18 18:02:00 2016:    Changing to red.
[RR] Mon Apr 18 18:04:00 2016: No-match, trying '20160418_1803'.
[RR] Mon Apr 18 18:04:00 2016: No-match, trying '20160418_1805'.
[RR] Mon Apr 18 18:05:01 2016: Ring going blue, full boot.
[RR] Mon Apr 18 18:05:01 2016: REC icon on.
[RR] Mon Apr 18 18:05:01 2016: Ring going red.
[RR] Mon Apr 18 18:16:59 2016: Recording end 25.
[RR] Mon Apr 18 18:18:59 2016: REC icon off.
[RR] Mon Apr 18 18:30:12 2016: Standby ring dim detected.
[RR] Mon Apr 18 18:30:12 2016: Standby ring dim detected.
[RR] Mon Apr 18 18:30:12 2016: Ring trying to go amber.

The second recording is not logged here either, though there are two lines mentioning 'no-match' at 18:04, the actual recording time.
I wonder if the incorrect start time in the filename and hmt file is the cause of the problem?