[DetectAds] Announcing DetectAds version 2

Just ran the manually cropped Chase and it was perfect. So there's a conundrum for you Myms.
 
Are you running arbookmarks or any other package that could add bookmarks, although not related to the corruption I wonder how you have acquired a bookmark at 3 seconds which detectads did not add
Code: 
Found bookmark at - 3
Found bookmark at - 33

For completeness, although possibly a red herring,: At the same time as recording The Chase in HD, I was also recording Strictly in HD, with the box tuned to BBC1HD. The next time I fired up the web UI, I got a big red warning about Strictly failing to Auto decrypt, but it was showing the Dec flag and there is a copy in the Deleted items folder with no Dec flag.
Click to expand...

This may not be a red herring - it may show that your box is being overloaded attempting to record two programs in HD simultaneously whilst decrypting and ad detecting one of them simultaneously. The fact that it showed the Dec flag show that the decryption was retried successfully later at 20:45 - it might be interesting to see the auto log and recmon logs for the period between 18:45 and 20:30 to see exactly when decryption failure first occurred.

Although I have done some testing with recording and ad detecting two HD programs simultaneously the majority of my recording/viewing is in SD since I only have a 500Gb drive, cant really see a quality difference on 32" TV and the lip sync annoys me.

Is Strictly/Chase the only time during the week where you are recording HD programs in parallel?
Perhaps next week you could turn on 'Auto-processing log level - Debugging information' in General Settings prior to the start of recording
 
Are you running arbookmarks or any other package that could add bookmarks, although not related to the corruption I wonder how you have acquired a bookmark at 3 seconds which detectads did not add
Click to expand...
Not as far as I know. Certainly not arbookmarks.
Is Strictly/Chase the only time during the week where you are recording HD programs in parallel?
Click to expand...
Possibly, but when I was 'testing' DA last week, I was certainly recording two HD progs, on ITV and CH4, at the same time without aparant problem, but I was mainly looking for the -crop files etc as opposed to miss cropped ones. All the other recordings that I actually watched, other than TC, cropped OK last week.
Here's the rest of the logs in question.
Code: 
Recmon
1109 08/11/2015 22:04 - FV: +++ Adding Can't Pay We'll Take It Away -Decrypt 08-11-15 2059
1108 08/11/2015 22:04 - FV: +++ Adding Can't Pay We'll Take It Away 08-11-15 2059
1107 08/11/2015 22:04 - FV: --> Removing Can't Pay_ We'll Take It Away_20151108_2059-dec (orphaned)
1106 08/11/2015 22:04 - FV: --> Removing Can't Pay_ We'll Take It Away_20151108_2059 (orphaned)
1105 08/11/2015 22:02 - FV: +++ Adding Can't Pay_ We'll Take It Away_20151108_2059-dec
1104 08/11/2015 22:01 - FV: +++ Adding Can't Pay_ We'll Take It Away_20151108_2059
1103 epgpatch: No patch required.
1102 epgpatch: Processing '/media/My Video/Can't Pay_ We'll Take It Away_20151108_2059'
1101 08/11/2015 19:55 - FV: +++ Adding Sunday Night at the Palladium_20151108_1850-dec
1100 08/11/2015 19:54 - FV: +++ Adding Sunday Night at the Palladium_20151108_1850
1099 epgpatch: No patch required.
1098 epgpatch: Processing '/media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium_20151108_1850'

