Opened 8 years ago
Closed 8 years ago
#12535 closed Bug Report - General (Upstream Bug)
Segmentation fault after starting livetv recording
Reported by: | Owned by: | JYA | |
---|---|---|---|
Priority: | major | Milestone: | 0.28 |
Component: | MythTV - Recording | Version: | 0.27.5 |
Severity: | medium | Keywords: | sigsegv segmentation fault segfault record |
Cc: | Ticket locked: | no |
Description
mythtv-backend segfaults after starting a recording of the current livetv program.
manually connecting to mysql and deleting contents of 'record' table will allow backend to start up again.
Contents of 'record' table which causes backend to segfault
mysql> select * from record \G *************************** 1. row *************************** recordid: 9 type: 1 chanid: 1004 starttime: 05:55:00 startdate: 2015-11-09 endtime: 06:50:00 enddate: 2015-11-09 title: Zoo Tales Special 3 (7) subtitle: description: Australian suurin vauva. Melbournen eläintarhaan on syntymässä toinen norsunpoikanen. Synnytys ei kuitenkaan suju aivan suunnitelmien mukaan, ja sekä poikanen että emo ovat vaarassa menehtyä. Australialainen dokumenttisarja. season: 0 episode: 0 category: Leisure/Hobbies profile: Default recpriority: 0 autoexpire: 0 maxepisodes: 0 maxnewest: 0 startoffset: 0 endoffset: 0 recgroup: Default dupmethod: 6 dupin: 15 station: Nelonen seriesid: programid: inetref: search: 0 autotranscode: 0 autocommflag: 1 autouserjob1: 0 autouserjob2: 0 autouserjob3: 0 autouserjob4: 0 autometadata: 1 findday: 2 findtime: 07:55:00 findid: 736276 inactive: 0 parentid: 0 transcoder: 0 playgroup: Default prefinput: 0 next_record: 0000-00-00 00:00:00 last_record: 0000-00-00 00:00:00 last_delete: 0000-00-00 00:00:00 storagegroup: Default avg_delay: 100 filter: 0 1 row in set (0.00 sec)
This happens repeatedly every time a Live TV program is recorded.
gdb output from mythbackend while a 'broken' recording is in the database, command gdb --args mythbackend --nologserver:
2015-11-09 08:12:38.145518 N AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min 2015-11-09 08:12:39.102962 I Bonjour: Service registration complete: name 'Mythbackend on digilaatikko' type '_mythbackend._tcp.' domain: 'local.' 2015-11-09 08:12:40.128034 I Reschedule requested for MATCH 0 0 0 - SchedulerInit Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7fff9dffb700 (LWP 3010)] 0x00007fffd8ed257d in my_datetime_to_str () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 (gdb) bt #0 0x00007fffd8ed257d in my_datetime_to_str () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #1 0x00007fffd8ec4ecf in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #2 0x00007fffd8ec5138 in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #3 0x00007fffd8ec905e in mysql_stmt_fetch () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #4 0x00007fffd9476011 in ?? () from /usr/lib/x86_64-linux-gnu/qt4/plugins/sqldrivers/libqsqlmysql.so #5 0x00007ffff69cb629 in MSqlQuery::next() () from /usr/lib/libmythbase-0.27.so.0 #6 0x00000000004d2ebc in ?? () #7 0x00000000004db2cf in ?? () #8 0x00000000004dde50 in ?? () #9 0x00000000004eb177 in ?? () #10 0x00007ffff3fc7e6c in ?? () from /usr/lib/x86_64-linux-gnu/libQtCore.so.4 #11 0x00007ffff5dcf0a4 in start_thread (arg=0x7fff9dffb700) at pthread_create.c:309 #12 0x00007ffff33f806d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Installed version
||/ Name Version Architecture Description +++-========================-=================-=================-===================================================== ii mythtv-backend 0.27.5+fixes20151 amd64 Personal video recorder application (server)
Change History (7)
comment:1 Changed 8 years ago by
Milestone: | unknown → 0.28 |
---|---|
Status: | new → infoneeded_new |
comment:2 Changed 8 years ago by
output with debug symbols enabled. Please note that this was built based on the deb-multimedia 'unstable' repo sources. The patches applied do not seem to touch any files that could affect this.
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7fff9dffb700 (LWP 32757)] 0x00007fffd8b2357d in my_datetime_to_str () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 (gdb) bt #0 0x00007fffd8b2357d in my_datetime_to_str () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #1 0x00007fffd8b15ecf in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #2 0x00007fffd8b16138 in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #3 0x00007fffd8b1a05e in mysql_stmt_fetch () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18 #4 0x00007fffd90cb011 in ?? () from /usr/lib/x86_64-linux-gnu/qt4/plugins/sqldrivers/libqsqlmysql.so #5 0x00007ffff697f9fe in MSqlQuery::next (this=0x7fff9dffa680) at mythdbcon.cpp:767 #6 0x00000000004d2c7b in Scheduler::AddNewRecords (this=0x8f9280) at scheduler.cpp:4078 #7 0x00000000004b0c47 in Scheduler::FillRecordList (this=0x8f9280) at scheduler.cpp:421 #8 0x00000000004c0774 in Scheduler::HandleReschedule (this=0x8f9280) at scheduler.cpp:2229 #9 0x00000000004be3bf in Scheduler::run (this=0x8f9280) at scheduler.cpp:1941 #10 0x00007ffff69628fb in MThreadInternal::run (this=0x8d2ab0) at mthread.cpp:79 #11 0x00007ffff3f2fe6c in ?? () from /usr/lib/x86_64-linux-gnu/libQtCore.so.4 #12 0x00007ffff5d370a4 in start_thread (arg=0x7fff9dffb700) at pthread_create.c:309 #13 0x00007ffff336006d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 (gdb)
comment:3 Changed 8 years ago by
trace with debugging symbols for libmysql18 and libqt4 enabled:
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7fff9dffb700 (LWP 4048)] my_datetime_to_str (l_time=<optimized out>, to=0x7fff9dff99e0 "2015-11-09 20:00:00", dec=31) at /root/mysql-5.6-5.6.27/sql-common/my_time.c:1322 1322 /root/mysql-5.6-5.6.27/sql-common/my_time.c: No such file or directory. (gdb) bt #0 my_datetime_to_str (l_time=<optimized out>, to=0x7fff9dff99e0 "2015-11-09 20:00:00", dec=31) at /root/mysql-5.6-5.6.27/sql-common/my_time.c:1322 #1 0x00007fffd8b232b6 in my_TIME_to_str (l_time=<optimized out>, to=to@entry=0x7fff9dff99e0 "2015-11-09 20:00:00", dec=<optimized out>) at /root/mysql-5.6-5.6.27/sql-common/my_time.c:1344 #2 0x00007fffd8b15a2f in fetch_datetime_with_conversion (param=param@entry=0x7fff98032410, field=field@entry=0x7fff98036510, my_time=<optimized out>) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:3549 #3 0x00007fffd8b15c98 in fetch_result_with_conversion (param=0x7fff98032410, field=0x7fff98036510, row=0x7fff9dff9ad0) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:3657 #4 0x00007fffd8b19dae in stmt_fetch_row (row=<optimized out>, stmt=0x7fff9802cbf0) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:4183 #5 mysql_stmt_fetch (stmt=0x7fff9802cbf0) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:4219 #6 0x00007fffd90cb011 in QMYSQLResult::fetchNext (this=0x7fff980173b0) at ../../../sql/drivers/mysql/qsql_mysql.cpp:529 #7 0x00007ffff697f9fe in MSqlQuery::next (this=0x7fff9dffa680) at mythdbcon.cpp:767 #8 0x00000000004d2c7b in Scheduler::AddNewRecords (this=0x8e4800) at scheduler.cpp:4078 #9 0x00000000004b0c47 in Scheduler::FillRecordList (this=0x8e4800) at scheduler.cpp:421 #10 0x00000000004c0774 in Scheduler::HandleReschedule (this=0x8e4800) at scheduler.cpp:2229 #11 0x00000000004be3bf in Scheduler::run (this=0x8e4800) at scheduler.cpp:1941 #12 0x00007ffff69628fb in MThreadInternal::run (this=0x8b4f40) at mthread.cpp:79 #13 0x00007ffff3f2fe6c in QThreadPrivate::start (arg=0x8b4f40) at thread/qthread_unix.cpp:352 #14 0x00007ffff5d370a4 in start_thread (arg=0x7fff9dffb700) at pthread_create.c:309 #15 0x00007ffff336006d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 (gdb)
comment:4 Changed 8 years ago by
full backtrace for the above trace. I'm reaaaaaly bad at c so I can't really figure out what/why this segfaults, looks like the 'to' char and 'dec' are set to sensible values.
#0 my_datetime_to_str (l_time=<optimized out>, to=0x7fffc9ff99e0 "2015-11-09 20:00:00", dec=31) at /root/mysql-5.6-5.6.27/sql-common/my_time.c:1322 len = 0 #1 0x00007fffd93242b6 in my_TIME_to_str (l_time=<optimized out>, to=to@entry=0x7fffc9ff99e0 "2015-11-09 20:00:00", dec=<optimized out>) at /root/mysql-5.6-5.6.27/sql-common/my_time.c:1344 No locals. #2 0x00007fffd9316a2f in fetch_datetime_with_conversion (param=param@entry=0x7fff9c038060, field=field@entry=0x7fff9c03c160, my_time=<optimized out>) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:3549 buff = "2015-11-09 20:00:00\000\377\377\377\377\000\071:\271\334^" length = <optimized out> #3 0x00007fffd9316c98 in fetch_result_with_conversion (param=0x7fff9c038060, field=0x7fff9c03c160, row=0x7fffc9ff9ad0) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:3657 tm = {year = 2015, month = 11, day = 9, hour = 20, minute = 0, second = 0, second_part = 0, neg = 0 '\000', time_type = MYSQL_TIMESTAMP_DATETIME} field_type = <optimized out> field_is_unsigned = <optimized out> #4 0x00007fffd931adae in stmt_fetch_row (row=<optimized out>, stmt=0x7fff9c033810) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:4183 end = <optimized out> null_ptr = 0x7fff9c02b05a "\003" bit = 16 '\020' my_bind = 0x7fff9c038060 field = 0x7fff9c03c160 truncation_count = 0 #5 mysql_stmt_fetch (stmt=0x7fff9c033810) at /root/mysql-5.6-5.6.27/libmysql/libmysql.c:4219 rc = <optimized out> row = 0x7fff9c02b058 "" #6 0x00007fffd98cc011 in QMYSQLResult::fetchNext (this=0x7fff9c0200b0) at ../../../sql/drivers/mysql/qsql_mysql.cpp:529 nRC = <optimized out> #7 0x00007ffff697f9fe in MSqlQuery::next (this=0x7fffc9ffa680) at mythdbcon.cpp:767 No locals. #8 0x00000000004d2c7b in Scheduler::AddNewRecords (this=0x8ecaf0) at scheduler.cpp:4078 schedTmpRecord = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7fff9c0171e0, static codecForCStrings = 0x0} dbstart = {tv_sec = 1447098699, tv_usec = 805598} dbend = {tv_sec = 1447098699, tv_usec = 806111} tmpList = {<std::_Deque_base<RecordingInfo*, std::allocator<RecordingInfo*> >> = {_M_impl = {<std::allocator<RecordingInfo*>> = {<__gnu_cxx::new_allocator<RecordingInfo*>> = {<No data fields>}, <No data fields>}, _M_map = 0x7fff9c034a80, _M_map_size = 8, _M_start = {_M_cur = 0x7fff9c034b30, _M_first = 0x7fff9c034b30, _M_last = 0x7fff9c034d30, _M_node = 0x7fff9c034a98}, _M_finish = {_M_cur = 0x7fff9c034b30, _M_first = 0x7fff9c034b30, _M_last = 0x7fff9c034d30, _M_node = 0x7fff9c034a98}}}, <No data fields>} cardMap = {{d = 0x7fff9c020440, e = 0x7fff9c020440}} enciter = {i = 0x8d2690} tooManyMap = {{d = 0x7fff9c035e20, e = 0x7fff9c035e20}} checkTooMany = false rlist = {<QSqlQuery> = {d = 0x7fff9c034f70}, m_db = 0x7fff9c016870, m_isConnected = true, m_returnConnection = false, m_last_prepared_query = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7fff9c0173e0, static codecForCStrings = 0x0}} prefinputpri = 2 hdtvpriority = 0 wspriority = 0 slpriority = 0 onscrpriority = 0 ccpriority = 0 hhpriority = 0 adpriority = 0 pwrpri = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7fff9c033eb0, static codecForCStrings = 0x0} result = {<QSqlQuery> = {d = 0x7fff9c0375f0}, m_db = 0x7fff9c016870, m_isConnected = true, m_returnConnection = false, m_last_prepared_query = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7fff9c031800, static codecForCStrings = 0x0}} query = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7fff9c031800, static codecForCStrings = 0x0} __FUNCTION__ = "AddNewRecords" lastp = 0x0 tmp = {_M_cur = 0x7fff00000020, _M_first = 0x7ffff3f3faa6 <QDateTime::currentDateTimeUtc()+166>, _M_last = 0x7fffc9ffa730, _M_node = 0x7fffc9ffa710} #9 0x00000000004b0c47 in Scheduler::FillRecordList (this=0x8ecaf0) at scheduler.cpp:421 __FUNCTION__ = "FillRecordList" res = false #10 0x00000000004c0774 in Scheduler::HandleReschedule (this=0x8ecaf0) at scheduler.cpp:2229 fillstart = {tv_sec = 1447098699, tv_usec = 804044} fillend = {tv_sec = 1447098699, tv_usec = 804044} matchTime = 0.00210499996 checkTime = 0.000534999999 placeTime = 4.59163468e-41 msg = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x7ffff43a6920 <QString::shared_null>, static codecForCStrings = 0x0} deleteFuture = true runCheck = true __FUNCTION__ = "HandleReschedule" worklistused = false it = {_M_cur = 0x5640f920, _M_first = 0xc2f2c, _M_last = 0x3300000027, _M_node = 0x900000015} #11 0x00000000004be3bf in Scheduler::run (this=0x8ecaf0) at scheduler.cpp:1941 t = {mds = 78699798} curtime = {d = {d = 0x7fff9c016ca0}} secs_to_next = 1209600 sched_sleep = 1209600000 haveRequests = true done = 171 checkSlaves = true lockit = {val = 9358201} prerollseconds = 300 wakeThreshold = 300 idleTimeoutSecs = 0 idleWaitForRecordingTime = 15 blockShutdown = true firstRun = true lastSleepCheck = {d = {d = 0x7fff9c0171c0}} startIter = {_M_cur = 0x93d4c0, _M_first = 0x93d4c0, _M_last = 0x93d6c0, _M_node = 0x8d2ff8} idleSince = {d = {d = 0x7fff9c016cc0}} schedRunTime = 0 statuschanged = false nextStartTime = {d = {d = 0x7fff9c017110}} nextWakeTime = {d = {d = 0x7fff9c017110}} __FUNCTION__ = "run" #12 0x00007ffff69628fb in MThreadInternal::run (this=0x8b4a10) at mthread.cpp:79 No locals. #13 0x00007ffff3f2fe6c in QThreadPrivate::start (arg=0x8b4a10) at thread/qthread_unix.cpp:352 __clframe = {__cancel_routine = 0x7ffff3f2ed00 <QThreadPrivate::finish(void*)>, __cancel_arg = 0x8b4a10, __do_it = 1, __cancel_type = <optimized out>} thr = 0x8b4a10 data = 0x8708b0 objectName = {static null = <same as static member of an already seen type>, static shared_null = <same as static member of an already seen type>, static shared_empty = <same as static member of an already seen type>, d = 0x92b3d0, static codecForCStrings = 0x0} #14 0x00007ffff5d370a4 in start_thread (arg=0x7fffc9ffb700) at pthread_create.c:309 __res = <optimized out> pd = 0x7fffc9ffb700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140736582366976, 849002495889893166, 1, 140737354125408, 140737488349008, 140736582366976, -848980504094972114, -849024309875316946}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> pagesize_m1 = <optimized out> sp = <optimized out> freesize = <optimized out> __PRETTY_FUNCTION__ = "start_thread" #15 0x00007ffff336006d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 No locals.
comment:5 Changed 8 years ago by
The problem (I think) is 'dec=31' which is invalid, the precision (dec parameter) for my_useconds_to_str() in libmysqlclient should be 1 to 6.
From my_time.c
/** Print the microsecond part: ".NNN" @param to OUT The string pointer to print at @param useconds The microseconds value. @param dec Precision, between 1 and 6. @return The length of the result string. */ static inline int my_useconds_to_str(char *to, ulong useconds, uint dec) { DBUG_ASSERT(dec <= DATETIME_MAX_DECIMALS); return sprintf(to, ".%0*lu", dec, useconds / (ulong) log_10_int[DATETIME_MAX_DECIMALS - dec]); }
DATETIME_MAX_DECIMALS is 6 as defined in my_time.h , so if the given 'dec' value is greater than 6, access to log_to_int[] ends up being negative. The dec value is picked from 'field->decimals' which is a MYSQL_FIELD, after that my skills in c fail me and I can't figure out where the decimals value is actually coming from.
Either this is a mysql (libmysqlclient) bug or something funny is happening in my database to return a dec value of 31?
comment:6 Changed 8 years ago by
Confirmed the problem to be an invalid 'dec' value, don't know what is causing it to be 31, but with custom libmysqlclient code, changing my_useconds_to_str to be
static inline int my_useconds_to_str(char *to, ulong useconds, uint dec) { int prec; if( dec > DATETIME_MAX_DECIMALS ) prec = DATETIME_MAX_DECIMALS; else prec = dec; DBUG_ASSERT(dec <= DATETIME_MAX_DECIMALS); return sprintf(to, ".%0*lu", prec, useconds / (ulong) log_10_int[DATETIME_MAX_DECIMALS - prec]); }
recordings do not crash the backend.
comment:7 Changed 8 years ago by
Resolution: | → Upstream Bug |
---|---|
Status: | infoneeded_new → closed |
In absence of any evidence to the contrary I'm going to call this an upstream bug.
Can you install the debug libraries and get a better backtrace that contains the decoded symbols?
It's quite difficult to tell where this is without the additional info.