Another runaway recording

[MymsMan]

The BBC local news South Today suffered a runaway recording last night - I was able to stop it using IR remote package this afternoon when I noticed it still going!

There was definitely a burst of RTS action scheduling new recordings during the period immediately following the end of the BBC national news whilst South Today was correctly recording so something managed to destroy the normal end recording processing by the humax!

Activity.log

336    17/03/2018 14:42:11 - Recorded: BBC News/South Today (977 minutes - BBC ONE South)
335    16/03/2018 22:31:56 - Scheduled A Question of Sport Relief @ 1521842400
334    16/03/2018 22:31:56 - Scheduled Sport Relief 2018 @ 1521831600
333    16/03/2018 22:31:53 - Scheduled Sport Relief 2018 @ 1521831600
332    16/03/2018 22:31:37 - Scheduled A Question of Sport Relief @ 1521842400
331    16/03/2018 22:31:33 - Recorded: QI/QI (29 minutes - BBC TWO HD)
330    16/03/2018 22:31:31 - Scheduled Winter Paralympics Today @ 1521381600
329    16/03/2018 22:25:06 - Recorded: BBC News/BBC News at Ten (24 minutes - BBC ONE South)

Nugget.log

130    [nugget]: Fri Mar 16 22:32:00 2018:     - Fri Mar 23 21:59:30 2018
129    [nugget]: Fri Mar 16 22:32:00 2018: Adding timer(1521842370)
128    [nugget]: Fri Mar 16 22:32:00 2018: Ready 1521842370 - Fri Mar 23 21:59:30 2018
127    [nugget]: Fri Mar 16 22:32:00 2018:  Wake 1521842400 - Fri Mar 23 22:00:00 2018
126    [nugget]: Fri Mar 16 22:32:00 2018: Good EPG data, retaining.
125    [nugget]: Fri Mar 16 22:32:00 2018:    @ 1521842400 (Fri Mar 23 22:00:00 2018)
124    [nugget]: Fri Mar 16 22:32:00 2018:   A Question of Sport Relief
123    [nugget]: Fri Mar 16 22:32:00 2018: Processing slot 15 (15)
122    [nugget]: Fri Mar 16 22:32:00 2018:     - Fri Mar 23 18:59:30 2018
121    [nugget]: Fri Mar 16 22:32:00 2018: Adding timer(1521831570)
120    [nugget]: Fri Mar 16 22:32:00 2018: Ready 1521831570 - Fri Mar 23 18:59:30 2018
119    [nugget]: Fri Mar 16 22:32:00 2018:  Wake 1521831600 - Fri Mar 23 19:00:00 2018
118    [nugget]: Fri Mar 16 22:32:00 2018: Good EPG data, retaining.
117    [nugget]: Fri Mar 16 22:32:00 2018:    @ 1521831600 (Fri Mar 23 19:00:00 2018)
116    [nugget]: Fri Mar 16 22:32:00 2018:   Sport Relief 2018
115    [nugget]: Fri Mar 16 22:32:00 2018: Processing slot 18 (18)
114    [nugget]: Fri Mar 16 22:32:00 2018: slots(76, 18,15)
113    [nugget]: Fri Mar 16 22:32:00 2018: schedule.restore 29 = 2
112    [nugget]: Fri Mar 16 22:32:00 2018: schedule reload complete (76).
111    [nugget]: Fri Mar 16 22:31:59 2018: Closing database.
110    [nugget]: Fri Mar 16 22:31:59 2018: schedule.stash 29 = 2
109    [nugget]: Fri Mar 16 22:31:59 2018: Re-loading schedule database (76).
108    [nugget]: Fri Mar 16 22:31:59 2018: schedule save complete.
107    [nugget]: Fri Mar 16 22:31:59 2018: schedule save starting.
106    [nugget]: Fri Mar 16 22:31:59 2018: Deferred thread exiting.
105    [nugget]: Fri Mar 16 22:31:59 2018:     - Fri Mar 23 18:44:30 2018
104    [nugget]: Fri Mar 16 22:31:59 2018: Adding timer(1521830670)
103    [nugget]: Fri Mar 16 22:31:59 2018: Ready 1521830670 - Fri Mar 23 18:44:30 2018
102    [nugget]: Fri Mar 16 22:31:59 2018:  Wake 1521830700 - Fri Mar 23 18:45:00 2018
101    [nugget]: Fri Mar 16 22:31:59 2018:       Fri Mar 23 22:35:00 2018 +145m
100    [nugget]: Fri Mar 16 22:31:59 2018:  [1] 131100,1521844500,1521853200,53687
99    [nugget]: Fri Mar 16 22:31:59 2018:       Fri Mar 23 19:00:00 2018 +180m
98    [nugget]: Fri Mar 16 22:31:59 2018:  [0] 131100,1521831600,1521842400,53686
97    [nugget]: Fri Mar 16 22:31:59 2018:   Events: 1FP.BBC.CO.UK/1REFZU|1FP.BBC.CO.UK/1REGF6|
96    [nugget]: Fri Mar 16 22:31:59 2018:   Last Event: 0
95    [nugget]: Fri Mar 16 22:31:59 2018:   Recorded:
94    [nugget]: Fri Mar 16 22:31:59 2018:   CRID: 2/[FP.BBC.CO.UK/P1EBQ7]
93    [nugget]: Fri Mar 16 22:31:59 2018:    @ 1521831600 (Fri Mar 23 19:00:00 2018)
92    [nugget]: Fri Mar 16 22:31:59 2018:   Sport Relief 2018
91    [nugget]: Fri Mar 16 22:31:59 2018: Processing slot +18 (18)
90    [nugget]: Fri Mar 16 22:31:59 2018:     - Fri Mar 23 21:44:30 2018
89    [nugget]: Fri Mar 16 22:31:59 2018: Adding timer(1521841470)
88    [nugget]: Fri Mar 16 22:31:59 2018: Ready 1521841470 - Fri Mar 23 21:44:30 2018
87    [nugget]: Fri Mar 16 22:31:59 2018:  Wake 1521841500 - Fri Mar 23 21:45:00 2018
86    [nugget]: Fri Mar 16 22:31:59 2018:       Fri Mar 23 22:00:00 2018 +40m
85    [nugget]: Fri Mar 16 22:31:59 2018:  [0] 131101,1521842400,1521844800,54007
84    [nugget]: Fri Mar 16 22:31:59 2018:   Events: 1FP.BBC.CO.UK/1RE985|
83    [nugget]: Fri Mar 16 22:31:59 2018:   Last Event: 0
82    [nugget]: Fri Mar 16 22:31:59 2018:   Recorded:
81    [nugget]: Fri Mar 16 22:31:59 2018:   CRID: 1/[FP.BBC.CO.UK/1RE985]
80    [nugget]: Fri Mar 16 22:31:59 2018:    @ 1521842400 (Fri Mar 23 22:00:00 2018)
79    [nugget]: Fri Mar 16 22:31:59 2018:   A Question of Sport Relief
78    [nugget]: Fri Mar 16 22:31:59 2018: Processing slot +15 (15)
77    [nugget]: Fri Mar 16 22:31:59 2018:     - Sun Mar 18 13:44:30 2018
76    [nugget]: Fri Mar 16 22:31:59 2018: Adding timer(1521380670)
75    [nugget]: Fri Mar 16 22:31:59 2018: Ready 1521380670 - Sun Mar 18 13:44:30 2018
74    [nugget]: Fri Mar 16 22:31:59 2018:  Wake 1521380700 - Sun Mar 18 13:45:00 2018
73    [nugget]: Fri Mar 16 22:31:59 2018:       Sun Mar 18 14:00:00 2018 +75m
72    [nugget]: Fri Mar 16 22:31:59 2018:  [0] 262243,1521381600,1521386100,14929
71    [nugget]: Fri Mar 16 22:31:59 2018:   Events: 1WWW.CHANNEL4.COM/67439/024|
70    [nugget]: Fri Mar 16 22:31:59 2018:   Last Event: 0
69    [nugget]: Fri Mar 16 22:31:59 2018:   Recorded:
68    [nugget]: Fri Mar 16 22:31:59 2018:   CRID: 1/[WWW.CHANNEL4.COM/67439/024]
67    [nugget]: Fri Mar 16 22:31:59 2018:    @ 1521381600 (Sun Mar 18 14:00:00 2018)
66    [nugget]: Fri Mar 16 22:31:59 2018:   Winter Paralympics Today
65    [nugget]: Fri Mar 16 22:31:59 2018: Processing slot +0 (0)
64    [nugget]: Fri Mar 16 22:31:59 2018: slots(76, +0,+15,+18)
63    [nugget]: Fri Mar 16 22:31:59 2018: schedule.restore 29 = 2
62    [nugget]: Fri Mar 16 22:31:59 2018: schedule reload complete (76).
61    [nugget]: Fri Mar 16 22:31:59 2018: Re-loading schedule database (76).
60    [nugget]: Fri Mar 16 22:31:58 2018: schedule.save - wait(1).
59    [nugget]: Fri Mar 16 22:31:57 2018: schedule.save - wait(1).
58    [nugget]: Fri Mar 16 22:31:56 2018: Deferred thread starting for '76:+0,+15,+18' (attempt 1)
57    [nugget]: Fri Mar 16 22:31:56 2018: Schedule failed to reload, deferring.
56    [nugget]: Fri Mar 16 22:31:56 2018: NULL database handle.
55    [nugget]: Fri Mar 16 22:31:56 2018: Schedule load failed.
54    [nugget]: Fri Mar 16 22:31:56 2018: Closing database.
53    [nugget]: Fri Mar 16 22:31:56 2018: schedule.stash 29 = 2
52    [nugget]: Fri Mar 16 22:31:56 2018: Re-loading schedule database (76).
51    [nugget]: Fri Mar 16 22:31:55 2018: schedule save complete.
50    [nugget]: Fri Mar 16 22:31:55 2018: schedule save starting.
49    [nugget]: Fri Mar 16 22:31:55 2018: Persistent log starting, v0.97

