Context Navigation

← Previous Ticket
Next Ticket →

Opened 14 years ago

Closed 12 years ago

#8142 closed defect (Unverified)

Frontend timeout when changing backend channels (bt878)

Reported by:	Chris Picton <chrisp@…>	Owned by:	Janne Grunau
Priority:	minor	Milestone:	unknown
Component:	MythTV - Recording	Version:	0.22-fixes
Severity:	medium	Keywords:
Cc:		Ticket locked:	no

Description

When changing channels while watching LiveTV, the frontend times out, giving an error 'Irrecoverable recorder error'

The frontend logs report an error

readStringList: Error, timed out after 7000 ms. (This is similar to http://svn.mythtv.org/trac/ticket/8137, but changing the timeout all the way up to 40000 ms still gives the same error)

The same error is seen with two separate frontends.

If, however, I set up a recording schedule which changes channels, the channels are recorded without error.

Which logs would be best to help track down the problem?

I am running 0.22-fixes revision 23604

Change History (7)

comment:1 Changed 14 years ago by stuartm

Component:	MythTV - General → MythTV - Recording
Owner:	changed from Isaac Richards to danielk

comment:2 Changed 14 years ago by Janne Grunau

Owner:	changed from danielk to Janne Grunau
Status:	new → accepted

mythbackend -v record,channel is required

comment:3 Changed 14 years ago by robertm

Status:	accepted → infoneeded

comment:4 Changed 14 years ago by anonymous

Here is a result of scantv to show which channels are available, and then the backend logs:

# scantv

please select your TV norm
   0: NTSC
   1: NTSC-M
   2: NTSC-M-JP
   3: NTSC-M-KR
   4: PAL
   5: PAL-BG
   6: PAL-H
   7: PAL-I
   8: PAL-DK
   9: PAL-M
  10: PAL-N
  11: PAL-Nc
  12: PAL-60
  13: SECAM
  14: SECAM-B
  15: SECAM-G
nr ? 7

please select a frequency table
   0: us-bcast
   1: us-cable
   2: us-cable-hrc
   3: japan-bcast
   4: japan-cable
   5: europe-west
   6: europe-east
   7: italy
   8: newzealand
   9: australia
  10: ireland
  11: france
  12: china-bcast
  13: southafrica
  14: argentina
  15: australia-optus
  16: russia
nr ? 13
[global]
freqtab = southafrica

[defaults]
input = Television
norm = PAL-I


scanning channel list southafrica...
1    (175.25 MHz): no station
2    (183.25 MHz): no station
3    (191.25 MHz): ???
[unknown (3)]
channel = 3

4    (199.25 MHz): no station
5    (207.25 MHz): no station
6    (215.25 MHz): ???
[unknown (6)]
channel = 6

7    (223.25 MHz): no station
8    (231.25 MHz): no station
9    (239.25 MHz): no station
10   (247.25 MHz): ???
[unknown (10)]
channel = 10

11   (255.25 MHz): no station
12   (263.25 MHz): no station
13   (271.25 MHz): no station
21   (471.25 MHz): no station
22   (479.25 MHz): no station
23   (487.25 MHz): no station
24   (495.25 MHz): no station
25   (503.25 MHz): no station
26   (511.25 MHz): no station
27   (519.25 MHz): no station
28   (527.25 MHz): no station
29   (535.25 MHz): no station
30   (543.25 MHz): no station
31   (551.25 MHz): no station
32   (559.25 MHz): no station
33   (567.25 MHz): no station
34   (575.25 MHz): no station
35   (583.25 MHz): no station
36   (591.25 MHz): no station
37   (599.25 MHz): no station
38   (607.25 MHz): no station
39   (615.25 MHz): no station
40   (623.25 MHz): no station
41   (631.25 MHz): no station
42   (639.25 MHz): no station
43   (647.25 MHz): no station
44   (655.25 MHz): no station
45   (663.25 MHz): no station
46   (671.25 MHz): no station
47   (679.25 MHz): ???
[unknown (47)]
channel = 47

48   (687.25 MHz): no station
49   (695.25 MHz): no station
50   (703.25 MHz): no station
51   (711.25 MHz): no station
52   (719.25 MHz): no station
53   (727.25 MHz): no station
54   (735.25 MHz): no station
55   (743.25 MHz): no station
56   (751.25 MHz): no station
57   (759.25 MHz): no station
58   (767.25 MHz): no station
59   (775.25 MHz): no station
60   (783.25 MHz): no station
61   (791.25 MHz): no station
62   (799.25 MHz): no station
63   (807.25 MHz): no station
64   (815.25 MHz): no station
65   (823.25 MHz): no station
66   (831.25 MHz): no station
67   (839.25 MHz): no station
68   (847.25 MHz): no station
69   (855.25 MHz): no station

############## Startup
2010-04-13 19:14:45.771 mythbackend version:  [23604] www.mythtv.org
2010-04-13 19:14:45.771 Using runtime prefix = /usr
2010-04-13 19:14:45.771 Using configuration directory = /home/mythtv/.mythtv
2010-04-13 19:14:45.771 Empty LocalHostName.
2010-04-13 19:14:45.772 Using localhost value of snark.picton.nom.za
2010-04-13 19:14:45.772 Testing network connectivity to '172.17.17.1'
2010-04-13 19:14:45.784 New DB connection, total: 1
2010-04-13 19:14:45.790 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:14:45.791 Closing DB connection named 'DBManager0'
2010-04-13 19:14:45.791 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:14:45.795 Current MythTV Schema Version (DBSchemaVer): 1244
2010-04-13 19:14:45.797 MythBackend: Starting up as the master server.
2010-04-13 19:14:45.800 New DB connection, total: 2
2010-04-13 19:14:45.801 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:14:45.803 TVRec(1): Start channel: 10.
2010-04-13 19:14:45.804 Channel(/dev/video0): Device name 'BT878 video (Leadtek WinFast 20' driver 'bttv'.
2010-04-13 19:14:45.804 New DB connection, total: 3
2010-04-13 19:14:45.805 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:14:45.807 ChannelBase(1): Input #1: 'Television' schan(10) sourceid(1) ccid(1)
2010-04-13 19:14:45.807 ChannelBase(1): Current Input #1: 'Television'
2010-04-13 19:14:45.808 Global TVFormat Setting 'PAL-I'
2010-04-13 19:14:45.808 Channel(/dev/video0): Input #1: 'Television' schan(10) tun() v4l1(PAL) v4l2(PAL-I)
2010-04-13 19:14:45.808 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:14:45.808 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:14:45.809 Channel(/dev/video0): SetFormat(PAL-I) fmt(PAL-I) input(1)
2010-04-13 19:14:45.810 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:14:45.811 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:14:45.812 Channel(/dev/video0): SetChannelByString(10)
2010-04-13 19:14:45.813 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:14:45.813 Channel(/dev/video0)::TuneTo(10): curList[6].freq(223250)
2010-04-13 19:14:45.813 Channel(/dev/video0): Tune(223250000, , analog, analog)
2010-04-13 19:14:45.814 Channel(/dev/video0)::Tune(): Frequency is now 223250000
2010-04-13 19:14:45.815 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:14:45.816 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:14:45.817 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:14:45.818 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:14:45.825 TVRec(1): SetFlags(RunMainLoop,) -> RunMainLoop,
2010-04-13 19:14:45.825 TVRec(1): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
2010-04-13 19:14:45.826 New DB scheduler connection
2010-04-13 19:14:45.827 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:14:45.846 Enabling Upnpmedia rebuild thread.
2010-04-13 19:14:47.184 Main::Registering HttpStatus Extension
2010-04-13 19:14:47.185 Enabled verbose msgs:  important general record channel
2010-04-13 19:14:47.187 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-04-13 19:14:48.852 Reschedule requested for id -1.
2010-04-13 19:14:48.886 Scheduled 0 items in 0.0 = 0.02 match + 0.02 place
2010-04-13 19:14:48.889 Seem to be woken up by USER
2010-04-13 19:14:55.848 UPnpMedia: BuildMediaMap - no VideoStartupDir set,  skipping scan.


############## Start LiveTV on client
2010-04-13 19:15:06.400 MainServer::ANN Monitor
2010-04-13 19:15:06.401 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:06.404 MainServer::ANN Monitor
2010-04-13 19:15:06.404 adding: jubjub-ion as a client (events: 1)
2010-04-13 19:15:06.409 Getting next free recorder after : -1
2010-04-13 19:15:06.410 Checking card 1. Best card so far 1
2010-04-13 19:15:06.481 MainServer::ANN Playback
2010-04-13 19:15:06.481 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:06.485 TVRec(1): Changing from None to Watching WatchingLiveTV
2010-04-13 19:15:06.485 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2010-04-13 19:15:06.485 TVRec(1): Request: Program(no) channel() input() flags(LiveTV,)
2010-04-13 19:15:06.485 TVRec(1): Start channel: 10.
2010-04-13 19:15:06.488 TVRec(1): HW Tuner: 1->1
2010-04-13 19:15:06.488 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2010-04-13 19:15:06.488 TVRec(1): No recorder yet, calling TuningFrequency
2010-04-13 19:15:06.489 Channel(/dev/video0): Device name 'BT878 video (Leadtek WinFast 20' driver 'bttv'.
2010-04-13 19:15:06.491 ChannelBase(1): Input #1: 'Television' schan(10) sourceid(1) ccid(1)
2010-04-13 19:15:06.491 ChannelBase(1): Current Input #1: 'Television'
2010-04-13 19:15:06.491 Global TVFormat Setting 'PAL-I'
2010-04-13 19:15:06.491 Channel(/dev/video0): Input #1: 'Television' schan(10) tun() v4l1(PAL) v4l2(PAL-I)
2010-04-13 19:15:06.491 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:06.492 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:15:06.494 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:15:06.495 Channel(/dev/video0): SetChannelByString(10)
2010-04-13 19:15:06.498 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:06.498 Channel(/dev/video0)::TuneTo(10): curList[6].freq(223250)
2010-04-13 19:15:06.498 Channel(/dev/video0): Tune(223250000, , analog, analog)
2010-04-13 19:15:06.499 Channel(/dev/video0)::Tune(): Frequency is now 223250000
2010-04-13 19:15:06.500 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.501 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.502 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.502 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.503 TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,
2010-04-13 19:15:06.503 TVRec(1): SetFlags(NeedToStartRecorder,) -> RunMainLoop,NeedToStartRecorder,
2010-04-13 19:15:06.503 TVRec(1): Starting Recorder
2010-04-13 19:15:06.520 SampleRate: Attempted to add a rate 32000 Hz, which is not in the list of allowed rates.
2010-04-13 19:15:06.523 Using profile 'Live TV' to record
2010-04-13 19:15:06.523 TVRec(1): CreateLiveTVRingBuffer()
2010-04-13 19:15:06.524 TVRec(1): GetProgramRingBufferForLiveTV()
2010-04-13 19:15:06.545 TVRec(1): StartedRecording(0x7f89b9a58a00) fn(/var/samba/mythtv/recorded/1003_20100413191506.nuv)
2010-04-13 19:15:06.560 Chain: Appended@0 '1003_20100413191506'
2010-04-13 19:15:06.561 TVRec(1): SetFlags(RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
2010-04-13 19:15:06.570 RecBase(1:/dev/video0): SetRingBuffer(0x7f89b9a7e630) '/var/samba/mythtv/recorded/1003_20100413191506.nuv'
2010-04-13 19:15:06.584 RecBase(1:/dev/video0): SetRecording(0x7f89b9a91130) title(News)
2010-04-13 19:15:06.586 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.587 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.588 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.589 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:06.592 AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
ioctl VIDIOC_G_FMT: Invalid argument
2010-04-13 19:15:06.600 NVR(/dev/video0): v4l2: format set, getting yuv420 from v4l
2010-04-13 19:15:06.605 TVRec(1): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2010-04-13 19:15:06.605 TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2010-04-13 19:15:06.606 TVRec(1): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
strange error flushing buffer ...
2010-04-13 19:15:06.729 MainServer::ANN Playback
2010-04-13 19:15:06.729 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:06.736 MainServer::HandleAnnounce FileTransfer
2010-04-13 19:15:06.736 adding: jubjub-ion as a remote file transfer
2010-04-13 19:15:07.831 RecBase(1:/dev/video0): GetKeyframePositions(1,9223372036854775807,#0) out of 1
2010-04-13 19:15:09.100 TVRec(1): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,


############## Change to Channel 47 on client
2010-04-13 19:15:15.690 TVRec(1): SetChannel(47) -- begin
2010-04-13 19:15:15.690 TVRec(1): ClearFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:15.690 TVRec(1): Request: Program(no) channel(47) input() flags(LiveTV,)
2010-04-13 19:15:15.690 ChannelBase(1): Looking for startchannel '47' on input 'Television'
2010-04-13 19:15:15.693 ChannelBase(1): Found startchannel '47' on input 'Television'
2010-04-13 19:15:15.693 TVRec(1): HW Tuner: 1->1
2010-04-13 19:15:15.693 TVRec(1): ClearFlags(PENDINGACTIONS,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:15.693 TVRec(1): Waiting for recorder pause..
2010-04-13 19:15:15.693 TVRec(1): SetFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForRecPause,RecorderRunning,
2010-04-13 19:15:15.713 TVRec(1): ClearFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:15.713 TVRec(1): Recorder paused, calling TuningFrequency
2010-04-13 19:15:15.714 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:15:15.716 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:15:15.717 Channel(/dev/video0): SetChannelByString(47)
2010-04-13 19:15:15.720 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:15.721 Channel(/dev/video0)::TuneTo(47): curList[36].freq(679250)
2010-04-13 19:15:15.721 Channel(/dev/video0): Tune(679250000, , analog, analog)
2010-04-13 19:15:15.721 Channel(/dev/video0)::Tune(): Frequency is now 679250000
2010-04-13 19:15:15.723 Channel(/dev/video0): InitPictureAttribute(brightness):  32768
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:15.724 Channel(/dev/video0): InitPictureAttribute(  contrast):  32768
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:15.725 Channel(/dev/video0): InitPictureAttribute(    colour):  32768
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:15.726 Channel(/dev/video0): InitPictureAttribute(       hue):  32768
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:15.726 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:15.726 TVRec(1): SetFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,
2010-04-13 19:15:15.726 TVRec(1): Restarting Recorder
2010-04-13 19:15:15.728 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:15.728 Chain: Updated endtime for '1003_20100413191506' to 20100413191515
2010-04-13 19:15:15.729 Finished recording News: channel 1003
2010-04-13 19:15:15.730 TVRec(1): SwitchLiveTVRingBuffer(discont 1, set_rec 1)
2010-04-13 19:15:15.730 TVRec(1): GetProgramRingBufferForLiveTV()
2010-04-13 19:15:15.740 TVRec(1): StartedRecording(0x7f89a4011bc0) fn(/var/samba/mythtv/recorded/1000_20100413191515.nuv)
2010-04-13 19:15:15.747 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:15.748 Chain: Updated endtime for '1003_20100413191506' to 20100413191515
2010-04-13 19:15:15.751 Finished recording News: channel 1003
2010-04-13 19:15:15.754 Preview: 'myth://172.17.17.1:6543/1003_20100413191506.nuv' is not local,
                        replacing with '/var/samba/mythtv/recorded/1003_20100413191506.nuv', which is local.
2010-04-13 19:15:15.766 Chain: Appended@1 '1000_20100413191515'
2010-04-13 19:15:15.827 mythbackend version:  [23604] www.mythtv.org
2010-04-13 19:15:15.827 Using runtime prefix = /usr
2010-04-13 19:15:15.827 Using configuration directory = /home/mythtv/.mythtv
2010-04-13 19:15:15.827 Empty LocalHostName.
2010-04-13 19:15:15.827 Using localhost value of snark.picton.nom.za
2010-04-13 19:15:15.827 Testing network connectivity to '172.17.17.1'
2010-04-13 19:15:15.840 New DB connection, total: 1
2010-04-13 19:15:15.846 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:15.846 Closing DB connection named 'DBManager0'
2010-04-13 19:15:15.847 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:15.850 Current MythTV Schema Version (DBSchemaVer): 1244
2010-04-13 19:15:15.851 New DB connection, total: 2
2010-04-13 19:15:15.852 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:15.896 RecBase(1:/dev/video0): SetRingBuffer(0x7f89a4017e90) '/var/samba/mythtv/recorded/1000_20100413191515.nuv'
2010-04-13 19:15:15.896 TVRec(1): RingBufferChanged()
2010-04-13 19:15:15.898 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:15.899 Chain: Updated endtime for '1003_20100413191506' to 20100413191515
2010-04-13 19:15:15.900 Finished recording News: channel 1003
2010-04-13 19:15:16.002 TVRec(1): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2010-04-13 19:15:16.003 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2010-04-13 19:15:16.007 AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2010-04-13 19:15:16.008 TVRec(1): SetChannel(47) -- end
2010-04-13 19:15:16.196 Preview: Grabbed preview '/var/samba/mythtv/recorded/1003_20100413191506.nuv' 480x576@64s
2010-04-13 19:15:16.283 MainServer::ANN Playback
2010-04-13 19:15:16.283 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:16.286 MainServer::HandleAnnounce FileTransfer
2010-04-13 19:15:16.286 adding: jubjub-ion as a remote file transfer
2010-04-13 19:15:16.395 RecBase(1:/dev/video0): GetKeyframePositions(0,9223372036854775807,#1) out of 1


############## Change to Channel 10 on client
2010-04-13 19:15:35.750 TVRec(1): SetChannel(10) -- begin
2010-04-13 19:15:35.751 TVRec(1): ClearFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:35.752 TVRec(1): Request: Program(no) channel(10) input() flags(LiveTV,)
2010-04-13 19:15:35.752 ChannelBase(1): Looking for startchannel '10' on input 'Television'
2010-04-13 19:15:35.754 ChannelBase(1): Found startchannel '10' on input 'Television'
2010-04-13 19:15:35.754 TVRec(1): HW Tuner: 1->1
2010-04-13 19:15:35.754 TVRec(1): ClearFlags(PENDINGACTIONS,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:35.755 TVRec(1): Waiting for recorder pause..
2010-04-13 19:15:35.755 TVRec(1): SetFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForRecPause,RecorderRunning,
2010-04-13 19:15:35.779 TVRec(1): ClearFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:35.779 TVRec(1): Recorder paused, calling TuningFrequency
2010-04-13 19:15:35.780 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:15:35.782 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:15:35.783 Channel(/dev/video0): SetChannelByString(10)
2010-04-13 19:15:35.786 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:35.786 Channel(/dev/video0)::TuneTo(10): curList[6].freq(223250)
2010-04-13 19:15:35.786 Channel(/dev/video0): Tune(223250000, , analog, analog)
2010-04-13 19:15:35.787 Channel(/dev/video0)::Tune(): Frequency is now 223250000
2010-04-13 19:15:35.788 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:35.789 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:35.790 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:35.791 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:35.791 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:35.791 TVRec(1): SetFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,
2010-04-13 19:15:35.791 TVRec(1): Restarting Recorder
2010-04-13 19:15:35.793 TVRec(1): FinishedRecording(eNews Prime Time) in recgroup: LiveTV
2010-04-13 19:15:35.794 Chain: Updated endtime for '1000_20100413191515' to 20100413191535
2010-04-13 19:15:35.797 Finished recording eNews Prime Time: channel 1000
2010-04-13 19:15:35.798 TVRec(1): SwitchLiveTVRingBuffer(discont 1, set_rec 1)
2010-04-13 19:15:35.798 TVRec(1): GetProgramRingBufferForLiveTV()
2010-04-13 19:15:35.811 TVRec(1): StartedRecording(0x7f89b9a1dee0) fn(/var/samba/mythtv/recorded/1003_20100413191535.nuv)
2010-04-13 19:15:35.818 TVRec(1): FinishedRecording(eNews Prime Time) in recgroup: LiveTV
2010-04-13 19:15:35.818 Chain: Updated endtime for '1000_20100413191515' to 20100413191535
2010-04-13 19:15:35.822 Finished recording eNews Prime Time: channel 1000
2010-04-13 19:15:35.824 Preview: 'myth://172.17.17.1:6543/1000_20100413191515.nuv' is not local,
                        replacing with '/var/samba/mythtv/recorded/1000_20100413191515.nuv', which is local.
2010-04-13 19:15:35.852 Chain: Appended@2 '1003_20100413191535'
2010-04-13 19:15:35.915 mythbackend version:  [23604] www.mythtv.org
2010-04-13 19:15:35.915 Using runtime prefix = /usr
2010-04-13 19:15:35.915 Using configuration directory = /home/mythtv/.mythtv
2010-04-13 19:15:35.915 Empty LocalHostName.
2010-04-13 19:15:35.915 Using localhost value of snark.picton.nom.za
2010-04-13 19:15:35.916 Testing network connectivity to '172.17.17.1'
2010-04-13 19:15:35.949 New DB connection, total: 1
2010-04-13 19:15:35.954 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:35.954 Closing DB connection named 'DBManager0'
2010-04-13 19:15:35.955 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:35.959 Current MythTV Schema Version (DBSchemaVer): 1244
2010-04-13 19:15:35.960 New DB connection, total: 2
2010-04-13 19:15:35.960 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:36.069 RecBase(1:/dev/video0): SetRingBuffer(0x7f89b9add3c0) '/var/samba/mythtv/recorded/1003_20100413191535.nuv'
2010-04-13 19:15:36.069 TVRec(1): RingBufferChanged()
2010-04-13 19:15:36.071 TVRec(1): FinishedRecording(eNews Prime Time) in recgroup: LiveTV
2010-04-13 19:15:36.072 Chain: Updated endtime for '1000_20100413191515' to 20100413191536
2010-04-13 19:15:36.072 Finished recording eNews Prime Time: channel 1000
2010-04-13 19:15:36.262 TVRec(1): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2010-04-13 19:15:36.263 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2010-04-13 19:15:36.265 TVRec(1): SetChannel(10) -- end
2010-04-13 19:15:36.269 AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2010-04-13 19:15:36.467 Preview: Grabbed preview '/var/samba/mythtv/recorded/1000_20100413191515.nuv' 480x576@64s
2010-04-13 19:15:36.510 MainServer::ANN Playback
2010-04-13 19:15:36.510 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:36.513 MainServer::HandleAnnounce FileTransfer
2010-04-13 19:15:36.514 adding: jubjub-ion as a remote file transfer
2010-04-13 19:15:36.532 RecBase(1:/dev/video0): GetKeyframePositions(0,9223372036854775807,#1) out of 1


############## Change to Channel 6 on client
2010-04-13 19:15:44.987 TVRec(1): SetChannel(6) -- begin
2010-04-13 19:15:44.987 TVRec(1): ClearFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:44.987 TVRec(1): Request: Program(no) channel(6) input() flags(LiveTV,)
2010-04-13 19:15:44.987 ChannelBase(1): Looking for startchannel '6' on input 'Television'
2010-04-13 19:15:44.990 ChannelBase(1): Found startchannel '6' on input 'Television'
2010-04-13 19:15:44.990 TVRec(1): HW Tuner: 1->1
2010-04-13 19:15:44.990 TVRec(1): ClearFlags(PENDINGACTIONS,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:44.990 TVRec(1): Waiting for recorder pause..
2010-04-13 19:15:44.990 TVRec(1): SetFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForRecPause,RecorderRunning,
2010-04-13 19:15:45.077 TVRec(1): ClearFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:45.077 TVRec(1): Recorder paused, calling TuningFrequency
2010-04-13 19:15:45.078 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:15:45.080 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:15:45.082 Channel(/dev/video0): SetChannelByString(6)
2010-04-13 19:15:45.094 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:45.094 Channel(/dev/video0)::TuneTo(6): curList[2].freq(191250)
2010-04-13 19:15:45.094 Channel(/dev/video0): Tune(191250000, , analog, analog)
2010-04-13 19:15:45.095 Channel(/dev/video0)::Tune(): Frequency is now 191250000
2010-04-13 19:15:45.096 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:45.097 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:45.098 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:45.099 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:15:45.099 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:45.099 TVRec(1): SetFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,
2010-04-13 19:15:45.100 TVRec(1): Restarting Recorder
2010-04-13 19:15:45.102 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:45.102 Chain: Updated endtime for '1003_20100413191535' to 20100413191545
2010-04-13 19:15:45.106 Finished recording News: channel 1003
2010-04-13 19:15:45.107 TVRec(1): SwitchLiveTVRingBuffer(discont 1, set_rec 1)
2010-04-13 19:15:45.107 TVRec(1): GetProgramRingBufferForLiveTV()
2010-04-13 19:15:45.120 TVRec(1): StartedRecording(0x7f89b9a1dee0) fn(/var/samba/mythtv/recorded/1002_20100413191545.nuv)
2010-04-13 19:15:45.129 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:45.130 Chain: Updated endtime for '1003_20100413191535' to 20100413191545
2010-04-13 19:15:45.133 Finished recording News: channel 1003
2010-04-13 19:15:45.136 Preview: 'myth://172.17.17.1:6543/1003_20100413191535.nuv' is not local,
                        replacing with '/var/samba/mythtv/recorded/1003_20100413191535.nuv', which is local.
2010-04-13 19:15:45.152 Chain: Appended@3 '1002_20100413191545'
2010-04-13 19:15:45.211 mythbackend version:  [23604] www.mythtv.org
2010-04-13 19:15:45.212 Using runtime prefix = /usr
2010-04-13 19:15:45.212 Using configuration directory = /home/mythtv/.mythtv
2010-04-13 19:15:45.212 Empty LocalHostName.
2010-04-13 19:15:45.212 Using localhost value of snark.picton.nom.za
2010-04-13 19:15:45.212 Testing network connectivity to '172.17.17.1'
2010-04-13 19:15:45.228 New DB connection, total: 1
2010-04-13 19:15:45.234 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:45.234 Closing DB connection named 'DBManager0'
2010-04-13 19:15:45.236 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:45.242 RecBase(1:/dev/video0): SetRingBuffer(0x7f89b9a573c0) '/var/samba/mythtv/recorded/1002_20100413191545.nuv'
2010-04-13 19:15:45.242 TVRec(1): RingBufferChanged()
2010-04-13 19:15:45.244 TVRec(1): FinishedRecording(News) in recgroup: LiveTV
2010-04-13 19:15:45.244 Chain: Updated endtime for '1003_20100413191535' to 20100413191545
2010-04-13 19:15:45.245 Current MythTV Schema Version (DBSchemaVer): 1244
2010-04-13 19:15:45.245 Finished recording News: channel 1003
2010-04-13 19:15:45.247 New DB connection, total: 2
2010-04-13 19:15:45.247 Connected to database 'mythconverg' at host: 172.17.17.1
2010-04-13 19:15:45.331 TVRec(1): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2010-04-13 19:15:45.332 TVRec(1): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2010-04-13 19:15:45.335 TVRec(1): SetChannel(6) -- end
2010-04-13 19:15:45.337 AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2010-04-13 19:15:45.573 Preview: Grabbed preview '/var/samba/mythtv/recorded/1003_20100413191535.nuv' 480x576@64s
2010-04-13 19:15:45.574 MainServer::ANN Playback
2010-04-13 19:15:45.575 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:15:45.579 MainServer::HandleAnnounce FileTransfer
2010-04-13 19:15:45.579 adding: jubjub-ion as a remote file transfer
2010-04-13 19:15:45.597 RecBase(1:/dev/video0): GetKeyframePositions(0,9223372036854775807,#1) out of 1

############## Change to Channel 3 on client - client goes black and times out after a while
2010-04-13 19:15:53.251 TVRec(1): SetChannel(3) -- begin
2010-04-13 19:15:53.252 TVRec(1): ClearFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:53.252 TVRec(1): Request: Program(no) channel(3) input() flags(LiveTV,)
2010-04-13 19:15:53.252 ChannelBase(1): Looking for startchannel '3' on input 'Television'
2010-04-13 19:15:53.255 ChannelBase(1): Found startchannel '3' on input 'Television'
2010-04-13 19:15:53.255 TVRec(1): HW Tuner: 1->1
2010-04-13 19:15:53.255 TVRec(1): ClearFlags(PENDINGACTIONS,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:53.255 TVRec(1): Waiting for recorder pause..
2010-04-13 19:15:53.255 TVRec(1): SetFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForRecPause,RecorderRunning,
2010-04-13 19:15:53.273 TVRec(1): ClearFlags(WaitingForRecPause,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,
2010-04-13 19:15:53.274 TVRec(1): Recorder paused, calling TuningFrequency
2010-04-13 19:15:53.274 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:15:53.276 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:15:53.278 Channel(/dev/video0): SetChannelByString(3)
2010-04-13 19:15:53.281 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:15:53.281 Channel(/dev/video0) Error: GetCurrentChannelNum(3): Failed to find Channel
2010-04-13 19:15:53.281 Channel(/dev/video0)::TuneTo(3): curList[-1].freq(-1)
2010-04-13 19:15:53.281 Channel(/dev/video0)::TuneTo(3): Error, failed to find channel.
2010-04-13 19:15:53.281 TVRec(1) Error: Failed to set channel to 3. Reverting to kState_None
2010-04-13 19:15:53.281 TVRec(1): Changing from Watching WatchingLiveTV to None
2010-04-13 19:15:53.281 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,
2010-04-13 19:15:53.281 TVRec(1): Request: Program(no) channel() input() flags(KillRec,KillRingBuffer,)
2010-04-13 19:15:53.282 Unknown type, recording width was 0
2010-04-13 19:15:53.716 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,
2010-04-13 19:15:53.723 TVRec(1): FinishedRecording(Nuus) in recgroup: LiveTV
2010-04-13 19:15:53.723 Chain: Updated endtime for '1002_20100413191545' to 20100413191553
2010-04-13 19:15:53.728 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,
2010-04-13 19:15:53.728 TVRec(1): Tearing down RingBuffer
2010-04-13 19:15:53.788 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2010-04-13 19:16:01.533 MainServer::ANN Playback
2010-04-13 19:16:01.533 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:16:01.535 TVRec(1): StopLiveTV(void) curRec: 0x0 pseudoRec: 0x0
2010-04-13 19:16:01.537 TVRec(1): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,
2010-04-13 19:16:01.542 Getting next free recorder after : -1
2010-04-13 19:16:01.543 Checking card 1. Best card so far 1
2010-04-13 19:16:01.618 MainServer::ANN Playback
2010-04-13 19:16:01.618 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:16:01.621 TVRec(1): Changing from None to Watching WatchingLiveTV
2010-04-13 19:16:01.621 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2010-04-13 19:16:01.621 TVRec(1): Request: Program(no) channel() input() flags(LiveTV,)
2010-04-13 19:16:01.622 TVRec(1): Start channel: 6.
2010-04-13 19:16:01.624 TVRec(1): HW Tuner: 1->1
2010-04-13 19:16:01.624 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2010-04-13 19:16:01.624 TVRec(1): No recorder yet, calling TuningFrequency
2010-04-13 19:16:01.626 Channel(/dev/video0): Device name 'BT878 video (Leadtek WinFast 20' driver 'bttv'.
2010-04-13 19:16:01.627 ChannelBase(1): Input #1: 'Television' schan(6) sourceid(1) ccid(1)
2010-04-13 19:16:01.628 ChannelBase(1): Current Input #1: 'Television'
2010-04-13 19:16:01.628 Global TVFormat Setting 'PAL-I'
2010-04-13 19:16:01.628 Channel(/dev/video0): Input #1: 'Television' schan(6) tun() v4l1(PAL) v4l2(PAL-I)
2010-04-13 19:16:01.628 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:16:01.628 Channel(/dev/video0)::SwitchToInput(in 1, '')
2010-04-13 19:16:01.630 Channel(/dev/video0): SetInputAndFormat(1, PAL-I) (v4l v2)
2010-04-13 19:16:01.631 Channel(/dev/video0): SetChannelByString(6)
2010-04-13 19:16:01.634 Channel(/dev/video0): SetFormat(Default) fmt(PAL-I) input(1)
2010-04-13 19:16:01.634 Channel(/dev/video0)::TuneTo(6): curList[2].freq(191250)
2010-04-13 19:16:01.634 Channel(/dev/video0): Tune(191250000, , analog, analog)
2010-04-13 19:16:01.635 Channel(/dev/video0)::Tune(): Frequency is now 191250000
2010-04-13 19:16:01.636 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.637 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.638 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.639 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.639 TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,
2010-04-13 19:16:01.639 TVRec(1): SetFlags(NeedToStartRecorder,) -> RunMainLoop,NeedToStartRecorder,
2010-04-13 19:16:01.639 TVRec(1): Starting Recorder
2010-04-13 19:16:01.656 SampleRate: Attempted to add a rate 32000 Hz, which is not in the list of allowed rates.
2010-04-13 19:16:01.659 Using profile 'Live TV' to record
2010-04-13 19:16:01.659 TVRec(1): CreateLiveTVRingBuffer()
2010-04-13 19:16:01.659 TVRec(1): GetProgramRingBufferForLiveTV()
2010-04-13 19:16:01.670 TVRec(1): StartedRecording(0x7f899406e5d0) fn(/var/samba/mythtv/recorded/1002_20100413191601.nuv)
2010-04-13 19:16:01.696 Chain: Appended@0 '1002_20100413191601'
2010-04-13 19:16:01.697 TVRec(1): SetFlags(RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
2010-04-13 19:16:01.705 RecBase(1:/dev/video0): SetRingBuffer(0x7f899400deb0) '/var/samba/mythtv/recorded/1002_20100413191601.nuv'
2010-04-13 19:16:01.719 RecBase(1:/dev/video0): SetRecording(0x7f899400d4f0) title(Nuus)
2010-04-13 19:16:01.721 Channel(/dev/video0): InitPictureAttribute(brightness):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.722 Channel(/dev/video0): InitPictureAttribute(  contrast):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.723 Channel(/dev/video0): InitPictureAttribute(    colour):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
2010-04-13 19:16:01.724 Channel(/dev/video0): InitPictureAttribute(       hue):  32750
                        [    0,65535] dflt(32768, 0.50, 0)
ioctl VIDIOC_G_FMT: Invalid argument
2010-04-13 19:16:01.727 NVR(/dev/video0): v4l2: format set, getting yuv420 from v4l
2010-04-13 19:16:01.732 AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2010-04-13 19:16:01.739 TVRec(1): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2010-04-13 19:16:01.739 TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2010-04-13 19:16:01.740 TVRec(1): SetChannel(3) -- end
2010-04-13 19:16:01.740 TVRec(1): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2010-04-13 19:16:01.742 MainServer, Warning: Unknown socket closing MythSocket(0x7f89b9a40680)
2010-04-13 19:16:01.743 MythSocket(7f89b9a40680:-1): writeStringList: Error, socket went unconnected.
                        We wrote 0 of 10 bytes with 1 errors
strange error flushing buffer ...
2010-04-13 19:16:01.871 MainServer::ANN Playback
2010-04-13 19:16:01.871 adding: jubjub-ion as a client (events: 0)
2010-04-13 19:16:01.878 MainServer::HandleAnnounce FileTransfer
2010-04-13 19:16:01.878 adding: jubjub-ion as a remote file transfer
2010-04-13 19:16:01.992 TVRec(1): StopLiveTV(void) curRec: 0x7f899406e5d0 pseudoRec: 0x0
2010-04-13 19:16:01.994 TVRec(1): Changing from Watching WatchingLiveTV to None
2010-04-13 19:16:01.994 TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2010-04-13 19:16:01.994 TVRec(1): Request: Program(no) channel() input() flags(KillRec,KillRingBuffer,)
2010-04-13 19:16:01.996 Unknown type, recording width was 0
2010-04-13 19:16:02.138 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2010-04-13 19:16:02.141 TVRec(1): FinishedRecording(Nuus) in recgroup: LiveTV
2010-04-13 19:16:02.142 Chain: Updated endtime for '1002_20100413191601' to 20100413191602
2010-04-13 19:16:02.142 Finished recording Nuus: channel 1002
2010-04-13 19:16:02.143 TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2010-04-13 19:16:02.143 TVRec(1): Tearing down RingBuffer
2010-04-13 19:16:02.189 TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2010-04-13 19:16:05.832 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-04-13 19:16:05.833 Expiring 13 MBytes for 1003 @ Tue Apr 13 19:00:00 2010 => News

comment:5 Changed 14 years ago by robertm

Status:	infoneeded → assigned

comment:6 Changed 14 years ago by dgatwood <dgatwood@…>

It's not just while Live TV is running. I was about to file basically the same bug because of Live TV refusing to start at all. It turns out that my problems are also caused by the channel change script taking too long and the front end timing out.

Changing the timeout (as suggested in the related bug) would lock up the front end, and is thus highly undesirable. However, blaming it on the script doesn't solve this very real and common problem. Channel changing scripts with an IR blaster may take several seconds to execute, and apparently, some other types of receivers have an inherent problem with this as well, so this bug does need to be addressed.

Ultimately, the best way to solve the problem is to not block the backend while the channel changing script is executing at all. This requires two or three changes:

Start the channel change script asynchronously (spawn a helper thread) and return control immediately to allow normal backend operation. If the frontend really needs to know when the channel change is complete, it could periodically poll for the status of the command (not sure if that would require changes to the protocol or not), but it's probably not important enough to bother.

Immediately reject any attempts to change the channel if an instance of the channel change script (or the helper thread that controls it) is still running. This is critical to prevent scripts that use irsend from interleaving multiple channel numbers during rapid channel changes.

You might consider adding a brief delay after the channel change before allowing the next one. Some scripts may need to add additional delays on a per-device basis as needed, but a small delay in the backend itself might reduce the number of scripts that would require changes. Or don't, and just tell script writers to add the delay as needed.

If there are weird setups that this sort of scheme would break, I'd be okay with a checkbox to control whether to run it asynchronously. If so, please put it right beside/below the command field, and provide an explanation of why you may want to check the checkbox so that folks won't waste so much time trying to figure out what's wrong. That said, I wouldn't think that would be necessary.

As a workaround for anyone running into this:

mv channel_change_script.sh channel_change_script_guts.sh

cat <<EOF > channel_change_script.sh
#!/bin/sh

/path/to/channel_change_script_guts.sh "$@" &

exit 0
EOF

chmod a+rx channel_change_script.sh

comment:7 Changed 12 years ago by danielk

Resolution:	→ Unverified
Status:	assigned → closed

It appears that we weren't getting any data there are several ways this is addressed in more recent code. I'm closing this because it's a ticket against 0.22 for a problem that is probably fixed in more recent code.

Note: See TracTickets for help on using tickets.

Download in other formats: