[mythtv-users] Cancelled recordings in 0.25

Sun Apr 22 04:31:58 UTC 2012

Hi,

 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).

  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?

  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?

[mythbackend.log]
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
Apr  4 18:52:09 mythtv-desktop mythbackend[5654]: I HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
Apr  4 18:54:24 mythtv-desktop mythbackend[5654]: I Scheduler
scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0.
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
Apr  4 18:54:29 mythtv-desktop mythbackend[5654]: I TVRecEvent
tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(10): ASK_RECORDING 10 29 0 0
Apr  4 18:54:30 mythtv-desktop mythbackend[5654]: I TVRecEvent
tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(8): ASK_RECORDING 8 29 0 0
Apr  4 18:54:55 mythtv-desktop mythbackend[5654]: N ProcessRequest
mainserver.cpp:3825 (HandleRecorderQuery) Received: CANCEL_NEXT_RECORDING 0
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
Apr  4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent
tv_rec.cpp:1014 (HandleStateChange) TVRec(10): Changing from None to
RecordingOnly
Apr  4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent
mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 12
Apr  4 18:55:00 mythtv-desktop mythbackend[5654]: I TVRecEvent
tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(10): HW Tuner: 10->10
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
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
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
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
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)
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'
Apr  4 18:57:15 mythtv-desktop mythbackend[5654]: I HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
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
Apr  4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
Apr  4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client
(events: 0)
Apr  4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Apr  4 19:01:49 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote
file transfer
Apr  4 19:01:49 mythtv-desktop mythbackend[5654]: W ProcessRequest
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing
MythSocket(0xffffffffacd5ca88)
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
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client
(events: 0)
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote
file transfer
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'.
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: E ProcessRequest
mainserver.cpp:1547 (HandleAnnounce) Empty filename, cowardly aborting!
Apr  4 19:01:53 mythtv-desktop mythbackend[5654]: W Socket
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing
MythSocket(0xffffffffacd07280)
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1362 (HandleAnnounce) adding: mythtv-desktop as a client
(events: 0)
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: I ProcessRequest
mainserver.cpp:1477 (HandleAnnounce) adding: mythtv-desktop as a remote
file transfer
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'.
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: E ProcessRequest
mainserver.cpp:1547 (HandleAnnounce) Empty filename, cowardly aborting!
Apr  4 19:01:54 mythtv-desktop mythbackend[5654]: W Socket
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket closing
MythSocket(0xffffffffacd5bd28)

[mythfrontend.log]
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)
Apr  4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext
mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 103ms for
video buffers ADAAAADLAAAAdA
Apr  4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext
mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 206ms for
video buffers ADAAAADLAAAAdA
Apr  4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext
mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 308ms for
video buffers ADAAAADLAAAAdA
Apr  4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext
mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 411ms for
video buffers ADAAAADLAAAAdA
Apr  4 18:30:29 mythtv-desktop mythfrontend[1984]: N CoreContext
mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(q): Waited 513ms for
video buffers ADAAAADLAAAAdA
Apr  4 18:32:22 mythtv-desktop mythfrontend[1984]: I CoreContext
weatherSource.cpp:424 (startUpdate) Starting update of yrno-XML
Apr  4 18:32:22 mythtv-desktop mythfrontend[1984]: I CoreContext
weatherSource.cpp:424 (startUpdate) Starting update of wunderground
Apr  4 18:47:22 mythtv-desktop mythfrontend[1984]: I CoreContext
weatherSource.cpp:424 (startUpdate) Starting update of yrno-XML
Apr  4 18:47:22 mythtv-desktop mythfrontend[1984]: I CoreContext
weatherSource.cpp:424 (startUpdate) Starting update of wunderground
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
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
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
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
Apr  4 19:01:49 mythtv-desktop mythfrontend[1984]: I CoreContext
mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72
Apr  4 19:01:53  mythfrontend[1984]: last message repeated 3 times
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
Apr  4 19:01:53 mythtv-desktop mythfrontend[1984]: E CoreContext
mythuihelper.cpp:1349 (LoadScaleImage) MythUIHelper: LoadScaleImage(myth://
ChannelIcon at 192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png)
failed to load remote image
Apr  4 19:01:53 mythtv-desktop mythfrontend[1984]: E CoreContext
mythuihelper.cpp:1398 (LoadScaleImage) MythUIHelper: LoadScaleImage(myth://
ChannelIcon at 192.168.1.8:6543/home/myth/.shepherd/icons/frogman_blue_one.png)
invalid image dimensions
Apr  4 19:01:54 mythtv-desktop mythfrontend[1984]: I CoreContext
mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72
Apr  4 19:01:54 mythtv-desktop mythfrontend[1984]: I CoreContext
mythcorecontext.cpp:1177 (CheckProtoVersion) Using protocol version 72

Greg
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.mythtv.org/pipermail/mythtv-users/attachments/20120422/b3a90e74/attachment.html>