Context Navigation

← Previous Ticket
Next Ticket →

Opened 19 years ago

Closed 19 years ago

#430 closed defect (fixed)

Tuner busy on consecutive recordings

Reported by:	anonymous	Owned by:	danielk
Priority:	critical	Milestone:	unknown
Component:	mythtv	Version:	head
Severity:	high	Keywords:
Cc:		Ticket locked:	no

Description

When two shows are consecutive in the schedules the latter is not being recorded and the scheduler reports that the tuner is busy. This has started happening in the last 2-3 days with SVN.

Change History (13)

comment:1 Changed 19 years ago by mythtv@…

Confirmed here. I've missed 2 shows since upgrading to revision 7398 on Oct 6.

I have a small amount of pre-roll and post-roll. Any confirmations from others that this might be the cause?

comment:2 Changed 19 years ago by anonymous

I have seen the problem. I have about 90-120 seconds of pre and over record but I assume most people do so this might not be the cause. It could be a DVB problem but 7391 did make scheduler changes within the right time-frame.

Between the backend memory leaks and this issue Myth is fatally wounded for me at the moment, I'm probably going to roll-back before I miss too many recordings and get it in the neck from the family!

comment:3 Changed 19 years ago by mythtv@…

I wouldn't assume pre and post roll is the norm. I've used Myth for years and just turned it on last week.

It is not specific to DVB either. I lost a DVB recording last night going from Joey to Will & Grace, but I lost a regular analog recording this morning when I went from recording a single analog show to recording 2 analog shows (using a dual tuner PVR-500). One of the second group recorded and one did not.

comment:4 Changed 19 years ago by danielk

Owner:	changed from Isaac Richards to danielk
Status:	new → assigned

KeithAndJill?, can you find out the exact revision that causes the problem?

Go back a few weeks to revision that does not have the problem, then try a revision half way between then and a revision that does have the problem.

Repeat bisecting the between a revision with and without the problem, until you find the one revision causing the problem. Make sure to do a distclean between each test, and use something like ccache so you don't spend all day compiling.

comment:5 Changed 19 years ago by stuart@…

Daniel, just a minute ago I saw the problem and happened to glimpse the error on the backend console. It looks like a scheduler problem to me and therefore is most likely a problem with gigem's commit on Wednesday (7391).

It said something to the effect that it was trying to record X but the current state was RecordingOnly?. This to me rules out card access problems. After the current, reactivated, recording finishes I'll revert to 7390.

comment:6 Changed 19 years ago by anonymous

Here is one of these events from last night from the logs for mb -v record. I had never seen this until Thursday 10/6. On Wed 10/5 I had several back to back recordings with no failures.

Here "Mail Call: Hurricane Katrina" should have ended and 21:00 on card 2 and "The Amazing Race" should have started. However, at 21:00:00.977 it reported that it was starting overrecord time anyway and failed to start "The Amazing Race" reporting rsTunerBusy.

There were no log entries for 15 minutes before this point nor any frontend events.

2005-10-06 20:59:30.775 TVRec(2): SetFlags(AskAllowRecording,) -> FrontendReady,RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-06 20:59:30.848 TVRec(2): ClearFlags(AskAllowRecording,) -> FrontendReady,RunMainLoop,RecorderRunning,
2005-10-06 21:00:00.977 TVRec(2): Switching to overrecord for 24 more seconds
2005-10-06 21:00:01.003 TVRec(2): ClearFlags(FinishRecording,) -> FrontendReady,RunMainLoop,RecorderRunning,
2005-10-06 21:00:04.065 Started recording The Apprentice "Something Old, Something New": channel 1003 on cardid 1, sourceid 1
2005-10-06 21:00:04.201 scheduler: Last message repeated 1 times
2005-10-06 21:00:04.208 scheduler: Started recording
2005-10-06 21:00:04.336 TVRec(2): ClearFlags(AskAllowRecording,) -> FrontendReady,RunMainLoop,RecorderRunning,
2005-10-06 21:00:04.340 TVRec(2): Wanted to record: The Amazing Race 2344 Thu Oct 6 21:00:00 2005 Thu Oct 6 22:00:00 2005
                        But the current state is: RecordingOnly                 Currently recording: Mail Call: Hurricane Katrina 1043 Thu Oct 6 20:00:0
0 2005 Thu Oct 6 21:00:00 2005
2005-10-06 21:00:04.341 TVRec(2): ClearFlags(CancelNextRecording,) -> FrontendReady,RunMainLoop,RecorderRunning,
2005-10-06 21:00:04.342 TVRec(2): Changing from RecordingOnly to None
2005-10-06 21:00:04.343 TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,
2005-10-06 21:00:04.344 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-06 21:00:04.347 TVRec(2): Request: Program(no) channel() input() flags(CloseRec,KillRingBuffer,)
2005-10-06 21:00:04.348 TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-06 21:00:04.352 Finished recording Mail Call: Hurricane Katrina: channel 1043
2005-10-06 21:00:04.371 scheduler: Finished recording
2005-10-06 21:00:04.630 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,
2005-10-06 21:00:04.633 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,
2005-10-06 21:00:04.634 TVRec(2): Tearing down RingBuffer
2005-10-06 21:00:04.649 TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,
2005-10-06 21:00:04.667 Canceled recording The Amazing Race "Mow Em Down Like Grass": channel 2344 on cardid 2, sourceid 2
2005-10-06 21:00:04.672 scheduler: Canceled recording

I tried to reproduce the problem with some manual recordings but the later recording started, however, it still started overrecord then finished three seconds later and stared the other recording late.

