Hi,<div><br></div><div> Since upgrading to 0.25 a couple of weeks ago (on Mythbuntu 11.10) some of my recordings are not working. In 'Upcoming recordings' I can see that the recordings have been successfully set and will record but sometimes the recording doesn't happen (about twice a week across all of my recordings). </div>
<div><br></div><div> I happened to notice the other day that while we were watching TV and the "Myth wants to record, what do you want to do?" box came up. I left it at it's default "Let it record and change channels" and the channel didn't change. The recording also didn't appear in my recordings list. I selected to manually record (pressing 'r') and then the recording was there. I looked into the logs (see below - it's The Biggest Loser that's failing) and can see that the recording was cancelled, but not why. Could it be that there are two programmes recording at the same time and there's some kind of race?</div>
<div><br></div><div> It's really frustrating that I can't trust the recording mechanism, it's our highest use feature and my WAF is dropping significantly. Any ideas?
</div><div><br></div><div>[mythbackend.log]</div><div>Apr 4 18:49:08 mythtv-desktop mythbackend[5654]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(8:/dev/dvb/adapter0/frontend0): GetKeyframePositions(27882,9223372036854775807,#15) out of 2339</div>
<div>Apr 4 18:52:09 mythtv-desktop mythbackend[5654]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread</div><div>Apr 4 18:54:24 mythtv-desktop mythbackend[5654]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0.</div>
<div>Apr 4 18:54:24 mythtv-desktop mythbackend[5654]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 18 items in 0.8 = 0.02 match + 0.76 place</div><div>Apr 4 18:54:29 mythtv-desktop mythbackend[5654]: I TVRecEvent tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(10): ASK_RECORDING 10 29 0 0</div>
<div>Apr 4 18:54:30 mythtv-desktop mythbackend[5654]: I TVRecEvent tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(8): ASK_RECORDING 8 29 0 0</div><div>Apr 4 18:54:55 mythtv-desktop mythbackend[5654]: N ProcessRequest mainserver.cpp:3825 (HandleRecorderQuery) Received: CANCEL_NEXT_RECORDING 0</div>
<div>Apr 4 18:54:55 mythtv-desktop mythbackend[5654]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(8:/dev/dvb/adapter0/frontend0): GetKeyframePositions(28062,9223372036854775807,#725) out of 3064</div>
<div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(10): Changing from None to RecordingOnly</div><div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 12</div>
<div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(10): HW Tuner: 10->10</div><div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: N Scheduler autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min</div>
<div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording: "ABC News": channel 1002 on cardid 10, sourceid 1</div><div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: N Scheduler autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min</div>
<div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Started recording: "The Biggest Loser": channel 1010 on cardid 8, sourceid 1</div><div>Apr 4 18:55:00 mythtv-desktop mythbackend[5654]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for "ABC News" on cardid 10 (Tuning => Recording)</div>
<div>Apr 4 18:55:01 mythtv-desktop mythbackend[5654]: I TVRecEvent tv_rec.cpp:3950 (TuningNewRecorder) TVRec(10): rec->GetPathname(): '/opt/data/video/1002_20120404185500.mpg'</div><div>Apr 4 18:57:15 mythtv-desktop mythbackend[5654]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread</div>
<div>Apr 4 18:59:10 mythtv-desktop mythbackend[5654]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(8:/dev/dvb/adapter0/frontend0): GetKeyframePositions(36756,9223372036854775807,#531) out of 3595</div>
<div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback</div><div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client (events: 0)</div>
<div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer</div><div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote file transfer</div>
<div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: W ProcessRequest mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing MythSocket(0xffffffffacd5ca88)</div><div>Apr 4 19:01:49 mythtv-desktop mythbackend[5654]: E ProcessRequest mythsocket.cpp:358 (writeStringList) MythSocket(ffffffffacd5ca88:-1): writeStringList: Error, socket went unconnected.#012#011#011#011We wrote 0 of 10 bytes with 1 errors#012#011#011#011starts with: 2 ok</div>
<div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback</div><div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client (events: 0)</div>
<div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer</div><div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote file transfer</div>
<div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: E ProcessRequest mainserver.cpp:6068 (LocalFilePath) ERROR: LocalFilePath unable to find local path for 'frogman_blue_one.png'.</div><div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: E ProcessRequest mainserver.cpp:1547 (HandleAnnounce) Empty filename, cowardly aborting!</div>
<div>Apr 4 19:01:53 mythtv-desktop mythbackend[5654]: W Socket mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing MythSocket(0xffffffffacd07280)</div><div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback</div>
<div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client (events: 0)</div><div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer</div>
<div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote file transfer</div><div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: E ProcessRequest mainserver.cpp:6068 (LocalFilePath) ERROR: LocalFilePath unable to find local path for 'frogman_blue_one.png'.</div>
<div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: E ProcessRequest mainserver.cpp:1547 (HandleAnnounce) Empty filename, cowardly aborting!</div><div>Apr 4 19:01:54 mythtv-desktop mythbackend[5654]: W Socket mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing MythSocket(0xffffffffacd5bd28)</div>
<div><br></div><div>[mythfrontend.log]</div><div><div>Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: I CoreContext mythrender_vdpau.cpp:587 (CheckOutputSurfaces) VDPAU: Added 2 output surfaces (total 4, max 4)</div><div>
Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 103ms for video buffers ADAAAADLAAAAdA</div><div>Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 206ms for video buffers ADAAAADLAAAAdA</div>
<div>Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 308ms for video buffers ADAAAADLAAAAdA</div><div>Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 411ms for video buffers ADAAAADLAAAAdA</div>
<div>Apr 4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 513ms for video buffers ADAAAADLAAAAdA</div><div>Apr 4 18:32:22 mythtv-desktop mythfrontend[1984]: I CoreContext weatherSource.cpp:424 (startUpdate) Starting update of yrno-XML</div>
<div>Apr 4 18:32:22 mythtv-desktop mythfrontend[1984]: I CoreContext weatherSource.cpp:424 (startUpdate) Starting update of wunderground</div><div>Apr 4 18:47:22 mythtv-desktop mythfrontend[1984]: I CoreContext weatherSource.cpp:424 (startUpdate) Starting update of yrno-XML</div>
<div>Apr 4 18:47:22 mythtv-desktop mythfrontend[1984]: I CoreContext weatherSource.cpp:424 (startUpdate) Starting update of wunderground</div><div>Apr 4 18:54:30 mythtv-desktop mythfrontend[1984]: I CoreContext tv_play.cpp:8787 (customEvent) TV: ASK_RECORDING 10 29 0 0 hasrec: 0 haslater: 0</div>
<div>Apr 4 18:54:30 mythtv-desktop mythfrontend[1984]: I CoreContext tv_play.cpp:8787 (customEvent) TV: ASK_RECORDING 10 29 0 0 hasrec: 0 haslater: 0</div><div>Apr 4 18:54:30 mythtv-desktop mythfrontend[1984]: I CoreContext tv_play.cpp:8787 (customEvent) TV: ASK_RECORDING 8 29 0 0 hasrec: 0 haslater: 0</div>
<div>Apr 4 18:54:30 mythtv-desktop mythfrontend[1984]: I CoreContext tv_play.cpp:8787 (customEvent) TV: ASK_RECORDING 8 29 0 0 hasrec: 0 haslater: 0</div><div>Apr 4 19:01:49 mythtv-desktop mythfrontend[1984]: I CoreContext mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72</div>
<div>Apr 4 19:01:53 mythfrontend[1984]: last message repeated 3 times</div><div>Apr 4 19:01:53 mythtv-desktop mythfrontend[1984]: E CoreContext remotefile.cpp:172 (openSocket) RemoteFile::openSocket(file data socket): Failed to open socket, error was filetransfer_filename_empty</div>
<div>Apr 4 19:01:53 mythtv-desktop mythfrontend[1984]: E CoreContext mythuihelper.cpp:1349 (LoadScaleImage) MythUIHelper: LoadScaleImage(myth://<a href="http://ChannelIcon@192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png">ChannelIcon@192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png</a>) failed to load remote image</div>
<div>Apr 4 19:01:53 mythtv-desktop mythfrontend[1984]: E CoreContext mythuihelper.cpp:1398 (LoadScaleImage) MythUIHelper: LoadScaleImage(myth://<a href="http://ChannelIcon@192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png">ChannelIcon@192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png</a>) invalid image dimensions</div>
<div>Apr 4 19:01:54 mythtv-desktop mythfrontend[1984]: I CoreContext mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72</div><div>Apr 4 19:01:54 mythtv-desktop mythfrontend[1984]: I CoreContext mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72</div>
</div><div><br></div><div>Greg</div><div><br></div><div><br></div>