[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