Auto
1230 08/11/2015 22:03:50 - autotrigger[19431]: Renaming /media/My Video/Can't Pay_ We'll Take It Away 08-11-15 2059.ts to Can't Pay We'll Take It Away 08-11-15 2059
1229 08/11/2015 22:03:50 - autotrigger[19431]: Renaming /media/My Video/Can't Pay_ We'll Take It Away_20151108_2059.ts to Can't Pay_ We'll Take It Away 08-11-15 2059
1228 08/11/2015 22:03:46 - autotrigger[19431]: Renaming /media/My Video/Can't Pay_ We'll Take It Away -Decrypt 08-11-15 2059.ts to Can't Pay We'll Take It Away -Decrypt 08-11-15 2059
1227 08/11/2015 22:03:46 - autotrigger[19431]: Renaming /media/My Video/Can't Pay_ We'll Take It Away_20151108_2059-dec.ts to Can't Pay_ We'll Take It Away -Decrypt 08-11-15 2059
1226 08/11/2015 22:03:45 - autotrigger[19431]: Done... 1.08 GiB in 111.765 seconds - 9.92 MiB/s
1225 08/11/2015 22:03:43 - autotrigger[19431]: Removing/binning old copy.
1224 08/11/2015 22:01:53 - autotrigger[19431]: DLNA: http://127.0.0.1:9000/web/media/4626.TS
1223 08/11/2015 22:01:53 - autotrigger[19431]: DECRYPT: /media/My Video/Can't Pay_ We'll Take It Away_20151108_2059
1222 08/11/2015 20:07:04 - FV: +++ Adding Sunday Night at the Palladium 08-11-15 1850
1221 08/11/2015 20:07:04 - FV: +++ Adding Sunday Night at the Palladium -Decrypt 08-11-15 1850
1220 08/11/2015 20:07:03 - FV: --> Removing Sunday Night at the Palladium_20151108_1850 (orphaned)
1219 08/11/2015 20:07:03 - FV: --> Removing Sunday Night at the Palladium_20151108_1850-dec (orphaned)
1218 08/11/2015 20:07:00 - ... ERROR Target already exists
1217 08/11/2015 20:07:00 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium 08-11-15 1850.ts to Sunday Night at the Palladium 08-11-15 1850
1216 08/11/2015 20:07:00 - ... ERROR Target already exists
1215 08/11/2015 20:07:00 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium -Decrypt 08-11-15 1850.ts to Sunday Night at the Palladium -Decrypt 08-11-15 1850
1214 08/11/2015 20:07:00 - ... ERROR Target already exists
1213 08/11/2015 20:07:00 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium 01-11-15 1854.ts to Sunday Night at the Palladium 01-11-15 1854
1212 08/11/2015 20:06:59 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium_20151108_1850-dec.ts to Sunday Night at the Palladium -Decrypt 08-11-15 1850
1211 08/11/2015 20:06:58 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium_20151108_1850.ts to Sunday Night at the Palladium 08-11-15 1850
1210 08/11/2015 20:06:58 - ... ERROR Target already exists
1209 08/11/2015 20:06:58 - Renaming /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium 01-11-15 1854.ts to Sunday Night at the Palladium 01-11-15 1854
1208 08/11/2015 20:06:52 - Done... 1.08 GiB in 107.15 seconds - 10.3 MiB/s
1207 08/11/2015 20:06:52 - Removing/binning old copy.
1206 08/11/2015 20:05:05 - DLNA: http://127.0.0.1:9000/web/media/4624.TS
1205 08/11/2015 20:05:05 - DECRYPT: /media/My Video/Sunday Night at the Palladium/Sunday Night at the Palladium_20151108_1850
1204 08/11/2015 14:05:09 - FV: --> Skipping (in-use): Strictly Come Dancing 07-11-15 1831
1203 08/11/2015 13:45:09 - FV: --> Skipping (in-use): Strictly Come Dancing 07-11-15 1831
1202 08/11/2015 13:25:09 - FV: --> Skipping (in-use): Strictly Come Dancing 07-11-15 1831
1201 08/11/2015 13:05:09 - FV: --> Skipping (in-use): Strictly Come Dancing 07-11-15 1831
1200 08/11/2015 12:45:10 - FV: --> Skipping (in-use): Strictly Come Dancing 07-11-15 1831
1199 07/11/2015 22:25:10 - FV: --> Skipping (in-use): The Chase Celebrity Special 07-11-15 1858
1198 07/11/2015 22:05:12 - FV: --> Skipping (in-use): The Chase Celebrity Special 07-11-15 1858
1197 07/11/2015 20:53:20 - FV: +++ Adding Strictly Come Dancing 07-11-15 1831
1196 07/11/2015 20:53:20 - FV: --> Removing Strictly Come Dancing 07-11-15 1831 (inode mismatch)
1195 07/11/2015 20:53:08 - Done... 5.31 GiB in 484.865 seconds - 11.21 MiB/s
1194 07/11/2015 20:53:06 - Removing/binning old copy.
1193 07/11/2015 20:45:03 - DLNA: http://192.168.0.11:9000/web/media/3798.TS
1192 07/11/2015 20:45:03 - DECRYPT: /media/My Video/Strictly Come Dancing 07-11-15 1831
1191 07/11/2015 20:30:29 - autotrigger[16014]: Renaming /media/My Video/The Chase_ Celebrity Special/The Chase_ Celebrity Special 07-11-15 1858.ts to The Chase Celebrity Special 07-11-15 1858
1190 07/11/2015 20:30:28 - autotrigger[16014]: Renaming /media/My Video/The Chase_ Celebrity Special/The Chase_ Celebrity Special_20151107_1858.ts to The Chase_ Celebrity Special 07-11-15 1858
1189 07/11/2015 20:30:27 - autotrigger[16014]: Renaming /media/My Video/The Chase_ Celebrity Special/New_ The Chase_ Celebrity Special_20151107_1858.ts to The Chase_ Celebrity Special_20151107_1858
1188 07/11/2015 20:30:27 - autotrigger[16014]: Setting title for /media/My Video/The Chase_ Celebrity Special/New_ The Chase_ Celebrity Special_20151107_1858.ts to The Chase: Celebrity Special
1187 07/11/2015 20:30:23 - autotrigger[16014]: Renaming /media/My Video/Strictly Come Dancing_20151107_1831.ts to Strictly Come Dancing 07-11-15 1831
1186 07/11/2015 20:30:02 - autotrigger[16014]: /media/My Video/Strictly Come Dancing_20151107_1831.ts - File did not decrypt properly.
1185 07/11/2015 20:11:20 - autotrigger[16083]: failed to get lock
1184 07/11/2015 20:01:03 - autotrigger[16014]: DLNA: http://127.0.0.1:9000/web/media/4606.TS
1183 07/11/2015 20:01:03 - autotrigger[16014]: DECRYPT: /media/My Video/Strictly Come Dancing_20151107_1831
1182 07/11/2015 19:05:15 - FV: +++ Adding New_ The Chase_ Celebrity Special_20151107_1858-crop
The Chase in use at 22:05 and 22:25 was when we were watching it and the Stictly 'In use' at around 12:45 Sunday was when we were watching it but that seems to refer to FlatView.
Seems that the first failed attempt to decrypt Strictly was at 20:01 (just after it had finished) and the successful one was at 20:45.
Could the fact that TC and Strictly both finished at 20:00 be a pointer?
 
