[mythtv-users] Occasional Recording Failures with 'Program not found in PAT' error.
David Watkins
watkinshome at gmail.com
Tue Sep 20 12:57:39 UTC 2011
I'm having a smattering of failed recordings on my newly built
combined BE/FE (6 failures since mid July), characterised by this type
of error message in the backend log:
2011-09-14 20:29:01.600278 E [1712/3141] DVBRead
dtvsignalmonitor.cpp:302 (HandlePAT) -
DTVSM(/dev/dvb/adapter101/frontend0): Program #25792 not found in PAT!
Program Association Table
PSIP tableID(0x0) length(29) extension(0x4084)
version(5) current(1) section(0) last_section(0)
tsid: 16516
programCount: 5
program number 0 has PID 0x 10 data 0x 0 0x 0 0xe0 0x10
program number 17472 has PID 0x 64 data 0x44 0x40 0xe0 0x64
program number 17540 has PID 0x19c8 data 0x44 0x84 0xf9 0xc8
program number 17604 has PID 0x c8 data 0x44 0xc4 0xe0 0xc8
program number 17664 has PID 0x 12c data 0x45 0x 0 0xe1 0x2c
2011-09-14 20:29:02.046931 E [1712/3141] DVBRead
mpeg/mpegstreamdata.cpp:783 (ProcessPAT) - ProcessPAT: Program not
found in PAT.
Rescan your transports.
2011-09-14 20:29:02.047113 E [1712/3141] DVBRead
mpeg/mpegstreamdata.cpp:418 (CreatePATSingleProgram) - Desired program
#25792 not found in PAT.
Cannot create single program PAT.
(I have rescanned a couple of times but, since most recordings
succeed, it's hard to tell if it had any effect.)
... and about a minute later:
2011-09-14 20:30:37.165623 E [1712/1810] TVRecEvent dtvchannel.cpp:251
(SetChannelByString) - DTVChan(/dev/dvb/adapter101/frontend0):
SetChannelByString(82): Requested channel '82' is not available
because the tuner is currently in use on another transport.
2011-09-14 20:30:37.165669 E [1712/1810] TVRecEvent tv_rec.cpp:3638
(TuningFrequency) - TVRec(1): Failed to set channel to 82. Reverting
to kState_None
Channel 82 is Sky News (not something I've ever scheduled to record).
I'm guessing this is PAT #25792 on some other multiplex, but I don't
know how to check.
As best I can tell, that Program Association Table listing is correct
for the intended recording on BBC1 HD (UK Crystal Palace, DVBT-2
mux), but #25792 is a PAT entry from a different multiplex.
Five of the failures correspond to attempts to record DVBT-2
programmes using a PAT entry from on of the DVB multiplexes, while the
sixth corresponds to trying to record a DVB program using one of the
DVBT-2 PAT entries.
The result is that no recording file is created, with no further
errors in the backend log.
I've recently discovered that if another recording subsequently starts
on a second virtual tuner on the same capture card then, at the point
when the second recording starts, myth starts capturing the remaining
portion of the first programme as well.
System
-----------
Combined BE/FE running v0.25pre-3072-g50606cd with two capture cards:
Nanostick PCTV 290e
WinTV NOVA-T USB2
each with two virtual tuners.
I've attached the complete log from just before the first recording
starts at 20:29 until its scheduled finish at 21:03. I ended up with
a four-minute recording from 20:59 till 21:03 because a second
recording started at 20:59.
I realise that I'm running 'unstable' and some parts may be broken but
I've searched trac and not found a reference to this sort of error.
Has anyone seen this before - could it be a configuration error?
Would it warrant a ticket if it's not been seen before?
I think I need to find out what the incorrect PAT entries refer to and
see if I can see a pattern.
-------------- next part --------------
2011-09-14 20:28:29.896560 I [1712/1810] TVRecEvent tv_rec.cpp:1494 (HandlePendingRecordings) - TVRec(1): ASK_RECORDING 1 29 0 0
2011-09-14 20:28:30.023557 I [1712/1813] TVRecEvent tv_rec.cpp:1494 (HandlePendingRecordings) - TVRec(2): ASK_RECORDING 2 29 0 0
2011-09-14 20:28:59.081080 I [1712/1813] TVRecEvent tv_rec.cpp:992 (HandleStateChange) - TVRec(2): Changing from None to RecordingOnly
2011-09-14 20:28:59.081486 I [1712/1813] TVRecEvent mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager260
2011-09-14 20:28:59.081553 I [1712/1813] TVRecEvent mythdbcon.cpp:298 (popConnection) - New DB connection, total: 16
2011-09-14 20:28:59.082725 I [1712/1813] TVRecEvent mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:28:59.085835 I [1712/1813] TVRecEvent tv_rec.cpp:3434 (TuningCheckForHWChange) - TVRec(2): HW Tuner: 2->2
2011-09-14 20:29:00.230284 N [1712/1819] Scheduler autoexpire.cpp:263 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2011-09-14 20:29:00.230395 I [1712/1819] Scheduler scheduler.cpp:2466 (HandleRecordingStatusChange) - Tuning recording: "Planet Dinosaur":"Lost World": channel 1050 on cardid 2, sourceid 1
2011-09-14 20:29:00.748025 E [1712/3182] ProcessRequest programinfo.cpp:2158 (GetPlaybackURL) - ProgramInfo(1050_20110914202900.mpg): GetPlaybackURL: '1050_20110914202900.mpg' should be local, but it can not be found.
2011-09-14 20:29:00.925314 E [1712/3182] ProcessRequest programinfo.cpp:2158 (GetPlaybackURL) - ProgramInfo(1050_20110914202900.mpg): GetPlaybackURL: '1050_20110914202900.mpg' should be local, but it can not be found.
2011-09-14 20:29:01.104186 E [1712/3182] ProcessRequest programinfo.cpp:2158 (GetPlaybackURL) - ProgramInfo(1050_20110914202900.mpg): GetPlaybackURL: '1050_20110914202900.mpg' should be local, but it can not be found.
2011-09-14 20:29:01.600278 E [1712/3141] DVBRead dtvsignalmonitor.cpp:302 (HandlePAT) - DTVSM(/dev/dvb/adapter101/frontend0): Program #25792 not found in PAT!
Program Association Table
PSIP tableID(0x0) length(29) extension(0x4084)
version(5) current(1) section(0) last_section(0)
tsid: 16516
programCount: 5
program number 0 has PID 0x 10 data 0x 0 0x 0 0xe0 0x10
program number 17472 has PID 0x 64 data 0x44 0x40 0xe0 0x64
program number 17540 has PID 0x19c8 data 0x44 0x84 0xf9 0xc8
program number 17604 has PID 0x c8 data 0x44 0xc4 0xe0 0xc8
program number 17664 has PID 0x 12c data 0x45 0x 0 0xe1 0x2c
2011-09-14 20:29:02.046931 E [1712/3141] DVBRead mpeg/mpegstreamdata.cpp:783 (ProcessPAT) - ProcessPAT: Program not found in PAT.
Rescan your transports.
2011-09-14 20:29:02.047113 E [1712/3141] DVBRead mpeg/mpegstreamdata.cpp:418 (CreatePATSingleProgram) - Desired program #25792 not found in PAT.
Cannot create single program PAT.
2011-09-14 20:29:03.216700 I [1712/1712] CoreContext scheduler.cpp:611 (UpdateRecStatus) - Updating status for "Planet Dinosaur":"Lost World" on cardid 2 (Tuning => Recording)
2011-09-14 20:29:03.293397 I [1712/1813] TVRecEvent tv_rec.cpp:3948 (TuningNewRecorder) - TVRec(2): rec->GetPathname(): '/mythtv/store/1050_20110914202900.mpg'
2011-09-14 20:29:03.403174 I [1712/3141] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager254'
2011-09-14 20:29:36.747243 I [1712/3149] PT34 mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager257'
2011-09-14 20:30:26.025162 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id 0.
2011-09-14 20:30:26.989988 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Playback
2011-09-14 20:30:26.990094 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 0)
2011-09-14 20:30:26.992759 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Monitor
2011-09-14 20:30:26.992800 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 1)
2011-09-14 20:30:28.129271 E [1712/3230] PreviewGenerator previewgenerator.cpp:253 (Run) - Preview: Encountered problems running '/usr/local/bin/mythpreviewgen --size 0x0 --chanid 1050 --starttime 20110914202900 --verbose general --loglevel info --quiet --nodblog' (128)
2011-09-14 20:30:29.031219 I [1712/3228] DeleteThread mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager261
2011-09-14 20:30:29.031344 I [1712/3228] DeleteThread mythdbcon.cpp:298 (popConnection) - New DB connection, total: 15
2011-09-14 20:30:29.033058 I [1712/3228] DeleteThread mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:30:29.819128 I [1712/3144] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager255'
2011-09-14 20:30:31.660532 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 5.6 = 0.00 match + 5.55 place
2011-09-14 20:30:32.340423 I [1712/3242] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager262
2011-09-14 20:30:32.340496 I [1712/3242] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 15
2011-09-14 20:30:32.341592 I [1712/3242] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:30:35.498184 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id 0.
2011-09-14 20:30:37.165623 E [1712/1810] TVRecEvent dtvchannel.cpp:251 (SetChannelByString) - DTVChan(/dev/dvb/adapter101/frontend0): SetChannelByString(82): Requested channel '82' is not available because the tuner is currently in use on another transport.
2011-09-14 20:30:37.165669 E [1712/1810] TVRecEvent tv_rec.cpp:3638 (TuningFrequency) - TVRec(1): Failed to set channel to 82. Reverting to kState_None
2011-09-14 20:30:41.461181 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 5.9 = 0.00 match + 5.87 place
2011-09-14 20:32:18.415327 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:32:35.499210 I [1712/3228] PT37 mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager261'
2011-09-14 20:33:08.707691 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id -1.
2011-09-14 20:33:17.671976 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 8.9 = 3.18 match + 5.69 place
2011-09-14 20:35:36.678592 I [1712/3242] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager262'
2011-09-14 20:35:38.975752 I [1712/3251] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager263
2011-09-14 20:35:38.975825 I [1712/3251] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 14
2011-09-14 20:35:38.976999 I [1712/3251] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:36:41.029285 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id -1.
2011-09-14 20:36:49.800676 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 8.7 = 3.18 match + 5.50 place
2011-09-14 20:37:18.423213 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:40:43.840557 I [1712/3251] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager263'
2011-09-14 20:40:46.405465 I [1712/3254] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager264
2011-09-14 20:40:46.405543 I [1712/3254] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 14
2011-09-14 20:40:46.406692 I [1712/3254] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:42:25.430457 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:43:28.460751 N [1712/1822] Expire autoexpire.cpp:263 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2011-09-14 20:45:50.682162 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id -1.
2011-09-14 20:45:50.951984 I [1712/3254] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager264'
2011-09-14 20:45:52.110368 I [1712/3257] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager265
2011-09-14 20:45:52.110443 I [1712/3257] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 14
2011-09-14 20:45:52.111661 I [1712/3257] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:45:59.540858 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 8.8 = 3.19 match + 5.57 place
2011-09-14 20:47:28.437907 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:50:58.118713 I [1712/3257] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager265'
2011-09-14 20:51:00.333563 I [1712/3262] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager266
2011-09-14 20:51:00.333635 I [1712/3262] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 14
2011-09-14 20:51:00.334929 I [1712/3262] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:52:35.445993 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:56:05.221408 I [1712/3262] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager266'
2011-09-14 20:56:06.978428 I [1712/3265] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager267
2011-09-14 20:56:06.978503 I [1712/3265] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 14
2011-09-14 20:56:06.979632 I [1712/3265] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:57:25.217654 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id -1.
2011-09-14 20:57:28.700708 N [1712/1822] Expire autoexpire.cpp:263 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2011-09-14 20:57:33.904081 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 8.6 = 3.09 match + 5.51 place
2011-09-14 20:57:36.454356 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 20:58:34.683499 I [1712/1813] TVRecEvent tv_rec.cpp:1494 (HandlePendingRecordings) - TVRec(2): ASK_RECORDING 2 25 0 0
2011-09-14 20:58:34.693797 I [1712/1810] TVRecEvent tv_rec.cpp:1494 (HandlePendingRecordings) - TVRec(1): ASK_RECORDING 1 25 0 0
2011-09-14 20:58:59.041808 I [1712/1810] TVRecEvent tv_rec.cpp:992 (HandleStateChange) - TVRec(1): Changing from None to RecordingOnly
2011-09-14 20:58:59.045346 I [1712/1810] TVRecEvent tv_rec.cpp:3434 (TuningCheckForHWChange) - TVRec(1): HW Tuner: 1->1
2011-09-14 20:58:59.259586 I [1712/3270] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager268
2011-09-14 20:58:59.259701 I [1712/3270] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 15
2011-09-14 20:58:59.260846 I [1712/3270] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 20:58:59.504454 N [1712/1819] Scheduler autoexpire.cpp:263 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min
2011-09-14 20:58:59.504520 I [1712/1819] Scheduler scheduler.cpp:2466 (HandleRecordingStatusChange) - Tuning recording: "Grand Designs": channel 1052 on cardi
d 1, sourceid 1
2011-09-14 20:59:00.130283 E [1712/3182] ProcessRequest programinfo.cpp:2158 (GetPlaybackURL) - ProgramInfo(1052_20110914205900.mpg): GetPlaybackURL: '1052_20110914205900.mpg' should be local, but it can not be found.
2011-09-14 20:59:01.187785 I [1712/1712] CoreContext scheduler.cpp:611 (UpdateRecStatus) - Updating status for "Grand Designs" on cardid 1 (Tuning => Recording)
2011-09-14 20:59:01.359337 I [1712/1810] TVRecEvent tv_rec.cpp:3948 (TuningNewRecorder) - TVRec(1): rec->GetPathname(): '/mythtv/store/1052_20110914205900.mpg'
2011-09-14 20:59:02.433617 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Playback
2011-09-14 20:59:02.433663 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 0)
2011-09-14 20:59:02.437358 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Monitor
2011-09-14 20:59:02.437401 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 1)
2011-09-14 21:00:02.938734 I [1712/1819] Scheduler scheduler.cpp:2018 (HandleReschedule) - Reschedule requested for id -1.
2011-09-14 21:00:12.870247 I [1712/1819] Scheduler scheduler.cpp:2076 (HandleReschedule) - Scheduled 282 items in 9.8 = 3.35 match + 6.47 place
2011-09-14 21:00:49.068465 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Playback
2011-09-14 21:00:49.068514 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 0)
2011-09-14 21:00:49.070896 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Monitor
2011-09-14 21:00:49.070941 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 1)
2011-09-14 21:00:54.294589 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Playback
2011-09-14 21:00:54.294639 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 0)
2011-09-14 21:00:54.299362 I [1712] ProcessRequest mainserver.cpp:1256 (HandleAnnounce) - MainServer::ANN Monitor
2011-09-14 21:00:54.299402 I [1712] ProcessRequest mainserver.cpp:1258 (HandleAnnounce) - adding: accordian.watkinscheung.co.uk as a client (events: 1)
2011-09-14 21:01:12.338232 I [1712/3265] DVBRead mythdbcon.cpp:479 (CloseDatabases) - Closing DB connection named 'DBManager267'
2011-09-14 21:01:14.300435 I [1712/3326] DVBRead mythdbcon.cpp:75 (MSqlDatabase) - Database connection created: DBManager269
2011-09-14 21:01:14.300508 I [1712/3326] DVBRead mythdbcon.cpp:298 (popConnection) - New DB connection, total: 15
2011-09-14 21:01:14.301706 I [1712/3326] DVBRead mythdbcon.cpp:179 (OpenDatabase) - Connected to database 'mythconverg' at host: localhost
2011-09-14 21:02:41.461510 I [1712/1821] HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2011-09-14 21:03:00.058229 I [1712/1813] TVRecEvent tv_rec.cpp:992 (HandleStateChange) - TVRec(2): Changing from RecordingOnly to None
2011-09-14 21:03:00.100506 I [1712/1712] CoreContext scheduler.cpp:611 (UpdateRecStatus) - Updating status for "Planet Dinosaur":"Lost World" on cardid 2 (Recording => Recorded)
2011-09-14 21:03:00.105576 I [1712/1813] TVRecEvent recordinginfo.cpp:1104 (FinishedRecording) - Finished recording Planet Dinosaur "Lost World": channel 1050
More information about the mythtv-users
mailing list