[mythtv-users] recent mythbackend crashing
Mike Perkins
mikep at randomtraveller.org.uk
Sat Jun 4 20:13:29 UTC 2022
On 04/06/2022 20:35, David Hampton via mythtv-users wrote:
> On Sat, 2022-06-04 at 10:28 +0200, Klaas de Waal wrote:
>>
>>
>> On Sat, 4 Jun 2022 at 09:02, Klaas de Waal <klaas.de.waal at gmail.com>
>> wrote:
>>>
>>>
>>> On Fri, 3 Jun 2022 at 16:55, Eyal Lebedinsky <eyal at eyal.emu.id.au>
>>> wrote:
>>>>
>>>>
>>>> On 02/06/2022 09.26, Eyal Lebedinsky wrote:
>>>>>
>>>>>
>>>>> On 01/06/2022 09.06, David Engel wrote:
>>>>>> On Tue, May 31, 2022 at 10:32:17PM +0000, Gary Buhrmaster
>>>>>> wrote:
>>>>>>> On Tue, May 31, 2022 at 7:28 PM Klaas de Waal
>>>>>>> <klaas.de.waal at gmail.com> wrote:
>>>>>>>
>>>>>>>> What is a bit strange is that you get the abort signal.
>>>>>>>> Usually we get the segmentation fault.
>>>>>>>
>>>>>>> (g)libc (and other libraries) will SIGABRT due to various
>>>>>>> "critical" errors, which all too often tend not to be
>>>>>>> anywhere
>>>>>>> near the actual root cause (which is why the extended
>>>>>>> mythtv logging and a full bt is probably going to be
>>>>>>> required).
>>>>>>
>>>>>> I can confirm that. I had some occasional, but frequent
>>>>>> enough to be
>>>>>> very frustrating, crashes over several months that I finally
>>>>>> tracked
>>>>>> down to glibc aborting due to the process exceeding the
>>>>>> default limit
>>>>>> on open, file descriptors.
>>>>>>
>>>>>> David
>>>>>
>>>>> I am running for over a day with EIT enabled and [Service]
>>>>> includes:
>>>>> Type=simple
>>>>> Environment=MYTHCONFDIR=/etc/mythtv
>>>>> User=mythtv
>>>>> ExecStart=/usr/bin/mythbackend --logpath /var/log/mythtv
>>>>> -v channel,eit --loglevel=debug # added '-v ...'
>>>>> Restart=always # new line
>>>>> LimitNOFILE=16384 # new line
>>>>>
>>>>> The last 3 lines were changed/added recently.
>>>>>
>>>>> Tonight, after more than a day, I had the first crash (see log
>>>>> below) when the backend was idle.
>>>>> Same lines in mythbackend log and system messages.
>>>>>
>>>>> I do not see anything unusuall, does anyone else?
>>>>>
>>>>> I will now disable EIT (and the debug options) until the next
>>>>> experiment.
>>>>>
>>>>> Regards,
>>>>> Eyal
>>>>
>>>> [log trimmed]
>>>>
>>>> I now re-enabled debug and EIT scan. Many crashes in the last
>>>> hour so disabled EIT.
>>>> Running gdb requested to install over 200 packages, now done so
>>>> we have debuginfo available.
>>>> Following is what I hope will offer enough information to
>>>> diagnose the problem.
>>>>
>>>> The last crash had these lines at the end of mythbackend.log
>>>> 2022-06-03 23:30:41.085749 E [4085639/4086085] DVBRead
>>>> recorders/dtvrecorder.cpp:884 (FindH2645Keyframes) - DTVRec[33]:
>>>> PES start code not found in TS packet with PUSI set
>>>> 2022-06-03 23:30:59.981311 C [4085639/4085639] CoreContext
>>>> signalhandling.cpp:294 (handleSignal) - Received Aborted: Code -
>>>> 6, PID 4085639, UID 490, Value 0x00000000
>>>> However the first line did not precede other crashes so it may be
>>>> unrelated.
>>>>
>>>> $ gdb -q -nh /bin/mythbackend
>>>> core.mythbackend.490.3ae7044308f446d6b1b21313833d93b8.4085639.165
>>>> 4263060000000
>>>> Reading symbols from /bin/mythbackend...
>>>> Reading symbols from /usr/lib/debug/usr/bin/mythbackend-32.0-
>>>> 1.30.20220510git26079f815a.fc34.x86_64.debug...
>>>> [New LWP 4086085]
>>>> ... many threads
>>>> [Thread debugging using libthread_db enabled]
>>>> Using host libthread_db library "/lib64/libthread_db.so.1".
>>>> Core was generated by `/usr/bin/mythbackend --logpath
>>>> /var/log/mythtv -v channel,eit --loglevel=debug'.
>>>> Program terminated with signal SIGABRT, Aborted.
>>>> #0 __GI_raise (sig=sig at entry=6) at
>>>> ../sysdeps/unix/sysv/linux/raise.c:49
>>>> 49 return ret;
>>>> [Current thread is 1 (Thread 0x7f2ad1ffb640 (LWP 4086085))]
>>>> (gdb) bt
>>>> #0 __GI_raise (sig=sig at entry=6) at
>>>> ../sysdeps/unix/sysv/linux/raise.c:49
>>>> #1 0x00007f2c3c5338a4 in __GI_abort () at abort.c:79
>>>> #2 0x00007f2c3e478b48 in std::__replacement_assert(char const*,
>>>> int, char const*, char const*)
>>>> (__file=__file at entry=0x7f2c3ec36013
>>>> "/usr/include/c++/11/array", __line=__line at entry=196,
>>>> __function=__function at entry=0x7f2c3ec7e8d8 "constexpr const
>>>> value_type& std::array<_Tp, _Nm>::operator[](std::array<_Tp,
>>>> _Nm>::size_type) const [with _Tp = unsigned char; long unsigned
>>>> int _Nm = 4; std::array<_Tp, _Nm>::const_reference = const "...,
>>>> __condition=__condition at entry=0x7f2c3ec36000 "__n < this-
>>>>> size()")
>>>> at /usr/include/c++/11/x86_64-redhat-
>>>> linux/bits/c++config.h:2663
>>>> #3 0x00007f2c3e60bc27 in std::array<unsigned char,
>>>> 4ul>::operator[](unsigned long) const (this=0x7f2abc008004,
>>>> __n=4) at /usr/include/c++/11/array:196
>>>> #4 std::array<unsigned char, 4ul>::operator[](unsigned long)
>>>> const (__n=4, this=0x7f2abc008004) at
>>>> /usr/include/c++/11/array:193
>>>> #5 TSHeader::AdaptationFieldSize() const (this=0x7f2abc008004)
>>>> at mpeg/tspacket.h:97
>>>> #6 PESPacket::AddTSPacket(TSPacket const*, int, bool&)
>>>> (this=this at entry=0x7f2abc2c3e20,
>>>> packet=packet at entry=0x7f2abc008004, cardid=33,
>>>> broken=@0x7f2ad1ffa6f7: true) at mpeg/pespacket.cpp:52
>>>> #7 0x00007f2c3e635a0f in MPEGStreamData::AssemblePSIP(TSPacket
>>>> const*, bool&) (this=0x7f2bf80152e8, tspacket=0x7f2abc008004,
>>>> moreTablePackets=@0x7f2ad1ffa7df: true) at
>>>> mpeg/mpegstreamdata.cpp:214
>>>> #8 0x00007f2c3e63660d in MPEGStreamData::HandleTSTables(TSPacket
>>>> const*) (this=0x7f2bf80152e8, tspacket=0x7f2abc008004) at
>>>> mpeg/mpegstreamdata.cpp:874
>>>> #9 0x00007f2c3e6406f0 in
>>>> MPEGStreamData::ProcessTSPacket(TSPacket const&) (tspacket=...,
>>>> this=0x7f2bf80152e8) at mpeg/mpegstreamdata.cpp:1064
>>>> #10 MPEGStreamData::ProcessTSPacket(TSPacket const&)
>>>> (this=0x7f2bf80152e8, tspacket=...) at
>>>> mpeg/mpegstreamdata.cpp:1006
>>>> #11 0x00007f2c3e63731c in MPEGStreamData::ProcessData(unsigned
>>>> char const*, int)
>>>> (this=0x7f2bf80152e8, buffer=0x7f2abc006f20
>>>> "G\006\341\020k\241\272\266\274\317l\227\256\065c\302\220W\277\33
>>>> 6\213i\"\300\063\060\343\023\351\f\016\036\245\243\210\331\024\02
>>>> 6Ap\a\a@\341{q\tw\244l#a\326", len=6768)
>>>> at mpeg/mpegstreamdata.cpp:988
>>>> #12 0x00007f2c3ebec30a in DVBStreamHandler::RunTS()
>>>> (this=0x7f2c18003100) at recorders/dvbstreamhandler.cpp:266
>>>> #13 0x00007f2c3ebf144e in DVBStreamHandler::run()
>>>> (this=0x7f2c18003100) at recorders/dvbstreamhandler.cpp:119
>>>> #14 0x00007f2c3c9ff4c6 in QThreadPrivate::start(void*)
>>>> (arg=0x7f2c180013e0) at thread/qthread_unix.cpp:329
>>>> #15 0x00007f2c3d9af2a5 in start_thread (arg=0x7f2ad1ffb640) at
>>>> pthread_create.c:481
>>>> #16 0x00007f2c3c60d323 in clone () at
>>>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
>>>>
>>>>
>>>>
>>>
>>> Thanks for the perfect traceback. I think that I do understand what
>>> is happening.
>>>
>>> For those who do love the details, this is my tentative analysis.
>>> MPEG transport stream packets have a fixed size of 188 bytes. The
>>> first 4 bytes is the header and the remaining 184 bytes is the
>>> payload.
>>> The original parsing code, written somewhere in the beginning of
>>> this century, uses C-style pointer and array arithmetic, with the
>>> knowledge that the payload does always follow the header. The code
>>> that now fails wants to obtain the length of a so-called Adaptation
>>> Field. If there is an adaptation field, which is signalled by a bit
>>> in the header, the length is present in the first byte following
>>> the header.
>>> Somewhere along the line, in an effort to replace C-style coding
>>> with C++ style coding, the header is now defined as a 4-byte
>>> std::array type.
>>> The code to read the adaptation field length effectively reads the
>>> fifth byte and the code generated by the std::array template then
>>> does the abort.
>>> The change to using std::array is already a few years old, so I do
>>> guess that compilers and compiler versions can have their own
>>> interpretation of what to do when reading beyond the end of the
>>> array and that the compiler that you are using is now enforcing
>>> array boundary limits on std::array types.
>>>
>>> I will have a look on how to fix this, but first it would be great
>>> if I can reproduce the problem. This probably needs more compiler
>>> options than what I use regularly.
>>>
>>>
>>
>>
>> In tspacket.h there are many more functions that do access the
>> payload. To support this a separate data() function is defined that
>> returns a pointer to the packet.
>> This data() function should also have been used in the
>> AdaptationFieldSize function as this also accesses data beyond the
>> first four header bytes.
>>
>> This is the patch that is now being tested:
>> --- patch start -------------
>> diff --git a/mythtv/libs/libmythtv/mpeg/tspacket.h
>> b/mythtv/libs/libmythtv/mpeg/tspacket.h
>> index 0a971c436f..a15ff12c34 100644
>> --- a/mythtv/libs/libmythtv/mpeg/tspacket.h
>> +++ b/mythtv/libs/libmythtv/mpeg/tspacket.h
>> @@ -94,7 +94,7 @@ class MTV_PUBLIC TSHeader
>> bool Scrambled(void) const { return bool(m_tsData[3]&0x80); }
>> bool HasAdaptationField(void) const { return bool(m_tsData[3] &
>> 0x20); }
>> size_t AdaptationFieldSize(void) const
>> - { return (HasAdaptationField() ?
>> static_cast<size_t>(m_tsData[4]) : 0); }
>> + { return (HasAdaptationField() ? static_cast<size_t>(data()[4])
>> : 0); }
>> bool HasPayload(void) const { return bool(m_tsData[3] & 0x10); }
>>
>> bool GetDiscontinuityIndicator(void) const
>> --- patch end ------------
>>
>> This patch will be committed to master today and then a bit later
>> into fixes/32, after which it will propagate into the packages.
>
> To be honest, from looking at the code I'm not sure either of those
> lines of code every returned the proper value. The code appears to
> have divided a 188 byte TS packet into a TSHeader object and an
> TSPayload object at least as far back as 0.26. The former contains the
> first four bytes of data from the TS packet, and the latter contains
> the other 184 bytes. These two data items are not necessarily
> contiguous. Regardless of whether m_tsData is defined as a
> "std::array<uint8_t,4>" or a "unsigned char [4]", reading the fifth
> byte of m_tsData is reading at a the first byte of memory following the
> TSHeader object. It is never reading at the first byte of the
> TSPayload object's data field. The only difference between the two
> declarations is that the latter complains about reading past the array.
>
> Klaas, I think you've fixed the crash, but I think the underlying code
> is still wrong. Maybe I'm missing something. (I hope I'm missing
> something.)
>
> Investigating further, I suspect that we've always just gotten lucky
> with the alignment of variables in an object. Since TSPacket is based
> on TSHeader, the byte arrays declared in each object just happen to be
> placed in consecutive memory locations making the code work. Any
> variable added to either object has the potential to break this happy
> accident.
>
> The GetDiscontinuityIndicator(), HasPCR(), GetPCRbase(), and
> GetPCRext() functions all also appear to be benefit from this layout of
> variables in the base and derived objects being assigned consecutive
> memory locations.
>
> All of the code in libmythtv/mpeg is all black magic (at least to me).
> I think it could use profiling to see which lines of code are covered
> by the existing test cases, and then it needs a bunch of additional
> test cases to cover the remainder of the code. I know there are a
> bunch of Coverity tests that complain about insecure data handling, so
> there should be some negative testing as well as positive testing. I'm
> willing to start this process, but I need some sample packets
> containing all the various tables (PAT, CAT, PMT, NIT, BAT, SDT3).
>
As a (retired) coder with no knowledge of the immediate subject at all, I'm wondering why a packet
known to be a fixed length of 188 bytes has to be split into two different objects. Wouldn't a
single one have done for all purposes?
--
Mike Perkins
More information about the mythtv-users
mailing list