Problem with detectads

Trev · Dec 13, 2018

I have been running detect ads with 'chaserun', 'Asap', No, Yes, Yes, Same as input for a whils and have noticed that I get quite a few -Crop recordings.
For instance, last night I recorded:
Old peoples Home..... CH4 HD record started 21:08 (Single recording scheduled for 20:00)
I'm a Celeb..................... ITV HD record started 21:00 (Single recording scheduled for 21:00)
Secret Life of the Zoo CH4 HD record started 20:05 (Series recording scheduled for 20:00)

The last one recorded OK into its series folder but the first two were in my !videos folder (where they should be) but with the full 'DEC' recording and a shorter -Crop recording (normally looking shorter having had the crop done).
On firing up this morning I got a 'Length' error for both on the Web IF. One was only several bytes but the other was a much larger error.
Anyone any idea of what's going on.
Here is the relevant parts of the auto.log and the detectads.log

Code:

Auto.log

92    12/12/2018 22:43:47 - Resetting unwatched recording flag for /media/My Video
91    12/12/2018 22:43:47 - Resetting unwatched recording flag for /media/My Video/!Videos
90    12/12/2018 22:43:06 - moveset(/media/My Video/I'm a Celebrity   Get Me    12-12-18 2100.ts) -> /media/My Video/!Videos
89    12/12/2018 22:43:06 - move /media/My Video/I'm a Celebrity   Get Me    12-12-18 2100.ts to !Videos
88    12/12/2018 22:43:05 - Renaming /media/My Video/I'm a Celebrity___Get Me___ 12-12-18 2100.ts to I'm a Celebrity   Get Me    12-12-18 2100
87    12/12/2018 22:43:04 - Renaming /media/My Video/I'm a Celebrity___Get Me____20181212_2100.ts to I'm a Celebrity___Get Me___ 12-12-18 2100
86    12/12/2018 22:43:04 - Renaming /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts to I'm a Celebrity___Get Me____20181212_2100
85    12/12/2018 22:43:04 - Setting title for /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts to I'm a Celebrity...Get Me...
84    12/12/2018 22:36:13 -     OK - Done. - 
83    12/12/2018 22:35:33 - thumb:     THUMB: /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100 @ 29
82    12/12/2018 22:35:33 - thumb:     Using thumbnail @ 29
81    12/12/2018 22:35:32 - De-queuing 2564 - thumb - /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts
80    12/12/2018 22:35:32 -   /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100 - Queued for thumb.
79    12/12/2018 22:35:32 - Done...
78    12/12/2018 22:35:32 - Processed in: 0.00s
77    12/12/2018 22:35:32 - Recording already has bookmarks, skipping.
76    12/12/2018 22:35:32 -   ARBOOKMARK: /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100
75    12/12/2018 22:35:32 -     OK - 3.12 GiB in 326.702 seconds - 9.78 MiB/s - 
74    12/12/2018 22:35:31 - decrypt:  bin = (/media/My Video/[Deleted Items]/webif_autodecrypt)
73    12/12/2018 22:35:31 - decrypt:  finding bin for /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts
72    12/12/2018 22:35:31 - decrypt:  Removing/binning old copy.
71    12/12/2018 22:30:05 - decrypt:  DLNA: http://127.0.0.1:9000/web/media/5556.TS
70    12/12/2018 22:30:05 - decrypt:  DECRYPT: /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100
69    12/12/2018 22:30:03 - De-queuing 2555 - decrypt - /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts
68    12/12/2018 22:29:47 - ts load failed.
67    12/12/2018 22:29:47 - De-queuing 2556 - thumb - /mnt/hd2/My Video/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts
66    12/12/2018 22:29:47 -     OK - Done. - 
65    12/12/2018 22:29:08 - thumb:     THUMB: /mnt/hd2/My Video/!Videos/I'm a Celebrity   Get Me    -Crop 12-12-18 2100 @ 5
64    12/12/2018 22:29:08 - thumb:     Using argument @ 5
63    12/12/2018 22:29:08 - De-queuing 2557 - thumb - /mnt/hd2/My Video/!Videos/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts
62    12/12/2018 22:29:08 - ts load failed.
61    12/12/2018 22:29:08 - De-queuing 2559 - thumb - /mnt/hd2/My Video/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts
60    12/12/2018 22:29:08 -     OK - Done. - 
59    12/12/2018 22:28:25 - thumb:     THUMB: /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    -Crop 12-12-18 2108 @ 5
58    12/12/2018 22:28:25 - thumb:     Using argument @ 5
57    12/12/2018 22:28:25 - De-queuing 2561 - thumb - /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts
56    12/12/2018 22:28:25 - ts load failed.
55    12/12/2018 22:28:25 - De-queuing 2553 - detectads - /mnt/hd2/My Video/Old People's Home for 4 Year____20181212_2108.ts
54    12/12/2018 22:28:24 -     OK - Done. - 
53    12/12/2018 22:27:48 - thumb:     THUMB: /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108 @ 14
52    12/12/2018 22:27:48 - thumb:     Using thumbnail @ 14
51    12/12/2018 22:27:48 - De-queuing 2563 - thumb - /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108.ts
50    12/12/2018 22:27:48 -   /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108 - Queued for thumb.
49    12/12/2018 22:27:48 - Done...
48    12/12/2018 22:27:48 - Processed in: 0.00s
47    12/12/2018 22:27:48 - Recording already has bookmarks, skipping.
46    12/12/2018 22:27:48 -   ARBOOKMARK: /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108
45    12/12/2018 22:27:47 -     OK - 2.28 GiB in 254.728 seconds - 9.16 MiB/s - 
44    12/12/2018 22:27:46 - decrypt:  bin = (/media/My Video/[Deleted Items]/webif_autodecrypt/!Videos)
43    12/12/2018 22:27:46 - decrypt:  finding bin for /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108.ts
42    12/12/2018 22:27:46 - decrypt:  Removing/binning old copy.
41    12/12/2018 22:23:32 - decrypt:  DLNA: http://192.168.0.200:9000/web/media/5560.TS
40    12/12/2018 22:23:32 - decrypt:  DECRYPT: /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108
39    12/12/2018 22:23:31 - De-queuing 2562 - decrypt - /mnt/hd2/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108.ts
38    12/12/2018 22:23:31 -     DEFER - Recording did not decrypt properly - 
37    12/12/2018 22:23:21 - decrypt:  /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts - File did not decrypt properly.
36    12/12/2018 22:19:18 -   /media/My Video/!Videos/Old People's Home for 4 Year    12-12-18 2108.ts - Queued for decryption.
35    12/12/2018 22:19:13 - Resetting unwatched recording flag for /media/My Video
34    12/12/2018 22:19:11 - Resetting unwatched recording flag for /media/My Video/!Videos
33    12/12/2018 22:18:48 - Queued /media/My Video/!Videos/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts for thumb -offset 5
32    12/12/2018 22:18:46 - Queued /media/My Video/!Videos/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts for thumb -offset 5
31    12/12/2018 22:18:15 - moveset(/media/My Video/Old People's Home for 4 Year    12-12-18 2108.ts) -> /media/My Video/!Videos
30    12/12/2018 22:18:15 - move /media/My Video/Old People's Home for 4 Year    12-12-18 2108.ts to !Videos
29    12/12/2018 22:18:13 - Renaming /media/My Video/Old People's Home for 4 Year___ 12-12-18 2108.ts to Old People's Home for 4 Year    12-12-18 2108
28    12/12/2018 22:18:13 - Renaming /media/My Video/Old People's Home for 4 Year____20181212_2108.ts to Old People's Home for 4 Year___ 12-12-18 2108
27    12/12/2018 22:18:12 - moveset(/media/My Video/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts) -> /media/My Video/!Videos
26    12/12/2018 22:18:12 - move /media/My Video/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts to !Videos
25    12/12/2018 22:18:10 - Queued /media/My Video/Old People's Home for 4 Year    -Crop 12-12-18 2108.ts for thumb -offset 5
24    12/12/2018 22:18:09 - Renaming /media/My Video/Old People's Home for 4 Year___ -Crop 12-12-18 2108.ts to Old People's Home for 4 Year    -Crop 12-12-18 2108
23    12/12/2018 22:18:09 - Renaming /media/My Video/Old People's Home for 4 Year____20181212_2108-crop.ts to Old People's Home for 4 Year___ -Crop 12-12-18 2108
22    12/12/2018 22:07:01 - Resetting unwatched recording flag for /media/My Video
21    12/12/2018 22:06:58 - Resetting unwatched recording flag for /media/My Video/!Videos
20    12/12/2018 22:06:17 - Queued /media/My Video/!Videos/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts for thumb -offset 5
19    12/12/2018 22:05:19 - moveset(/media/My Video/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts) -> /media/My Video/!Videos
18    12/12/2018 22:05:19 - move /media/My Video/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts to !Videos
17    12/12/2018 22:05:18 - Queued /media/My Video/I'm a Celebrity   Get Me    -Crop 12-12-18 2100.ts for thumb -offset 5
16    12/12/2018 22:05:16 - Renaming /media/My Video/I'm a Celebrity___Get Me___ -Crop 12-12-18 2100.ts to I'm a Celebrity   Get Me    -Crop 12-12-18 2100
15    12/12/2018 22:05:16 - Renaming /media/My Video/I'm a Celebrity___Get Me____20181212_2100-crop.ts to I'm a Celebrity___Get Me___ -Crop 12-12-18 2100
14    12/12/2018 22:05:15 - Renaming /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100-crop.ts to I'm a Celebrity___Get Me____20181212_2100-crop
13    12/12/2018 22:05:15 - Setting title for /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100-crop.ts to I'm a Celebrity...Get Me... -Crop
12    12/12/2018 22:04:07 - decrypt:  DLNA: http://127.0.0.1:9000/web/media/5556.TS
11    12/12/2018 22:04:07 - decrypt:  DECRYPT: /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100
10    12/12/2018 22:04:04 - De-queuing 2555 - decrypt - /mnt/hd2/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts
9    12/12/2018 22:03:49 - autotrigger[16016]:   /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts - Queued for decryption.
8    12/12/2018 21:19:36 -     OK - Done. - 
7    12/12/2018 21:18:05 - thumb:     THUMB: /mnt/hd2/My Video/The Secret Life of the Zoo/Secret Life of the Zoo 12-12-18 2005 @ 5
6    12/12/2018 21:18:05 - thumb:     Using argument @ 5
5    12/12/2018 21:18:04 - De-queuing 2554 - thumb - /mnt/hd2/My Video/The Secret Life of the Zoo/Secret Life of the Zoo 12-12-18 2005.ts
4    12/12/2018 21:17:14 - Queued /media/My Video/The Secret Life of the Zoo/Secret Life of the Zoo 12-12-18 2005.ts for thumb -offset 5
3    12/12/2018 21:17:14 - Renaming /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo 12-12-18 2005.ts to Secret Life of the Zoo 12-12-18 2005
2    12/12/2018 21:17:14 - Setting title for /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo 12-12-18 2005.ts to Secret Life of the Zoo
1    12/12/2018 21:17:13 - Renaming /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005.ts to The Secret Life of the Zoo 12-12-18 2005

Code:

detectads.log

1104    Removed /mod/tmp/Old People's Home for 4 Year____20181212_2108-dec.nts<br>
1103    Removed /mod/tmp/Old People's Home for 4 Year____20181212_2108-dec.ts<br>
1102    Removed /mod/tmp/Old People's Home for 4 Year____20181212_2108-inp.hmt<br>
1101    Removed /mod/tmp/Old People's Home for 4 Year____20181212_2108-inp.nts<br>
1100    Removed /mod/tmp/Old People's Home for 4 Year____20181212_2108-inp.ts<br>
1099    12/12/2018 22:13:13 DA(11167)- done...processed /media/My Video/Old People's Home for 4 Year____20181212_2108.ts in 3706.547s 01:01:47 - 5 ad breaks detected
1098    12/12/2018 22:13:13 DA(11167)- /mod/tmp/Old People's Home for 4 Year____20181212_2108-dec.ts deleted
1097    12/12/2018 22:12:54 DA(11167)- Queing /media/My Video/Old People's Home for 4 Year____20181212_2108.ts for retry of detectads due to significant file length error
1096    12/12/2018 22:12:53 DA(11167)- /media/My Video/Old People's Home for 4 Year____20181212_2108.ts Incomplete data retrieval -189489472 bytes missing (00:04:42)
1095    12/12/2018 22:12:53 DA(11167)- Final bookmarks: 14 740 984 1819 2038 2709 2933 3507 3598
1094    12/12/2018 22:12:53 NS(11167)- New Program Length = 2807s
1093    12/12/2018 22:12:53 NS(11167)- Wrote 70565 entries to /media/My Video/Old People's Home for 4 Year____20181212_2108-crop. Stripped 756262 packets (141799k) of EPG data
1092    12/12/2018 22:12:53 NS(11167)- -+++++++++++-----+++++++++++++-----++++++++++-----+++++++++-
1091    12/12/2018 22:12:52 DA(11167)-   ad break found 58:27-59:58 (3507 - 3598) Frames: 87672 - 89938
1090    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-dec.hmt<br>
1089    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-dec.nts<br>
1088    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-dec.ts<br>
1087    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-inp.hmt<br>
1086    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-inp.nts<br>
1085    Removed /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-inp.ts<br>
1084    12/12/2018 22:03:24 DA(10118)- done...processed /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts in 3585.907s 00:59:46 - 5 ad breaks detected
1083    12/12/2018 22:03:24 DA(10118)- /mod/tmp/New_ I'm a Celebrity___Get Me____20181212_2100-dec.ts deleted
1082    12/12/2018 22:03:02 DA(10118)- /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts Incomplete data retrieval -14 bytes missing (00:00:00)
1081    12/12/2018 22:03:01 DA(10118)- Final bookmarks: 29 887 1141 1823 2067 2616 2860 3600 3699
1080    12/12/2018 22:03:01 NS(10118)- New Program Length = 2831s
1079    12/12/2018 22:03:01 NS(10118)- Wrote 110169 entries to /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100-crop. Stripped 761911 packets (142858k) of EPG data
1078    12/12/2018 22:03:01 NS(10118)- -++++++++++++++++++++------++++++++++++++++-----++++++++++++++-----+++++++++++++++++++--
1077    12/12/2018 22:03:00 DA(10118)-   ad break found 60:00-61:39 (3600 - 3699) Frames: 90007 - 92467
1076    12/12/2018 21:58:45 DA(11167)-   ad break found 45:09-48:53 (2709 - 2933) Frames: 67715 - 73320
1075    12/12/2018 21:50:34 DA(10118)-   ad break found 43:36-47:40 (2616 - 2860) Frames: 65401 - 71505
1074    12/12/2018 21:43:52 DA(11167)-   ad break found 30:19-33:58 (1819 - 2038) Frames: 45466 - 50945
1073    12/12/2018 21:37:06 DA(10118)-   ad break found 30:23-34:27 (1823 - 2067) Frames: 45576 - 51680
1072    12/12/2018 21:26:37 DA(11167)-   ad break found 12:20-16:24 (740 - 984) Frames: 18496 - 24595
1071    12/12/2018 21:21:38 DA(10118)-   ad break found 14:47-19:01 (887 - 1141) Frames: 22176 - 28530
1070    12/12/2018 21:12:43 DA(11167)-   ad break found 0:00-0:14 (0 - 14) Frames: 1 - 359
1069    12/12/2018 21:11:27 NS(11167)- progLen = 0s, 0 bookmarks, HD = 1
1068    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-dec.hmt<br>
1067    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-dec.nts<br>
1066    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-dec.ts<br>
1065    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-inp.hmt<br>
1064    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-inp.nts<br>
1063    Removed /mod/tmp/The Secret Life of the Zoo_20181212_2005-inp.ts<br>
1062    12/12/2018 21:09:34 DA(3972)- done...processed /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005.ts in 3645.016s 01:00:45 - 5 ad breaks detected
1061    12/12/2018 21:09:34 DA(3972)- /mod/tmp/The Secret Life of the Zoo_20181212_2005-dec.ts deleted
1060    12/12/2018 21:09:23 DA(3972)- /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005.ts deleted
1059    12/12/2018 21:09:23 DA(3972)- Final bookmarks: 20 797 1041 1838 2083 2707 2952 3612 3756
1058    12/12/2018 21:09:23 NS(3972)- New Program Length = 2857s
1057    12/12/2018 21:09:23 NS(3972)- Wrote 71596 entries to /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005-crop. Stripped 774644 packets (145245k) of EPG data
1056    12/12/2018 21:09:23 NS(3972)- -++++++++++++-----++++++++++++-----++++++++++-----++++++++++--
1055    12/12/2018 21:09:22 DA(3972)-   ad break found 60:12-62:36 (3612 - 3756) Frames: 90310 - 93898
1054    12/12/2018 21:08:30 DA(11167)- ==DETECTADS Chase Run: /media/My Video/Old People's Home for 4 Year____20181212_2108.ts 
1053    12/12/2018 21:08:30 RM(11165)-   DETECTADS: Started /media/My Video/Old People's Home for 4 Year____20181212_2108.ts for chaserun advert detection
1052    12/12/2018 21:08:30 RM(11165)-   DETECTADS: Checking /media/My Video/Old People's Home for 4 Year____20181212_2108.ts (Channel 4 HD) for channel exclusion
1051    12/12/2018 21:04:58 DA(10118)-   ad break found 0:00-0:29 (0 - 29) Frames: 1 - 727
1050    12/12/2018 21:03:39 NS(10118)- progLen = 0s, 0 bookmarks, HD = 1
1049    12/12/2018 21:00:40 DA(10118)- ==DETECTADS Chase Run: /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts 
1048    12/12/2018 21:00:39 RM(10112)-   DETECTADS: Started /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts for chaserun advert detection
1047    12/12/2018 21:00:39 RM(10112)-   DETECTADS: Checking /media/My Video/New_ I'm a Celebrity___Get Me____20181212_2100.ts (ITV HD) for channel exclusion
1046    12/12/2018 20:56:43 DA(3972)-   ad break found 45:07-49:12 (2707 - 2952) Frames: 67671 - 73801
1045    12/12/2018 20:42:08 DA(3972)-   ad break found 30:38-34:43 (1838 - 2083) Frames: 45962 - 52076
1044    12/12/2018 20:24:55 DA(3972)-   ad break found 13:17-17:21 (797 - 1041) Frames: 19915 - 26026
1043    12/12/2018 20:13:35 DA(3972)-   ad break found 0:00-0:20 (0 - 20) Frames: 1 - 501
1042    12/12/2018 20:08:49 NS(3972)- progLen = 0s, 0 bookmarks, HD = 1
1041    12/12/2018 20:05:50 DA(3972)- ==DETECTADS Chase Run: /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005.ts 
1040    12/12/2018 20:05:50 RM(3967)-   DETECTADS: Started /media/My Video/The Secret Life of the Zoo/The Secret Life of the Zoo_20181212_2005.ts for chaserun advert detection

MymsMan · Dec 13, 2018

Occasionally decryption fails to deliver a decrypted file that is exactly the same length as the original, why is unknown but it often works when retried later.

If DetectAds detects a significant (>20s) discrepancy during chaserun processing it queues the file to be retried later. This can be upset if Sweeper or Newk moves or renames the recording before the reprocessing takes place.

The other form of length error is when the recording length detected by ffmpeg differs from that reported by the Humax. This can be caused by periods of picture/sound droput or pixellation in the recording. Such problems are permanent so no retry is attempted.

Both can cause cut points to be misplaced so the original and -crop file are left so you can choose whether to watch the the cropped or uncropped versions

Matthew · Dec 13, 2018

I get a 'Length' error every now and then, sometimes I know the cause, often not, to date there has never been a problem with the created file.

Trev · Dec 13, 2018

Thanks for your comments Myms. I will have a good stiff read tomorrow and respond accordingly. In the mean time i'm watching the -Crop version of celebrity.

Trev · Dec 14, 2018

MymsMan said:
This can be upset if Sweeper or Newk moves or renames the recording before the reprocessing takes place.

Yep, I am doing both of those.

This can be caused by periods of picture/sound droput or pixellation in the recording. Such problems are permanent so no retry is attempted.

One of the reported files did have some pixcellation not caused by the cropping process, so that would account for one of them then.

Both can cause cut points to be misplaced so the original and -crop file are left so you can choose whether to watch the the cropped or uncropped versions

I watched the -Crop files, and they were both OK.
Just have to do a double delete when finished watching. No biggie really.

Thanks for your input Myms.

Matthew · Jan 2, 2019

I've had another instance of Ad detect stuck in the queue, in this instance I know why the process baulked, I had deleted the file that was being processed, but why is the failure not immediately detected and why once a queue process is running can it not be deleted or stopped?

In this case after a reboot Ad detect was still stuck in the queue., then I noticed content sharing had yet again turned itself off, on turning it back on the process stopped and indicated read failure.

MymsMan · Jan 2, 2019

Matthew said:
In this case after a reboot Ad detect was still stuck in the queue., then I noticed content sharing had yet again turned itself off, on turning it back on the process stopped and indicated read failure.

I use boot settings package to guard against content sharing turning itself off but odd things happen on the humax

I just noticed that nothing had processed on the queue since 19:30 on 19/12 - the deq programme was no longer authorised to run!

Heaven knows how a file could suddenly lose permission on a normally running system - a simple chmod cured the problem

Matthew · Jan 4, 2019

Matthew said:
I've had another instance of Ad detect stuck in the queue

I've had this YET again, this time it would NOT go away, whatever I did, checking, the cause this time was content sharing turned off yet again! (yes I have now belatedly added the boot settings package, thanks MymsMan)

So I have two queries, why is content sharing turned off not being checked by Detectads, checking the code I see the check is done in one process, but not the other! Why?

I would also question why the check is not done by queue first anyway? So I came back to 'why once a queue process is running can it not be deleted or stopped', checking /mod/webif/lib/queue.class I find:

Code:

        and status != 'RUNNING'

preventing any delete or stop, WHY? and why not tell the user why their request was being ignored?

Removing the above I was finally able to delete the annoying stuck process and my queue could continue.

MymsMan · Jan 4, 2019

Matthew said:
So I have two queries, why is content sharing turned off not being checked by Detectads, checking the code I see the check is done in one process, but not the other! Why?

Content sharing is only relevant to decryption and not all auto Queue processing needs decryption, in detectads the run process handles files that have already been decrypted while chaserun handles encrypted recordings and so does need to check the setting, but if it is not enabled it exits immediately return {"FAILED" "Content Sharing Disabled"} so I cant see why that could cause the process to be stuck in Running, It might be better to return DEFER to allow automatic retry when content sharing is restored.

I can only guess is that somehow Content sharing was active at the start of processing but has become turned off in the middle - something that I have never seen or considered possible. The DLNA server can go inactive if the system goes into standby but chaseget handles that by waking the system up again but it doesn't check whether content sharing has been turned off - I will add a check and terminate if it goes off because I don't think there is any way to dynamically re-enable it.

How is your Humax connected to the network and is the connection in any way flaky? Losing network connection could be a reason for content sharing turning off and it is known that the Humax code does not handle networking problems well and this can result in crashes/hangs.

Matthew said:
So I came back to 'why once a queue process is running can it not be deleted or stopped',

Removing the entry from the queue didn't kill the running process and so far there has been insufficient need for a cancel running process option for @af123 to add one, cancelling a process can leave the system in an unpredictable state and could potentially cause other problems

Matthew · Jan 4, 2019

MymsMan said:
How is your Humax connected to the network and is the connection in any way flaky?

The Humax is connected via a Unmanaged Switch to the router, the PC is also connected to the router, all via LAN, its a stable connection.

MymsMan said:
Removing the entry from the queue didn't kill the running process

The process was dead, it was simply the queue that thought it was still running! I had even deleted detectads, then rebooted, it was still in the queue!! Detectads had created a crop file, but that remained at 0 bytes, so the failure must have been early. The file did not require decryption.

Is there any way to tell what processes are running in memory on the Humax?

Matthew · Jan 5, 2019

I would suggest the following needs to be added to queue:

For process showing in dBase as running, file length and resolution and decryption status indicate process should last x, if that plus margin has elapsed, assume process has failed and abort.

Any 'running' processes in dBase at boot time cancelled.

af123 · Jan 5, 2019

Matthew said:
Any 'running' processes in dBase at boot time cancelled.

This should already be in place, not at boot time but each time the de-queue process starts, RUNNING jobs get moved to INTERRUPTED and after enough interruptions, they are set to FAILED, see https://github.com/hummypkg/webif/blob/master/webif/lib/queue.class#L96

Matthew · Jan 5, 2019

af123 said:
This should already be in place, not at boot time but each time the de-queue process starts, RUNNING jobs get moved to INTERRUPTED and after enough interruptions, they are set to FAILED, see https://github.com/hummypkg/webif/blob/master/webif/lib/queue.class#L96

Hmmm yes I see that in the code, but its not happening, I`ve had things stuck in the queue for a day, never gets the status INTERRUPTED! even after a reboot

Where does 'queue startup' get called from, can't find it, neither can I find how dequeue is getting going!

MymsMan · Jan 5, 2019

Matthew said:
The process was dead, it was simply the queue that thought it was still running! I had even deleted detectads, then rebooted, it was still in the queue!! Detectads had created a crop file, but that remained at 0 bytes, so the failure must have been early. The file did not require decryption.

Now I am thoroughly confused (not hard to achieve)
If the file didn't require decryption and problem survives reboot then the content share thoughts are a red herring although suspiciously coincidental
I have no idea what could cause a repeatable hang otherwise.

I think we need full copies of the auto.log for the period when the file was first processed and following the reboot.
Add -d to the DetectAds Other options to increase logging in case of recurrence
Do you still have the original problem recording? Can we recreate the problem by requeuing it for DetectAds? or by running from the Opt+ menu?
Have you tried without your changes to eliminate them from suspicions?

Matthew said:
Is there any way to tell what processes are running in memory on the Humax?

See https://www.tecmint.com/ps-command-examples-for-linux-process-monitoring/ top command shows most active processes and pgrep/pkill find and kill by name

Dequeue is the deq program run from chrontab.

Matthew · Jan 5, 2019

MymsMan said:
Now I am thoroughly confused (not hard to achieve)
I think we need full copies of the auto.log for the period when the file was first processed and following the reboot.
Add -d to the DetectAds Other options to increase logging in case of recurrence
Do you still have the original problem recording? Can we recreate the problem by requeuing it for DetectAds? or by running from the Opt+ menu?
Have you tried without your changes to eliminate them from suspicions?

Sorry the file is deleted, I`ll add the -d option and post if/when it re-occurs. I've been having this issue for ages and well before I made any changes to the code, I can't see they would have any effect on this anyway.

Thanks for the info.

MymsMan · Jan 5, 2019

Do you have the auto.logs for the last occurrence - even without full debug log we might get a clue.

Matthew · Jan 5, 2019

Sorry, I`ve looked and as I have debugging log level on its creating big logs and as I`ve set size limits there is nothing left for yesterday.

MymsMan · Jan 5, 2019

I use Rotated logs 5 and Rotate logs when they exceed 100kb and dont have problems keeping several days worth of logs, months of less active ones

MymsMan · Jan 6, 2019

I have updated DetectAds and ChaseGet to handle Content Sharing being turned off better.

DetectAds will now issue a system notify message (red box in webif) to alert the user and will defer Queue processing so that it will automatically be retried.
ChaseGet will also issue a notify message if it is turned off mid-processing and wait up to 10 minutes for it to be re-enabled before giving up.

I have not included Matthew's other changes yet and if there are other problems with already decrypted files we will have to wait for more diagnostics.

Matthew · Jan 7, 2019

I`ve had another failure, though I don't think its related, this time queue states plugin failure.

The file is a timeslip one (it did not need processing, but got grabbed anyway) I tried several times and background process failed the same each time, error seems to be:

Code:

4967    06/01/2019 17:45:06 NS(12793)- Failure to read .ts in timeslip offset scan
4966    06/01/2019 17:45:06 NS(12793)- Timeslip recording detected - attempting to sync .nts and .ts
4965    06/01/2019 17:45:06 NS(12793)- progLen = 0s, 0 bookmarks, HD = 0

The log states:

Code:

4981    06/01/2019 17:46:14 -    Plugin failure
4980    06/01/2019 17:46:14 -     -1 -  -
4979    06/01/2019 17:46:14 - detectads:    /mod/webif/plugin/detectads/detectads.jim:1107 @ puts
4978    06/01/2019 17:46:14 - detectads:::detectads::dequeue: pipe: Broken pipe

Line 1105 - 1110 is

Code:

            set totalEndSeconds [expr {$endMinutes * 60 + $endSeconds}]
            set cropline "-chkpt $($totalEndSeconds *10)"
            puts $cropInput $cropline
            flush $cropInput
            set_HMT_durn "$tpath/$tname" $stime $totalEndSeconds
            log "Hearbeat: Frame $endFrame Time: $endMinutes:$endSeconds Seconds: $totalEndSeconds" 1

I have tested with the updated file, same error.
I`ve added a debug line to show values for $cropInput $cropline which are:

Code:

<reference.<functio>.00000000000000000014> -chkpt 1640

Running detectads 'manually' works with no errors reported.

I have full logs if needed

Problem with detectads

The Dumb One

Ad detector

Active Member

The Dumb One

The Dumb One

Active Member

Ad detector

Active Member

Ad detector

Active Member

Active Member

Administrator

Active Member

Ad detector

Active Member

Ad detector

Active Member

Ad detector

Ad detector

Active Member