2005-10-06 22:34:30.741 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-06 22:35:00.859 TVRec(2): Switching to overrecord for 24 more seconds
2005-10-06 22:35:00.865 TVRec(2): ClearFlags(FinishRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-06 22:35:02.872 TVRec(2): ClearFlags(AskAllowRecording,) -> RunMainLoop,RecorderRunning,RingBufferReset,
2005-10-06 22:35:02.873 TVRec(2): Changing from RecordingOnly to None
2005-10-06 22:35:02.874 TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReset,
2005-10-06 22:35:02.875 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-06 22:35:02.876 TVRec(2): Request: Program(no) channel() input() flags(CloseRec,KillRingBuffer,)
2005-10-06 22:35:02.877 TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-06 22:35:02.879 Finished recording Third (Manual Record) "Thu Oct 6 22:30:00 2005": channel 1003
2005-10-06 22:35:03.044 scheduler: Finished recording
2005-10-06 22:35:03.224 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.252 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.254 TVRec(2): Tearing down RingBuffer
2005-10-06 22:35:03.266 TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.267 TVRec(2): ClearFlags(CancelNextRecording,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.268 TVRec(2): Changing from None to RecordingOnly
2005-10-06 22:35:03.269 TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.270 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.271 TVRec(2): Request: Program(yes) channel() input() flags(Recording,)
2005-10-06 22:35:03.272 TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.273 TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-06 22:35:03.307 TVRec(2): SetFlags(NeedToStartRecorder,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,RingBufferReset,
2005-10-06 22:35:03.308 TVRec(2): Starting Recorder
2005-10-06 22:35:03.351 TVRec(2): Using profile 'Low Quality' to record
2005-10-06 22:35:03.365 SetRecording(0x0x834f798)
2005-10-06 22:35:03.366 Prog title: Fourth (Manual Record)
2005-10-06 22:35:03.389 TVRec(2): SetFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,RecorderRunning,RingBufferReset,
2005-10-06 22:35:03.406 Started recording Fourth (Manual Record) "Thu Oct 6 22:35:00 2005": channel 1003 on cardid 2, sourceid 1
2005-10-06 22:35:03.412 scheduler: Started recording

comment:7 Changed 19 years ago by danielk

(In [7410]) References #430.

Possible fix, this waits for the internal state to change to kState_None after canceling an overrecord. This isn't entirely safe because someone may start LiveTV at just the wrong time, making this block for the length of the LiveTV recording.

But this was an existing problem in the code since overrecord was first implemented, and no one complained about this actually happening in practice.

comment:8 Changed 19 years ago by anonymous

I think this fix worked. Two sets of two shows in a row now transitioned correctly with overrecord on.

comment:9 Changed 19 years ago by jr@…

Using r7410 it still misses every consecutive recording I throw at it. I recently enabled 90 global seconds of under and over recording just to see if it made a difference, but it didn't. It seems to not do consecutive recordings whether there is any global under and over recording time or not.

2005-10-08 01:59:53.488 read  <- 14 35      QUERY_REMOTEENCODER 1[]:[]GET_STATE
2005-10-08 01:59:53.488 write -> 14 1       4
2005-10-08 01:59:53.500 read  <- 14 539     QUERY_REMOTEENCODER 1[]:[]START_RECORDING
[]:[]No Opportunity Wast...
2005-10-08 01:59:53.500 TVRec(1): ClearFlags(AskAllowRecording,) -> RunMainLoop,Recor
derRunning,
2005-10-08 01:59:53.501 TVRec(1): Wanted to record: No Opportunity Wasted 2721 Sat Oc
t 8 02:00:00 2005 Sat Oct 8 03:00:00 2005
                        But the current state is: RecordingOnly                 Curre
ntly recording: Attack of the Show! 2353 Sat Oct 8 00:59:00 2005 Sat Oct 8 02:00:00 2
005
2005-10-08 01:59:53.501 TVRec(1): ClearFlags(CancelNextRecording,) -> RunMainLoop,Rec
orderRunning,
2005-10-08 01:59:53.501 write -> 14 2       -8
2005-10-08 01:59:53.538 read  <- 14 35      QUERY_REMOTEENCODER 2[]:[]GET_STATE
2005-10-08 01:59:53.538 write -> 14 1       4
2005-10-08 01:59:53.550 read  <- 14 414     QUERY_REMOTEENCODER 2[]:[]START_RECORDING
[]:[]KOCE High Definitio...
2005-10-08 01:59:53.550 TVRec(2): ClearFlags(AskAllowRecording,) -> RunMainLoop,SIPar
serRunning,RecorderRunning,RingBufferReset,
2005-10-08 01:59:53.551 TVRec(2): Wanted to record: KOCE High Definition TV 1112 Sat
Oct 8 02:00:00 2005 Sat Oct 8 06:00:00 2005
                        But the current state is: RecordingOnly                 Curre
ntly recording: Fox 11 Ten O'Clock News 1111 Sat Oct 8 00:59:00 2005 Sat Oct 8 02:00:
00 2005
2005-10-08 01:59:53.551 TVRec(2): ClearFlags(CancelNextRecording,) -> RunMainLoop,SIP
arserRunning,RecorderRunning,RingBufferReset,
2005-10-08 01:59:53.551 write -> 14 2       -8
2005-10-08 01:59:55.657 ParseATSCEIT: Adding data. ATSC Channel is 11_1.
2005-10-08 01:59:55.845 SIParser: EIT-0 Present on PID 0x1aa0
2005-10-08 01:59:55.845 SIParser: EIT-1 Present on PID 0x1aa1
2005-10-08 01:59:55.845 SIParser: EIT-2 Present on PID 0x1aa2
2005-10-08 01:59:55.845 SIParser: EIT-3 Present on PID 0x1aa3
2005-10-08 01:59:55.845 SIParser: CVCT Present on this Transport
2005-10-08 01:59:55.845 SIParser: Unknown Table  301 in MGT on PID 0x1ffb
2005-10-08 01:59:55.895 ParseATSCEIT: Adding data. ATSC Channel is 11_1.
2005-10-08 01:59:55.895 ParseATSCEIT: Adding data. ATSC Channel is 7_1.
2005-10-08 01:59:55.895 ParseATSCEIT: Adding data. ATSC Channel is 7_1.
2005-10-08 01:59:56.138 SIParser: EIT-0 Present on PID 0x1aa0
2005-10-08 01:59:56.138 SIParser: EIT-1 Present on PID 0x1aa1
2005-10-08 01:59:56.138 SIParser: EIT-2 Present on PID 0x1aa2
2005-10-08 01:59:56.138 SIParser: EIT-3 Present on PID 0x1aa3
2005-10-08 01:59:56.138 SIParser: CVCT Present on this Transport
2005-10-08 01:59:56.138 SIParser: Unknown Table  301 in MGT on PID 0x1ffb
2005-10-08 01:59:56.263 ParseATSCEIT: Adding data. ATSC Channel is 11_1.
2005-10-08 01:59:56.264 ParseATSCEIT: Adding data. ATSC Channel is 7_1.
2005-10-08 01:59:56.584 SIParser: EIT-0 Present on PID 0x1aa0
2005-10-08 01:59:56.585 SIParser: EIT-1 Present on PID 0x1aa1
2005-10-08 01:59:56.585 SIParser: EIT-2 Present on PID 0x1aa2
2005-10-08 01:59:56.585 SIParser: EIT-3 Present on PID 0x1aa3
2005-10-08 01:59:56.585 SIParser: CVCT Present on this Transport
2005-10-08 01:59:56.585 SIParser: Unknown Table  301 in MGT on PID 0x1ffb
2005-10-08 01:59:56.594 ParseATSCEIT: Adding data. ATSC Channel is 11_1.
2005-10-08 01:59:56.594 ParseATSCEIT: Adding data. ATSC Channel is 7_1.
2005-10-08 01:59:56.857 ParseATSCEIT: Adding data. ATSC Channel is 7_2.
2005-10-08 01:59:58.539 ParseATSCEIT: Adding data. ATSC Channel is 7_2.
2005-10-08 02:00:00.525 TVRec(1): Switching to overrecord for 90 more seconds
2005-10-08 02:00:00.525 TVRec(1): ClearFlags(FinishRecording,) -> RunMainLoop,Recorde
rRunning,
2005-10-08 02:00:00.574 TVRec(2): Switching to overrecord for 90 more seconds
2005-10-08 02:00:00.574 TVRec(2): ClearFlags(FinishRecording,) -> RunMainLoop,SIParse
rRunning,RecorderRunning,RingBufferReset,
2005-10-08 02:00:33.183 JobQueue currently set at 1 job(s) max and to run new jobs fr
om 00:00 to 23:59
2005-10-08 02:00:33.185 JobQueue::GetJobsInQueue: findJobs search bitmask 4, found 5
total jobs
2005-10-08 02:00:33.185 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1
117 @ 20051007200100 in Finished state.
2005-10-08 02:00:33.185 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1
117 @ 20051007221000 in Finished state.
2005-10-08 02:00:33.186 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1
116 @ 20051008003600 in Finished state.
2005-10-08 02:00:33.186 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 2
353 @ 20051008005900 in Finished state.
2005-10-08 02:00:33.186 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1
111 @ 20051008005900 in Finished state.
2005-10-08 02:01:30.783 TVRec(1): ClearFlags(FinishRecording,) -> RunMainLoop,Recorde
rRunning,
2005-10-08 02:01:30.783 TVRec(1): Changing from RecordingOnly to None
2005-10-08 02:01:30.783 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> R
unMainLoop,RecorderRunning,
2005-10-08 02:01:30.783 TVRec(1): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllo
wRecording,RecorderRunning,
2005-10-08 02:01:30.783 TVRec(1): Request: Program(no) channel() input() flags(CloseR
ec,KillRingBuffer,)
2005-10-08 02:01:30.783 TVRec(1): ClearFlags(WaitingForSIParser,SIParserRunning,) ->
RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-08 02:01:30.783 TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAll
owRecording,RecorderRunning,
2005-10-08 02:01:30.784 write -> 14 103     BACKEND_MESSAGE[]:[]UPDATE_RECORDING_STAT
US 1 2353 2005-10-08T01:...
2005-10-08 02:01:30.795 read  <- 14 16      QUERY_FREE_SPACE
2005-10-08 02:01:30.795 write -> 14 35      0[]:[]742268928[]:[]0[]:[]171384832
2005-10-08 02:01:30.800 read  <- 14 16      QUERY_FREE_SPACE
2005-10-08 02:01:30.800 write -> 14 35      0[]:[]742268928[]:[]0[]:[]171384832
2005-10-08 02:01:30.823 Finished recording Attack of the Show!: channel 2353
2005-10-08 02:01:30.824 write -> 14 51      BACKEND_MESSAGE[]:[]DONE_RECORDING 1 3783
[]:[]empty
2005-10-08 02:01:30.834 TVRec(2): ClearFlags(FinishRecording,) -> RunMainLoop,SIParse
rRunning,RecorderRunning,RingBufferReset,
2005-10-08 02:01:30.834 TVRec(2): Changing from RecordingOnly to None
2005-10-08 02:01:30.834 TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> R
unMainLoop,SIParserRunning,RecorderRunning,RingBufferReset,
2005-10-08 02:01:30.834 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllo
wRecording,SIParserRunning,RecorderRunning,RingBufferReset,
2005-10-08 02:01:30.834 TVRec(2): Request: Program(no) channel() input() flags(CloseR
ec,KillRingBuffer,)
2005-10-08 02:01:30.834 SIParser: Stopping DVB Section Reader
2005-10-08 02:01:30.941 SIParser: DVB Section Reader thread stopped
[Thread 425997 (LWP 1949) exited]
2005-10-08 02:01:30.969 DVB#0 Rec: Closing DVB recorder
2005-10-08 02:01:31.125 TVRec(2): SetFlags(RingBufferReset,) -> RunMainLoop,AskAllowR
ecording,SIParserRunning,RecorderRunning,RingBufferReset,
2005-10-08 02:01:31.125 TVRec(2): ClearFlags(WaitingForSIParser,SIParserRunning,) ->
RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-08 02:01:31.125 TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAll
owRecording,RecorderRunning,RingBufferReset,
2005-10-08 02:01:31.125 write -> 14 103     BACKEND_MESSAGE[]:[]UPDATE_RECORDING_STAT
US 2 1111 2005-10-08T01:...
2005-10-08 02:01:32.184 Finished recording Fox 11 Ten O'Clock News: channel 1111
2005-10-08 02:01:32.184 write -> 14 51      BACKEND_MESSAGE[]:[]DONE_RECORDING 2 7545
[]:[]empty
[Thread 475155 (LWP 1953) exited]
2005-10-08 02:01:32.221 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllo
wRecording,RingBufferReset,
[Thread 376848 (LWP 1945) exited]
2005-10-08 02:01:32.243 TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllo
wRecording,RingBufferReset,
2005-10-08 02:01:32.243 TVRec(2): Tearing down RingBuffer
[Thread 458770 (LWP 1952) exited]
2005-10-08 02:01:32.269 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllo
wRecording,
2005-10-08 02:01:32.269 Firewire: releasing iec61883_mpeg2 object
2005-10-08 02:01:32.270 Firewire: disconnecting channel 0
2005-10-08 02:01:32.270 write -> 14 51      BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE
[]:[]empty
[Thread 442385 (LWP 1951) exited]
2005-10-08 02:01:32.285 TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllow
Recording,RingBufferReset,
2005-10-08 02:01:32.287 Firewire: releasing raw1394 handle
2005-10-08 02:01:32.288 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllo
wRecording,
2005-10-08 02:01:32.288 TVRec(1): Tearing down RingBuffer
2005-10-08 02:01:32.288 write -> 14 51      BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE
[]:[]empty
[Thread 360463 (LWP 1943) exited]
[Thread 344078 (LWP 1942) exited]
2005-10-08 02:01:32.329 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllow
Recording,

comment:10 Changed 19 years ago by danielk

Resolution:	→ fixed
Status:	assigned → closed

(In [7427]) Fixes #430.

This fixes two additional problems that cause lost follow on recordings:

Overrecord race problem, an old problem that was made worse by event loop improvements.
Clock drift problem, another old problem.

Fixing the clock drift problem required a MythTV protocol change so you must upgrade all your backends & frontends. Basically, it adds a GET_CURRENT_RECORDING query so that we can find out if the slave backend is recording something the master backend thinks should be done by now.

It is still important to keep the backend clocks in sync with something line NTP, but with this commit minor clock drift will only mean you might lose a few seconds of you recording, not the entire follow on recording.

The overrecord race problem is also made worse by a clock drift, basically if the slave is over 2 seconds "slower" than the frontend you almost always lost the race, otherwise you lost the race in rough proportion to how far you were out of sync with the master backend's clock.

comment:11 Changed 19 years ago by bjm

Resolution:	fixed
Status:	closed → reopened

As of [7427] each consecutive recording on a slave host gets canceled.

Here it successfully started "The Amazing Race" at 9pm (21:00) on card 2 but cancels "The Surreal Life" for card 1 on a slave host. At 21:02 it is reactivated but then at 22:00 the following show, "Filthy Rich: Cattle Drive" was canceled also.

mythbackend -v record
...
2005-10-09 20:59:25.804 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-09 20:59:57.557 TVRec(2): ClearFlags(AskAllowRecording,) -> RunMainLoop,RingBufferReset,
2005-10-09 20:59:57.559 TVRec(2): ClearFlags(CancelNextRecording,) -> RunMainLoop,RingBufferReset,
2005-10-09 20:59:57.560 TVRec(2): Changing from None to RecordingOnly
2005-10-09 20:59:57.561 TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReset,
2005-10-09 20:59:57.562 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-09 20:59:57.563 TVRec(2): Request: Program(yes) channel() input() flags(Recording,)
2005-10-09 20:59:57.564 TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-09 20:59:57.565 TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,RingBufferReset,
2005-10-09 20:59:58.589 ret_pid(15704) child(15704) status(0x0)
2005-10-09 20:59:58.591 External Tuning program exited with no error
2005-10-09 20:59:58.592 TVRec(2): SetFlags(NeedToStartRecorder,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,RingBufferReset,
2005-10-09 20:59:58.593 TVRec(2): Starting Recorder
2005-10-09 20:59:58.631 TVRec(2): Using profile 'Live TV' to record
2005-10-09 20:59:58.645 SetRecording(0x0x8353530)
2005-10-09 20:59:58.648 Prog title: The Amazing Race
2005-10-09 20:59:58.673 TVRec(2): SetFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,RecorderRunning,RingBufferReset,
strange error flushing buffer ...
2005-10-09 20:59:58.686 Started recording: The Amazing Race "We Got a Gnome! We Got a Gnome!": channel 2344 on cardid 2, sourceid 2
2005-10-09 20:59:58.721 scheduler: Last message repeated 5 times
2005-10-09 20:59:58.743 scheduler: Started
2005-10-09 20:59:58.842 TVRec(2): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-09 21:00:02.933 Canceled recording: The Surreal Life "The Last Straw": channel 1039 on cardid 1, sourceid 1
2005-10-09 21:00:02.944 scheduler: Canceled
2005-10-09 21:00:24.241 Reschedule requested for id 0.
2005-10-09 21:00:25.078 Scheduled 295 items in 0.8 = 0.00 match + 0.78 place
2005-10-09 21:00:25.084 scheduler: Scheduled items
2005-10-09 21:00:51.311 Commercial Flagging Starting for The Amazing Race "We Got a Gnome! We Got a Gnome!" recorded from channel 2344 at Sun Oct 9 21:0
0:00 2005
2005-10-09 21:00:51.316 commflag: Commercial Flagging Starting
2005-10-09 21:00:54.437 Using runtime prefix = /usr/local
2005-10-09 21:00:54.853 New DB connection, total: 1
2005-10-09 21:00:54.945 New DB connection, total: 2
2005-10-09 21:00:55.033 Connecting to backend server: 192.168.0.35:6543 (try 1 of 5)
2005-10-09 21:01:54.227 MainServer::HandleAnnounce Playback
2005-10-09 21:01:54.228 adding: moktoo as a client (events: 0)
2005-10-09 21:01:54.519 MainServer::HandleAnnounce Playback
2005-10-09 21:01:54.528 adding: moktoo as a client (events: 1)
2005-10-09 21:02:02.078 Reschedule requested for id 0.
2005-10-09 21:02:02.876 Scheduled 295 items in 0.8 = 0.00 match + 0.78 place
2005-10-09 21:02:03.845 Started recording: The Surreal Life "The Last Straw": channel 1039 on cardid 1, sourceid 1
2005-10-09 21:02:03.850 scheduler: Last message repeated 1 times
2005-10-09 21:02:03.855 scheduler: Started
2005-10-09 21:02:41.526 MainServer::HandleAnnounce Playback
2005-10-09 21:02:41.528 adding: sleepy as a client (events: 0)
2005-10-09 21:02:42.195 MainServer::HandleAnnounce Playback
2005-10-09 21:02:42.204 adding: sleepy as a client (events: 1)
2005-10-09 21:59:30.852 TVRec(2): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,RingBufferReset,
2005-10-09 22:00:02.818 Canceled recording: Filthy Rich: Cattle Drive "Finale": channel 1036 on cardid 1, sourceid 1
2005-10-09 22:00:02.865 scheduler: Canceled

comment:12 Changed 19 years ago by bjm

Here is a simpler more controlled experiment. "One (Manual Record)" is scheduled for 23:05 - 23:10. "Two (Manual Record)" is scheduled for 23:10 - 23:15. Both are assigned to card 1 on a slave backend. Here are the logs from both backends with -v record.

Master backend

2005-10-09 23:05:04.131 Started recording: One (Manual Record) "Sun Oct 9 23:05:00 2005": channel 1003 on cardid 1, sourceid 1
2005-10-09 23:05:04.137 scheduler: Last message repeated 1 times
2005-10-09 23:05:04.141 scheduler: Started
2005-10-09 23:05:33.430 Reschedule requested for id 6617.
2005-10-09 23:05:33.976 Scheduled 290 items in 0.5 = 0.13 match + 0.41 place
2005-10-09 23:05:33.981 scheduler: Scheduled items
2005-10-09 23:10:02.229 Canceled recording: Two (Manual Record) "Sun Oct 9 23:10:00 2005": channel 1003 on cardid 1, sourceid 1
2005-10-09 23:10:02.234 scheduler: Canceled
2005-10-09 23:10:24.299 Reschedule requested for id 0.
2005-10-09 23:10:24.741 Scheduled 289 items in 0.4 = 0.00 match + 0.42 place
2005-10-09 23:10:24.748 scheduler: Scheduled items

Slave backend

2005-10-09 23:05:03.657 TVRec(1): ClearFlags(AskAllowRecording,) -> RunMainLoop,CancelNextRecording,
2005-10-09 23:05:03.659 TVRec(1): ClearFlags(CancelNextRecording,) -> RunMainLoop,
2005-10-09 23:05:03.660 TVRec(1): Changing from None to RecordingOnly
2005-10-09 23:05:03.661 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2005-10-09 23:05:03.662 TVRec(1): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,
2005-10-09 23:05:03.663 TVRec(1): Request: Program(yes) channel() input() flags(Recording,)
2005-10-09 23:05:03.664 TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,
2005-10-09 23:05:03.665 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,
2005-10-09 23:05:03.705 TVRec(1): SetFlags(NeedToStartRecorder,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,
2005-10-09 23:05:03.706 TVRec(1): Starting Recorder
2005-10-09 23:05:04.022 TVRec(1): Using profile 'Low Quality' to record
2005-10-09 23:05:04.098 SetRecording(0x0x81aec98)
2005-10-09 23:05:04.100 Prog title: One (Manual Record)
2005-10-09 23:05:04.147 TVRec(1): SetFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,NeedToStartRecorder,RecorderRunning,
strange error flushing buffer ...
2005-10-09 23:05:04.260 TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-09 23:09:30.617 TVRec(1): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-09 23:10:02.210 TVRec(1): ClearFlags(AskAllowRecording,) -> RunMainLoop,RecorderRunning,
2005-10-09 23:10:02.212 TVRec(1): Wanted to record: Two (Manual Record) 1003 Sun Oct 9 23:10:00 2005 Sun Oct 9 23:15:00 2005
                        But the current state is: RecordingOnly                 Currently recording: One (Manual Record) 1003 Sun Oct 9 23:05:00 2005 Su
n Oct 9 23:10:00 2005
2005-10-09 23:10:02.213 TVRec(1): ClearFlags(CancelNextRecording,) -> RunMainLoop,RecorderRunning,
2005-10-09 23:10:24.267 TVRec(1): ClearFlags(FinishRecording,) -> RunMainLoop,RecorderRunning,
2005-10-09 23:10:24.268 TVRec(1): Changing from RecordingOnly to None
2005-10-09 23:10:24.270 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,
2005-10-09 23:10:24.273 TVRec(1): SetFlags(AskAllowRecording,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-09 23:10:24.274 TVRec(1): Request: Program(no) channel() input() flags(CloseRec,KillRingBuffer,)
2005-10-09 23:10:24.276 TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,AskAllowRecording,RecorderRunning,
2005-10-09 23:10:24.305 Finished recording One (Manual Record) "Sun Oct 9 23:05:00 2005": channel 1003
2005-10-09 23:10:24.337 scheduler: Finished recording
2005-10-09 23:10:24.531 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,
2005-10-09 23:10:24.536 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,AskAllowRecording,
2005-10-09 23:10:24.543 TVRec(1): Tearing down RingBuffer
2005-10-09 23:10:24.553 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,AskAllowRecording,

comment:13 Changed 19 years ago by danielk

Resolution:	→ fixed
Status:	reopened → closed

(In [7433]) Fixes #430.

This is a simpler fix for the time skew portion of the consecutive recording problem. Part of the problem I was trying to solve was already solved by David Engel. MythTV should no longer try to schedule something for recording that is already recording on a slave backend. So the GetRecording?() request is not needed in the scheduler. We can instead simply cancel any non-LiveTV recording if the master backend requests a new recording.

Note: See TracTickets for help on using tickets.

Download in other formats: