[mythtv-commits] Ticket #10802: Error Log Information Missing
MythTV
noreply at mythtv.org
Tue Jun 12 16:34:59 UTC 2012
#10802: Error Log Information Missing
----------------------------------+----------------------------
Reporter: ewilde@… | Owner: danielk
Type: Bug Report - General | Status: new
Priority: minor | Milestone: unknown
Component: MythTV - Recording | Version: 0.25-fixes
Severity: medium | Resolution:
Keywords: | Ticket locked: 0
----------------------------------+----------------------------
Changes (by ewilde@…):
* status: closed => new
* resolution: Need more Info =>
Comment:
I looked at the following logs, at the time of the problem:
auth.log
dmesg
faillog
kern.log
mysql.err
mysql.log
all of the other mythtv logs (you saw the backend log)
syslog
upstart/mythtv-backend.log
There were no problems, although I did see the following in the backend
log, about 2-1/2 hours after the problem occurred:
Jun 5 09:29:42 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e7b
Jun 5 09:29:44 mythbackend[1639]: last message repeated 6 times
Jun 5 09:29:44 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e7c
Jun 5 09:29:45 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e7d
Jun 5 09:29:46 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e7e
Jun 5 09:29:47 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e7f
Jun 5 09:29:48 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1e80
Jun 5 09:29:49 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x0
Jun 5 09:29:50 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x1
Jun 5 09:29:51 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x30
Jun 5 09:29:52 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d01
Jun 5 09:29:53 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d02
Jun 5 09:29:54 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d03
Jun 5 09:29:55 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d04
Jun 5 09:29:56 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x0
Jun 5 09:29:57 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x1
Jun 5 09:29:58 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x30
Jun 5 09:29:59 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d01
Jun 5 09:30:00 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d02
Jun 5 09:30:01 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d03
Jun 5 09:30:02 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d04
Jun 5 09:30:03 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x0
Jun 5 09:30:04 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid 0x1
Jun 5 09:30:05 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x30
Jun 5 09:30:06 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d01
Jun 5 09:30:07 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d02
Jun 5 09:30:08 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d03
Jun 5 09:30:09 keck mythbackend[1639]: E DVBRead
dvbstreamhandler.cpp:608 (Open) PIDInfo(/dev/dvb/adapter0/frontend0):
Failed to open demux device /dev/dvb/adapter0/demux0 for filter on pid
0x1d04
.
.
.
The hard drive is brand new and, at the time, had been up and spinning for
about 5 days. I dumped the SMART information:
overall-health self-assessment test: Passed
error log version: 1, No errors logged
Then, I ran the short offline test:
completed without error
So, there doesn't appear to be anything wrong.
Regardless, I'm not sure I understand your point about creating log
entries for all problems. There is no entry saying that the encoder is
ending the recording, for example. There should be one because knowing
when it did end would be helpful for debugging purposes (was it 1 second
or 60). You are assuming that it was after three minutes, which could
cause you to go looking for red herrings, like tuningTimeout. But nowhere
is there an actual log entry saying that the recording ends after 3
minutes. What there is is a log entry that says the state was changed
from RecordingOnly to None, which we are to assume happened right after
the encoder gave up. My experience with event notifications is that
sometimes they happen promptly and sometimes they don't. I much prefer a
hard entry from the guy who ended things saying what the status was (e.g.
"Tuning ended, on encoder blah, bytes captured blah, bytes written to disk
blah, encoder flags blah, done because end time reached [or whatever]").
Then you'll see the state change following it at some point in time.
And, if there is a recording in progress, I don't see how it can end
recording without there being any kind of error code. Somebody must be
copying bytes from the encoder to the hard disk. Did this task not get
any bytes from the encoder? Why? Did it fail to write to the disk? Why?
Did the file not get created because of security problems?
I generally write an entry to the log file at every exit from the code, no
matter how trivial it seems it may be. The text is different (even if
only slightly) so that it is easy search for it. Also, every state
change. And, I usually dump the byte traffic, file names and values being
set into the device, so that I can see if it got set up correctly, did its
work OK and where it was trying to put things.
Transient errors like this one appears to be will only get resolved by
good log information. When you don't know what's going wrong, the more,
the better. And, if that logging code's already in there, let me know how
to turn it on and I'll be happy to run with it enabled for the next six
months....
--
Ticket URL: <http://code.mythtv.org/trac/ticket/10802#comment:4>
MythTV <http://code.mythtv.org/trac>
MythTV Media Center
More information about the mythtv-commits
mailing list