mythfilldatabase hangs on MacOS in QFSFileEnginePrivate::nativeRead

[Andy Stevenson <lists@…>]

I have a patch that fixes (works around) the hang in mythfilldatabase on MacOS.

According to some old posts, this bug appeared in 0.22 and is still present in 0.23. It worked fine in 0.21.

Reference post with stack trace:

​http://www.gossamer-threads.com/lists/mythtv/users/411232

I have been running for several days with my patch, and it's working well. I am using 0.23-fixes.

The bug is that QFSFileEnginePrivate::nativeRead does not correctly exit from its read loop when the end-of-stream is reached. Instead, it gets stuck in a loop with errno==EINTR.

GDB backtrace:

• 0 0x9029d153 in fgetc ()
• 1 0x8ea6acee in QFSFileEnginePrivate::nativeRead ()
• 2 0x8ea2e1e0 in QFile::readData ()
• 3 0x8ea34440 in QIODevice::read ()
• 4 0x8cfb397e in copy ()

Though the actual bug is likely down inside Qt, isolating that with a proper test case and producing a safe/correct fix is too high a barrier, so I hope this workaround will suffice for now.

./mythbackend.intel --version Please attach all output as a file in bug reports. MythTV Version : 25586 MythTV Branch : branches/release-0-23-fixes Network Protocol : 23056 Library API : 0.23.1.201000710-1 QT Version : 4.6.0 Options compiled in:

debug darwin_da using_corevideo using_backend using_darwin using_disable_mmx_for_debugging using_firewire using_frontend using_hdhomerun using_iptv using_lirc using_mheg using_opengl_video using_qtwebkit using_appleremote using_bindings_perl using_bindings_python using_darwin_da using_opengl using_ffmpeg_threads using_live using_mheg

[Nigel]

Haven't reproduced yet. tested OK with mythfilldatabase --file, and invoking XMLTV grabber:

% ./mythfilldatabase
2010-09-27 14:56:28.781 Using runtime prefix = /Volumes/Backups/MythTV/.osx-packager/src/myth-svn/mythtv/programs/Resources
2010-09-27 14:56:28.781 Using configuration directory = /Users/nigel/.mythtv
2010-09-27 14:56:28.782 Using localhost value of MacBook.local
2010-09-27 14:56:28.784 New DB connection, total: 1
2010-09-27 14:56:28.785 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:56:28.785 Closing DB connection named 'DBManager0'
2010-09-27 14:56:28.785 Current locale en_US
2010-09-27 14:56:28.785 No locale defaults file for en_US, skipping
2010-09-27 14:56:28.786 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:56:28.788 Loading en_us translation for module mythfrontend
2010-09-27 14:56:28.791 Current MythTV Schema Version (DBSchemaVer): 1263
2010-09-27 14:56:28.795 New DB connection, total: 2
2010-09-27 14:56:28.796 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:56:28.797 Updating source #5 (ZZZZZZ) with grabber /Volumes/Users/nigel/tv_grab_au_oztivo.pl
2010-09-27 14:56:28.798 No channels are configured to use grabber.
2010-09-27 14:56:28.848 Grabber has capabilities: baseline cache preferredmethod  
2010-09-27 14:56:28.898 Grabber prefers method: allatonce
2010-09-27 14:56:28.899 New DB connection, total: 3
2010-09-27 14:56:28.900 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:56:28.901 XMLTV config file is: /Users/nigel/.mythtv/ZZZZZZ.xmltv
2010-09-27 14:56:28.901 New DB connection, total: 4
2010-09-27 14:56:28.902 Connected to database 'mythconverg' at host: 127.0.0.1
/Volumes/Users/nigel/tv_grab_au_oztivo.pl doesn't use config files yet
Use of uninitialized value in concatenation (.) or string at /Volumes/Users/nigel/tv_grab_au_oztivo.pl line 438.
2010-09-27 14:57:01.176 New DB connection, total: 5
2010-09-27 14:57:01.177 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:57:02.006 New DB DataDirect connection
2010-09-27 14:57:02.072 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:57:02.084 New DB connection, total: 6
2010-09-27 14:57:02.086 Connected to database 'mythconverg' at host: 127.0.0.1
2010-09-27 14:57:02.172 IconData: Updating icons for sourceid: 5
2010-09-27 14:57:38.501 Updated programs: 5700 Unchanged programs: 0
2010-09-27 14:57:38.637 Data fetching complete.
2010-09-27 14:57:38.637 Adjusting program database end times.
2010-09-27 14:57:38.687     3 replacements made
2010-09-27 14:57:38.687 Marking generic episodes.
2010-09-27 14:57:38.778     Found 23
2010-09-27 14:57:38.779 Fudging non-unique programids with multiple parts.
2010-09-27 14:57:38.796     Found 0
2010-09-27 14:57:38.797 Marking repeats.
2010-09-27 14:57:38.886     Found 0
2010-09-27 14:57:38.886 Unmarking new episode rebroadcast repeats.
2010-09-27 14:57:38.900     Found 0
2010-09-27 14:57:39.113 Marking episode first showings.
2010-09-27 14:57:44.646     Found 4365
2010-09-27 14:57:44.646 Marking episode last showings.
2010-09-27 14:57:49.571     Found 4365
2010-09-27 14:57:49.574 
===============================================================
| Attempting to contact the master backend for rescheduling.  |
| If the master is not running, rescheduling will happen when |
| the master backend is restarted.                            |
===============================================================
2010-09-27 14:57:49.581 MythCoreContext: Connecting to backend server: 127.0.0.1:6543 (try 1 of 1)
2010-09-27 14:57:49.581 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

