Beta [Real-time scheduling] schedule without rebooting

[Black Hole]

Is there anyway to lower the chance of this happening?

Not until we have a handle on why it happens.

Black Hole, does it ever happen to you? I'm wondering if keeping my Humax on 24/7 would help.

Only once. No idea.

 

[HeadlessChicken]

Thank you.

I'm away for the next two weeks, and will be using the web-if to control the HDR (via a VPN to 'be on my local network'). If this was to happen again is there anyway to stop the recording via the web-if?

 

[MymsMan]

Last night I had the 'Occasionally a recording will just keep going past the time it should have stopped' bug.

Is there anyway to lower the chance of this happening?

Black Hole, does it ever happen to you? I'm wondering if keeping my Humax on 24/7 would help.

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

 

[MymsMan]

I'm away for the next two weeks, and will be using the web-if to control the HDR (via a VPN to 'be on my local network'). If this was to happen again is there anyway to stop the recording via the web-if?

You can try using the webif remote control page to send a STOP button signal to the Humax
A random hang/crash is far more likely than another runaway and it is useful to have your Humax connected to a time switch to force an overnight power off which will prevent you losing more than a days worth of recordings and also kill a runaway should it occur.

 

[Black Hole]

Runaway recordings are extremely rare and I haven't seen one since we successfully identified and fixed a bug in April

...and mine (just before that) seems to have been related to the "missing" hour in a GMT-to-BST clock change.

 

[HeadlessChicken]

Thanks everyone! I'll make sure I run those nugget commands if it happens again.

I've posted in the main forum here: https://hummy.tv/forum/threads/real-time-scheduling-runaway-recording.9405/

Thanks for the tip about the time switch. I'll set that up before I go. Should I do the same with my Foxsat do you think?

 

[4ndy]

RTS is apparently not running. A programme scheduled by RS mid-morning still pending. RS is showing last synced 7:12pm and I know has synced several times before that. Which packages does it use? How do I get it working again please?

 

[MymsMan]

Try nugget ping to see if it replies Pong

Check your advanced setting to ensure RTS is enabled
A reboot may be needed

 

[4ndy]

Replied pong.

Pending schedule now processed. Obviously working but not as quickly as expected. I have noticed other, mainly auto-schedule seem to hang about all day.

My boxes are left on all day, even though RS seems to sync every 3 hours or so.


Sent from my iPad using Tapatalk

 

[Black Hole]

My boxes are left on all day, even though RS seems to sync every 3 hours or so.

My RS syncs every 10 minutes.

 

[4ndy]

My RS syncs every 10 minutes.

I was going by the last seen time on RS. Is the 10 minutes user definable?


Sent from my iPad using Tapatalk

 

[MymsMan]

I was going by the last seen time on RS. Is the 10 minutes user definable?

Yes, in /mod/var/spool/cron/crontabs/root

*/10 * * * * /mod/sbin/rs_process >> /mod/tmp/rs.log 2>&1

But in your case the recording was in Pending rather than Queued status showing that it had been received by the Humax and was awaiting a reboot (eg RTS had not scheduled it)

Look at nugget.log and rsvsync.log for any clues

BTW Nugget.log timestamps show GMT not BST, rsvsysnc is in BST

 

[4ndy]

rsvsync.log = looks like it stopped working for several hours. I copying some files off this box for an hour or so late morning, but box remained on all day and was not locked or anything when I went to it this evening.