rsvsync.log

753    Fri Mar 16 22:31:59 2018: Loading schedule information to HumaxTV binary.
752    Fri Mar 16 22:31:59 2018: Final schedule entries: 76
751    Fri Mar 16 22:31:59 2018: Slots: 18,15
750    Fri Mar 16 22:31:59 2018: Padding slot 15 = 0/120
749    Fri Mar 16 22:31:59 2018: Found slot 15 for 3/131101/1521842400/54007
748    Fri Mar 16 22:31:59 2018: Padding slot 18 = 0/120
747    Fri Mar 16 22:31:59 2018: Found slot 18 for 3/131100/1521831600/53686
746    Fri Mar 16 22:31:59 2018: Opening /var/lib/humaxtv/rsvp.db
745    Fri Mar 16 22:31:59 2018: Schedule saved.
744    Fri Mar 16 22:31:57 2018: Nugget is available.
743    Fri Mar 16 22:31:57 2018: Real-time mode.
742    Fri Mar 16 22:31:57 2018: rsvsync starting, version 1.1.12.
741    16/03/2018 22:31:56 - multimode: converting A Question of Sport Relief to pad <0,120>
740    16/03/2018 22:31:56 - multimode: converting Sport Relief 2018 to pad <0,120>
739    Fri Mar 16 22:31:56 2018: Loading schedule information to HumaxTV binary.
738    Fri Mar 16 22:31:56 2018: Final schedule entries: 76
737    Fri Mar 16 22:31:56 2018: Slots: +0,+15,+18
736    Fri Mar 16 22:31:55 2018: Moving pending entry 2 to spare slot 18
735    Fri Mar 16 22:31:55 2018: Moving pending entry 1 to spare slot 15
734    Fri Mar 16 22:31:55 2018: Moving pending entry 0 to spare slot 0
733    Fri Mar 16 22:31:55 2018: Opening /var/lib/humaxtv/rsvp.db
732    Fri Mar 16 22:31:55 2018: Schedule saved.
731    Fri Mar 16 22:31:55 2018: Nugget is available.
730    Fri Mar 16 22:31:55 2018: Real-time mode.
729    Fri Mar 16 22:31:55 2018: rsvsync starting, version 1.1.12.
728    Fri Mar 16 07:49:48 2018: Final schedule entries: 75

