[mythtv-commits] Ticket #3720: Backend can recursively send messages to itself with a socket to connected to itself
MythTV
mythtv at cvs.mythtv.org
Fri Jul 13 04:17:29 UTC 2007
#3720: Backend can recursively send messages to itself with a socket to connected
to itself
-----------------------+----------------------------------------------------
Reporter: anonymous | Owner: ijr
Type: defect | Status: new
Priority: minor | Milestone: unknown
Component: mythtv | Version: head
Severity: medium | Mlocked: 0
-----------------------+----------------------------------------------------
I have been tracking down an issue that I have been seeing for a while now
where my master backend will get into a nice loop where it will
continually send BACKEND_MESSAGES to it's self, and in doing so process
the message again, and repeat the process. This tends to make the backend
not very responsive after that, and tho while it generally does not crash,
it does not respond to things in a timely manner.
This is a snippet from a log showing the symptom: (pruned a bit w/ some of
my debug)
{{{
2007-07-12 20:58:39.117 write -> 25 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.128 read <- 22 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.178 MythEvent: RECORDING_LIST_CHANGE
2007-07-12 20:58:39.316 write -> 19 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.335 write -> 25 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.350 GAD: Got a event that we might want to
redistribute RECORDING_LIST_CHANGE
2007-07-12 20:58:39.358 read <- 22 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.374 MythEvent: RECORDING_LIST_CHANGE
2007-07-12 20:58:39.468 write -> 19 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.481 write -> 25 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.489 GAD: Got a event that we might want to
redistribute RECORDING_LIST_CHANGE
2007-07-12 20:58:39.615 read <- 22 51
BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
2007-07-12 20:58:39.646 MythEvent: RECORDING_LIST_CHANGE
}}}
I believe that the culprit to this problem is there are some cases where
ConnectToMasterServer can be called despite the fact that we *ARE* the
master server.
I see this in the log:
{{{
2007-07-12 22:31:27.930 read <- 14 543 QUERY_GENPIXMAP[]:[]Modern
Marvels[]:[]It Came From Outer Space[]...
2007-07-12 22:31:27.960 MythSocket(2aaaac1a1870:20): new socket
2007-07-12 22:31:27.973 Connecting to backend server: 192.168.1.10:6543
(try 1 of 5)
2007-07-12 22:31:27.982 MythSocket(2aaaac17bfe0:21): new socket
2007-07-12 22:31:27.990 MythSocket(2aaaac17bfe0:21): attempting connect()
to (192.168.1.10:6543)
2007-07-12 22:31:27.998 MythSocket(2aaaac17bfe0:21): state change Idle ->
Connected
2007-07-12 22:31:27.998 MythSocket(7183f0:23): new socket
2007-07-12 22:31:28.006 write -> 21 21 MYTH_PROTO_VERSION 34
2007-07-12 22:31:28.024 MythSocket(7183f0:23): setSocket: 22
2007-07-12 22:31:28.050 MythSocket(7183f0:22): state change Idle ->
Connected
2007-07-12 22:31:28.058 MythSocket(7183f0:22): UpRef: 1
2007-07-12 22:31:28.066 MythSocket(7183f0:22): socket is readable
2007-07-12 22:31:28.081 MythSocket(7183f0:22): cb->readyRead()
2007-07-12 22:31:28.090 MythSocket(7183f0:22): UpRef: 2
2007-07-12 22:31:28.098 read <- 22 21 MYTH_PROTO_VERSION 34
2007-07-12 22:31:28.102 write -> 22 13 ACCEPT[]:[]34
2007-07-12 22:31:28.103 read <- 21 13 ACCEPT[]:[]34
2007-07-12 22:31:28.106 Using protocol version 34
2007-07-12 22:31:28.107 write -> 21 33 ANN Monitor palidor 0 pid8391
2007-07-12 22:31:28.103 MythSocket(7183f0:22): DownRef: 1
2007-07-12 22:31:28.108 MythSocket(7183f0:22): socket is readable
2007-07-12 22:31:28.118 MythSocket(7183f0:22): cb->readyRead()
2007-07-12 22:31:28.119 MythSocket(7183f0:22): UpRef: 2
2007-07-12 22:31:28.120 read <- 22 33 ANN Monitor palidor 0 pid8391
2007-07-12 22:31:28.125 MainServer::HandleAnnounce Monitor
2007-07-12 22:31:28.126 adding: palidor as a client (events: 0)
2007-07-12 22:31:28.127 write -> 22 2 OK
2007-07-12 22:31:28.128 read <- 21 2 OK
2007-07-12 22:31:28.134 MythSocket(2aaaac1a1870:20): attempting connect()
to (192.168.1.10:6543)
2007-07-12 22:31:28.135 MythSocket(2aaaac1a1870:20): state change Idle ->
Connected
2007-07-12 22:31:28.136 write -> 20 33 ANN Monitor palidor 1 pid8391
2007-07-12 22:31:28.135 MythSocket(87d140:24): new socket
2007-07-12 22:31:28.129 MythSocket(7183f0:22): DownRef: 1
2007-07-12 22:31:28.142 MythSocket(87d140:24): setSocket: 23
2007-07-12 22:31:28.154 MythSocket(87d140:23): state change Idle ->
Connected
2007-07-12 22:31:28.156 MythSocket(87d140:23): UpRef: 1
2007-07-12 22:31:28.157 MythSocket(87d140:23): socket is readable
2007-07-12 22:31:28.164 MythSocket(87d140:23): cb->readyRead()
2007-07-12 22:31:28.166 MythSocket(87d140:23): UpRef: 2
2007-07-12 22:31:28.173 read <- 23 33 ANN Monitor palidor 1 pid8391
2007-07-12 22:31:28.178 MainServer::HandleAnnounce Monitor
2007-07-12 22:31:28.182 adding: palidor as a client (events: 1)
2007-07-12 22:31:28.183 write -> 23 2 OK
2007-07-12 22:31:28.190 read <- 20 2 OK
}}}
Once these extra sockets are created, it's only a matter of time before
things going awry.
I think this can be re-created in several different ways, however I did
find one sure fire one -- backtrace:
{{{
#0 MythContext::ConnectServer (this=0x6beab0, eventSock=0x2aaaac00e040,
hostname=@0x4800fc60, port=6543, blockingClient=false)
at mythcontext.cpp:880
#1 0x00002aaba6f1f97b in MythContext::ConnectToMasterServer
(this=0x6beab0, blockingClient=false) at mythcontext.cpp:867
#2 0x00002aaba6f1fa88 in MythContext::SendReceiveStringList
(this=0x6beab0, strlist=@0x4800fef0, quickTimeout=false, block=true)
at mythcontext.cpp:2451
#3 0x00002aaba5a316bf in RemoteCheckFile (pginfo=0x2aaaac10ea00,
checkSlaves=true) at remoteutil.cpp:117
#4 0x00002aaba599a18b in ProgramInfo::MarkAsInUse (this=0x2aaaac10ea00,
inuse=true, usedFor=@0x48010370) at programinfo.cpp:4019
#5 0x00002aaba5c65886 in NuppelVideoPlayer (this=0x2aaaac183720,
inUseID=@0x480106d0, info=0x2aaaac116640)
at NuppelVideoPlayer.cpp:269
#6 0x00002aaba5af8018 in PreviewGenerator::GetScreenGrab
(pginfo=0x2aaaac116640, filename=@0x2aaaac1166a0, secondsin=64,
bufferlen=@0x4801087c, video_width=@0x48010878,
video_height=@0x48010874, video_aspect=@0x48010870) at
previewgenerator.cpp:481
#7 0x000000000044b8e4 in MainServer::HandleGenPreviewPixmap
(this=0x2aaaac00af50, slist=@0x48010dd0, pbs=0x2aaaac0354d0)
at mainserver.cpp:3580
}}}
What I do here is using mythweb to retrieve the recording list, it needs
to generate a pixmap for a recording that was recorded on a slave backend.
I'd make a patch to fix something here, but I'm not sure appropriate fix,
and/or which aspect of this is a bug vs a feature.
Some Questions:
Is it ok for the MBE to open a socket to himself to receive events on?
Is it ok for the MBE to redistribute BACKEND_MESSAGES to all of the
sockets connected? or should there be a recursion check in there?
I've found this one case that will reproduce it, but I have a hunch there
there are more. (like the clearsettingscache on backend/main.cpp:487 seems
like it would also trigger it.) Obviously it might be better to prevent
the "bad stuff" from occuring, rather than trying to track down all of the
places that open sockets to the MBE.
If a dev wants to make a suggestion of how to proceed, then I'll gladly
patch/test this case. I finally took the time to track it down, but this
has been plaguing me for months. I have also noticed another with this
problem: [http://www.gossamer-threads.com/lists/mythtv/users/270452]
My myth config if it matters: Master BE/FE with 2 HD tuners and *all* the
storage. [diskless] slave BE/FE with pvr-150 recording to nfs storage on
master. MBO is on. Addtional frontends.
Any questions, feel free.
--
Ticket URL: <http://svn.mythtv.org/trac/ticket/3720>
MythTV <http://svn.mythtv.org/trac>
MythTV
More information about the mythtv-commits
mailing list