Opened 12 years ago

Closed 12 years ago

#4234 closed defect (fixed)

mythbackend using 1100% of cpu in deadlock

Reported by: johnsonn@… Owned by: Nigel
Priority: blocker Milestone: 0.21
Component: mythtv Version: head
Severity: high Keywords:
Cc: Ticket locked: no

Description

Hello all,

I have had myth running for months, and download and full compile daily.(sometimes more often) Myth present version is 14973M, but myth was working just fine after sunday compile, but I updated and compiled last night and the mythbackend won't even start. I have a dual core 64 bit system, and both cores start running at 100% with the below ASSERT message. I did a rm -r * and redownloaded everything with a full compile and still no go. The only other thing I changed was I removed beagle desktop search and all the related components. Assuming thats where I messed up I put all the components back and did a full compile and still had the problem.

later, Jonathan

mythtv-setup dies the same way

mythbackend -v all


2007-11-27 22:16:38.803 Using runtime prefix = /usr/local 2007-11-27 22:16:38.804 Using localhost value of mythdvr 2007-11-27 22:16:38.804 MCP::DefaultUPnP() - config.xml has default PIN and host USN: uuid:b845a148-9ce2-4fd3-93b9-05d27c64afef::urn:schemas-mythtv-org:device:MasterMediaServer:1 2007-11-27 22:16:38.804 Setting UPnP client for backend autodiscovery... 2007-11-27 22:16:38.804 UPnp - Constructor 2007-11-27 22:16:38.805 ThreadPool:AddWorkerThread - HTTP_WorkerThread 2007-11-27 22:16:38.805 UPnp::Initialize - Begin 2007-11-27 22:16:38.805 UPnp::Initialize - Starting TaskQueue? 2007-11-27 22:16:38.805 UPnp::Initialize - Creating SSDP Thread 2007-11-27 22:16:38.807 UPnp::Initialize - End 2007-11-27 22:16:38.807 UPnp::UPnp:Starting SSDP Thread (Multicast) ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373) ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373)


mythbackend stops loading at this point.

Attachments (1)

4234-dbg-v1.patch (609 bytes) - added by danielk 12 years ago.
Prevents an out of bounds array access in LookupUDN()

Download all attachments as: .zip

Change History (29)

comment:1 Changed 12 years ago by johnsonn@…

I even deleted my whole database (after backing it up of course), and starting over and it still does the same thing.

later, Jonathan

comment:2 Changed 12 years ago by johnsonn@…

Here's the compile script I have been using for at least a year with only changes to the kernel verison made.

make clean ./configure --enable-proc-opt --enable-dvb --dvb-path=/usr/src/linux-2.6.23.9/include --enable-xvmc --enable-xvmc-pro qmake mythtv.pro make -j 3 make install =============================================================\ Results of mythbackend --version

Source code version : 14973M SVN branch : trunk Library API version : 0.21.20071127-1 Network Protocol Version: 36 Options compiled in:

linux release using_oss using_alsa using_arts using_jack using_backend using_dbox2 using_directfb using_dvb using_frontend using_hdhomerun using_iptv using_ivtv using_joystick_menu using_lirc using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmcw using_xvmc_vld using_bindings_perl using_opengl using_live

comment:3 Changed 12 years ago by anonymous

you must use make distclean

comment:4 Changed 12 years ago by Nigel

This could also be a bug in the UPnP stuff. You can check that by deleting ~/.mythtv/config.xml, so that ~/.mythtv/mysql.txt is used instead.

I'm also curious if mythfrontend behaves the same way?

comment:5 Changed 12 years ago by johnsonn@…

To anonymous: I did also do the make distclean

The mythfrontend loads just fine.

I removed this ~/.mythtv/config.xml and no change. Do I have to do a full recompile???

comment:6 Changed 12 years ago by johnsonn@…

I also re-imported my sql database backup since removing it had no effect.

comment:7 Changed 12 years ago by anonymous

This has something to do with the UPNP fix. If you rename your mysql.txt (find them as they are all over; /usr/share/mythtv/mysql.txt; ~/.mythtv/msyql.txt; /usr/local/share/mythtv/mysql.txt) to mysql.txt.old and try it, the problem goes away (although it defaults at that point)

I actually tried rewriting the mysql.txt's to be consistant and point to my hostname and it still threw that error (only not specifying the hostname fixes it)

My config is Backend/Fronetnd? on same box.

