[Real-time scheduling] - Runaway recording

[HeadlessChicken]

Hi,

In the beta forum post about Real-time scheduling I asked about a runaway recording (that I had about 24 hours ago), and MymsMan recommended that I post here.


To answer MymsMan's questions:

Firstly are you up to date with customised firmware and all packages, in particular what version of the nugget package do you have installed?

I believe everything is up-to-date. Nugget is 1.0, Web interface version 1.4.4-10, Custom firmware version 3.13 (build 4028), Humax Version 1.03.12 (kernel HDR_CFW_3.13), Loader Version a7.30.

Were you able to stop the recording using the remote control or did you need to power off the machine.

The remote worked.

Did you schedule or delete scheduled recordings whilst the recording was in progress?

Yes. I deleted one or two, and scheduled around 20.


The recording started at midnight on Channel 4 HD (Snackmasters if you're interested), and should have stopped at 1am. At around 11:50am I opened the web-if to plan the following seven days of recording. At about 1:30am I noticed a schedule entry in the web-if listing for the same show for the 24th, but with no time or duration. It said something like 'last on 17th Oct'. As far as I'm concerned I didn't select 'Record series', but maybe I did by mistake. I deleted this entry, and then a few minutes later noticed that the show was still recording. I went to the Humax and stopped the recording using the remote.

Also, while I was in the web-if the Humax was recording two channels, and was 'watching' a third channel.

Let me know if any other information would be useful.

 

[Black Hole]

Runaway recordings are extremely rare and I haven't seen one since we successfully identified and fixed a bug in April
Nobody else has reported a runaway since then,
The code has been out of Beta for a long time now - so it would best to start a new thread in the main forum

We will need a lot more detail of the circumstances of your problem
Firstly are you up to date with customised firmware and all packages, in particular what version of the nugget package do you have installed?
Were you able to stop the recording using the remote control or did you need to power off the machine.
Did you schedule or delete scheduled recordings whilst the recording was in progress?
If it occurs again try to issue from a telnet command line

nugget tuners.dump
nugget recordings
nugget schedule.timers
nugget schedule.entry <slot number>

Where <slot number> is the number for the problem recording

See also https://hummy.tv/forum/threads/runaway-recording-in-progress.9219/

 

[MymsMan]

The recording started at midnight on Channel 4 HD (Snackmasters if you're interested), and should have stopped at 1am. At around 11:50am I opened the web-if to plan the following seven days of recording. At about 1:30am I noticed a schedule entry in the web-if listing for the same show for the 24th, but with no time or duration. It said something like 'last on 17th Oct'. As far as I'm concerned I didn't select 'Record series', but maybe I did by mistake. I deleted this entry, and then a few minutes later noticed that the show was still recording. I went to the Humax and stopped the recording using the remote.

To confirm my understanding of the above:

• You thought you had scheduled a single program recording for Snackmasters at 00:10 on 17/10 (but may have accidentally scheduled a series)
• Whilst Snackmasters was recording you noticed a schedule entry for Snackmasters for next week 24/10 but with no start time shown (though in your description you said "At about 1:30am" by which time Snackmasters should have finished is that correct?)
• You deleted this schedule entry using the webif (not Remote Scheduling) whilst recording of the current episode was still in progress
• The entry disappeared from your recording schedule
• After the scheduled end of Snackmasters (01:05) you noticed it was still recording and stopped it with the remote control

Is that correct?
The reason that I want to get the chronology correct is that is somewhat similar to what I experienced in April and I can see that deleting the details, including the timers used to stop recording, from an in progress recording could cause a runaway recording. In the previous thread @af123 said that

In general we are not supposed to be able to make changes to things which are in-progress, but I can't remember the mechanism; I'll have to refresh my memory.

So you should not have been able to delete Snackmasters whilst it was recording but perhaps the current checks are inadequate.

Posting the relevant portions of activity.log, nugget.log and rsvsync.log may help the diagnosis

I am curious about the schedule entry for Snackmasters since a 'normal' in progress recording looks like

while the Last on date/time is only shown for series with no future episodes

From your description it seems that you had some mixture of the two formats, If it occurs again a screenshot would be interesting.

Edit: To query time when entry was deleted

 

[HeadlessChicken]

I've attached the relevant portions of the requested logs.

My memory is not the best, so the it's getting harder to remember the order in which things happened...but I'm trying my best, and the logs have helped me. Using most of your words:

• I thought I had scheduled a single program recording for Snackmasters at 00:10 on 17/10 (but may have accidentally scheduled a series - I don't know how to tell from the logs)
• Whilst Snackmasters was recording I noticed a schedule entry for Snackmasters for next week 24/10 but with no start time shown (In my memory this was at about 1:30am, so after the recording should have stopped. Also there's an interesting line in activity.log: 17/10/2019 01:45:10 - Scheduled Snackmasters @ 1571267400 - I didn't schedule another recording of Snackmasters, and 1571267400 is 17 October 2019 00:10, so is this the time I deleted the schedule entry?)
• I deleted this schedule entry using the webif (not Remote Scheduling, which I haven't got installed) whilst recording of the current episode was still in progress
• The entry disappeared from my recording schedule
• At 02:03 (almost an hour after the scheduled end of Snackmasters) I noticed it was still recording and stopped it with the remote control

I am curious about the schedule entry for Snackmasters since a 'normal' in progress recording looks like

while the Last on date/time is only shown for series with no future episodes

From your description it seems that you had some mixture of the two formats, If it occurs again a screenshot would be interesting.

From memory it was very similar to the second one. But I'll make sure to screenshot it if it happens again.

Thank you for helping

 

[MymsMan]

Also there's an interesting line in activity.log: 17/10/2019 01:45:10 - Scheduled Snackmasters @ 1571267400 - I didn't schedule another recording of Snackmasters, and 1571267400 is 17 October 2019 00:10, so is this the time I deleted the schedule entry?)

Yes, that is the deletion event (& your memory was correct) - I have complained before about the confusing use of 'Scheduled' when deleting/skipping entries

Since this is way after the scheduled end of the recording it cant have been the cause of the runaway recording - the horse had already bolted.

This is not good for the purposes of diagnosis - one of the previous schedule events probably caused the problem but how and why. I routinely schedule recordings whilst recordings are in progress and so rarely does a problem occur that it is impossible to create a reproducible test case, it must be some small timing window

I had hoped that the fixes made in April would finally cure the runaway problem but unfortunately it appears not

 

[prpr]

I've just had a runaway recording - 1968 minutes long.
I'm afraid I just stopped it without bothering to investigate.

 

[prpr]

I've just had a runaway recording

And future recordings on that series link are now not taking place, despite all the CRIDs looking correct. I'll power cycle it at some convenient point and see if the next recording works. Other recordings seem OK so far.

 

[MymsMan]

And future recordings on that series link are now not taking place, despite all the CRIDs looking correct. I'll power cycle it at some convenient point and see if the next recording works. Other recordings seem OK so far.

I you get a chance try nugget timers slot-number and anything from nugget.log and rsvsync.log
Were you doing anything with the schedule around then.
Do you have Schedchk installed? If you do try fmtrsv -s slot-number or fmtrsv -n name, any mesages from schedchk
Slot number is shown on webif schedule list

 

[prpr]

I you get a chance try nugget timers slot-number and anything from nugget.log and rsvsync.log

I didn't. Is nugget timers the same as nugget schedule.timers? The former isn't listed when you run it without parameters, but the latter is. They appear to produce the same output.

Were you doing anything with the schedule around then.

Three days before - I added an item for something that was already in progress, but I think i did it on the SD instead of HD version and then corrected it. It worked OK for three days and then failed on the fourth.
I added something else about 30 mins after the runaway recording was scheduled to stop so it can't have been that.

Do you have Schedchk installed?

No, not on that machine.

 

[MymsMan]

Is nugget timers the same as nugget schedule.timers?

Yes, I'm too lazy to type the longer version

So we still have an unexplained but very rare chance of overruns, but overruns are less of a problem than unexplained hangs & crashes

 

[salad dodger]

I got back from holiday last weekend to find a long running BBC4 recording, started at 10pm Thursday until I stopped it around 3pm Saturday at which point i had a very full drive.
I think this was a very hot day, my living room was very warm with no one at the house and in high pressure my tv signal can be severely affected.

 

[prpr]

I think my signal had turned marginal too (I was not there), as lots of muxes were affected with blockiness. Perhaps that was the cause. Solved with a £12 Proception 10dB amp. from Toolstation a day later, replacing a passive splitter.

 

[MymsMan]

I got back from holiday last weekend to find a long running BBC4 recording, started at 10pm Thursday until I stopped it around 3pm Saturday at which point i had a very full drive.
I think this was a very hot day, my living room was very warm with no one at the house and in high pressure my tv signal can be severely affected.

Interesting. That would have been a very large recording!

Did you have any other recordings scheduled around the same time or after 10pm Thursday?
Apart from recordings on BBC4 did they record OK?
Did you use remote scheduling to schedule the runaway programme or to make any other changes to the schedule with remote scheduling whilst away

It can be useful to have the humax plugged into a simple time switch to force a delay reboot in the middle of he night while you are away from home to limit the damage caused by runaway recordings or the more common random hangs and crashes.

 

[Black Hole]

BBC4 recording, started at 10pm Thursday until I stopped it around 3pm Saturday

I'm not clear how that happened. BBC FOUR goes off-air (data service only) during the day, so I'm not saying it can't happen but I would have expected the recording to drop. It would be interesting to see what is in the recording, but I imagine you have deleted it.

I'm sure no ordinary recording would work. There is a certain amount of autonomous DMA going on, so could this be a clue to what the runaway recording syndrome might be: how about if the block count is accidentally set to a negative or very large value?

 

[salad dodger]

Can't exactly remember how I scheduled it, the programme about the Porton Down facility which wasn't watchable. I don't think it would have been remote via the web but 99% likely to have been via the web ui direct rather than the guide itself on screen. No other programmes recorded subsequently, as I wanted to watch Criterium du Dauphine on itv4 but those had failed. Didn't think much of it at the time, just that i was fortunate to notice when I did. Yes I deleted it to recover my drive space.

 

[EEPhil]

I'm not clear how that happened. BBC FOUR goes off-air (data service only) during the day, so I'm not saying it can't happen but I would have expected the recording to drop. It would be interesting to see what is in the recording, but I imagine you have deleted it.

I suspect what would happen is that the recording would not drop automatically. You would record 10pm Thursday to closedown Friday morning and 7pm Friday to closedown Saturday at full BBC4 data rates. The off-air bit would consume minimal data. There would be an error message indicating a broken recording. If you played it back I'd bet the recording jumps from closedown Friday to 7pm Friday with, perhaps, just a few glitches.

 

[Code is a Hole]

I'm not sure if this is related, but I tried [ schedchk ] on a couple of my Humax HDR Fox T2 units and have a selection of programmes set to record as single events, [ sweeper ] is set to file them away neatly, I have also noticed that the runaway recording syndrome has occurred, one I noticed had amassed a file size of 50GB, the recording was stopped by doing a [ reboot ] via a telnet session, (wasn't near the TV to use the remote control)

Is the runaway recording issue to do with [ schedchk ]

I'm also getting a lot of failed recording notifications on one unit, whereby an orphaned [ .hmt ], is in a list at the top of the [ remote scheduling ] web page, clicking the waste bin sets up a 'delete' command, followed shortly after with [ '/[Deleted Items]/**********.hmt' ], which is then processed with another 'delete' command, thanks to [ real-time scheduling ]

 

[Code is a Hole]

Just had to force-stop another runaway recording

 

[MymsMan]

Schechk could be implicated in runaway recordings since it does use RTS to schedule recordings,
Did you get any alerts from schedchk saying it was scheduling something? Are there any messages from schedchk in auto.log or schedchk.log
Are the failed recordings ones that schedchk has issued messages about?

 

[Code is a Hole]

Are there any messages from schedchk in auto.log or schedchk.log

I must admit, not sure when I noticed the runaway recordings, I uninstalled the schedchk package as it was the last thing I had installed

I did have a look at the auto.log and found some entries that have a similar appearance to the options displayed in the options page of schedchk