[mythtv] deadlock?? problem, but not when running mythbackend through gdb
Robert Verspuy
robert at exa-omicron.nl
Sun Oct 2 13:12:21 UTC 2011
I've bin trying for a while now, but I can't seem to find what exactly
is going wrong.
I'm using CentOS 6 (latest updates), and just downloaded today mythtv
from github.
When running mythbackend with loglevel debug and verbose all, I see the
following message in mythfrontend
> 2011-10-02 15:02:57.499332 I MythCoreContext: Connecting to backend
> server: 10.84.100.60:6543 (try 1 of 1)
> 2011-10-02 15:02:57.499342 D MythSocket(14a7760:-1): new socket
> 2011-10-02 15:02:57.499361 I MythSocket(14a7760:-1): IP is local,
> using loopback address instead
> 2011-10-02 15:02:57.499367 I MythSocket(14a7760:-1): attempting
> connect() to (127.0.0.1:6543)
> 2011-10-02 15:02:57.499370 I MSocketDevice::connect: setting Protocol
> to IPv4
> 2011-10-02 15:02:57.499372 I MSocketDevice::connect: attempting to
> create new socket
> 2011-10-02 15:02:57.499428 D MythSocket(14a7760:69): state change
> Idle -> Connected
> 2011-10-02 15:02:57.499439 I MythSocket(14a7760:69): write -> 69
> 30 MYTH_PROTO_VERSION 69 63835135
> 2011-10-02 15:02:57.499459 D MythSocket(14a7760:69):
> writeBlock(0x1550488, 38)
> 2011-10-02 15:03:00.087801 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:00.087835 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:00.187965 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:00.187991 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:00.288139 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:00.288164 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:02.538408 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:02.538434 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:02.638577 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:02.638601 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:02.738812 D SSDP::ProcessData - requestLine:
> M-SEARCH * HTTP/1.1
> 2011-10-02 15:03:02.738836 D SSDP::ProcessSearchrequest :
> [urn:schemas-upnp-org:device:MediaServer:1] MX=2
> 2011-10-02 15:03:04.503860 E MythSocket(14a7760:69): readStringList:
> Error, timed out after 7000 ms.
> 2011-10-02 15:03:04.503868 D MythSocket(14a7760:69): state change
> Connected -> Idle
> 2011-10-02 15:03:04.503887 D MSocketDevice::close: Closed socket 69
> 2011-10-02 15:03:04.503893 C 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 in due to bugs or hardware failure.
> 2011-10-02 15:03:04.503899 D MythSocket(14a7760:-1): DownRef: -1
> 2011-10-02 15:03:04.503903 D MythSocket(14a7760:-1): delete socket
In the backend, I don't see any logging line from this incomming
connection, totally nothing.
But when I start the mythbackend through gdb with gdb --args
/usr/local/bin/mythbackend --loglevel debug -v all
I see the following, when a mythfrontend is connecting.
>
> [New Thread 0x7fff8ebfd700 (LWP 29056)]
> [New Thread 0x7fff8e1fc700 (LWP 29057)]
> 2011-10-02 15:06:26.851946 D MythSocket(c681e0:-1): new socket
> 2011-10-02 15:06:26.851957 D MythSocket(c681e0:-1): setSocket: 57
> 2011-10-02 15:06:26.851967 D MSocketDevice::setBlocking(false)
> 2011-10-02 15:06:26.851976 D MythSocket(c681e0:57): state change Idle
> -> Connected
> 2011-10-02 15:06:26.852836 D MythSocketThread: readyread thread start
> 2011-10-02 15:06:26.852844 D MythSocketThread: ProcessAddRemoveQueues
> 2011-10-02 15:06:26.852848 D MythSocketThread: Construct FD_SET
> 2011-10-02 15:06:26.852851 D MythSocketThread: Empty FD_SET, sleeping
> 2011-10-02 15:06:26.852870 D MythSocket(c681e0:57): UpRef: 1
> 2011-10-02 15:06:26.852887 D MythSocketThread: Empty FD_SET, woken up
> 2011-10-02 15:06:26.852889 D MythSocketThread: ProcessAddRemoveQueues
> 2011-10-02 15:06:26.852894 D MythSocketThread: Construct FD_SET
> 2011-10-02 15:06:26.852915 D MythSocketThread: Waiting on select..
> 2011-10-02 15:06:26.852924 D MythSocketThread: Got data on select
> 2011-10-02 15:06:26.852927 D MythSocketThread: Processing ready reads
> 2011-10-02 15:06:26.852937 D MythSocketThread(sock 0xc681e0:57):
> socket is readable
> 2011-10-02 15:06:26.852951 D MythSocketThread(sock 0xc681e0:57):
> calling m_cb->readyRead()
> 2011-10-02 15:06:26.852959 D MythSocket(c681e0:57): UpRef: 2
> 2011-10-02 15:06:26.853690 D MythSocketThread: Total read time: 1ms,
> on sockets {57,1ms}
> 2011-10-02 15:06:26.853696 D MythSocketThread: Reacquired ready read lock
> 2011-10-02 15:06:26.853699 D MythSocketThread: ProcessAddRemoveQueues
> 2011-10-02 15:06:26.853703 D MythSocketThread: Construct FD_SET
> 2011-10-02 15:06:26.853705 D MythSocketThread: Empty FD_SET, sleeping
> 2011-10-02 15:06:26.853757 D MythSocketThread: Empty FD_SET, woken up
> 2011-10-02 15:06:26.853763 D MythSocketThread: ProcessAddRemoveQueues
> 2011-10-02 15:06:26.853779 D MythSocketThread: Construct FD_SET
> 2011-10-02 15:06:26.853787 D MythSocketThread: Empty FD_SET, sleeping
> 2011-10-02 15:06:26.853797 D MythSocket(c681e0:57):
> readBlock(0x7fff7800b348, 8) called
> 2011-10-02 15:06:26.853817 D MythSocket(c681e0:57):
> readBlock(0x7fff7800b388, 30) called
> 2011-10-02 15:06:26.853838 I MythSocket(c681e0:57): read <- 57
> 30 MYTH_PROTO_VERSION 69 63835135
> 2011-10-02 15:06:26.853851 D MythSocketThread: Empty FD_SET, woken up
> 2011-10-02 15:06:26.853853 D command='MYTH_PROTO_VERSION'
> 2011-10-02 15:06:26.853859 D MythSocketThread: ProcessAddRemoveQueues
> 2011-10-02 15:06:26.853863 D MythSocketThread: Construct FD_SET
> 2011-10-02 15:06:26.853865 D MythSocketThread: Empty FD_SET, sleeping
> 2011-10-02 15:06:26.853870 I MythSocket(c681e0:57): write -> 57
> 13 ACCEPT[]:[]69
> 2011-10-02 15:06:26.853878 D MythSocket(c681e0:57):
> writeBlock(0x7fff7800c558, 21)
> 2011-10-02 15:06:26.853915 D MythSocket(c681e0:57): DownRef: 1
> <cut>
So inside gdb it has no problem connecting to mythbackend, but without
gdb, it can not.
I assume it's some kind of timing issue?
What to do next...
Can somebody point me into the right direction for further debugging or
do I have to create a bugreport on trac for this?
I also had this same issue on the v0.24.1 version from atrpms for centos
6, but it seems this problem still exists in the latest git version.
I already completelly disabled ipv6 on the server, just to be sure.
With kind regards,
Robert Verspuy
--
*Exa-Omicron*
Patroonsweg 10
3892 DB Zeewolde
Tel.: 088-OMICRON (66 427 66)
http://www.exa-omicron.nl
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.mythtv.org/pipermail/mythtv-dev/attachments/20111002/d65ee32f/attachment.html
More information about the mythtv-dev
mailing list