[mythtv-users] recent mythbackend crashing

David Hampton mythtv at love2code.net
Sat Jun 4 19:35:47 UTC 2022


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

David




More information about the mythtv-users mailing list