id summary reporter owner description type status priority milestone component version severity resolution keywords cc mlocked 12314 mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to 100%. Paul Netherwood "Mythbackend locks up during recording after a period of time of usage. This does not happen immediately but after a day or so and often during when 2 or more recordings are occurring simultaneously either on the DVB-T cards, the DVB-S2 card or both. Frontend, mythweb (and mythbackend --setloglevel debug) do not respond. Logs fill up with sockets errors as frontend tries and fails to connect. Mythweb just hangs. CPU is at 100% while deadlock occurs. Eventually after 5 to 15 minutes mythbackend sometimes becomes responsive again. A restart of mythbackend removes the problem temporarily. Disabling the EIT scanner reduces the frequency of the problem and the deadlock only lasts a few minutes. The log files do not show much since logging freezes during deadlock. All that is shown is problems with the sockets. See example logs below. I'm using the latest 0.27.4 fixes and Ubuntu 14.04 with the latest updates. My hardware setup is: 4 x Haupauge Nova-T DVB-T PCI cards 1 x TBS 6920 DVB-S2 PCIe card I am on the latest version of the TBS Drivers which are v141019. All cards are set to record on two Mux's. I am using remote frontend (Acer Revo) using the version of Mythtv and Ubuntu. This problem did not occur in releases prior to 0.27. The hardware setup is unchanged. I have attached a gdb stack dump (a short and a full one). Looking at the thread trace it looks like the scheduler is waiting on a lock. This error seems similar to ticket #9261 but that code has changed quite a bit in scheduler.cpp. The fact that disabling the EIT scanner reduces the frequency of the problem implies its something to do with locking during DVB recording. '''uname -a:''' {{{ Linux mythbackend 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:30:01 UTC 2014 i686 i686 i686 GNU/Linux }}} '''mythbackend --version:''' {{{ MythTV Version : v0.27.4-6-ge0b0027 MythTV Branch : fixes/0.27 Network Protocol : 77 Library API : 0.27.20141016-1 QT Version : 4.8.6 Options compiled in: linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_crystalhd using_dvb using_firewire using_frontend using_hdhomerun using_ceton using_hdpvr using_ivtv using_joystick_menu using_libcrypto using_libdns_sd using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl using_opengl_video using_qtwebkit using_qtscript using_qtdbus using_sdl using_taglib using_v4l2 using_x11 using_xrandr using_xv using_profiletype using_bindings_perl using_bindings_python using_bindings_php using_mythtranscode using_opengl using_vaapi using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2 }}} '''Frontend log:''' {{{ Nov 2 13:26:50 mythrevo3 mythfrontend.real: mythfrontend[1454]: N CoreContext mythmainwindow.cpp:2742 (PauseIdleTimer) Resuming idle timer Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal) MythSocket(ffffffffaad42fc8:49): ReadStringList: Error, timed out after 30000 ms. Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E ProgramInfoLoader mythsocket.cpp:353 (SendReceiveStringList) MythSocket(ffffffffaad42fc8:-1): No response. Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: N ProgramInfoLoader mythcorecontext.cpp:1264 (SendReceiveStringList) Connection to backend server lost Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: N MythSocketThread(-1) mythcorecontext.cpp:1500 (connectionClosed) Event socket closed. No connection to the backend. Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: I ProgramInfoLoader mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E MythSocketThread(-1) mythsocket.cpp:737 (WriteStringListReal) MythSocket(ffffffff8d9ebe50:50): WriteStringList: Error, invalid string list . Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E ProgramInfoLoader mythsocket.cpp:347 (SendReceiveStringList) MythSocket(ffffffff8d9ebe50:50): Failed to send command. Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: C ProgramInfoLoader mythcorecontext.cpp:1307 (SendReceiveStringList) Reconnection to backend server failed Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: I SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 2 13:28:00 mythrevo3 mythfrontend.real: mythfrontend[1454]: W CoreContext playbackbox.cpp:1799 (UpdateUILists) PlaybackBox: SortedList is Empty Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal) MythSocket(ffffffff8d984af0:71): ReadStringList: Error, timed out after 30000 ms. Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E ProgramInfoLoader mythsocket.cpp:353 (SendReceiveStringList) MythSocket(ffffffff8d984af0:-1): No response. Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: N ProgramInfoLoader mythcorecontext.cpp:1264 (SendReceiveStringList) Connection to backend server lost Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: N MythSocketThread(-1) mythcorecontext.cpp:1500 (connectionClosed) Event socket closed. No connection to the backend. Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: I ProgramInfoLoader mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E MythSocketThread(-1) mythsocket.cpp:737 (WriteStringListReal) MythSocket(ffffffffa790d3b0:50): WriteStringList: Error, invalid string list . Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E ProgramInfoLoader mythsocket.cpp:347 (SendReceiveStringList) MythSocket(ffffffffa790d3b0:50): Failed to send command. Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: C ProgramInfoLoader mythcorecontext.cpp:1307 (SendReceiveStringList) Reconnection to backend server failed Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: I SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: W CoreContext playbackbox.cpp:1799 (UpdateUILists) PlaybackBox: SortedList is Empty }}} and also {{{ Nov 3 08:17:15 mythrevo3 mythfrontend.real: mythfrontend[1439]: I SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for module mythgallery Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for module mythgame Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext schemawizard.cpp:118 (Compare) Current MythMusic Schema Version (MusicDBSchemaVer): 1020 Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for module mythmusic Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext serverpool.cpp:404 (listen) Listening on TCP 127.0.0.1:6546 Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext serverpool.cpp:404 (listen) Listening on TCP 192.168.1.63:6546 Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext serverpool.cpp:404 (listen) Listening on TCP [::1]:6546 Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I CoreContext serverpool.cpp:404 (listen) Listening on TCP [fe80::201:6cff:fe6c:caca%eth0]:6546 Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: N CoreContext main.cpp:1062 (RunMenu) Found mainmenu.xml for theme 'Mythbuntu' Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: E MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal) MythSocket(ffffffffa7942570:49): ReadStringList: Error, timed out after 7000 ms. Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: C SendMessage mythcorecontext.cpp:1520 (CheckProtoVersion) Protocol version check failure.#012#011#011#011The response to MYTH_PROTO_VERSION was empty.#012#011#011#011This happens when the backend is too busy to respond,#012#011#011#011or has deadlocked due to bugs or hardware failure. Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: I SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket) MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of 1) Nov 3 08:17:29 mythrevo3 mythfrontend.real: mythfrontend[1439]: E MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal) MythSocket(ffffffffa7942b78:49): ReadStringList: Error, timed out after 7000 ms. }}} '''Backend logs:''' {{{ Oct 30 23:59:46 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[9]: ASK_RECORDING 9 75 0 0 Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:1050 (HandleStateChange) TVRec[9]: Changing from None to RecordingOnly Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:3603 (TuningCheckForHWChange) TVRec[9]: HW Tuner: 9->9 Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: N Scheduler autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2689 (HandleRecordingStatusChange) Tuning recording: ""CSI: Crime Scene Investigation"":Cockroaches: channel 11710 on car did 9, sourceid 4 Oct 31 00:00:15 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:4130 (TuningNewRecorder) TVRec[9]: rec->GetPathname(): '/data1/recordings/11710_20141031000000.mpg' Oct 31 00:03:39 mythbackend mythbackend: mythbackend[2292]: I CoreContext scheduler.cpp:704 (UpdateRecStatus) Updating status for ""CSI: Crime Scene Investigation"":Cockroaches on cardid 9 (Tuning => Recordi ng) Oct 31 00:04:29 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[1]: ASK_RECORDING 1 29 0 0 Oct 31 00:04:29 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[2]: ASK_RECORDING 2 29 0 0 Oct 31 00:04:59 mythbackend mythbackend: mythbackend[2292]: N Scheduler autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:04:59 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2689 (HandleRecordingStatusChange) Started recording: ""The Big Bang Theory"":""The Russian Rocket Reaction"": channel 1028 on cardid 1, sourceid 1 Oct 31 00:05:00 mythbackend mythbackend: mythbackend[2292]: I DVBRead tv_rec.cpp:3399 (RingBufferChanged) TVRec[1]: RingBufferChanged() Oct 31 00:05:00 mythbackend mythbackend: mythbackend[2292]: I DVBRead recordinginfo.cpp:1075 (FinishedRecording) Finished recording The Big Bang Theory ""The Wiggly Finger Catalyst"": channel 1028 Oct 31 00:05:11 mythbackend mythbackend: mythbackend[2292]: I Metadata_27770 jobqueue.cpp:2156 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for ""The Big Bang Theory"":""The Wiggly Finger Catal yst"" recorded from channel 1028 at 2014-10-30T23:36:00Z Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE PrepareToRecord Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE PrepareToRecord Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: E CoreContext mainserver.cpp:970 (customEvent) MainServer: PREVIEW_SUCCESS but no receivers. Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I CoreContext scheduler.cpp:704 (UpdateRecStatus) Updating status for ""The Big Bang Theory"":""The Wiggly Finger Catalyst"" on cardid 1 (Recording = > Recorded) Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(173) mythsocket.cpp:745 (WriteStringListReal) MythSocket(94131d8:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(81) mythsocket.cpp:745 (WriteStringListReal) MythSocket(93a63a0:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(172) mythsocket.cpp:745 (WriteStringListReal) MythSocket(940ca40:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(79) mythsocket.cpp:745 (WriteStringListReal) MythSocket(93ae388:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(175) mythsocket.cpp:745 (WriteStringListReal) MythSocket(940b3e0:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(177) mythsocket.cpp:745 (WriteStringListReal) MythSocket(940f6a8:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:06:42 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2243 (HandleReschedule) Reschedule interrupted, will retry Oct 31 00:11:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:18:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:21:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for CHECK -3 1627 0 UpdateRecStatus2 | The Big Bang Theory | The Wiggly Fi nger Catalyst | Raj feels upset about not being in a relationship, so Penny sets out to find a date and introduces him to a girl he can actually talk to. They hit it off, but when it becomes apparent he ha s been buying her expensive gifts, his friends suspect she is only interested in his wealth. | EP10079709745 Oct 31 00:21:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE Interrupted Oct 31 00:21:50 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 923 items in 50.8 = 0.11 match + 0.09 check + 50.62 place Oct 31 00:25:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:32:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:35:16 mythbackend mythbackend: mythbackend[2292]: I Metadata_27772 jobqueue.cpp:2156 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for ""The Big Bang Theory"":""The Russian Rocket Reac tion"" recorded from channel 1028 at 2014-10-31T00:05:00Z Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(65) mythsocket.cpp:745 (WriteStringListReal) MythSocket(940c250:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(64) mythsocket.cpp:745 (WriteStringListReal) MythSocket(9400490:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(79) mythsocket.cpp:745 (WriteStringListReal) MythSocket(93fa120:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:40:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min Oct 31 00:41:01 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent tv_rec.cpp:1050 (HandleStateChange) TVRec[1]: Changing from RecordingOnly to None Oct 31 00:41:02 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent recordinginfo.cpp:1075 (FinishedRecording) Finished recording The Big Bang Theory ""The Russian Rocket Reaction"": channel 1028 Oct 31 00:48:51 mythbackend mythbackend: mythbackend[2292]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: I CoreContext scheduler.cpp:704 (UpdateRecStatus) Updating status for ""The Big Bang Theory"":""The Russian Rocket Reaction"" on cardid 1 (Recording => Recorded) Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for CHECK -3 1627 0 UpdateRecStatus2 | The Big Bang Theory | The Russian R ocket Reaction | Sheldon's old adversary Wil Wheaton returns and invites everyone to a housewarming party. Leonard is eager to go, but Sheldon threatens to shun him if he attends. However, he soon changes his mind when he finds out that Star Trek: The Next Generation actor Brent Spiner will also be there. | EP10079709755 Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(59) mythsocket.cpp:745 (WriteStringListReal) MythSocket(92be3b8:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(61) mythsocket.cpp:745 (WriteStringListReal) MythSocket(93aaff8:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E MythSocketThread(64) mythsocket.cpp:745 (WriteStringListReal) MythSocket(93fac78:-1): WriteStringList: Error, called with unconnected socket. Oct 31 00:53:07 mythbackend mythbackend: mythbackend[2292]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor }}} " Bug Report - Hang/Deadlock closed major 0.27.5 MythTV - General 0.27.4 medium Invalid deadlock 100% CPU 0