[mythtv-users] Many recordings fail and then succeed a second later
Ross Boylan
rossboylan at stanfordalumni.org
Sat Jan 18 22:06:46 UTC 2020
Running mythtv 30 with HDHR Dual tuner in the US. Often the server
attempts to record a show, fails to get a lock, and then a second attempt
succeeds. The failed recordings still show on the myth client as 0 byte
files. The associated file name does not exist on disk, generating
further, recurring complaints on the log. The logs also show many "failed
to get lock" messages, apparently while doing a scan. Even when I'm not
recording there is steady traffic from the tuner to the server, which seems
odd.
Less commonly, the recordings just fail.
There are no other devices through which we try to access the tuner,
although there are other devices on the network and I suppose they could be
engaging in some kind of interactions with the tuner (zeroconf?). I use
schedules direct, but did also try to get schedule info OTA.
I think I may have created too many card inputs, and wonder if this could
be related to some of the problems. Here's what I think is the key info
from the capturecard table, emphasizing columns that differed between cards
or were non-NULL or 0:
| cardid | parentid | cardtype | defaultinput | hostname |
dvb_wait_for_seqstart | dvb_diseqc_type | signal_timeout | channel_timeout
| diseqcid | dvb_eitscan | sourceid | startchan | displayname | schedorder
| reclimit | schedgroup |
+--------+----------+-----------+--------------+----------+-----------------------+-----------------+----------------+-----------------+----------+-------------+----------+-----------+--------------+------------+----------+------------+
| 1 | 0 | HDHOMERUN | Television | barley |
1 | NULL | 1000 | 3000 | NULL |
1 | 2 | 36_4 | antenna | 1 | 2 |
1 |
| 2 | 1 | HDHOMERUN | Television | barley |
1 | 0 | 1000 | 3000 | 0 |
1 | 2 | 7_1 | antenna | 0 | 2 |
0 |
| 3 | 0 | HDHOMERUN | Television | barley |
1 | NULL | 1000 | 3000 | NULL |
0 | 2 | 36_4 | HDHR tuner 2 | 1 | 2 |
1 |
| 4 | 3 | HDHOMERUN | Television | barley |
1 | 0 | 1000 | 3000 | 0 |
0 | 2 | 36_2 | HDHR tuner 2 | 0 | 2 |
0 |
+--------+----------+-----------+--------------+----------+-----------------------+-----------------+----------------+-----------------+----------+-------------+----------+-----------+--------------+------------+----------+------------+
videosource has only 1 entry:
| sourceid | name | xmltvgrabber | userid | freqtable | lineupid |
password | useeit | configpath | dvb_nit_id |
+----------+--------+-------------------+--------+-----------+----------+----------+--------+------------+------------+
| 2 | sdjson | tv_grab_zz_sdjson | | default | NULL |
NULL | 1 | NULL | -1 |
+----------+--------+-------------------+--------+-----------+----------+----------+--------+------------+------------+
My intention was to be able to use both tuners, recording up to 2 shows on
each tuner (e.g., 9.1 and 9.2).
Here's a typical log section for one of these failed/succeeded recordings.
# for comments:
2020-01-14 15:58:00.140392 I [3238/3258] TVRecEvent tv_rec.cpp:1091
(HandleStateChange) - TVRec[1]: Changing from None to RecordingOnly
2020-01-14 15:58:00.140986 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
2020-01-14 15:58:00.145173 E [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:468 (TunerSet) - HDHRSH[1](10424297):
DeviceSet(channel 8vsb:563000000): ERROR: lock no longer held
2020-01-14 15:58:00.145178 E [3238/3258] TVRecEvent
recorders/dtvchannel.cpp:303 (SetChannelByString) - DTVChan[1](10424297):
SetChannelByString(5_2): Tuning to frequency.
2020-01-14 15:58:00.145184 E [3238/3258] TVRecEvent tv_rec.cpp:3758
(TuningFrequency) - TVRec[1]: Failed to set channel to 5_2. Reverting to
kState_None
2020-01-14 15:58:00.145197 I [3238/3258] TVRecEvent tv_rec.cpp:1091
(HandleStateChange) - TVRec[1]: Changing from RecordingOnly to None
2020-01-14 15:58:00.148222 I [3238/3238] CoreContext scheduler.cpp:730
(UpdateRecStatus) - Updating status for "Cold Case":Daniela on cardid [1]
(Pending => Recorder Failed)
# unclear to me why it is an error at this point (i.e., after we've given
up) that the lock is no longer held.
2020-01-14 15:58:00.150643 E [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:468 (TunerSet) - HDHRSH[1](10424297):
DeviceSet(channel none): ERROR: lock no longer held
2020-01-14 15:58:00.167410 I [3238/4383] Scheduler scheduler.cpp:2937
(HandleRecordingStatusChange) - Tuning recording: "Cold Case":Daniela:
channel 20502 on cardid [1], sourceid 2
2020-01-14 15:58:00.168539 I [3238/4383] Scheduler scheduler.cpp:2357
(HandleReschedule) - Reschedule requested for CHECK -9 465 737647
UpdateRecStatus2 | Cold Case | Daniela | Daniela: Lilly receives a home
movie in which a runaway teen is apparently shot and killed, prompting her
to take another look at the 1979 case. | EP005927270026
# maybe next line is attempt to lookup failed recording?
2020-01-14 15:58:00.218005 C [3238/3238] CoreContext programinfo.cpp:347
(ProgramInfo) - ProgramInfo(): Failed to find recorded entry for 0.
2020-01-14 15:58:00.240907 E [3238/4383] Scheduler recordinginfo.cpp:1073
(InsertProgram) -
RecordingInfo::InsertProgram(ProgramInfo(20502_20200114235800.ts):
channame(StartTV) startts(Wed Jan 15 00:00:00 2020 GMT) endts(Wed Jan 15
01:00:00 2020 GMT)
recstartts(Tue Jan 14 23:58:00 2020 GMT) recendts(Wed Jan 15
01:00:00 2020 GMT)
title(Cold Case)): recording already exists...
# apparent start of 2nd recording attempt
2020-01-14 15:58:00.244578 I [3238/3258] TVRecEvent tv_rec.cpp:1091
(HandleStateChange) - TVRec[1]: Changing from None to RecordingOnly
2020-01-14 15:58:00.244739 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
# why is it adding devices that have been there all along?
2020-01-14 15:58:00.260951 I [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:378 (Connect) - HDHRSH[1](10424297): Added
2 devices from 10424297
2020-01-14 15:58:00.279216 I [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:396 (Connect) - HDHRSH[1](10424297):
Connected to device(10424297-0)
2020-01-14 15:58:00.387953 E [3238/4383] Scheduler scheduler.cpp:793
(ChangeRecordingEnd) - Failed to change end time on card 1 to
2020-01-15T01:00:00Z
2020-01-14 15:58:00.402869 I [3238/4383] Scheduler scheduler.cpp:2473
(HandleReschedule) - Scheduled 533 items in 0.2 = 0.00 match + 0.00 check +
0.18 place
#success
2020-01-14 15:58:01.210772 I [3238/3238] CoreContext scheduler.cpp:730
(UpdateRecStatus) - Updating status for "Cold Case":Daniela on cardid [1]
(Tuning => Recording)
2020-01-14 15:58:01.275394 I [3238/3258] TVRecEvent tv_rec.cpp:4229
(TuningNewRecorder) - TVRec[1]: rec->GetPathname():
'/srv/media10/media10-barley/20502_20200114235801.ts'
2020-01-14 15:58:01.275518 I [3238/3258] TVRecEvent tv_rec.cpp:4261
(TuningNewRecorder) - TVRec[1]: TuningNewRecorder - CreateRecorder()
2020-01-14 15:58:01.275533 E [3238/3258] TVRecEvent
recorders/recorderbase.cpp:231 (SetStrOption) - RecBase[1](10424297):
SetStrOption(...recordingtype): Option not in profile.
#next lines are looking for filename original recording attempt should have
created, ending in 00.ts
# the second try ends in 01.ts
2020-01-14 15:58:21.688934 E [3238/4386] JobQueue programinfo.cpp:2781
(GetPlaybackURL) - ProgramInfo(20502_20200114235800.ts): GetPlaybackURL:
'20502_20200114235800.ts' should be local, but it can not be found.
2020-01-14 15:58:21.689666 E [3238/4386] JobQueue programinfo.cpp:2781
(GetPlaybackURL) - ProgramInfo(20502_20200114235800.ts): GetPlaybackURL:
'20502_20200114235800.ts' should be local, but it can not be found.
2020-01-14 15:58:21.691430 I [3238/12634] Metadata_9022 jobqueue.cpp:2218
(DoMetadataLookupThread) - JobQueue: Metadata Lookup Starting for "Cold
Case":Daniela recorded from channel 20502 at 2020-01-14T23:58:00Z
Example of apparent failed channel scans:
2020-01-14 14:45:50.301669 E [3238/3258] TVRecEvent tv_rec.cpp:3974
(TuningSignalCheck) - TVRec[1]: TuningSignalCheck: SignalMonitor timed out
2020-01-14 14:45:50.310361 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
2020-01-14 14:45:50.310372 E [3238/3258] TVRecEvent tv_rec.cpp:3758
(TuningFrequency) - TVRec[1]: Failed to set channel to . Reverting to
kState_None
2020-01-14 14:48:16.325407 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
2020-01-14 14:48:16.328409 E [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:468 (TunerSet) - HDHRSH[1](10424297):
DeviceSet(channel 8vsb:207000000): ERROR: lock no longer held
2020-01-14 14:48:16.328411 E [3238/3258] TVRecEvent
recorders/dtvchannel.cpp:303 (SetChannelByString) - DTVChan[1](10424297):
SetChannelByString(11_1): Tuning to frequency.
2020-01-14 14:48:16.328413 E [3238/3258] TVRecEvent tv_rec.cpp:3758
(TuningFrequency) - TVRec[1]: Failed to set channel to 11_1. Reverting to
kState_None
2020-01-14 14:51:49.348529 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
2020-01-14 14:51:49.353559 E [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:468 (TunerSet) - HDHRSH[1](10424297):
DeviceSet(channel 8vsb:563000000): ERROR: lock no longer held
2020-01-14 14:51:49.353572 E [3238/3258] TVRecEvent
recorders/dtvchannel.cpp:303 (SetChannelByString) - DTVChan[1](10424297):
SetChannelByString(5_1): Tuning to frequency.
2020-01-14 14:51:49.353584 E [3238/3258] TVRecEvent tv_rec.cpp:3758
(TuningFrequency) - TVRec[1]: Failed to set channel to 5_1. Reverting to
kState_None
2020-01-14 14:54:19.368540 I [3238/3258] TVRecEvent tv_rec.cpp:3680
(TuningFrequency) - TVRec[1]: TuningFrequency
2020-01-14 14:54:19.371222 E [3238/3258] TVRecEvent
recorders/hdhrstreamhandler.cpp:468 (TunerSet) - HDHRSH[1](10424297):
DeviceSet(channel 8vsb:593000000): ERROR: lock no longer held
2020-01-14 14:54:19.371224 E [3238/3258] TVRecEvent
recorders/dtvchannel.cpp:303 (SetChannelByString) - DTVChan[1](10424297):
SetChannelByString(66_3): Tuning to frequency.
2020-01-14 14:54:19.371226 E [3238/3258] TVRecEvent tv_rec.cpp:3758
(TuningFrequency) - TVRec[1]: Failed to set channel to 66_3. Reverting to
kState_None
Example of recurring complaints, apparently caused by missing files:
2020-01-14 20:34:36.103096 E [3238/26349] ProcessRequest
programinfo.cpp:2781 (GetPlaybackURL) -
ProgramInfo(23604_20190521175800.ts): GetPlaybackURL:
'23604_20190521175800.ts' should be local, but it can not be found.
2020-01-14 20:34:36.103423 E [3238/26349] ProcessRequest
programinfo.cpp:2781 (GetPlaybackURL) -
ProgramInfo(22001_20190522025800.ts): GetPlaybackURL:
'22001_20190522025800.ts' should be local, but it can not be found.
2020-01-14 20:34:36.103779 E [3238/26349] ProcessRequest
programinfo.cpp:2781 (GetPlaybackURL) -
ProgramInfo(20502_20190522195800.ts): GetPlaybackURL:
'20502_20190522195800.ts' should be local, but it can not be found.
2020-01-14 20:34:36.104099 E [3238/26349] ProcessRequest
programinfo.cpp:2781 (GetPlaybackURL) -
ProgramInfo(24403_20190523075800.ts): GetPlaybackURL:
'24403_20190523075800.ts' should be local, but it can not be found.
2020-01-14 20:34:36.104742 E [3238/26349] ProcessRequest
programinfo.cpp:2781 (GetPlaybackURL) -
ProgramInfo(20502_20190525195800.ts): GetPlaybackURL:
'20502_20190525195800.ts' should be local, but it can not be found.
There are many more of both types of complaints, both in the sense of
involving more targets (channels or files) and in the sense that they recur
repeatedly.
Thanks for any help.
Ross
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20200118/b1fd0567/attachment.htm>
More information about the mythtv-users
mailing list