rs.log

1363    Already up-to-date.
1362    Sending pending schedule information to remote server.
1361    >>> Skipped 0.
1360    Sending skiplist information to remote server.
1359     Updating...
1358    Sending TBL_RESERVATION schedule information to remote server.
1357    _Successfully scheduled event.
1356    _Found event - Sport Relief 2018
1355    *Trying source service/event ID.
1354    *Schedule 4163/53686/2/1/BBC ONE South/1521831600/Sport Relief 2018
1353    Processing command 'schedule '
1352    _Successfully scheduled event.
1351    _Found event - A Question of Sport Relief
1350    *Trying source service/event ID.
1349    *Schedule 4287/54007/1/2/BBC TWO/1521842400/A Question of Sport Relief
1348    Processing command 'schedule '
1347    _Successfully scheduled event.
1346    _Found event - Winter Paralympics Today
1345    *Trying source service/event ID.
1344    *Schedule 8384/14929/1/4/Channel 4/1521381600/Winter Paralympics Today
1343    Processing command 'schedule

Any other information that would be useful for debugging?

 

[Black Hole]

At last a hypothesis to test: runaway recordings are the result of the schedule database being updated by CF while a recording is in progress (which would not be possible without RTS).

I'll see if I can make it happen.

 

[MymsMan]