Just my 2 cents Hosts file


localhost 127.0.0.1 MythTV 127.0.0.1

Hostname: MythTV

Dave

comment:8 Changed 12 years ago by mythtv@…

SVN revision 14963 works OK. SVN revision 14964 wont compile. SVN revision 14965 fixes 14964 so it will compile

SVN revision 14965 generates the ASSERT error message and mythbackend does not run.

comment:9 Changed 12 years ago by Nigel

Owner: changed from Isaac Richards to Nigel

Jonathan, sorry we haven't worked this out yet. I will create a patch with extra UPnP debug soon.

I am very surprised that only mythbackend is hanging. Have you tried other programs (e.g. mythcommflag, mythfilldatabase, mythwelcome)?

Could you provide the output from mythfrontend -v upnp?

comment:10 Changed 12 years ago by johnsonn@…

User who suggested deleting/renaming mysql.txt sorry didn't work for me. I also let it run for 8.5 hours and it did not free itself. I will be ready for patch to increase upnp debugging, and compile immediately. mythfilldatabase affected mythwelcome affected mythcommflag affected mythfrotnend unaffected

Here's the mythbackend -v upnp It appears to be exactly the same as previous post except for the date/time stamps.


2007-11-28 16:22:29.973 Using runtime prefix = /usr/local 2007-11-28 16:22:29.974 Using localhost value of mythdvr 2007-11-28 16:22:29.974 MCP::DefaultUPnP() - config.xml has default PIN and host USN: uuid:b845a148-9ce2-4fd3-93b9-05d27c64afef::urn:schemas-mythtv-org:device:MasterMediaServer:1 2007-11-28 16:22:29.974 Setting UPnP client for backend autodiscovery... 2007-11-28 16:22:29.975 UPnp - Constructor 2007-11-28 16:22:29.975 ThreadPool:AddWorkerThread - HTTP_WorkerThread 2007-11-28 16:22:29.975 UPnp::Initialize - Begin 2007-11-28 16:22:29.975 UPnp::Initialize - Starting TaskQueue? 2007-11-28 16:22:29.975 UPnp::Initialize - Creating SSDP Thread 2007-11-28 16:22:29.977 UPnp::Initialize - End 2007-11-28 16:22:29.977 UPnp::UPnp:Starting SSDP Thread (Multicast) ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373) ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373)

comment:11 Changed 12 years ago by johnsonn@…

Hello all,

These are the lines of code added by the new patch 14977


2007-11-28 16:59:17.484 UPnp::Initialize - Creating SSDP Thread at port 6549 2007-11-28 16:59:17.486 UPnp::Initialize - End 2007-11-28 16:59:17.486 UPnp::Start - Starting SSDP Thread (Multicast) 2007-11-28 16:59:17.486 UPnp::Start - Enabling Notifications ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373) ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373)

comment:12 in reply to:  10 Changed 12 years ago by Nigel

Replying to johnsonn@matc.edu:

Here's the mythbackend -v upnp It appears to be exactly the same as previous post except for the date/time stamps.


2007-11-28 16:22:29.973 Using runtime prefix = /usr/local 2007-11-28 16:22:29.974 Using localhost value of mythdvr 2007-11-28 16:22:29.974 MCP::DefaultUPnP() - config.xml has default PIN and host USN: uuid:b845a148-9ce2-4fd3-93b9-05d27c64afef::urn:schemas-mythtv-org:device:MasterMediaServer:1 2007-11-28 16:22:29.974 Setting UPnP client for backend autodiscovery...

1) Just committed more debug.

2) That is still showing that its loading config.xml. Maybe do 'find / -name config.xml' to work out what directory it is getting this file from? (and then delete it) That should get you working again, though if you have the time to compile/install/report, I would like to get to the bottom of this hang.

comment:13 Changed 12 years ago by johnsonn@…

if you have the time to compile/install/report, I would like to get to the bottom of this hang. Keep the debug code coming. I don't need to record anything till Saturday at 9am CST. Latest svn update results in:


007-11-28 17:39:49.512 ThreadPool:AddWorkerThread - HTTP_WorkerThread 2007-11-28 17:39:49.513 UPnp::Initialize - Begin 2007-11-28 17:39:49.513 UPnp::Initialize - Starting TaskQueue? 2007-11-28 17:39:49.513 UPnp::Initialize - Creating SSDP Thread at port 6549 2007-11-28 17:39:49.515 UPnp::Initialize - End 2007-11-28 17:39:49.515 UPnp::Start - Starting SSDP Thread (Multicast) 2007-11-28 17:39:49.515 UPnp::Start - Enabling Notifications 2007-11-28 17:39:49.515 SSDP::EnableNotifications?() - creating new task 2007-11-28 17:39:49.515 SSDP::EnableNotifications?() - sending NTS_byebye ASSERT: "i <= nodes" in /usr/lib/qt3/include/qvaluelist.h (373)

comment:14 Changed 12 years ago by johnsonn@…

Only to help the diagnostic process I renamed config.xml That works, so at least I have an emergency plan. I changed the file back to config.xml so further testing can occur. You'll notice the "NTS alive" is never reached

Later, Jonathan


2007-11-28 17:58:33.568 SSDP::EnableNotifications?() - creating new task 2007-11-28 17:58:33.569 SSDP::EnableNotifications?() - sending NTS_byebye 2007-11-28 17:58:34.925 SSDP::EnableNotifications?() - sending NTS_alive 2007-11-28 17:58:34.925 SSDP::EnableNotifications?() - Task added to UPnP queue 2007-11-28 17:58:34.925 UPnp::Start - Returning 2007-11-28 17:58:34.925 MediaServer::End 2007-11-28 17:58:34.925 Main::Registering HttpStatus? Extension


Changed 12 years ago by danielk

Attachment: 4234-dbg-v1.patch added

Prevents an out of bounds array access in LookupUDN()

comment:15 Changed 12 years ago by danielk

Milestone: 0.220.21

Nigel, I have spent all of 15 seconds on this, only because I couldn't run mythtv-setup. So I have no idea if this patch is correct; I didn't even check to see if the users of LookupUDN() are checking for null returns. But the existing code was getting stuck in an infinite loop after trying to access item # -2 in a linked list of size 0. With this patch it just prints this instead:

2007-11-28 19:20:01.665 LookupUDN(), Error: Not enough tokens

comment:16 Changed 12 years ago by johnsonn@…

The mythbackend works now Yeah!!! However, I am getting error message listed above about now enough tokens. Is that bad, should I be doing something to resolve said error.

comment:17 Changed 12 years ago by Nigel

Status: newassigned

comment:18 Changed 12 years ago by Nigel

(In [14982]) Apply (modified version of) 15sec. fix from Daniel. See #4234

comment:19 in reply to:  16 Changed 12 years ago by anonymous

Replying to johnsonn@matc.edu:

Is that bad, should I be doing something to resolve said error.

Not hugely bad, but I am curious about why. Feel free to attach/include the output from the SVN patch of libs/libmythupnp/upnputil.cpp

comment:20 Changed 12 years ago by johnsonn@…

results from mythbackend -v upnp


2007-11-28 22:02:00.894 UPnp::Initialize - Begin 2007-11-28 22:02:00.895 UPnp::Initialize - Starting TaskQueue? 2007-11-28 22:02:00.895 UPnp::Initialize - Creating SSDP Thread at port 6544 2007-11-28 22:02:00.898 UPnp::Initialize - End 2007-11-28 22:02:00.898 MediaServer::Loading UPnp Description 2007-11-28 22:02:00.899 MediaServer::Registering MythXML Service. 2007-11-28 22:02:00.900 MediaServer::Registering MSRR Service. 2007-11-28 22:02:00.900 MediaServer::Registering CMGR Service. 2007-11-28 22:02:00.900 MediaServer::Registering CDS Service. 2007-11-28 22:02:00.901 MediaServer::Registering UPnpCDSTv Extension 2007-11-28 22:02:00.901 MediaServer::Registering UPnpCDSMusic Extension 2007-11-28 22:02:00.901 MediaServer::Registering UPnpCDSVideo Extension 2007-11-28 22:02:00.902 UPnp::Start - Starting SSDP Thread (Multicast) 2007-11-28 22:02:00.902 UPnp::Start - Enabling Notifications 2007-11-28 22:02:00.902 SSDP::EnableNotifications?() - creating new task 2007-11-28 22:02:00.902 SSDP::EnableNotifications?() - sending NTS_byebye 2007-11-28 22:02:01.679 LookupUDN(urn:schemas-mythtv-org:device:MasterMediaServer:1) sName=UPnP/UDN/MasterMediaServer, sUDN=b845a148-9ce2-4fd3-93b9-05d27c64afef 2007-11-28 22:02:02.145 SSDP::EnableNotifications?() - sending NTS_alive 2007-11-28 22:02:02.145 SSDP::EnableNotifications?() - Task added to UPnP queue 2007-11-28 22:02:02.145 UPnp::Start - Returning 2007-11-28 22:02:02.145 MediaServer::End 2007-11-28 22:02:02.145 Main::Registering HttpStatus? Extension 2007-11-28 22:02:02.145 mythbackend version: 0.21.20071127-1 www.mythtv.org 2007-11-28 22:02:02.145 Enabled verbose msgs: important general upnp 2007-11-28 22:02:02.146 AutoExpire?: Found max recording rate of 0 MB/min 2007-11-28 22:02:02.146 AutoExpire?: CalcParams?(): Required Free Space: 1.0 GB w/freq: 15 min 2007-11-28 22:02:03.898 Reschedule requested for id -1. 2007-11-28 22:02:03.919 Invalid search key in recordid 51 2007-11-28 22:02:03.919 Invalid search key in recordid 52 2007-11-28 22:02:03.919 Invalid search key in recordid 81