5000    Mon Jun 29 19:51:59 2020: Loading schedule information to HumaxTV binary.
4999    Mon Jun 29 19:51:59 2020: Final schedule entries: 95
4998    Mon Jun 29 19:51:59 2020: Slots: +71,+78
4997    Mon Jun 29 19:51:59 2020: Moving pending entry 1 to spare slot 78
4996    Mon Jun 29 19:51:59 2020: Moving pending entry 0 to spare slot 71
4995    Mon Jun 29 19:51:59 2020: Opening /var/lib/humaxtv/rsvp.db
4994    Mon Jun 29 19:51:59 2020: Schedule saved.
4993    Mon Jun 29 19:51:58 2020: Nugget is available.
4992    Mon Jun 29 19:51:58 2020: Real-time mode.
4991    Mon Jun 29 19:51:58 2020: rsvsync starting, version 1.1.13.
4990    Mon Jun 29 10:11:06 2020: Failed: database is locked (database is locked)
4989    Mon Jun 29 10:11:06 2020: Moving pending entry 1 to spare slot 78
4988    Mon Jun 29 10:11:06 2020: Moving pending entry 0 to spare slot 71
4987    Mon Jun 29 10:11:06 2020: Opening /var/lib/humaxtv/rsvp.db
4986    Mon Jun 29 10:11:06 2020: Schedule saved.
4985    Mon Jun 29 10:11:05 2020: Nugget is available.
4984    Mon Jun 29 10:11:05 2020: Real-time mode.
4983    Mon Jun 29 10:11:05 2020: rsvsync starting, version 1.1.13.
4982    Mon Jun 29 09:10:45 2020: Loading schedule information to HumaxTV binary.
4981    Mon Jun 29 09:10:45 2020: Final schedule entries: 93
4980    Mon Jun 29 09:10:45 2020: Slots: +5
4979    Mon Jun 29 09:10:45 2020: Moving pending entry 0 to spare slot 5
4978    Mon Jun 29 09:10:45 2020: Opening /var/lib/humaxtv/rsvp.db
4977    Mon Jun 29 09:10:45 2020: Schedule saved.
4976    Mon Jun 29 09:10:45 2020: Nugget is available.
4975    Mon Jun 29 09:10:45 2020: Real-time mode.
4974    Mon Jun 29 09:10:45 2020: rsvsync starting, version 1.1.13.
4973    Mon Jun 29 04:59:10 2020: Loading schedule information to HumaxTV binary.
4972    Mon Jun 29 04:59:10 2020: Final schedule entries: 92
4971    Mon Jun 29 04:59:10 2020: Slots: -5
4970    Mon Jun 29 04:59:10 2020: Delete slot 5
4969    Mon Jun 29 04:59:10 2020: Found slot 5 for 7/0/1593487800/0
4968    Mon Jun 29 04:59:10 2020: Opening /var/lib/humaxtv/rsvp.db
4967    Mon Jun 29 04:59:10 2020: Schedule saved.
4966    Mon Jun 29 04:59:09 2020: Nugget is available.
4965    Mon Jun 29 04:59:09 2020: Real-time mode.
4964    Mon Jun 29 04:59:09 2020: rsvsync starting, version 1.1.13.
4963    Sat Jan  1 00:00:06 2000: Final schedule entries: 92
4962    Sat Jan  1 00:00:06 2000: Slots:
4961    Sat Jan  1 00:00:06 2000: Ignoring: no such table: fav (no such table: fav)
4960    Sat Jan  1 00:00:06 2000: Restoring any favourites.
4959    Sat Jan  1 00:00:06 2000: Opening /var/lib/humaxtv/rsvp.db
4958    Sat Jan  1 00:00:06 2000: rsvsync starting, version 1.1.13.
4957    Sun Jun 28 18:11:16 2020: Loading schedule information to HumaxTV binary.
4956    Sun Jun 28 18:11:16 2020: Final schedule entries: 94
4955    Sun Jun 28 18:11:16 2020: Slots: +70,+75
4954    Sun Jun 28 18:11:16 2020: Moving pending entry 1 to spare slot 75
4953    Sun Jun 28 18:11:16 2020: Moving pending entry 0 to spare slot 70
4952    Sun Jun 28 18:11:16 2020: Opening /var/lib/humaxtv/rsvp.db
4951    Sun Jun 28 18:11:16 2020: Schedule saved.

Nugget.log

