Not Changing Channels

[xjim1]

Can someone tell me why Sage doesn't change channel to a Favorite recording?

I'm watching NFL Football. Not a manual or Favorite, just tuned into live tv. I have a Favorite scheduled of Star Trek Voyager at 2100. At 2055, Sage asks me if I want to change the channel. I say Yes.
At 2102 I see it is still recording NFL. I have to mark ST Voyager as manual to force it to record.

This is happening consistently now. Is there a parameter I may have inadvertently changed?

If I'm not otherwise watching live tv, recording happens as expected.

Log file attached.
Thanks for any help.

[GoAWest]

Sounds similar to the discussions in these threads:

https://forums.sagetv.com/forums/showthread.php?t=65030
https://forums.sagetv.com/forums/showthread.php?t=64290

[xjim1]

Originally Posted by GoAWest

Sounds similar to the discussions in these threads:

https://forums.sagetv.com/forums/showthread.php?t=65030
https://forums.sagetv.com/forums/showthread.php?t=64290

Yeah I looked at them. Those were both with multiple tuners, but could be related. I have a single tuner server, clicked "Yes" when prompted to change the channel, but it ignored it. With a simpler configuration, I'm hoping the log file would provide some insight. I recently upgraded to 9.1.7.

Thanks.

[wnjj]

So I finally had time to look through your logs from 11/5.

I think there's a hint when watching the schedule at this point:

Sun 11/5 20:00:01.389 [Scheduler@182021d] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Sun 11/5 20:00:01.389 [Scheduler@182021d] Hauppauge WinTV 418 TS Capture
Sun 11/5 20:00:01.391 [Scheduler@182021d] [A[2601046,2600889,"Star Trek: Deep Space Nine",87173@1105.20:00,60,T], A[2601047,2600892,"Star Trek: Voyager",87173@1105.21:00,60,T], A[2601019,370390,"News 5 at 10pm",51690@1105.22:00,30,T], 
.
.
.

You were expecting the channel to change at 21:00 for "Star Trek: Voyager" but according to the schedule there was already a missing "Star Trek: Deep Space Nine". Because there was a scheduled show for the 20:00-21:00 time slot, I believe it puts the live TV into "force watch" mode when you changed channels at 20:23 (during that time window) which means it has highest priority.

What doesn't make sense is the logic of asking you when you are watching in this "force" mode. The code I perused looks like saying "OK change it", merely leaves the upcoming recording in the schedule instead of removing it, but doesn't correct the priority issue.

I'm not sure I understand this well enough to explain, but in short I suspect that watching live TV during an existing favorite leads to this bad behavior.

Edit: There was also a missed recording at 19:00 that caused a conflict to log:

Sun 11/5 20:00:01.392 [Scheduler@182021d] Airing was dropped from conflict map; check for a missed recording: [A[2601045,268476,"Star Trek: The Next Generation",87173@1105.19:00,60,T]]
Sun 11/5 20:00:01.392 [Scheduler@182021d] Found missed recording for A[2601045,268476,"Star Trek: The Next Generation",87173@1105.19:00,60,T] post system message about it

Edit2: I'm now not even sure that "Deep Space Nine" is a favorite but may instead be in the schedule as an intelligent recording so my theory above may be off.

[xjim1]

Originally Posted by wnjj

So I finally had time to look through your logs from 11/5.

I think there's a hint when watching the schedule at this point:

Sun 11/5 20:00:01.389 [Scheduler@182021d] COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE
Sun 11/5 20:00:01.389 [Scheduler@182021d] Hauppauge WinTV 418 TS Capture
Sun 11/5 20:00:01.391 [Scheduler@182021d] [A[2601046,2600889,"Star Trek: Deep Space Nine",87173@1105.20:00,60,T], A[2601047,2600892,"Star Trek: Voyager",87173@1105.21:00,60,T], A[2601019,370390,"News 5 at 10pm",51690@1105.22:00,30,T], 
.
.
.

You were expecting the channel to change at 21:00 for "Star Trek: Voyager" but according to the schedule there was already a missing "Star Trek: Deep Space Nine". Because there was a scheduled show for the 20:00-21:00 time slot, I believe it puts the live TV into "force watch" mode when you changed channels at 20:23 (during that time window) which means it has highest priority.

Yeah I don't understand that. It's been a few weeks now, but I remember watching NFL Sunday Night Football (Oakland at Miami) as it approached 21:00. This was live tv (is that what AsyncWatch means?) on channel 5.1.

Looking through the log file it looks like up to 20:23, I was watching an NFL game (Kansas City vs Dallas) recording from earlier in the day. That's when I tuned into the Oakland game at 20:23:53:956. Deep Space Nine is not a favorite, and not scheduled. I see multiple entries between 20:00 and 21:00 that Next Record is Voyager, at 21:00

The list at 20:00 you mention contains a bunch of shows that I don't record. Don't know what that means.

Originally Posted by wnjj

What doesn't make sense is the logic of asking you when you are watching in this "force" mode. The code I perused looks like saying "OK change it", merely leaves the upcoming recording in the schedule instead of removing it, but doesn't correct the priority issue.

I'm not sure I understand this well enough to explain, but in short I suspect that watching live TV during an existing favorite leads to this bad behavior.

Edit: There was also a missed recording at 19:00 that caused a conflict to log.

At 20:55:00 there is a Channel Change Query then the Force Watch executing, then Keeping Record Just the way It Is entry.

Does that mean it's going to record Voyager or continue recording NFL football (which was live tv and not a favorite)?

I think what may be the best is to set up a test, with a fresh log file, and note the status of all scheduled recordings. I can reproduce it so I just need a free window.

Regarding the 19:00 conflict: that was a previously resolved conflict as Star Trek NG favorite was overridden by The Durrells in Corfu. That worked as expected and generated a system message.

Thanks for the help and let me know if the test setup is something you'd have time to look at.

[wnjj]

I had added another edit to clarify that I believe "Deep Space Nine" was an intelligent recording selection that gets tossed when there isn't a tuner. Are you running with IR on?

Asyncwatch is just the thread name for the medaplayer.

The channel change query is listed at 20:55 but a few lines later you'll see a 3 second delay to allow the popup to show up on the client so technically the answer to the question isn't available until the next pass, which happens at 20:59.59.

The thing is, forcewatch is still active which means the current live TV will take priority over the scheduled recording. I don't know what causes that forcewatch or how it goes away.

I'm happy look at log files but am still learning by looking through code so may not reach the right conclusions. Hopefully Narflex chimes in at some point though I get the feeling this code is a bit squirrely.

[xjim1]

Originally Posted by wnjj

I had added another edit to clarify that I believe "Deep Space Nine" was an intelligent recording selection that gets tossed when there isn't a tuner. Are you running with IR on?

Asyncwatch is just the thread name for the medaplayer.

The channel change query is listed at 20:55 but a few lines later you'll see a 3 second delay to allow the popup to show up on the client so technically the answer to the question isn't available until the next pass, which happens at 20:59.59.

The thing is, forcewatch is still active which means the current live TV will take priority over the scheduled recording. I don't know what causes that forcewatch or how it goes away.

I'm happy look at log files but am still learning by looking through code so may not reach the right conclusions. Hopefully Narflex chimes in at some point though I get the feeling this code is a bit squirrely.

No IR. Just checked to make sure.
Yeah I see the 20:59:59 too. Even though Voyager is set to record, the Force Watch overrides it.

I'm going to test with a new wiz.bin and see if that changes anything. A long shot, but simpler than downgrading. But I'll post another log file if that doesn't work.

Thanks for taking a look.

[wnjj]

So I spent some more time pouring through the seeker code. I'm fairly convinced now that the change channel will never actually do anything when you say "yes" to the prompt. Saying "no" will cancel the recording it wanted the tuner for, however.


I ran a test on my system: With all 3 tuners available, I watched liveTV. Checking the log files confirmed what I had found in the code, that liveTV is considered a "force watch". Once that's set, even scheduled recordings are ignored for that tuner. Saying "no" only removes the upcoming show from the schedule. Saying "yes" leaves it in the "must see" list and continues showing it as the "nextRecord" in the log file.

Part of the code section that passes the "nextRecord" (scheduled) to the "newRecord" (the one that actually records) is here:

          if ((nextTTA == 0) || (defaultRecord == null))
          {
            // The new record is ready to go OR it's lead time
            // is up and there's no default. Wake up when it's over
            wakeupTime = Math.min(wakeupTime, nextRecord.getSchedulingEnd());
            newRecord = nextRecord;
          }

The issue is, below that is this code:

        if (es.forceWatch != null)
        {
.
.
.
            if (!(es.forceWatch instanceof ManualRecord.FakeAiring) || wiz.isManualRecordOK(((ManualRecord.FakeAiring) es.forceWatch).getManualRecord()))
            {
              if (Sage.DBG) System.out.println("FORCE WATCH executing clients=" +
                  es.controllingClients);
              newRecord = es.forceWatch;
            }

This is what your log file shows is happening since the "executing clients" shows up. Notice how it clobbers "newRecord".

It seems to me like a "yes" response should null out the es.forcewatch variable or at least queue it up for null when the new recording is about to start. From what I found, only "endRecord()" will null it out, which happens when you press "stop" on liveTV.

Maybe change the above code to

          if ((nextTTA == 0) || (defaultRecord == null))
          {
            // The new record is ready to go OR it's lead time
            // is up and there's no default. Wake up when it's over
            wakeupTime = Math.min(wakeupTime, nextRecord.getSchedulingEnd());
            newRecord = nextRecord;
            if (completeChanChangeAsks.contains(nextRecord) && !deniedMustSees.contains(nextRecord))
            {
              es.forceWatch = null;
              es.forceProcessed = false;
            }
          }

[xjim1]

Wow. That's significant. And must have been a recent code change as I know this behavior wasn't always like this. I'd bet 9.1.5 didn't do that.

It may also hold implications with recordings which begin after a scheduled recording ends, for example:

Today watching a manual recording of football, and had marked a manual recording of the OT show after the game. It also chose to record the program following the OT show (Golf, lets say), even though I neither asked it to record nor was I watching live TV (it doesn't always do that). If the golf show continued and overlapped the next scheduled recording, I wonder if golf would have counted as a forcewatch.

How can I get that changed?
Thanks!

[wnjj]

Originally Posted by xjim1

Wow. That's significant. And must have been a recent code change as I know this behavior wasn't always like this. I'd bet 9.1.5 didn't do that.

It may also hold implications with recordings which begin after a scheduled recording ends, for example:

Today watching a manual recording of football, and had marked a manual recording of the OT show after the game. It also chose to record the program following the OT show (Golf, lets say), even though I neither asked it to record nor was I watching live TV (it doesn't always do that). If the golf show continued and overlapped the next scheduled recording, I wonder if golf would have counted as a forcewatch.

How can I get that changed?
Thanks!

I checked the original open source release and it looked the same. Are you sure older versions of V9 worked? If so, I can't see how, unless code outside of seeker was changed and interacts in a way I don't see.

[wayner]

Originally Posted by wnjj

So I spent some more time pouring through the seeker code. I'm fairly convinced now that the change channel will never actually do anything when you say "yes" to the prompt. Saying "no" will cancel the recording it wanted the tuner for, however.

Have you discussed this with Narflex? He should know this, inside and out.

[EnterNoEscape]

Originally Posted by wnjj

I checked the original open source release and it looked the same. Are you sure older versions of V9 worked? If so, I can't see how, unless code outside of seeker was changed and interacts in a way I don't see.

Originally Posted by wayner

Have you discussed this with Narflex? He should know this, inside and out.

You will also get more traction for proposed changes to the code base if you open an issue on GitHub.

[xjim1]

Originally Posted by wnjj

I checked the original open source release and it looked the same. Are you sure older versions of V9 worked? If so, I can't see how, unless code outside of seeker was changed and interacts in a way I don't see.

Yes, this definitely used to work. If I had a recording imminent, I remember the end of the timeline(?) bar would turn red if I was time shifted. That told me it was no longer recording my live tv session and started the scheduled recording. It's a single tuner server, so I'm attentive to such things.

I'm happy to open a report on Github, but probably would need some help with that.

I can go back to 9.1.5 to test, but need the time and enough of a window not to affect recordings. Just haven't had the chance yet.