Opened 14 years ago

Closed 12 years ago

#7251 closed defect (Invalid)

silent mythbackend failure has suddenly returned (possibly EIT stream related)

Reported by: Marc Randolph <mrand@…> Owned by: Janne Grunau
Priority: minor Milestone: unknown
Component: MythTV - General Version: head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

This is a long standing bug (was present well back into 0.21) that comes and goes for a group of people using EIT. The past few nights (since the great-retune event of 2009), it has reappeared on a trunk 0.22 system. Since it is a silent failure (no back trace) we're not sure how to debug this further than just collecting a backend log.

If you know what to look for and start searching, it is obvious that a number of people have run into this off and on over the past 18 months, and that I can find, none have resolved it:

http://www.gossamer-threads.com/lists/mythtv/users/340705 http://www.gossamer-threads.com/lists/mythtv/users/377245 http://www.gossamer-threads.com/lists/mythtv/users/393125 Then we have the three people here: https://bugs.launchpad.net/bugs/330272 This is possibly the same: Bug #4993 As might this be: Bug #5739

What appears to happen is that things run fine for a while (some number of hours), and at some point, "QSqlQuery::exec: empty query" starts appearing in the mythtvbackend.log. Sometime later, it devolves further into messages about database errors, yet the users have verified that the database is fine, as is the command sent to it.

This is a snip of a 0.21 log file with -v important,eit,siparser (we are attempting to get a 0.22 log and will attach that when it arrives):

2009-08-31 17:01:10.587 EITCache: Wrote 1 modified entries of 255 for channel 2734 to database. 2009-08-31 17:01:11.264 EITScanner (1): Now looking for EIT data on multiplex of channel 12 2009-08-31 17:01:11.265 EITCache: Pruning all entries that ended before UTC 2009-08-30T17:06:31 2009-08-31 17:01:11.425 EITCache: Deleting old cache entries from the database 2009-08-31 17:01:11.732 Created PMT Program Map Table ver(20) pid(0x3eb) pnum(1) len(67)

Stream #0 pid(0x12d) type(video-mpeg2 0x2) Stream Identifier Descriptor (0x52) length(1) Stream #1 pid(0x12e) type(audio-mp2-layer[1,2,3] 0x4) Stream Identifier Descriptor (0x52) length(1) ISO-639 Language: code(eng) canonical(eng) eng(English) Stream #2 pid(0x130) type(audio-mp2-layer[1,2,3] 0x4) Stream Identifier Descriptor (0x52) length(1) ISO-639 Language: code(eng) canonical(eng) eng(English) Stream #3 pid(0x12f) type(private-data 0x6) Stream Identifier Descriptor (0x52) length(1) Subtitling Descriptor (0x59) length(8)

2009-08-31 17:01:12.187 PESPacket: Failed CRC check 0x22160113 != 0xc3bfa4b5 for StreamID = 0x70 2009-08-31 17:01:12.231 EITScanner (1): Started passive scan. 2009-08-31 17:01:12.678 EITHelper: Added 2 events 2009-08-31 17:01:13.118 EITHelper: Added 2 events 2009-08-31 17:01:13.186 PESPacket: Failed CRC check 0x22160114 != 0xc3bfa4b5 for StreamID = 0x70 2009-08-31 17:01:13.590 EITHelper: Added 3 events 2009-08-31 17:01:14.038 EITHelper: Added 3 events QSqlQuery::exec: empty query QSqlQuery::exec: empty query

.... this goes on for a long while, along with other EIT related log messages, until finally the empty queries give way to the dreaded DB Error event occurs at a seemingly random spot (because the DB Error varies across users):

QSqlQuery::exec: empty query QSqlQuery::exec: empty query QSqlQuery::exec: empty query 222yyyy-22MM-22dd 22hh:22mm:22ss.22zzz DB Error (Update next_record):

The actual DB Error varies... "Looking up chanID" is another favorite. More complete logs are available on the launchpad bug referenced above.