2010-09-27 14:57:49.582 Error rescheduling id -1 in ScheduledRecording::signalChange
2010-09-27 14:57:49.582 MythCoreContext: Connecting to backend server: 127.0.0.1:6543 (try 1 of 1)
2010-09-27 14:57:49.582 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

2010-09-27 14:57:49.582 MythCoreContext: Connecting to backend server: 127.0.0.1:6543 (try 1 of 1)
2010-09-27 14:57:49.582 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

2010-09-27 14:57:49.583 mythfilldatabase run complete.
2010-09-27 14:57:49.583 DataDirect: Deleting temporary files

with recent binary:

% ../mythbackend/mythbackend --version
Please attach all output as a file in bug reports.
MythTV Version   : 26426M
MythTV Branch    : trunk
Network Protocol : 62
Library API      : 0.23.20100917-1
QT Version       : 4.6.0
Options compiled in:
 release darwin_da using_corevideo using_backend using_darwin using_firewire using_frontend using_hdhomerun using_iptv using_lirc using_mheg using_opengl_video using_qtdbus using_qtwebkit using_quartz_video using_appleremote using_darwin_da using_mythtranscode using_opengl using_ffmpeg_threads using_live using_mheg

[Andy Stevenson <lists@…>]

I'm using SchedulesDirect? in the US, for which I believe mythfilldatabase uses wget (streaming to stdout).

Here's a dump from my console the night I was working on this.