5000    [nugget]: Mon Jun 29 20:07:31 2020: /mnt/hd2/My Video/Broadchurch/Broadchurch_20200629_2059
4999    [nugget]: Mon Jun 29 20:07:31 2020: /mnt/hd2/My Video/Alan Bennett's Talking Heads/Alan Bennett's Talking Heads_20200629_2046
4998    [nugget]: Mon Jun 29 20:07:25 2020: /mnt/hd2/My Video/Broadchurch/Broadchurch_20200629_2059
4997    [nugget]: Mon Jun 29 20:07:25 2020: /mnt/hd2/My Video/Alan Bennett's Talking Heads/Alan Bennett's Talking Heads_20200629_2046
4996    [nugget]: Mon Jun 29 20:04:13 2020: /mnt/hd2/My Video/Broadchurch/Broadchurch_20200629_2059
4995    [nugget]: Mon Jun 29 20:04:13 2020: /mnt/hd2/My Video/Alan Bennett's Talking Heads/Alan Bennett's Talking Heads_20200629_2046
4994    [nugget]: Mon Jun 29 18:52:02 2020: Deferred thread exiting.
4993    [nugget]: Mon Jun 29 18:52:02 2020:     - Mon Jun 29 18:52:02 2020
4992    [nugget]: Mon Jun 29 18:52:02 2020: Adding timer(1593995370)
4991    [nugget]: Mon Jun 29 18:52:02 2020: Ready 1593995370 - Mon Jun 29 18:52:02 2020
4990    [nugget]: Mon Jun 29 18:52:02 2020:  Wake 1593995400 - Mon Jun 29 18:52:02 2020
4989    [nugget]: Mon Jun 29 18:52:02 2020:       Mon Jun 29 18:52:02 2020 +125m
4988    [nugget]: Mon Jun 29 18:52:02 2020:  [0] 262250,1593996300,1594003800,32354
4987    [nugget]: Mon Jun 29 18:52:02 2020:   Events: 1WWW.CHANNEL4.COM/67102/001|
4986    [nugget]: Mon Jun 29 18:52:02 2020:   Last Event: 0
4985    [nugget]: Mon Jun 29 18:52:02 2020:   Recorded:
4984    [nugget]: Mon Jun 29 18:52:02 2020:   CRID: 1/[WWW.CHANNEL4.COM/67102/001]
4983    [nugget]: Mon Jun 29 18:52:02 2020:    @ 1593996300 (Mon Jun 29 18:52:02 2020)
4982    [nugget]: Mon Jun 29 18:52:02 2020:   Marshland
4981    [nugget]: Mon Jun 29 18:52:02 2020: Processing slot +78 (78)
4980    [nugget]: Mon Jun 29 18:52:02 2020:     - Mon Jun 29 18:52:02 2020
4979    [nugget]: Mon Jun 29 18:52:02 2020: Adding timer(1593476970)
4978    [nugget]: Mon Jun 29 18:52:02 2020: Ready 1593476970 - Mon Jun 29 18:52:02 2020
4977    [nugget]: Mon Jun 29 18:52:02 2020:  Wake 1593477000 - Mon Jun 29 18:52:02 2020
4976    [nugget]: Mon Jun 29 18:52:02 2020:       Mon Jun 29 18:52:02 2020 +125m
4975    [nugget]: Mon Jun 29 18:52:02 2020:  [0] 262250,1593477900,1593485400,26947
4974    [nugget]: Mon Jun 29 18:52:02 2020:   Events: 1WWW.CHANNEL4.COM/66833/001|
4973    [nugget]: Mon Jun 29 18:52:02 2020:   Last Event: 0
4972    [nugget]: Mon Jun 29 18:52:02 2020:   Recorded:
4971    [nugget]: Mon Jun 29 18:52:02 2020:   CRID: 1/[WWW.CHANNEL4.COM/66833/001]
4970    [nugget]: Mon Jun 29 18:52:02 2020:    @ 1593477900 (Mon Jun 29 18:52:02 2020)
4969    [nugget]: Mon Jun 29 18:52:02 2020:   Men & Chicken
4968    [nugget]: Mon Jun 29 18:52:02 2020: Processing slot +71 (71)
4967    [nugget]: Mon Jun 29 18:52:02 2020: slots(95, +71,+78)
4966    [nugget]: Mon Jun 29 18:52:02 2020: schedule reload complete (95).
4965    [nugget]: Mon Jun 29 18:52:02 2020: Re-loading schedule database (95).
4964    [nugget]: Mon Jun 29 18:51:59 2020: Deferred thread starting for '95:+71,+78' (attempt 1)
4963    [nugget]: Mon Jun 29 18:51:59 2020: Schedule failed to reload, deferring.
4962    [nugget]: Mon Jun 29 18:51:59 2020: NULL database handle.
4961    [nugget]: Mon Jun 29 18:51:59 2020: Schedule load failed.
4960    [nugget]: Mon Jun 29 18:51:59 2020: Closing database.
4959    [nugget]: Mon Jun 29 18:51:59 2020: Re-loading schedule database (95).
4958    [nugget]: Mon Jun 29 18:51:59 2020: schedule save complete.
4957    [nugget]: Mon Jun 29 18:51:58 2020: schedule save starting.
4956    [nugget]: Mon Jun 29 09:11:06 2020: schedule save complete.
4955    [nugget]: Mon Jun 29 09:11:05 2020: schedule save starting.
4954    [nugget]: Mon Jun 29 08:10:48 2020: Deferred thread exiting.
4953    [nugget]: Mon Jun 29 08:10:48 2020:     - Mon Jun 29 08:10:48 2020
4952    [nugget]: Mon Jun 29 08:10:48 2020: Adding timer(1594064670)
4951    [nugget]: Mon Jun 29 08:10:48 2020: Ready 1594064670 - Mon Jun 29 08:10:48 2020

 

[MymsMan]

rsvsync doesn't run continually or at regular intervals. it only runs when there is work to do.
It seems to have stopped in the morning when it encountered a locked database

4990    Mon Jun 29 10:11:06 2020: Failed: database is locked (database is locked)

It is not clear what triggered it into action again at 19:51

It would be nice if it retried the database locked error or scheduled a later rerun

 

[Black Hole]

I was going by the last seen time on RS. Is the 10 minutes user definable?

Yes, but 10 mins is the default. That's the schedule on which the rs package on the HDR-FOX checks the RS site for new instructions, and where the "last seen" comes from, and if missing for a while emails you about it.

 

[4ndy]

