Opened 4 years ago

Closed 3 years ago

#12535 closed Bug Report - General (Upstream Bug)

Segmentation fault after starting livetv recording

Reported by: xenic@… 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 4 years ago by Stuart Auchterlonie

Milestone: unknown0.28
Status: newinfoneeded_new

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.

comment:2 Changed 4 years ago by xenic@…

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 4 years ago by xenic@…

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 4 years ago by xenic@…

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 4 years ago by xenic@…

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 4 years ago by xenic@…

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 3 years ago by paulh

Resolution: Upstream Bug
Status: infoneeded_newclosed

In absence of any evidence to the contrary I'm going to call this an upstream bug.

Note: See TracTickets for help on using tickets.