Your symptoms of failure to decrypt Strictly are virtually identical to PeterWorks in this thread Autodecrpyt problem - but only with 'Strictly'

I think we need to solve that problem, why are multiple episodes of the same program causing decryption problems on at least two users machines! I have no idea how go about debugging and resolving that condundrum, perfhaps AF123 might have some ideas,

I don't think it is a bug in detectads as such

When does Activity.log say The Chase finished recording on your system my guess is at 20:11 - ten minutes after the real end time
 
Code: 
546 08/11/2015 22:01:47 - Recorded: /Can't Pay? We'll Take It Away (61 minutes - Spike)
545 08/11/2015 19:54:16 - Recorded: Sunday Night at the Palladium/Sunday Night at the Palladium (63 minutes - ITV3)
544 08/11/2015 12:30:19 - System booted (Remote control handset).
543 08/11/2015 04:17:31 - System booted (Scheduled event).
542 07/11/2015 20:01:15 - Recorded: The Chase_ Celebrity Special/New: The Chase: Celebrity Special (62 minutes - ITV HD)
541 07/11/2015 20:01:00 - Recorded: /Strictly Come Dancing (89 minutes - BBC ONE HD)
Nothing but reboots after that.
All these new and exciting logs that you are introducing me to. ;=)
I'll have a read of Peter's thread and confirm if it's the same. I really only included this for completeness, but it seems that it could be a prob.

Yep, same same. Wierd or what? Forgotten I had already mentioned it in the other thread. But it seems that it's repeatable.
 
I give in.:( After a bunch of a tongue pie last night about a couple of recordings with ads still being in and missing bits and the subsequent hunt of the file system for a full copy and the fast forwarding to where we were, I un-installed DA for some peace and quiet. The agro is just not worth swapping for two presses on the skip button. :)
Sorry.
 