Not sure if this is related to the problems I was having with the same box earlier in the week, but I now have items stuck in RS. RS shows two items auto scheduled this morning, the scheduled reboot I entered (after I discovered that tunefix-update had been updated) and two auto scheduled items I wanted to delete about an hour ago. None have been implemented on the box.



Th RS log looks like it is throwing up an error repeatedly. Any ideas?

00    *Trying source service/event ID.
4999    *Schedule 28224/49687/2/81/TalkingPictures TV/1594325400/Harlow
4998    Processing command 'schedule auto'
4997    at file "/mod/lib/jim/oo.tcl", line 87
4996    at file "/mod/lib/jim/oo.tcl", line 73
4995    in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4994    in procedure '<reference.<svc____>.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4993    in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4992    /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable
4991    *Trying source service/event ID.
4990    *Schedule 28224/49687/2/81/TalkingPictures TV/1594325400/Harlow
4989    Processing command 'schedule auto'
4988    at file "/mod/lib/jim/oo.tcl", line 87
4987    at file "/mod/lib/jim/oo.tcl", line 73
4986    in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4985    in procedure '<reference.<svc____>.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4984    in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4983    /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable
4982    *Trying source service/event ID.
4981    *Schedule 28224/49687/2/81/TalkingPictures TV/1594325400/Harlow
4980    Processing command 'schedule auto'
4979    at file "/mod/lib/jim/oo.tcl", line 87
4978    at file "/mod/lib/jim/oo.tcl", line 73
4977    in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4976    in procedure '<reference.<svc____>.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4975    in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4974    /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable
4973    *Trying source service/event ID.
4972    *Schedule 28224/49687/2/81/TalkingPictures TV/1594325400/Harlow
4971    Processing command 'schedule auto'
4970    at file "/mod/lib/jim/oo.tcl", line 87
4969    at file "/mod/lib/jim/oo.tcl", line 73
4968    in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4967    in procedure '<reference.<svc____>.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4966    in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4965    /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable

 

[prpr]

Try editing /mod/sbin/rs_process at lines 180, 191 and 202 to change this:

set newservice [get_channel_attr_byorglcn $lcn usSvcid]​

to this:

set newservice [get_channel_attr_byorglcn $lcn usSvcId]​

It is case-sensitive - usSvcid vs usSvcId

 

[4ndy]

Looking further down the schedule I can see that the show “Harlow” (which seems to be where it falls over) is scheduled for an earlier showing on the 5th, so I would normally delete the second showing. I will try that first, to see if it clears the blockage.


Sent from my iPad using Tapatalk

 

[4ndy]

I really don’t know what is going on here.

Having checked the queue in RS, the schedule in webif and the RS log, I made my last post. When I went back to RS to delete the queued showing of “Harlow”, all of yesterday’s queue had gone, but this morning’s additions to the auto-queue (from which I had removed a couple of items) is still waiting.

The RS log shows this

 5000 *Trying source service/event ID.
4999 *Schedule 28224/49700/2/81/TalkingPictures TV/1594414800/The Rocky Horror Picture Show
4998 Processing command 'schedule auto'
4997 at file "/mod/lib/jim/oo.tcl", line 87
4996 at file "/mod/lib/jim/oo.tcl", line 73
4995 in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4994 in procedure '.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4993 in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4992 /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable
4991 *Trying source service/event ID.
4990 *Schedule 28224/49766/2/81/TalkingPictures TV/1594387800/Running for Pleasure
4989 Processing command 'schedule auto'
4988 at file "/mod/lib/jim/oo.tcl", line 87
4987 at file "/mod/lib/jim/oo.tcl", line 73
4986 in procedure 'svc get' called at file "/mod/lib/jim/oo.tcl", line 52
4985 in procedure '.00000000000000000000>' called at file "/mod/webif/lib/findhsvc", line 14
4984 in procedure 'get_channel_attr_bylcn' called at file "/mod/sbin/rs_process", line 191
4983 /mod/lib/jim/oo.tcl:87: Error: can't read "usSvcid": no such variable
4982 *Trying source service/event ID.
4981 *Schedule 28224/49766/2/81/TalkingPictures TV/1594387800/Running for Pleasure

“Running for Pleasure” was one of the items I deleted from RS, but the remaining two are still queuing. I have just left them in for testing.

@prpr I am not sure I feel confident changing lines of code, especially as the before and after look the same to me.


Sent from my iPad using Tapatalk

 

[MymsMan]

Try editing /mod/sbin/rs_process at lines 180, 191 and 202 to change this:

set newservice [get_channel_attr_byorglcn $lcn usSvcid]​

to this:

set newservice [get_channel_attr_byorglcn $lcn usSvcId]​

It might be case-sensitive - usSvcid vs usSvcId

Receently @af123 introduced a new svc class to replace the use of the findhsvc
'get_channel_attr_byxxxx' methods but left an updated findhsvc for compatibility with othe packages,
It apears that it isn't fully compatible