[mythtv-users] recent mythbackend crashing

Mon Jun 6 23:27:24 UTC 2022

On 04/06/2022 00.54, Eyal Lebedinsky 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

After a few quiet days, this morning I had a burst of crashes, 25 in one hour. Here is the crash trace of the last one. Still no EIT.

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 0x7fdd1ffff640 (LWP 2203949))]
...
Thread 1 (Thread 0x7fdd1ffff640 (LWP 2203949)):
#0  __GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
#1  0x00007fdeb2b858a4 in __GI_abort () at abort.c:79
#2  0x00007fdeb4acab48 in std::__replacement_assert(char const*, int, char const*, char const*) (__file=__file at entry=0x7fdeb5288013 "/usr/include/c++/11/array", __line=__line at entry=196, __function=__function at entry=0x7fdeb52d08d8 "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=0x7fdeb5288000 "__n < this->size()") at /usr/include/c++/11/x86_64-redhat-linux/bits/c++config.h:2663
#3  0x00007fdeb4c5dc27 in std::array<unsigned char, 4ul>::operator[](unsigned long) const (this=0x7fde90138534, __n=4) at /usr/include/c++/11/array:196
#4  std::array<unsigned char, 4ul>::operator[](unsigned long) const (__n=4, this=0x7fde90138534) at /usr/include/c++/11/array:193
#5  TSHeader::AdaptationFieldSize() const (this=0x7fde90138534) at mpeg/tspacket.h:97
#6  PESPacket::AddTSPacket(TSPacket const*, int, bool&) (this=this at entry=0x7fdd14004a80, packet=packet at entry=0x7fde90138534, cardid=33, broken=@0x7fdd1fffe6f7: true) at mpeg/pespacket.cpp:52
#7  0x00007fdeb4c87a0f in MPEGStreamData::AssemblePSIP(TSPacket const*, bool&) (this=0x7fde680188f8, tspacket=0x7fde90138534, moreTablePackets=@0x7fdd1fffe7df: true) at mpeg/mpegstreamdata.cpp:214
#8  0x00007fdeb4c8860d in MPEGStreamData::HandleTSTables(TSPacket const*) (this=0x7fde680188f8, tspacket=0x7fde90138534) at mpeg/mpegstreamdata.cpp:874
#9  0x00007fdeb4c926f0 in MPEGStreamData::ProcessTSPacket(TSPacket const&) (tspacket=..., this=0x7fde680188f8) at mpeg/mpegstreamdata.cpp:1064
#10 MPEGStreamData::ProcessTSPacket(TSPacket const&) (this=0x7fde680188f8, tspacket=...) at mpeg/mpegstreamdata.cpp:1006
#11 0x00007fdeb4c8931c in MPEGStreamData::ProcessData(unsigned char const*, int) (this=0x7fde680188f8, buffer=0x7fde90138010 "G\006\341\026E\005\313$_\247\t\210\314\252m\201\215h)\230\365\320\237\272\004\223\372\214\071H\351\350\031\177\021\225\342W%\201n\342\337RD\025P\032\353C\365\260\251\311\372i\301E~\316\070VO\302\341\324\250\337T\304$\224|\264 U\027\204t\264\355\346.,\370\067\341b\020}\v\346\025\273\245\233q\325x4q \261i\026k\005Q7]\026\030'sd\002\254m\215x\026\230{\264G\257\274\002\317+\366\333\n\205\212w\033\016MB\004\062\214\325\240/QT\037u\020\247\"\035\353\247\311\357@\217Y\"\004W\256\366\067:J\317\302\334\207\255s%\261\264\177\366}g19$> hG\206\341\027\274\272\342\070.\303\277\362"..., len=8460) at mpeg/mpegstreamdata.cpp:988
#12 0x00007fdeb523e30a in DVBStreamHandler::RunTS() (this=0x7fde6800c180) at recorders/dvbstreamhandler.cpp:266
#13 0x00007fdeb524344e in DVBStreamHandler::run() (this=0x7fde6800c180) at recorders/dvbstreamhandler.cpp:119
#14 0x00007fdeb30514c6 in QThreadPrivate::start(void*) (arg=0x7fde68015de0) at thread/qthread_unix.cpp:329
#15 0x00007fdeb40012a5 in start_thread (arg=0x7fdd1ffff640) at pthread_create.c:481
#16 0x00007fdeb2c5f323 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Looks identical to the earlier one, so this is a general issue not related specifically to EIT. Two recordings started around that time.

Now we really need a fix, or is there a workaround?

TIA

-- 
Eyal Lebedinsky (eyal at eyal.emu.id.au)