[mythtv-users] recent mythbackend crashing

Sat Jun 4 07:02:38 UTC 2022

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.1654263060000000
> 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\336\213i\"\300\063\060\343\023\351\f\016\036\245\243\210\331\024\026Ap\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.

Thanks,
Klaas.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20220604/85917687/attachment.htm>