I have been doing some more HD recording testing and because we have a weak HD signal my wife has had to put up with some seriously poor quality recordings! :(

However I have detected two problems that affect HD recordings more than SD, the first is relatively easy to fix and will probably cure most of your problems, the second one is more intractable but mainly affects recordings with weak signals - I may just attempt to detect the problem and keep the original recording for now.
A proper solution may involve a significant change and may not actually be feasible.
 
I've recorded a fair few films on Channel 4HD and ITV HD and I am impressed by how accurate the bookmarking is, though I don't have a signal problem (since having a new aerial installed). I have had a couple of lock-ups though when two programmes are being processed simultaneously (chaserun). Looking at sysmon this may be due to the CPU being maxed out. A feature I would find useful is an option to limit processing to a single chaserun at a time.
 
Trev said:
I give in.:( After a bunch of a tongue pie last night about a couple of recordings with ads still being in and missing bits and the subsequent hunt of the file system for a full copy and the fast forwarding to where we were, I un-installed DA for some peace and quiet. The agro is just not worth swapping for two presses on the skip button. :)
Sorry.
Click to expand...
Trev, I use the trailing bookmark option (no cuts). When the adbreak starts I just hit the "skip to next bookmark" button - which more often than not is at the beginning of the next programme segment. If it happens not to be, it's no biggie because no recording has actually been removed.
 
MontysEvilTwin said:
I've recorded a fair few films on Channel 4HD and ITV HD and I am impressed by how accurate the bookmarking is, though I don't have a signal problem (since having a new aerial installed). I have had a couple of lock-ups though when two programmes are being processed simultaneously (chaserun). Looking at sysmon this may be due to the CPU being maxed out. A feature I would find useful is an option to limit processing to a single chaserun at a time.
Click to expand...
Only one chaserun process actually runs at at a time, after reading the currently available recording the process sleeps for 30 seconds to allow more recording to accumulate and to allow chaserun for the second recording to processing. The lock on the DLNA helper files ensures the two processes don't overlap.

However it is still possible that the resources required to record two HD processes and run detectads simultaneously could be excessive especially if you are playing something else. ffmpeg is the big cpu hog in the process.
 
Yeah, thanks BH, but I find pressing skip twice easier because I us a harmony and goto bookmark is in the screen at the top which I always have to scrutinise and possibly change, if I have been on the screen that I have Media on, before I can get the right button.
BTW I don't have a weak signal.
When I record two progs at once, I always make sure that I have one of the channels selected on the T2 so there is no recording clash that I don't see because I am watching something else on the TV's tuner.
 
Yeah, I have the same problem with Harmony 300 - no bookmark button. If I was bothered I could reprogram one of the other buttons though (and the 300 has four uncommitted buttons) - which is what I would do if I rolled out DA to the supported user.
 
I have uploaded detectads Version 0.2.2-3 to the package catalogue

This version:
  • Fixes the bug that caused misplaced crops when using chaserun on HD files
  • Detects when poor quality recording cause a significant (>5 seconds) difference between detected program length and actual program length
  • Create System notify messages when errors are detectedFullscreen capture 14112015 192649.jpg
 
I received this message this morning:

Code: 
17/11/2015 22:03:58 - DetectAds /media/My Video/Catastrophe/Catastrophe_20151117_2202.ts Detection Length error, Bookmarks/crop may be upto 00:27:11 out
17/11/2015 22:03:58 - DetectAds /media/My Video/Catastrophe/Catastrophe_20151117_2202.ts Incomplete data retrieval 38379520 bytes missing (00:27:11)
17/11/2015 22:03:58 - Queing /media/My Video/Catastrophe/Catastrophe_20151117_2202.ts for retry of detectads due to significant file length error
17/11/2015 22:04:07 - DetectAds /media/My Video/Catastrophe/Catastrophe_20151117_2202.ts Detection Length error, Bookmarks/crop may be upto 00:27:11 out

It repeats the message numerous tines for the half hour program.
My Settings:
upload_2015-11-18_13-19-48.png

DetectAds.logs are attached.
 

Attachments

  • detectads.log.txt
    348 KB · Views: 3
I had to split the other 2mb (which I assume is the maximum size) log file into three. If there's a limit for file uploads, would it be possible to restrict the log file size to that limit?

I have another problem that probably isn't Detectads fault: the unit occasionally fails to wake up. So I can narrow down the error & also understand better how DA works is there a full list of which other packages it uses & in which order? I notice the 'under the covers' section of the wiki but it doesn't include wake-up or decrypt.

Edit: One other problem I've come across is the sound at the end of a crop is mute for about 3-5 seconds. The picture is visible.

Cheers
Dave F.
 

Attachments

  • detectads.20151118042726-1.log.txt
    665.6 KB · Views: 2
  • detectads.20151118042726-2.log.txt
    480.2 KB · Views: 2
  • detectads.20151118042726-3.log.txt
    557.8 KB · Views: 2
Last edited:
Dave F. said:
I had to split the other 2mb (which I assume is the maximum size) log file into three. If there's a limit for file uploads, would it be possible to restrict the log file size to that limit?

I have another problem that probably isn't Detectads fault: the unit occasionally fails to wake up. So I can narrow down the error & also understand better how DA works is there a full list of which other packages it uses & in which order? I notice the 'under the covers' section of the wiki but it doesn't include wake-up or decrypt.

Edit: One other problem I've come across is the sound at the end of a crop is mute for about 3-5 seconds. The picture is visible.

Cheers
Dave F.
Click to expand...

Thanks for all the log data, it is quite informative and bizarre!

You actually had a very similar exactly a week before but because the notify messages were not being generated at that time you probably didn't notice anything was wrong.

A week ago it affected the recordings of Lewis at 21:01 and Catastrophe at 22:04 on 10/11 and continued until 23:50 when suddenly the fault cured itself and you had no further problems until 22:02 yesterday 17/11 when the same problem recurred and continued until 23:38 when suddenly it was able to retrieve the recording.

Can you remember what you were doing during those time periods that somehow affected the Humax's ability to retrieve files?

The repeated error that I see in the logs is:
Code: 
17/11/2015 23:38:39 - CG(30640)- ChaseGet /mod/tmp/Catastrophe_20151117_2202-inp.ts
17/11/2015 23:38:39 - CG(30640)- Recording start: 22:02:49 end: 22:33:04
17/11/2015 23:38:39 - CG(30640)- DLNA Server is running.
17/11/2015 23:38:39 - CG(30640)- Start at offset 0  cur recording size: 1011159040
17/11/2015 23:38:39 - CG(30640)- duration: 1815 elapsed: 5750 remaining: -3935
17/11/2015 23:38:39 - CG(30640)-   /mod/tmp/Catastrophe_20151117_2202-inp.ts - Not yet indexed, trying helper.
17/11/2015 23:38:39 - CG(30640)-   DLNA: http://192.168.2.3:9000/web/media/1940.TS
17/11/2015 23:38:39 - CG(30640)- Curl pid 30647
17/11/2015 23:38:39 - CG(30640)- EOF detected 0 0
17/11/2015 23:38:42 - CG(30640)- No data returned
17/11/2015 23:38:42 - CG(30640)-  Failed to retrieve entire file 1011159040 bytes missing
17/11/2015 23:38:42 - CG(30640)-  Attempt to recreate failure message
17/11/2015 23:38:43 - CG(30640)- Curl message:
curl: (7) couldn't connect to host
17/11/2015 23:38:43 - CG(30640)- Curl error: -code 1 -level 0 -errorinfo {{} /mod/bin/chaseget 157} -errorcode {CHILDSTATUS 30651 7}
The DNLA server is running but for some reason it is not accepting connections from Curl, the program which actually does the retrieval of decrypted recordings.

I have no idea what is causing the connection failures and why they suddenly resolve just before midnight! The only thing I could attempt to do is slow the retry rate down to once every 20 minutes rather than every few seconds.
From past history I have a week to make the change before you next experience problems :)

detectads depends on the system waking up from standy to start recording, it just changes it to fully awake using the IR (infrared remote) package if needed and your logs show this has not been needed in the last week.

The sound muting after a crop is, I think, an feechur of the nicesplice program that I don't understand, it occurs if you use crop with manually created bookmarks - it can be annoying especially if there is a very short leadin from the ads before the action restarts
 
I don't appear to be getting on too well with this.

Is there a reason why programs don't crop with these settings:
upload_2015-12-22_12-59-10.png

Exclude channel list is the default.
ver 0.2.2-6
 
Two reasons!
  1. Only Bookmark end of ad breaks? Yes -prevents the use of Manual cropping since there is no record of when the break starts
  2. Crop recording following ad detection? No - Has turned off automatic cropping of the recording
 
You must log in or register to reply here.
Back
Top