[mythtv-users] myth backend restarting due to mythcommflag

Stephen Worthington stephen_agent at jsw.gen.nz
Mon Feb 22 01:39:09 UTC 2021 

On Sun, 21 Feb 2021 11:30:07 -0600, you wrote:

>I am seeing this and have had it happen while watching TV, something with
>mythcommflag job running locks up the process and systemd kills and
>restarts the process.
>
>Here is some of the output, looks like I have some old stale jobs that need
>cleaning up:
>
> 09:27:23 mythtv1804 mythbackend[31440]: mythbackend[31440]: C
>HttpServer103 programinfo.cpp:347 (ProgramInfo) ProgramInfo(): Failed to
>find recorded entry for 15097.
>Feb 21 09:27:26 mythtv1804 mythbackend[31440]: mythbackend[31440]: C
>CoreContext programinfo.cpp:347 (ProgramInfo) ProgramInfo(): Failed to find
>recorded entry for 15097.
>Feb 21 09:28:21 mythtv1804 mythbackend[31440]: mythbackend[31440]: C
>CoreContext programinfo.cpp:347 (ProgramInfo) ProgramInfo(): Failed to find
>recorded entry for 15097.
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: N
>CoreContext autoexpire.cpp:261 (CalcParams) AutoExpire: CalcParams(): Max
>required Free Space: 3.0 GB w/freq: 7 min
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: N
>TVRecEvent recordinginfo.cpp:703 (ApplyRecordRecGroupChange)
>ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: I
>HDHRStreamHandler mythdbcon.cpp:431 (PurgeIdleConnections) New DB
>connection, total: 21
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: N
>HDHRStreamHandler recorders/recorderbase.cpp:507 (FinishRecording) Finished
>Recording: Container: MPEG2-TS Video Codec: mpeg2video (19
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: I
>HDHRStreamHandler tv_rec.cpp:3408 (RingBufferChanged) TVRec[4]:
>RingBufferChanged()
>Feb 21 09:30:00 mythtv1804 mythbackend[31440]: mythbackend[31440]: C
>CoreContext signalhandling.cpp:305 (handleSignal) Received Segmentation
>fault: Code 128, PID 0, UID 0, Value 0x00000000

<<<<<< This is the problem

>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: C
>thread_unknown mythcommandlineparser.cpp:2607 (ConfigureLogging)
>mythpreviewgen version:  [v30.0] www.mythtv.org
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: C
>thread_unknown mythcommandlineparser.cpp:2609 (ConfigureLogging) Qt
>version: compile: 5.9.5, runtime: 5.9.5
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>thread_unknown mythcommandlineparser.cpp:2611 (ConfigureLogging) Enabled
>verbose msgs:  general
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>thread_unknown logging.cpp:734 (logStart) Setting Log Level to LOG_INFO
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>Logger logging.cpp:296 (run) Added logging to the console
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Interrupt
>handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Terminated
>handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
>Segmentation fault handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Aborted
>handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Bus error
>handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Floating
>point exception handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Illegal
>instruction handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Real-time
>signal 0 handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Hangup
>handler
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>LogForward loggingserver.cpp:246 (SyslogLogger) Added syslogging
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>thread_unknown mythdirs.cpp:203 (InitializeMythDirs) Using runtime prefix =
>/usr
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>thread_unknown mythdirs.cpp:205 (InitializeMythDirs) Using configuration
>directory = /home/mythtv/.mythtv
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcorecontext.cpp:272 (Init) Assumed character encoding:
>en_US.UTF-8
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcontext.cpp:641 (LoadDatabaseSettings) Empty LocalHostName.
>This is typical.
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcontext.cpp:650 (LoadDatabaseSettings) Using a profile name
>of: 'mythtv1804' (Usually the same as this host's name
>Feb 21 09:30:01 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcontext.cpp:900 (TestDBconnection) Start up testing
>connections. DB localhost, BE , attempt 0, status dbAwake, Del
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>CoreContext mythcorecontext.cpp:1780 (InitLocale) Setting QT default locale
>to EN_US
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcorecontext.cpp:1813 (SaveLocaleDefaults) Current locale
>EN_US
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: N
>CoreContext mythlocale.cpp:123 (LoadDefaultsFromXML) Reading locale
>defaults from /usr/share/mythtv//locales/en_us.xml
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: E
>CoreContext main.cpp:77 (preview_helper) Setting priority failed.
>
> eno: Permission denied (13)
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext previewgenerator.cpp:685 (LocalPreviewRun) Preview at
>calculated offset (1800 seconds)
>Feb 21 09:30:02 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>SendMessage mythcorecontext.cpp:451 (ConnectCommandSocket)
>MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
>Feb 21 09:30:09 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: E
>MythSocketThread(-1) mythsocket.cpp:826 (ReadStringListReal)
>MythSocket(7f1de8011910:16): ReadStringList: Error, timed out after 7
>Feb 21 09:30:09 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: C
>SendMessage mythcorecontext.cpp:1648 (CheckProtoVersion) Protocol version
>check failure.
>
> The response to MYTH_PROTO_VERSION was empty.
>
> This happens when the backend is too busy to respond,
>                                                                         or
>has deadlocked due to bugs or hardware failure.
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2223 (ScanStreams) AFD: codec AC3 has 6
>channels
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2772 (OpenAVCodec) AFD: Opened codec
>0x563b7aac1b40, id(AC3) type(Audio)
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2223 (ScanStreams) AFD: codec AC3 has 2
>channels
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2772 (OpenAVCodec) AFD: Opened codec
>0x563b7ab35b40, id(AC3) type(Audio)
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2670 (ScanStreams) AFD: Using ffmpeg for
>video decoding
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext avformatdecoder.cpp:2772 (OpenAVCodec) AFD: Opened codec
>0x563b7ab4d300, id(MPEG2VIDEO) type(Video)
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>Decoder mythcodeccontext.cpp:322 (InitDeinterlaceFilter) MythCodecContext:
>Disabled hardware decoder based deinterlacer.
>Feb 21 09:30:11 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext previewgenerator.cpp:859 (GetScreenGrab) Preview: Grabbed
>preview '/mnt/wdblue-1tb/mythtv-recordings/liveTV/10401_2021
>Feb 21 09:30:12 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>SendMessage mythcorecontext.cpp:451 (ConnectCommandSocket)
>MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
>Feb 21 09:30:12 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>CoreContext mythcontext.cpp:1672 (~MythContext) Waiting for threads to exit.
>Feb 21 09:30:14 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: E
>MythSocketThread(-1) mythsocket.cpp:834 (ReadStringListReal)
>MythSocket(7f1df0006120:-1): ReadStringList: Connection died.
>Feb 21 09:30:14 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: C
>SendMessage mythcorecontext.cpp:1648 (CheckProtoVersion) Protocol version
>check failure.
>
> The response to MYTH_PROTO_VERSION was empty.
>
> This happens when the backend is too busy to respond,
>                                                                         or
>has deadlocked due to bugs or hardware failure.
>Feb 21 09:30:14 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: I
>SendMessage mythcorecontext.cpp:451 (ConnectCommandSocket)
>MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
>Feb 21 09:30:14 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: E
>MythSocketThread(-1) mythsocket.cpp:697 (ConnectToHostReal)
>MythSocket(7f1de800fa30:-1): Failed to connect to (127.0.0.1:6543) Con
>Feb 21 09:30:14 mythtv1804 mythpreviewgen[3973]: mythpreviewgen[3973]: E
>SendMessage mythcorecontext.cpp:521 (ConnectCommandSocket) Connection to
>master server timed out.
>
> Either the server is down or the master server settings
>                                                                         in
>mythtv-settings does not contain the proper IP address
>Feb 21 09:30:14 mythtv1804 systemd[1]: mythtv-backend.service: Main process
>exited, code=killed, status=11/SEGV
>Feb 21 09:30:14 mythtv1804 mythcommflag[31506]: mythcommflag[31506]: N
>MythSocketThread(-1) mythcorecontext.cpp:1627 (connectionClosed)
>MythCoreContext::connectionClosed(): Event socket closed.  No conne
>Feb 21 09:30:14 mythtv1804 mythcommflag[31532]: mythcommflag[31532]: N
>MythSocketThread(-1) mythcorecontext.cpp:1627 (connectionClosed)
>MythCoreContext::connectionClosed(): Event socket closed.  No conne
>Feb 21 09:30:14 mythtv1804 mythcommflag[31506]: mythcommflag[31506]: C
>CoreContext signalhandling.cpp:305 (handleSignal) Received Terminated: Code
>0, PID 1, UID 0, Value 0x00000000
>Feb 21 09:30:14 mythtv1804 mythcommflag[31532]: mythcommflag[31532]: C
>CoreContext signalhandling.cpp:305 (handleSignal) Received Terminated: Code
>0, PID 1, UID 0, Value 0x00000000
>Feb 21 09:31:44 mythtv1804 systemd[1]: mythtv-backend.service: State
>'stop-sigterm' timed out. Killing.
>Feb 21 09:31:44 mythtv1804 systemd[1]: mythtv-backend.service: Killing
>process 31506 (mythcommflag) with signal SIGKILL.
>Feb 21 09:31:44 mythtv1804 systemd[1]: mythtv-backend.service: Killing
>process 31532 (mythcommflag) with signal SIGKILL.
>Feb 21 09:31:44 mythtv1804 systemd[1]: mythtv-backend.service: Failed with
>result 'signal'.
>Feb 21 09:31:45 mythtv1804 systemd[1]: mythtv-backend.service: Service
>hold-off time over, scheduling restart.
>Feb 21 09:31:45 mythtv1804 systemd[1]: mythtv-backend.service: Scheduled
>restart job, restart counter is at 7.
>Feb 21 09:31:45 mythtv1804 systemd[1]: Stopped MythTV Backend.
>Feb 21 09:31:45 mythtv1804 systemd[1]: Started MythTV Backend.
>
>Running 18.04 with v30+fixes for the backend (KVM image with HDhomerun
>tuners), any suggestions for getting it to look for and tweak, thanks.

You are not reading the log correctly.  The problem is not in
mythcommflag, but is a segfault in mythbackend.  That causes
mythbackend to shut down all its threads and stop talking.  This also
causes all the other things that are talking to it, such as
mythpreviewgen and mythcommflag, to fail and/or die.  When mythbackend
shuts down with a non-zero exit code, systemd restarts it.  This will
include killing any programs run from mythbackend that are still
running, in this case, mythcommflag.

To work out what the actual problem is, you probably need to get a
backtrace from the segfault.  It seems to be happening when a
recording has just stopped, which is a time when there is a fair bit
of activity in mythbackend.

More information about the mythtv-users mailing list