[mythtv-users] Myth failing to record. HDHR ...Resource temporarily unavailable

Tue Nov 13 17:07:13 UTC 2018

This morning found failed recordings and Myth non responsive to the
remote.  I rebooted and the remote started working but the recordings
showed failed. In Mythweb, the last recording of the evening shows a red
circle with a line through it showing "damaged". On mythfrontend it shows
displays in yellow. It plays back but stops before it should.  I put the
relevant parts of the log below.  One show at 2:30AM showed damaged and did
not record.  It has two entries and they show as gray with an x'ed out
circle.  GMA at 7AM showed two attempts at recording, one indicates 1 min
long, the other none.  All file sizes on the recordings this morning show
as "B".

After the reboot, Myth did not try and restart GMA and the schedule showed
"Failed" on the listings screen. I requested it be recorded and it worked
fine.  As this is the second time I had failures with the same "Resource
temporarily unavailable" messages in the log I thought it would be good to
fix it.  The recording incident at 2:32 this morning is documented in the
log below. I am unable to find anything on Google that is relevant.

A similar problem happened several weeks ago but that time I got pages and
pages of the same error message.  Specifically, the message would print
about 4 times a second for 20 minutes. This time I get the same message,
some repeated, nothing near as much.  This message, the one I got so much
of previously, is what I focused my search on Google

Nov 12 23:04:23 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)

When I rebooted, I did not power cycle the HDHR and they worked fine.

I have no idea what happened.

-----------------------Log for 11:59PM------------------------
Nov 12 22:59:13 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 22:59:29 NewMyth mythbackend: mythbackend[1137]: N Expire
autoexpire.cpp:251 (CalcParams) AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 14 min
Nov 12 22:59:29 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 22:59:48 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 22:59:50 NewMyth mythbackend: mythbackend[1137]: I
MythSocketThread(98) mainserver.cpp:7656 (connectionClosed) Playback
sock(871ab60) 'NewMyth' disconnected
Nov 12 22:59:51 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 22:59:52 NewMyth mythbackend: mythbackend[1137]: I
MythSocketThread(92) mainserver.cpp:7656 (connectionClosed) Playback
sock(875ab10) 'NewMyth' disconnected
Nov 12 22:59:52 NewMyth mythbackend: mythbackend[1137]: I
MythSocketThread(94) mainserver.cpp:7656 (connectionClosed) Monitor
sock(8817e18) 'NewMyth' disconnected
Nov 12 22:59:52 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 22:59:53 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 23:00:02 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 23:00:03 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 23:00:03 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 23:04:23 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 12 23:09:01 NewMyth mythbackend: mythbackend[1137]: E HDHRStreamHandler
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)