comment:21 Changed 12 years ago by anonymous

Also random segmentation faults that don't happen all the time just sometimes. I re-run the backend and everything is fine again.


2007-11-28 22:10:58.356 UPnp - Constructor 2007-11-28 22:10:58.357 ThreadPool:AddWorkerThread - HTTP_WorkerThread 2007-11-28 22:10:58.357 UPnp::Initialize - Begin 2007-11-28 22:10:58.357 UPnp::Initialize - Starting TaskQueue? 2007-11-28 22:10:58.357 UPnp::Initialize - Creating SSDP Thread at port 6549 2007-11-28 22:10:58.359 UPnp::Initialize - End 2007-11-28 22:10:58.359 UPnp::Start - Starting SSDP Thread (Multicast) 2007-11-28 22:10:58.360 UPnp::Start - Enabling Notifications 2007-11-28 22:10:58.360 SSDP::EnableNotifications?() - creating new task 2007-11-28 22:10:58.360 SSDP::EnableNotifications?() - sending NTS_byebye 2007-11-28 22:10:58.360 LookupUDN()- bad device type, not enough tokens 2007-11-28 22:10:58.787 SSDP::EnableNotifications?() - sending NTS_alive 2007-11-28 22:10:58.788 SSDP::EnableNotifications?() - Task added to UPnP queue 2007-11-28 22:10:58.788 UPnp::Start - Returning 2007-11-28 22:10:58.931 Cannot find default UPnP backend 2007-11-28 22:10:58.931 MythSocket?(2aaaac000b00:11): new socket 2007-11-28 22:10:58.931 MythSocket?(2aaaac000b00:11): attempting connect() to (0.0.0.0:3306) 2007-11-28 22:10:58.931 MythSocket?(2aaaac000b00:11): state change Idle -> Connected 2007-11-28 22:10:58.931 MythSocket?(2aaaac000b00:11): state change Connected -> Idle 2007-11-28 22:10:58.937 New DB connection, total: 1 2007-11-28 22:10:58.940 Connected to database 'mythconverg' at host: 127.0.0.1 2007-11-28 22:10:58.940 Closing DB connection named 'DBManager0' 2007-11-28 22:10:58.940 Clearing Settings Cache. 2007-11-28 22:10:58.941 Deleting UPnP client... 2007-11-28 22:10:58.941 UPnp - Destructor 2007-11-28 22:10:58.941 UPnp::CleanUp?() - disabling SSDP notifications 2007-11-28 22:10:59.127 UPnp::CleanUp?() - requesting SSDP terminate Segmentation fault mythdvr:~/svn/mythtv #

comment:22 Changed 12 years ago by Nigel