As I mentioned, users have verified that the database is fine, as is the command sent to it. The corrupted date causes me to suspect there is no database error at all, but rather a corruption (bogus pointer?) occurring within the EIT code that manages to stomp on unrelated things.

Are there any ideas on how we can help narrow this down further, or what might be causing it?

Much, much more can be found here, along with a full (at present, 0.21) log:

https://bugs.launchpad.net/bugs/330272

Change History (4)

comment:1 Changed 14 years ago by Marc Randolph <mrand@…>

Crap. Hate trac's automatic reformating. Here is the important part:

2009-08-31 17:01:10.587 EITCache: Wrote 1 modified entries of 255 for
channel 2734 to database.
2009-08-31 17:01:11.264 EITScanner (1): Now looking for EIT data on
multiplex of channel 12
2009-08-31 17:01:11.265 EITCache: Pruning all entries that ended
before UTC 2009-08-30T17:06:31
2009-08-31 17:01:11.425 EITCache: Deleting old cache entries from the database
2009-08-31 17:01:11.732 Created PMT
Program Map Table ver(20) pid(0x3eb) pnum(1) len(67)

Stream #0 pid(0x12d) type(video-mpeg2 0x2)
Stream Identifier Descriptor (0x52) length(1)
Stream #1 pid(0x12e) type(audio-mp2-layer[1,2,3] 0x4)
Stream Identifier Descriptor (0x52) length(1)
ISO-639 Language: code(eng) canonical(eng) eng(English)
Stream #2 pid(0x130) type(audio-mp2-layer[1,2,3] 0x4)
Stream Identifier Descriptor (0x52) length(1)
ISO-639 Language: code(eng) canonical(eng) eng(English)
Stream #3 pid(0x12f) type(private-data 0x6)
Stream Identifier Descriptor (0x52) length(1)
Subtitling Descriptor (0x59) length(8)

2009-08-31 17:01:12.187 PESPacket: Failed CRC check 0x22160113 !=
0xc3bfa4b5 for StreamID = 0x70
2009-08-31 17:01:12.231 EITScanner (1): Started passive scan.
2009-08-31 17:01:12.678 EITHelper: Added 2 events
2009-08-31 17:01:13.118 EITHelper: Added 2 events
2009-08-31 17:01:13.186 PESPacket: Failed CRC check 0x22160114 !=
0xc3bfa4b5 for StreamID = 0x70
2009-08-31 17:01:13.590 EITHelper: Added 3 events
2009-08-31 17:01:14.038 EITHelper: Added 3 events
QSqlQuery::exec: empty query
QSqlQuery::exec: empty query

.... this goes on for a long while, along with other EIT related log messages, until finally the empty queries give way to the dreaded DB
Error event occurs at a seemingly random spot (because the DB Error varies across users):

QSqlQuery::exec: empty query
QSqlQuery::exec: empty query
QSqlQuery::exec: empty query
222yyyy-22MM-22dd 22hh:22mm:22ss.22zzz DB Error (Update next_record):

The actual DB Error varies... "Looking up chanID" is another favorite. More complete logs are available on the launchpad bug referenced above.

comment:2 Changed 14 years ago by Janne Grunau

Milestone: 0.22unknown

The failed CRC check for StreamID 0x70 is unrelated, it is a EIT table without CRC but we check the CRC before we know that table it is.

The best way of debugging this would be a breakpoint at the code generating the "QSqlQuery::exec: empty query" message and posting backtraces if the debugger halts at this breakpointpoint.

comment:3 Changed 14 years ago by robertm

Owner: changed from Isaac Richards to Janne Grunau
Status: newassigned

comment:4 Changed 12 years ago by danielk

Resolution: Invalid
Status: assignedclosed

As mentioned by janne, we need a breakpoint at the query so we know where the empty query is coming from.

Note: See TracTickets for help on using tickets.