Opened 7 years ago

Closed 7 years ago

#10802 closed Bug Report - General (Need more Info)

Error Log Information Missing

Reported by: ewilde@… Owned by: danielk
Priority: minor Milestone: unknown
Component: MythTV - Recording Version: 0.25-fixes
Severity: medium Keywords:
Cc: Ticket locked: no

Description (last modified by Raymond Wagner)

In MythTV 0.25, when a recording fails, the information logged in the backend log is absolutely useless at figuring out what the problem is. Here is an example:

Jun  5 06:59:33 keck mythbackend[1639]: I TVRecEvent tv_rec.cpp:1518 (HandlePendingRecordings) TVRec(6): ASK_RECORDING 6 29 0 0
Jun  5 07:00:06 keck mythbackend[1639]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 10
Jun  5 07:00:06 keck mythbackend[1639]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(6): Changing from None to RecordingOnly
Jun  5 07:00:06 keck mythbackend[1639]: I TVRecEvent tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(6): HW Tuner: 6->6
Jun  5 07:02:03 keck mythbackend[1639]: I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
Jun  5 07:03:05 keck mythbackend[1639]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(6): Changing from RecordingOnly to None
Jun  5 07:03:05 keck mythbackend[1639]: E ProcessRequest programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(5071_20120605070000.mpg): GetPlaybackURL: '5071_20120605070000.mpg' should be local, but it can not be found.
Jun  5 07:03:08 keck mythbackend[1639]: E DeleteThread mainserver.cpp:114 (delete_file_immediately) Error deleting 'GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/keck/5071_20120605070000.mpg': No such file or directory

When a problem occurs, the log file is supposed to be the place where you turn to diagnose it. What is shown here? That the recording started at 07:00:06 and that it stopped at 07:03:05 (it was supposed to run until 09:00:00)? That the housekeeping task couldn't find the recording file? What else? Did the tuner not get set up? Did it fail to get a lock? Do the major/minor channel numbers not match what's in the CVCT? Was there no space available? Were the file permissions wrong? Don't be shy. The log file already has plenty of stuff in it. Adding a little more, useful information isn't going to upset anybody. When a requested operation fails for any reason, the log file needs to contain copious information about what was going on and what went wrong.

Incidentally, I've marked the priority of this bug as major (but I know you'll disagree). When a recording fails and I can't figure out why, it is a major problem.

Change History (5)

comment:1 Changed 7 years ago by Raymond Wagner

Description: modified (diff)
Priority: majorminor
Version: Unspecified0.25-fixes

comment:2 Changed 7 years ago by Raymond Wagner

Doesn't matter if we disagree or not. Priority is up to the person fixing the issue. The ticket howto specifically states not to touch them.

comment:3 Changed 7 years ago by danielk

Resolution: Need more Info
Status: newclosed

I looked at this and can't locate any instance of a recording abort that doesn't log why it's aborting the recordings. The prime suspect was the tuningTimeout in scheduler.cpp, as that will give up after exactly 3 minutes, but this prints out a message to VB_GENERAL at the LOG_INFO level. So that would have displayed a message.

I understand your frustration, but unless you can track down the cause of why the recording didn't happen we won't be able to fix this. I realize it's a week later, but perhaps the kernel spit out some message about the driver failing? There are SMART warnings coming from your hard drive? Any lead would be helpful.

I'm closing this with the "Need more info" resolution, update the ticket with info if you have it and I'll take another look.

comment:4 Changed 7 years ago by ewilde@…

Resolution: Need more Info
Status: closednew

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....

comment:5 Changed 7 years ago by danielk

Resolution: Need more Info
Status: newclosed

Run with "-v record,channel" to get every recording and channel state change logged. For detailed logging increase the --loglevel from the default "info" to "debug". But info should be enough to track down this issue when it re-occurs. Please reopen then.

Note: See TracTickets for help on using tickets.