• Normally it would hang at the end of the transfer, right before printing this line:

  2010-09-18 00:48:33 (38.9 KB/s) - `-' saved [324228] 
  

• I built everything debug and then stopped in the debugger... at the point that it was hung, the number of bytes read was equal to the filesize in bytes (in util.cpp), but the Qt reader kept returning errno==EINTR and never coming back.

$ ./mythfilldatabase 
2010-09-18 00:48:18.330 Using runtime prefix = /Users/andy/mythsrc/packaging/OSX/build/.osx-packager/build/bin
2010-09-18 00:48:18.344 Using configuration directory = /Users/andy/.mythtv
2010-09-18 00:48:18.354 Using localhost value of tinymac
2010-09-18 00:48:18.357 New DB connection, total: 1
2010-09-18 00:48:18.365 Connected to database 'mythconverg' at host: XXX
2010-09-18 00:48:18.365 Closing DB connection named 'DBManager0'
2010-09-18 00:48:18.366 Connected to database 'mythconverg' at host: XXX
2010-09-18 00:48:18.370 Current MythTV Schema Version (DBSchemaVer): 1254
2010-09-18 00:48:18.373 New DB connection, total: 2
2010-09-18 00:48:18.374 Connected to database 'mythconverg' at host: XXX
2010-09-18 00:48:23.860 Updating source #1 (Comcast Cable) with grabber schedulesdirect1
2010-09-18 00:48:23.861 Found 59 channels for source 1 which use grabber
2010-09-18 00:48:23.865 
2010-09-18 00:48:23.865 Checking day @ offset 0, date: Sat Sep 18 2010
2010-09-18 00:48:23.937 Data is already present for Sat Sep 18 2010, skipping
2010-09-18 00:48:23.939 
2010-09-18 00:48:23.939 Checking day @ offset 1, date: Sun Sep 19 2010
2010-09-18 00:48:23.939 Data Refresh always needed for tomorrow
2010-09-18 00:48:23.939 Refreshing data for Sun Sep 19 2010
2010-09-18 00:48:23.939 This DataDirect listings source is shared by 4 MythTV lineups
2010-09-18 00:48:23.940 We should keep data around after this one
2010-09-18 00:48:23.940 New DB DataDirect connection
2010-09-18 00:48:23.941 Connected to database 'mythconverg' at host: XXX
2010-09-18 00:48:23.942 Retrieving datadirect data.
2010-09-18 00:48:23.942 Grabbing data for Sat Sep 18 2010 offset 1
2010-09-18 00:48:23.943 From Sun Sep 19 05:00:00 2010 to Mon Sep 20 05:00:00 2010 (UTC)
2010-09-18 00:48:23.944 Grabbing listing data
2010-09-18 00:48:23.946 DataDirect: Saving listings to DD cache
--2010-09-18 00:48:24--  http://webservices.schedulesdirect.tmsdatadirect.com/schedulesdirect/tvlistings/xtvdService
Resolving webservices.schedulesdirect.tmsdatadirect.com... 144.142.232.53
Connecting to webservices.schedulesdirect.tmsdatadirect.com|144.142.232.53|:80... connected.
HTTP request sent, awaiting response... 401 Unauthorized
Connecting to webservices.schedulesdirect.tmsdatadirect.com|144.142.232.53|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/xml]
Saving to: `STDOUT'

    [                     <=>                                                                                                                                                     ] 324,228     54.0K/s   in 8.1s    

2010-09-18 00:48:33 (38.9 KB/s) - `-' saved [324228]

2010-09-18 00:48:33.273 New DB connection, total: 3
2010-09-18 00:48:33.274 Connected to database 'mythconverg' at host: XXX
2010-09-18 00:48:33.292 DataDirect: Your subscription expires on Sun Jun 19 (2011) 10:55 PM
2010-09-18 00:48:33.419 sourceid 1 has lineup type: Cable
2010-09-18 00:48:33.489 sourceid 4 has lineup type: CableDigital
2010-09-18 00:48:33.502 sourceid 2 has lineup type: LocalBroadcast
2010-09-18 00:48:46.859 Grab complete.  Actual data from Sun Sep 19 05:00:00 2010 to Mon Sep 20 05:00:00 2010 (UTC)
2010-09-18 00:48:46.861 Main temp tables populated.
2010-09-18 00:48:46.861 Updating myth channels.
2010-09-18 00:48:46.876 IconData: Updating icons for sourceid: 1
2010-09-18 00:48:46.877 Channels updated.
2010-09-18 00:48:47.143 Clearing data for source.
2010-09-18 00:48:47.143 Clearing from Sun Sep 19 00:00:00 2010 to Mon Sep 20 00:00:00 2010 (localtime)
2010-09-18 00:48:48.424 Data for source cleared.
2010-09-18 00:48:48.424 Updating programs.
2010-09-18 00:48:50.180 Program table update complete.
2010-09-18 00:48:50.181 
2010-09-18 00:48:50.181 Checking day @ offset 2, date: Mon Sep 20 2010
2010-09-18 00:48:50.287 Data is already present for Mon Sep 20 2010, skipping
2010-09-18 00:48:50.288 
...
...

[Nigel]

Andy, sorry for the lack of action on this. However, last week myth_system() had a major re-write committed, and most of the bugs are ironed out. Any chance of testing with a vanilla Qt, and recent trunk? (e.g. ​55661dbf7)

[Nigel]

I believe this was fixed in trunk (by Gavin on 3rd December) by the removal of popen(), and I am closing this. See ​eb71341f.
If there is strong demand (on mailing list please), I will try to backport to fixes/0.23.