------------------------LOG for 2:32AM-----------------------
Nov 13 02:30:11 NewMyth mythbackend: mythbackend[1137]: I ProcessRequest
mainserver.cpp:1730 (HandleAnnounce) MainServer: MainServer::ANN Playback
Nov 13 02:30:11 NewMyth mythbackend: mythbackend[1137]: I ProcessRequest
mainserver.cpp:1735 (HandleAnnounce) MainServer: adding: newmyth(8713ce0)
as a client (events: 0)
Nov 13 02:30:11 NewMyth mythbackend: mythbackend[1137]: I
MythSocketThread(84) mainserver.cpp:7694 (connectionClosed) FileTransfer
sock(863db68) disconnected
Nov 13 02:30:11 NewMyth mythbackend: mythbackend[1137]: I
MythSocketThread(68) mainserver.cpp:7656 (connectionClosed) Playback
sock(8713ce0) 'newmyth' disconnected
Nov 13 02:30:29 NewMyth mythbackend: mythbackend[1137]: N Expire
autoexpire.cpp:251 (CalcParams) AutoExpire: CalcParams(): Max required Free
Space: 1.0 GB w/freq: 15 min
Nov 13 02:31:00 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2269 (HandleReschedule) Reschedule requested for PLACE
PrepareToRecord
Nov 13 02:31:00 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2382 (HandleReschedule) Scheduled 63 items in 0.2 = 0.00
match + 0.00 check + 0.17 place
Nov 13 02:31:30 NewMyth mythbackend: mythbackend[1137]: I Scheduler
mythdbcon.cpp:422 (PurgeIdleConnections) New DB connection, total: 13
Nov 13 02:31:30 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1611 (HandlePendingRecordings) TVRec[4]: ASK_RECORDING 4 29 0 0
Nov 13 02:31:30 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1611 (HandlePendingRecordings) TVRec[3]: ASK_RECORDING 3 29 0 0
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: I CoreContext
mythdbcon.cpp:422 (PurgeIdleConnections) New DB connection, total: 13
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: C CoreContext
programinfo.cpp:351 (ProgramInfo) ProgramInfo(): Failed to find recorded
entry for 0.
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1074 (HandleStateChange) TVRec[3]: Changing from None to
RecordingOnly
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
mythdbcon.cpp:422 (PurgeIdleConnections) New DB connection, total: 13
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:3564 (TuningCheckForHWChange) TVRec[3]: HW Tuner: 3->3
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:3686 (TuningFrequency) TVRec[3]: TuningFrequency
Nov 13 02:32:00 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:382 (TunerGet) HDHRSH(10137DC1-1): Get
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/dtvchannel.cpp:310 (SetChannelByString) DTVChan[3](10137DC1-1):
SetChannelByString(7_1): Tuning to frequency.
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
tv_rec.cpp:3764 (TuningFrequency) TVRec[3]: Failed to set channel to 7_1.
Reverting to kState_None
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1074 (HandleStateChange) TVRec[3]: Changing from RecordingOnly
to None
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: I CoreContext
scheduler.cpp:725 (UpdateRecStatus) Updating status for Jeopardy!:"Teen
Tournament" on cardid 3 (Will Record => Recorder Failed)
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:382 (TunerGet) HDHRSH(10137DC1-1): Get
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2821 (HandleRecordingStatusChange) Tuning recording:
Jeopardy!:"Teen Tournament": channel 1071 on cardid 3, sourceid 1
Nov 13 02:32:01 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2269 (HandleReschedule) Reschedule requested for CHECK -9 3 0
UpdateRecStatus2 | Jeopardy! | Teen Tournament |  | EP000023484068
Nov 13 02:32:02 NewMyth mythbackend: mythbackend[1137]: E Scheduler
recordinginfo.cpp:1025 (InsertProgram)
RecordingInfo::InsertProgram(ProgramInfo(1071_20181113103200.ts):
channame(KGO-HD) startts(Tue Nov 13 10:32:00 2018 GMT) endts(Tue
 Nov 13 11:02:00 2018 GMT)#012             recstartts(Tue Nov 13 10:32:00
2018 GMT) recendts(Tue Nov 13 11:02:00 2018 GMT)#012
 title(Jeopardy!)): recording already exists...
