[mythtv-users] failed recordings on HVR-1600: DevRdB(/dev/dvb/adapter1/frontend0): Poll giving up 2

Brian J. Murrell brian at interlinx.bc.ca
Fri Dec 9 17:10:13 UTC 2011


The other night, my HVR-1600 was supposed to record two clearqam 
programs on the same transport (is that the correct nomenclature for the 
broadcast channel?) but seems to have failed.  Recordings prior and 
subsequent were successful.

The backend log reported during this failure:

2011-12-07 22:00:00.687331 I [1625/1949] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(1): Changing from None to RecordingOnly
2011-12-07 22:00:00.715160 I [1625/1949] TVRecEvent tv_rec.cpp:3434 
(TuningCheckForHWChange) - TVRec(1): HW Tuner: 1->1
2011-12-07 22:00:00.891411 I [1625/2194] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(11): Changing from RecordingOnly to None
2011-12-07 22:00:01.103688 I [1625/2194] TVRecEvent 
recordinginfo.cpp:1108 (FinishedRecording) - Finished recording Storage 
Wars "Tanks for the Memories": channel 1019
2011-12-07 22:00:01.115712 E [1625/7589] RecThread mpegrecorder.cpp:1044 
(run) - MPEGRec(/dev/video1): Device EOF detected
2011-12-07 22:00:01.990880 N [1625/2195] Scheduler autoexpire.cpp:264 
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB 
w/freq: 4 min
2011-12-07 22:00:01.991166 I [1625/2195] Scheduler scheduler.cpp:2456 
(HandleRecordingStatusChange) - Tuning recording: "CSI: Crime Scene 
Investigation":Zippered: channel 2917 on cardid 1, sourceid 2
2011-12-07 22:00:02.390675 I [1625/7049] DVBRead 
mpeg/mpegdescriptors.cpp:72 (ParseOnlyInclude) - Excluding Descriptor 83
2011-12-07 22:00:02.390718 I [1625/7049] DVBRead 
mpeg/mpegdescriptors.cpp:72 (ParseOnlyInclude) - Excluding Descriptor a
2011-12-07 22:00:02.390759 I [1625/7049] DVBRead 
mpeg/mpegdescriptors.cpp:72 (ParseOnlyInclude) - Excluding Descriptor 83
2011-12-07 22:00:02.390783 I [1625/7049] DVBRead 
mpeg/mpegdescriptors.cpp:72 (ParseOnlyInclude) - Excluding Descriptor a
2011-12-07 22:00:02.535747 I [1625/1949] TVRecEvent tv_rec.cpp:3948 
(TuningNewRecorder) - TVRec(1): rec->GetPathname(): 
'/video/mythtv/2917_20111207220000.mpg'
2011-12-07 22:00:02.965083 I [1625/7589] RecThread mythdbcon.cpp:479 
(CloseDatabases) - Closing DB connection named 'DBManager81'
2011-12-07 22:00:04.238409 I [1625/2085] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(2): Changing from RecordingOnly to None
2011-12-07 22:00:04.296911 I [1625/2085] TVRecEvent 
recordinginfo.cpp:1108 (FinishedRecording) - Finished recording Criminal 
Minds "Self-Fulfilling Prophecy": channel 2917
2011-12-07 22:00:04.415071 I [1625/7074] RecThread mythdbcon.cpp:75 
(MSqlDatabase) - Database connection created: DBManager100
2011-12-07 22:00:04.415170 I [1625/7074] RecThread mythdbcon.cpp:298 
(popConnection) - New DB connection, total: 35
2011-12-07 22:00:04.416565 I [1625/7074] RecThread mythdbcon.cpp:179 
(OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-12-07 22:00:04.435417 I [1625/7074] RecThread mythdbcon.cpp:479 
(CloseDatabases) - Closing DB connection named 'DBManager100'
2011-12-07 22:00:04.876862 I [1625/2085] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(2): Changing from None to RecordingOnly
2011-12-07 22:00:04.880716 I [1625/2085] TVRecEvent tv_rec.cpp:3434 
(TuningCheckForHWChange) - TVRec(2): HW Tuner: 2->2
2011-12-07 22:00:07.303591 N [1625/2195] Scheduler autoexpire.cpp:264 
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB 
w/freq: 4 min
2011-12-07 22:00:07.303697 I [1625/2195] Scheduler scheduler.cpp:2456 
(HandleRecordingStatusChange) - Tuning recording: Revenge:Loyalty: 
channel 3776 on cardid 2, sourceid 2
2011-12-07 22:00:08.767051 I [1625/2195] Scheduler scheduler.cpp:2456 
(HandleRecordingStatusChange) - Started recording: "CSI: Crime Scene 
Investigation":Zippered: channel 2917 on cardid 1, sourceid 2
2011-12-07 22:00:10.104434 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for "Happy Endings":"Grinches Be 
Crazy" on cardid 1 (Recording => Recorded)
2011-12-07 22:00:10.269066 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for "Storage Wars":"Tanks for the 
Memories" on cardid 11 (Recording => Recorded)
2011-12-07 22:00:10.370180 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for "Criminal 
Minds":"Self-Fulfilling Prophecy" on cardid 2 (Recording => Recorded)
2011-12-07 22:00:10.444919 E [1625/1625] CoreContext mainserver.cpp:868 
(customEvent) - MainServer: PREVIEW_SUCCESS but no receivers.
2011-12-07 22:00:10.524969 I [1625] ProcessRequest mainserver.cpp:1356 
(HandleAnnounce) - MainServer::ANN Playback
2011-12-07 22:00:10.525011 I [1625] ProcessRequest mainserver.cpp:1358 
(HandleAnnounce) - adding: pvr as a client (events: 0)
2011-12-07 22:00:10.541908 I [1625] ProcessRequest mainserver.cpp:1356 
(HandleAnnounce) - MainServer::ANN Playback
2011-12-07 22:00:10.541952 I [1625] ProcessRequest mainserver.cpp:1358 
(HandleAnnounce) - adding: pvr as a client (events: 0)
2011-12-07 22:00:10.559459 I [1625] ProcessRequest mainserver.cpp:1356 
(HandleAnnounce) - MainServer::ANN Monitor
2011-12-07 22:00:10.559499 I [1625] ProcessRequest mainserver.cpp:1358 
(HandleAnnounce) - adding: pvr as a client (events: 1)
2011-12-07 22:00:10.571540 I [1625] ProcessRequest mainserver.cpp:1356 
(HandleAnnounce) - MainServer::ANN Monitor
2011-12-07 22:00:10.571585 I [1625] ProcessRequest mainserver.cpp:1358 
(HandleAnnounce) - adding: pvr as a client (events: 1)
2011-12-07 22:00:13.500322 E [1625/7861] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(4097_20111201200000.mpg): GetPlaybackURL: 
'4097_20111201200000.mpg' should be local, but it can not be found.
2011-12-07 22:00:13.642245 E [1625/7861] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(1042_20111124110000.mpg): GetPlaybackURL: 
'1042_20111124110000.mpg' should be local, but it can not be found.
2011-12-07 22:00:13.727291 E [1625/7861] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(3776_20111207220000.mpg): GetPlaybackURL: 
'3776_20111207220000.mpg' should be local, but it can not be found.
2011-12-07 22:00:14.048552 I [1625] ProcessRequest mythdbcon.cpp:75 
(MSqlDatabase) - Database connection created: DBManager101
2011-12-07 22:00:14.048650 I [1625] ProcessRequest mythdbcon.cpp:298 
(popConnection) - New DB connection, total: 35
2011-12-07 22:00:14.051697 I [1625] ProcessRequest mythdbcon.cpp:179 
(OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-12-07 22:00:16.137967 E [1625/8197] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(4097_20111201200000.mpg): GetPlaybackURL: 
'4097_20111201200000.mpg' should be local, but it can not be found.
2011-12-07 22:00:16.259022 E [1625/8197] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(1042_20111124110000.mpg): GetPlaybackURL: 
'1042_20111124110000.mpg' should be local, but it can not be found.
2011-12-07 22:00:16.336523 E [1625/8197] ProcessRequest 
programinfo.cpp:2166 (GetPlaybackURL) - 
ProgramInfo(3776_20111207220000.mpg): GetPlaybackURL: 
'3776_20111207220000.mpg' should be local, but it can not be found.
2011-12-07 22:00:27.411592 E [1625/7050] DeviceReadBuffer 
DeviceReadBuffer.cpp:509 (Poll) - DevRdB(/dev/dvb/adapter1/frontend0): 
Poll giving up 2
2011-12-07 22:00:27.412040 E [1625/7049] DVBRead 
dvbstreamhandler.cpp:209 (RunTS) - DVBSH(/dev/dvb/adapter1/frontend0): 
Device error detected
2011-12-07 22:00:27.412083 E [1625/7049] DVBRead 
dvbstreamhandler.cpp:215 (RunTS) - DVBSH(/dev/dvb/adapter1/frontend0): 
Device EOF detected
2011-12-07 22:00:28.014487 I [1625/7049] DVBRead mythdbcon.cpp:479 
(CloseDatabases) - Closing DB connection named 'DBManager58'
2011-12-07 22:00:28.060048 E [1625/7601] RecThread dvbrecorder.cpp:134 
(run) - DVBRec(4:/dev/dvb/adapter1/frontend0): Stream handler died 
unexpectedly.
2011-12-07 22:00:28.060501 E [1625/8226] RecThread dvbrecorder.cpp:134 
(run) - DVBRec(1:/dev/dvb/adapter1/frontend0): Stream handler died 
unexpectedly.
2011-12-07 22:00:28.064247 I [1625/8226] RecThread mythdbcon.cpp:75 
(MSqlDatabase) - Database connection created: DBManager102
2011-12-07 22:00:28.064343 I [1625/8226] RecThread mythdbcon.cpp:298 
(popConnection) - New DB connection, total: 35
2011-12-07 22:00:28.065836 I [1625/8226] RecThread mythdbcon.cpp:179 
(OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-12-07 22:00:28.067934 I [1625/2091] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(4): Changing from RecordingOnly to None
2011-12-07 22:00:28.078658 I [1625/8226] RecThread mythdbcon.cpp:479 
(CloseDatabases) - Closing DB connection named 'DBManager102'
2011-12-07 22:00:28.092972 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for "Harry's Law":"Purple Hearts" on 
cardid 4 (Recording => Recorder Failed)
2011-12-07 22:00:28.130716 I [1625/7601] RecThread mythdbcon.cpp:75 
(MSqlDatabase) - Database connection created: DBManager103
2011-12-07 22:00:28.130814 I [1625/7601] RecThread mythdbcon.cpp:298 
(popConnection) - New DB connection, total: 35
2011-12-07 22:00:28.132021 I [1625/7601] RecThread mythdbcon.cpp:179 
(OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-12-07 22:00:28.137156 I [1625/7601] RecThread mythdbcon.cpp:479 
(CloseDatabases) - Closing DB connection named 'DBManager103'
2011-12-07 22:00:28.180190 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for Revenge:Loyalty on cardid 2 
(Tuning => Recorder Failed)
2011-12-07 22:00:28.215489 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:00:28.215529 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:00:28.215554 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:00:28.215579 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:00:28.215600 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:00:28.723666 I [1625/1949] TVRecEvent tv_rec.cpp:992 
(HandleStateChange) - TVRec(1): Changing from RecordingOnly to None
2011-12-07 22:00:28.755838 I [1625/1625] CoreContext scheduler.cpp:603 
(UpdateRecStatus) - Updating status for "CSI: Crime Scene 
Investigation":Zippered on cardid 1 (Recording => Recorder Failed)
2011-12-07 22:01:33.342789 N [1625/2197] Expire autoexpire.cpp:264 
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB 
w/freq: 14 min
2011-12-07 22:01:50.792157 I [1625/2195] Scheduler scheduler.cpp:2055 
(HandleReschedule) - Reschedule interrupted, will retry
2011-12-07 22:01:50.805021 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.
2011-12-07 22:01:50.805062 I [1625/2195] Scheduler scheduler.cpp:2008 
(HandleReschedule) - Reschedule requested for id 0.

Worth noting that the CSI and Harry's law that are reporting as failed 
were recorded in full.

The kernel log buffer reported at the same time frame:

Dec  7 22:00:01 pvr kernel: [34563.279588] cx18-0: Could not find buf 0 
for stream encoder MPEG
Dec  7 22:00:01 pvr kernel: [34563.473447] cx18-0: Unable to find blank 
work order form to schedule incoming mailbox command processing
Dec  7 22:00:01 pvr kernel: [34563.655761] cx18-0: ignoring gop_end: not 
(yet?) supported by the firmware
Dec  7 22:00:02 pvr kernel: [34564.150773] cx18-0: Skipped encoder MPEG, 
buffer 63, 29 times - it must have dropped out of rotation
Dec  7 22:00:02 pvr kernel: [34564.329266] cx18-0: Skipped TS, buffer 
84, 16 times - it must have dropped out of rotation

Any ideas?

Cheers,
b.


More information about the mythtv-users mailing list