(In [15014]) Prevent empty verbose line, eliminate one UPnP error (see #4234. see #4249).

comment:23 Changed 12 years ago by eric.bosch@…

I am running build 15016 and am experiencing random segfaults.

mythfilldatabas[6711]: segfault at 0000000000000021 rip 00002af88a303bf0 rsp 0000000041004958 error 4 mythcommflag[6798]: segfault at 0000000000000019 rip 00002b0dfd8fe60e rsp 0000000041004960 error 4 mythcommflag[6864]: segfault at 0000000000000021 rip 00002b0413fdabf0 rsp 0000000041004958 error 4

comment:24 Changed 12 years ago by Nigel

Eric, try debug.patch in ticket http://svn.mythtv.org/trac/ticket/4249, and please provide -v all output

comment:25 Changed 12 years ago by Nigel

(In [15020]) Work around random segfaults in UPnpNotifyTask::Execute() when disabling SSDP notifications. See #4234. See #4249. It seems that m_addressList has some bad values (not NULL, but not valid QStr). Suspect QString thread problem, but a QDeepCopy of the string or the stringlist does nothing. Deleting the threads before the SSDP object seems safe.

comment:26 Changed 12 years ago by johnsonn@…

Why is there not more diagnostic data available for UPNP so people can help diagnose problems?? For "-v upnp" supposing to be verbose, it is not. I can not tell if UPNP found any of my UPNP compatible devices, nor can I tell why they are not working. In my humble opinion "-v upnp" should report on every send and receive command sent over the network. If a device does not work the log should say I sent out this request and was expecting this response, but I got <raw packet dump here(in ascii and hex)> Then we can manual interpet the response data and build a patch much easier. Also I believe there should be a GUI entry for UPNP under settings or something that lists all detected devices and there status. If a device is broken it should say something like "broken at phase 2" or "devices response fails at phase 1". Maybe a section where we can assist the decoding process by telling mythtv at what offset to find the data it is expecting. I would be willing to apply patches, and report results.

comment:27 in reply to:  26 Changed 12 years ago by anonymous

Replying to johnsonn@matc.edu:

I can not tell if UPNP found any of my UPNP compatible devices

These lines show that:

2007-12-06 07:53:26.453 UPnpNotifyTask::SendNotifyMsg : 239.255.255.250 : upnp:rootdevice : uuid:1b8ec80a-2972-48fe-ba80-bc060d34925e::upnp:rootdevice
2007-12-06 07:53:26.453 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.7
2007-12-06 07:53:26.482 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.6
.......2007-12-06 07:53:26.720 UPnpNotifyTask::SendNotifyMsg : 239.255.255.250 : uuid:1b8ec80a-2972-48fe-ba80-bc060d34925e : uuid:1b8ec80a-2972-48fe-ba80-bc060d34925e
2007-12-06 07:53:26.720 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.7
.........2007-12-06 07:53:26.964 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.6
...2007-12-06 07:53:27.022 UPnpNotifyTask::SendNotifyMsg : 239.255.255.250 : urn:schemas-upnp-org:device:MediaRenderer:1 : uuid:1b8ec80a-2972-48fe-ba80-bc060d34925e::urn:schemas-upnp-org:device:MediaRenderer:1
2007-12-06 07:53:27.022 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.7
.2007-12-06 07:53:27.045 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.6
.2007-12-06 07:53:27.078 UPnpNotifyTask::SendNotifyMsg : 239.255.255.250 : urn:schemas-upnp-org:service:ConnectionManager:1 : uuid:1b8ec80a-2972-48fe-ba80-bc060d34925e::urn:schemas-upnp-org:service:ConnectionManager:1
2007-12-06 07:53:27.078 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.7
.2007-12-06 07:53:27.111 UPnpNotifyTask::SendNotifyMsg() - address: 192.168.0.6
..........................................................
2007-12-06 07:53:28.576 UPnPautoconf() - No UPnP backends found
2007-12-06 07:53:28.576 No UPnP backends found

The "........" are when its waiting for a response, and the last few lines should be fairly self explanatory?


In my humble opinion "-v upnp" should report on every send and receive command sent over the network.

That is possible. I will try to add some -v network UPnP stuff for you.


Also I believe there should be a GUI entry for UPNP under settings or something that lists all detected devices and there status.

Having a GUI setting is difficult, because most of the UPnP happens before there is a database to check settings in, but uncommenting line 1308 of mythcontext.cpp will do a dump of the post-autodiscovery device cache.

Just remember that autodiscovery will not be called if there is a ~/.mythtv/config.xml

comment:28 Changed 12 years ago by Nigel

Resolution: fixed
Status: acceptedclosed

I am hoping that the fix in #4301, which was applied in [15184], completely fixes the original problem. If not, please open a new ticket - this one is too busy to follow.

I haven't added any extra debug. I think snoop or tcpdump are good enough to narrow down any problems.

Note: See TracTickets for help on using tickets.