At last a hypothesis to test: runaway recordings are the result of the schedule database being updated by CF while a recording is in progress (which would not be possible without RTS).

I'll see if I can make it happen.

I have also scheduled many recording whilst recording without causing a runaway so there is some obscure timing window in place.
The South Today is a long standing series recording and not a product of RTS.

 

[af123]

I'll have a look through those logs when I get a few hours in the week, thanks for posting them.
The problem I have is that although I understood the assembly language involved for RTS when I implemented it, and I do have a commented version of the code again, I'll need time to get back into it as I've most definitely swapped it out of my head in the intervening time.

 

[Trev]

Ah Ha. The good old mental swap file. I have to use it all the time now.

 

[MymsMan]

Ah Ha. The good old mental swap file. I have to use it all the time now.

Trouble is I have a faulty file-system and it rarely swaps back in completely
I have enough trouble trying to understand the code I wrote myself or remembering why I went upstairs.

 

[Black Hole]

I went upstairs, and when I came back down I realised I hadn't done what I went up for. So I went back up and found that I had.

 

[MymsMan]

At least I can't be guilty of the old cliché of going out and leaving the iron on!

 

[EEPhil]

Ah Ha. The good old mental swap file. I have to use it all the time now.

Unlike a real swap file on a microVAX I used years ago (with simulated version run today)

OpenVMS V7.3  on node $£&*^  18-MAR-2018 13:27:23.98  Uptime  0 00:09:38
  Pid    Process Name    State  Pri      I/O       CPU       Page flts  Pages
00000056 BATCH_2         HIBO     3       --  swapped  out  --          11986  B
00000057 BATCH_3         HIBO     4       --  swapped  out  --           6980  B

That's what happened when you tried to get a quart into a pint pot (big simulations, not much memory). Things swapped out, became difficult to "take back control" , often happened when the an important visitor arrived. Usually required a quick kick up the reboot button - or the damn thing crashed and rebooted itself. I wouldn't like to translate that into an analogy with anything human!

I have enough trouble trying to understand the code I wrote myself

And not just the code for the simulations (c 1983-91). I have trouble understanding the code I wrote last year to interface with the 2000T. Or the code I was trying to develop to examine the .ts files.