[mythtv-users] 0.25 skipping post-processing

Fri Apr 20 15:03:56 UTC 2012

On Thu, Apr 19, 2012 at 9:32 PM, Steve Harrington <umhssteve at gmail.com> wrote:
> On Wed, Apr 18, 2012 at 10:22 AM, James Orr <james.orr7 at gmail.com> wrote:
>>
>> I've noticed a couple of recordings have not performed their post-processing tasks (meta-data lookup and commercial flag).  In both cases they have been the second of back-to-back recordings.  In the latest case the back-to-back recordings were from the same recording rule ... the post-processing jobs were run for the first but not the second.
>>
>
>
> Hi all -
>
> I'd like to say that I'm also experiencing this behavior.  Metadata
> lookup and commflagging are being ignored.  Touch had the commflag and
> metadata jobs start but Grey's Anatomy did not.  Will this keep my
> wife from watching Grey's? Probably not, oh well.  Both shows started
> recording at 21:00.  Backend log:
>
> Apr 19 20:51:26 mythdish mythbackend[6494]: I HouseKeeping
> housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> Apr 19 20:56:31 mythdish mythbackend[6494]: I HouseKeeping
> housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> Apr 19 20:59:20 mythdish mythbackend[6494]: N Expire
> autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required
> Free Space: 3.0 GB w/freq: 14 min
> Apr 19 20:59:29 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(14): ASK_RECORDING 14
> 29 0 0
> Apr 19 20:59:30 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(10): ASK_RECORDING 10
> 29 0 0
> Apr 19 20:59:30 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(12): ASK_RECORDING 12
> 29 0 0
> Apr 19 20:59:59 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:1014 (HandleStateChange) TVRec(12): Changing from None to
> RecordingOnly
> Apr 19 20:59:59 mythdish mythbackend[6494]: I TVRecEvent
> mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 19
> Apr 19 21:00:00 mythdish mythbackend[6494]: E ProcessRequest
> programinfo.cpp:2278 (GetPlaybackURL)
> ProgramInfo(1041_20120419210000.mpg): GetPlaybackURL:
> '1041_20120419210000.mpg' should be local, but it can not be found.
> Apr 19 21:00:00 mythdish mythbackend[6494]: E ProcessRequest
> programinfo.cpp:2278 (GetPlaybackURL)
> ProgramInfo(1041_20120419210000.mpg): GetPlaybackURL:
> '1041_20120419210000.mpg' should be local, but it can not be found.
> Apr 19 21:00:00 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(12): HW Tuner: 12->12
> Apr 19 21:00:00 mythdish mythbackend[6494]: N Scheduler
> autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required
> Free Space: 3.0 GB w/freq: 7 min
> Apr 19 21:00:00 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording:
> "The Office":"Angry Andy": channel 1041 on cardid 12, sourceid 1
> Apr 19 21:00:01 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:1014 (HandleStateChange) TVRec(14): Changing from None to
> RecordingOnly
> Apr 19 21:00:01 mythdish mythbackend[6494]: I TVRecEvent
> mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 19
> Apr 19 21:00:01 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(14): HW Tuner: 14->14
> Apr 19 21:00:01 mythdish mythbackend[6494]: N Scheduler
> autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required
> Free Space: 3.0 GB w/freq: 4 min
> Apr 19 21:00:01 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording:
> Touch:"Lost and Found": channel 1021 on cardid 14, sourceid 1
> Apr 19 21:00:01 mythdish mythbackend[6494]: I PreviewGeneratorQueue
> mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 19
> Apr 19 21:00:02 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:3950 (TuningNewRecorder) TVRec(12): rec->GetPathname():
> '/recordings2/1041_20120419210000.mpg'
> Apr 19 21:00:02 mythdish mythbackend[6494]: E TVRecEvent
> recorderbase.cpp:164 (SetStrOption) RecBase(12:10324852-1):
> SetStrOption(...recordingtype): Option not in profile.
> Apr 19 21:00:02 mythdish mythbackend[6494]: I TVRecEvent
> tv_rec.cpp:3950 (TuningNewRecorder) TVRec(14): rec->GetPathname():
> '/recordings1/1021_20120419210000.mpg'
> Apr 19 21:00:02 mythdish mythbackend[6494]: E TVRecEvent
> recorderbase.cpp:164 (SetStrOption) RecBase(14:10328477-0):
> SetStrOption(...recordingtype): Option not in profile.
> Apr 19 21:00:04 mythdish mythbackend[6494]: N Scheduler
> autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required
> Free Space: 3.0 GB w/freq: 4 min
> Apr 19 21:00:04 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2459 (HandleRecordingStatusChange) Started recording:
> "Grey's Anatomy":"The Girl With No Name": channel 1071 on cardid 10,
> sourceid 1
> Apr 19 21:00:04 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2459 (HandleRecordingStatusChange) Started recording:
> "The Office":"Angry Andy": channel 1041 on cardid 12, sourceid 1
> Apr 19 21:00:04 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2459 (HandleRecordingStatusChange) Started recording:
> Touch:"Lost and Found": channel 1021 on cardid 14, sourceid 1
> Apr 19 21:00:04 mythdish mythbackend[6494]: I HDHRStreamHandler
> mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 21
> Apr 19 21:00:04 mythdish mythbackend[6494]: I HDHRStreamHandler
> tv_rec.cpp:3253 (RingBufferChanged) TVRec(10): RingBufferChanged()
> Apr 19 21:00:04 mythdish mythbackend[6494]: I CoreContext
> scheduler.cpp:634 (UpdateRecStatus) Updating status for Missing:"A
> Busy Solitude" on cardid 10 (Recording => Recorded)
> Apr 19 21:00:04 mythdish mythbackend[6494]: I HDHRStreamHandler
> recordinginfo.cpp:1113 (FinishedRecording) Finished recording Missing
> "A Busy Solitude": channel 1071
> Apr 19 21:00:04 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0.
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 1)
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:13 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 1)
> Apr 19 21:00:27 mythdish mythbackend[6494]: I Scheduler
> scheduler.cpp:2068 (HandleReschedule) Scheduled 1259 items in 22.8 =
> 0.00 match + 22.84 place
> Apr 19 21:00:47 mythdish mythbackend[6494]: I Metadata_5841
> jobqueue.cpp:2150 (DoMetadataLookupThread) JobQueue: Metadata Lookup
> Starting for "The Office":"Angry Andy" recorded from channel 1041 at
> 2012-04-19T21:00:00
> Apr 19 21:00:50 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:50 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:50 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:50 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 1)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I Metadata_5843
> jobqueue.cpp:2150 (DoMetadataLookupThread) JobQueue: Metadata Lookup
> Starting for Touch:"Lost and Found" recorded from channel 1021 at
> 2012-04-19T21:00:00
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: basement1110 as a client
> (events: 0)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: basement1110 as a client
> (events: 1)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: basement1110 as a client
> (events: 0)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce
> FileTransfer
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1477 (HandleAnnounce) adding: basement1110 as a remote
> file transfer
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: basement1110 as a client
> (events: 0)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce
> FileTransfer
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1477 (HandleAnnounce) adding: basement1110 as a remote
> file transfer
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: basement1110 as a client
> (events: 0)
> Apr 19 21:00:52 mythdish mythbackend[6494]: I ProcessRequest
> recorderbase.cpp:386 (GetKeyframePositions) RecBase(12:10324852-1):
> GetKeyframePositions(1294,9223372036854775807,#14) out of 102
> Apr 19 21:00:53 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:53 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:53 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:53 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 1)
> Apr 19 21:00:57 mythdish mythbackend[6494]: I Commflag_5844
> jobqueue.cpp:2275 (DoFlagCommercialsThread) JobQueue: Commercial
> Detection Starting for Touch:"Lost and Found" recorded from channel
> 1021 at 2012-04-19T21:00:00
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 1)
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> mainserver.cpp:1362 (HandleAnnounce) adding: mythdish as a client
> (events: 0)
> Apr 19 21:00:57 mythdish mythbackend[6494]: I ProcessRequest
> recorderbase.cpp:386 (GetKeyframePositions) RecBase(14:10328477-0):
> GetKeyframePositions(2803,9223372036854775807,#31) out of 219
> Apr 19 21:01:33 mythdish mythbackend[6494]: I HouseKeeping
> housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
> Apr 19 21:06:33 mythdish mythbackend[6494]: I HouseKeeping
> housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
>
>
> Thanks!
> Steve

I'll throw my hat into this ring as well. It happens fairly
infrequently for me, but it is always on consecutive recordings, and
in at least the most recent case, on the same tuner for the same rule.
As the OP said, it is not just commercial flagging, but all jobqueue
related activity (metadata lookup and commercial flagging). It's not
mentioned in the backend log anywhere for the second recording.
I'll run with -v general,jobqueue for a while to see if I can gather
some more information.

--
Justin Johnson