Nov 13 02:32:02 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1074 (HandleStateChange) TVRec[3]: Changing from None to
RecordingOnly
Nov 13 02:32:02 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:3564 (TuningCheckForHWChange) TVRec[3]: HW Tuner: 3->3
Nov 13 02:32:02 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:3686 (TuningFrequency) TVRec[3]: TuningFrequency
Nov 13 02:32:02 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:382 (TunerGet) HDHRSH(10137DC1-1): Get
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/dtvchannel.cpp:310 (SetChannelByString) DTVChan[3](10137DC1-1):
SetChannelByString(7_1): Tuning to frequency.
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
tv_rec.cpp:3764 (TuningFrequency) TVRec[3]: Failed to set channel to 7_1.
Reverting to kState_None
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: I TVRecEvent
tv_rec.cpp:1074 (HandleStateChange) TVRec[3]: Changing from RecordingOnly
to None
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: I CoreContext
scheduler.cpp:725 (UpdateRecStatus) Updating status for Jeopardy!:"Teen
Tournament" on cardid 3 (Tuning => Recorder Failed)
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:382 (TunerGet) HDHRSH(10137DC1-1): Get
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E TVRecEvent
recorders/hdhrstreamhandler.cpp:421 (TunerSet) HDHRSH(10137DC1-1): Set
request failed#012#011#011#011eno: Resource temporarily unavailable (11)
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: E Scheduler
scheduler.cpp:787 (ChangeRecordingEnd) Failed to change end time on card 3
to 2018-11-13T11:02:00Z
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2373 (HandleReschedule) Reschedule interrupted, will retry
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2269 (HandleReschedule) Reschedule requested for CHECK -9 3 0
UpdateRecStatus2 | Jeopardy! | Teen Tournament |  | EP000023484068
Nov 13 02:32:03 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2269 (HandleReschedule) Reschedule requested for PLACE
Interrupted
Nov 13 02:32:04 NewMyth mythbackend: mythbackend[1137]: I Scheduler
scheduler.cpp:2382 (HandleReschedule) Scheduled 63 items in 0.1 = 0.00
match + 0.00 check + 0.13 place
Nov 13 02:32:05 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103200.ts):
GetPlaybackURL: '1071_20181113103200.ts' should be local, but it can not be
found.
Nov 13 02:32:05 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103200.ts):
GetPlaybackURL: '1071_20181113103200.ts' should be local, but it can not be
found.
Nov 13 02:32:05 NewMyth mythbackend: mythbackend[1137]: I Metadata_773
jobqueue.cpp:2157 (DoMetadataLookupThread) JobQueue: Metadata Lookup
Starting for Jeopardy!:"Teen Tournament" recorded from channel 1071 at
2018-11-13T10:32:00Z
Nov 13 02:32:10 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103201.ts):
GetPlaybackURL: '1071_20181113103201.ts' should be local, but it can not be
found.
Nov 13 02:32:10 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103201.ts):
GetPlaybackURL: '1071_20181113103201.ts' should be local, but it can not be
found.
Nov 13 02:32:10 NewMyth mythbackend: mythbackend[1137]: I Metadata_775
jobqueue.cpp:2157 (DoMetadataLookupThread) JobQueue: Metadata Lookup
Starting for Jeopardy!:"Teen Tournament" recorded from channel 1071 at
2018-11-13T10:32:01Z
Nov 13 02:32:15 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103200.ts):
GetPlaybackURL: '1071_20181113103200.ts' should be local, but it can not be
found.
Nov 13 02:32:15 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103200.ts):
GetPlaybackURL: '1071_20181113103200.ts' should be local, but it can not be
found.
Nov 13 02:32:15 NewMyth mythbackend: mythbackend[1137]: I Commflag_774
jobqueue.cpp:2282 (DoFlagCommercialsThread) JobQueue: Commercial Detection
Starting for Jeopardy!:"Teen Tournament" recorded from channel 1071 at
2018-11-13T10:32:00Z
Nov 13 02:32:16 NewMyth mythbackend: mythbackend[1137]: E Commflag_774
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103200.ts):
GetPlaybackURL: '1071_20181113103200.ts' should be local, but it can not be
found.
Nov 13 02:32:20 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103201.ts):
GetPlaybackURL: '1071_20181113103201.ts' should be local, but it can not be
found.
Nov 13 02:32:20 NewMyth mythbackend: mythbackend[1137]: E JobQueue
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103201.ts):
GetPlaybackURL: '1071_20181113103201.ts' should be local, but it can not be
found.
Nov 13 02:32:20 NewMyth mythbackend: mythbackend[1137]: I Commflag_776
jobqueue.cpp:2282 (DoFlagCommercialsThread) JobQueue: Commercial Detection
Starting for Jeopardy!:"Teen Tournament" recorded from channel 1071 at
2018-11-13T10:32:01Z
Nov 13 02:32:21 NewMyth mythbackend: mythbackend[1137]: E Commflag_776
programinfo.cpp:2616 (GetPlaybackURL) ProgramInfo(1071_20181113103201.ts):
GetPlaybackURL: '1071_20181113103201.ts' should be local, but it can not be
found.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20181113/8094b43b/attachment.html>