[mythtv-users] backend deadlocked: MythSocket(9ba1fc0:11): readStringList: Error, timed out after 7000 ms.

Brian J. Murrell brian at interlinx.bc.ca
Wed Oct 13 12:00:56 UTC 2010


While watching a recording on a frontend last night the playback stopped
mid-stream and finally timed out back to the recordings menu where it
simply failed to populate.  Clearly failure to communicate with the
backend.

At this same time, on the backend (r26407 on 0.23-fixes) the following
happened at the same time:

2010-10-12 22:08:32.464 RecBase(1:/dev/dvb/adapter0/frontend0): GetKeyframePositions(568,9223372036854775807,#985) out of 1035
2010-10-12 22:08:32.608 RecBase(3:/dev/dvb/adapter0/frontend0): GetKeyframePositions(475,9223372036854775807,#1003) out of 1048
2010-10-12 22:08:32.839 ProgramInfo(): Updated pathname '':'' -> '2077_20100927213100.mpg'
2010-10-12 22:08:35.043 Unknown file transfer socket: 72
2010-10-12 22:08:57.214 MythSocket(9d08528:17): readStringList: Error, timed out after 7000 ms.
2010-10-12 22:08:57.215 RemoteEncoder::SendReceiveStringList(): No response.
2010-10-12 22:08:57.216 Dec: DoFastForward(): desiredFrame(12448) > last_frame(12432)

And then the backend continued along with:

2010-10-12 22:11:11.787 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:15:12.056 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:16:00.595 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:16:01.678 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:18:33.991 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2010-10-12 22:18:34.138 UPnpMedia: BuildMediaMap Done. Found 107 objects
2010-10-12 22:19:12.269 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:23:12.443 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:27:12.619 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:31:12.833 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:35:13.041 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:37:28.390 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:39:13.236 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:41:02.502 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:43:13.689 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:43:13.756 Expiring 146 MBytes for 1015 @ Thu Oct 7 22:00:00 2010 => Anderson Cooper 360
2010-10-12 22:43:13.951 autoexpire: Expiring Program: Expiring 146 MBytes for 1015 @ Thu Oct 7 22:00:00 2010 => Anderson Cooper 360
2010-10-12 22:47:14.356 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:48:35.338 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2010-10-12 22:48:35.672 UPnpMedia: BuildMediaMap Done. Found 107 objects
2010-10-12 22:50:49.526 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:51:14.693 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:55:14.924 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:59:03.235 RingBuf(/video/mythtv/2011_20101012220000.mpg): Waited 1.0 seconds for data to become available...
2010-10-12 22:59:15.103 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
2010-10-12 22:59:15.106 Expiring 579 MBytes for 1032 @ Thu Oct 7 22:30:00 2010 => House Hunters International
2010-10-12 22:59:15.161 autoexpire: Expiring Program: Expiring 579 MBytes for 1032 @ Thu Oct 7 22:30:00 2010 => House Hunters International
2010-10-12 23:00:00.559 TVRec(2): Changing from RecordingOnly to None
2010-10-12 23:00:00.639 ProgramInfo(): Updated pathname '':'' -> '2936_20101012220100.mpg'
2010-10-12 23:00:00.671 Finished recording Detroit 1-8-7 "Royal Bubbles/Needle Drop": channel 2936
2010-10-12 23:00:00.703 scheduler: Finished recording: Detroit 1-8-7 "Royal Bubbles/Needle Drop": channel 2936
2010-10-12 23:00:00.876 TVRec(1): Changing from RecordingOnly to None
2010-10-12 23:00:00.908 TVRec(3): Changing from RecordingOnly to None
2010-10-12 23:00:01.036 ProgramInfo(): Updated pathname '':'' -> '2077_20101012220000.mpg'
2010-10-12 23:00:01.088 ProgramInfo(2936_20101012220100.mpg), Error: Unknown type, recording width was 704
2010-10-12 23:00:01.104 ProgramInfo(): Updated pathname '':'' -> '2011_20101012220000.mpg'
2010-10-12 23:00:01.120 Finished recording The Good Wife "Breaking Fast": channel 2077
2010-10-12 23:00:01.120 Finished recording Parenthood "The Booth Job": channel 2011
2010-10-12 23:00:01.443 New DB connection, total: 5
2010-10-12 23:00:01.444 New DB connection, total: 6
2010-10-12 23:00:01.649 New DB connection, total: 7
2010-10-12 23:00:01.786 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:01.787 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:01.787 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:01.829 scheduler: Finished recording: Parenthood "The Booth Job": channel 2011
2010-10-12 23:00:01.874 scheduler: Finished recording: The Good Wife "Breaking Fast": channel 2077
2010-10-12 23:00:01.879 ProgramInfo(2011_20101012220000.mpg), Error: Unknown type, recording width was 704
2010-10-12 23:00:01.881 ProgramInfo(2077_20101012220000.mpg), Error: Unknown type, recording width was 720
2010-10-12 23:00:02.053 ProgramInfo(): Updated pathname '':'' -> '2936_20101012220100.mpg'
2010-10-12 23:00:02.066 ProgramInfo(): Updated pathname '':'' -> '2077_20101012220000.mpg'
2010-10-12 23:00:02.223 Finished recording Detroit 1-8-7 "Royal Bubbles/Needle Drop": channel 2936
2010-10-12 23:00:02.265 Finished recording The Good Wife "Breaking Fast": channel 2077
2010-10-12 23:00:02.309 scheduler: Finished recording: Detroit 1-8-7 "Royal Bubbles/Needle Drop": channel 2936
2010-10-12 23:00:02.312 scheduler: Finished recording: The Good Wife "Breaking Fast": channel 2077
2010-10-12 23:00:02.318 ProgramInfo(): Updated pathname '':'' -> '2011_20101012220000.mpg'
2010-10-12 23:00:02.558 Finished recording Parenthood "The Booth Job": channel 2011
2010-10-12 23:00:02.575 scheduler: Finished recording: Parenthood "The Booth Job": channel 2011

And as you can see, continued on to finish recording the programs it was
recording at the time.  Throughout the night, the backend seemed to
continue to be active:

2010-10-12 23:00:12.908 mythbackend version: branches/release-0-23-fixes [26407] www.mythtv.org
2010-10-12 23:00:12.908 mythbackend version: branches/release-0-23-fixes [26407] www.mythtv.org
2010-10-12 23:00:12.908 mythbackend version: branches/release-0-23-fixes [26407] www.mythtv.org
2010-10-12 23:00:12.910 Using runtime prefix = /usr
2010-10-12 23:00:12.911 Using runtime prefix = /usr
2010-10-12 23:00:12.911 Using configuration directory = /home/mythtv/.mythtv
2010-10-12 23:00:12.911 Using runtime prefix = /usr
2010-10-12 23:00:12.912 Using configuration directory = /home/mythtv/.mythtv
2010-10-12 23:00:12.914 Using configuration directory = /home/mythtv/.mythtv
2010-10-12 23:00:12.985 Using localhost value of pvr
2010-10-12 23:00:12.988 Using localhost value of pvr
2010-10-12 23:00:12.989 Using localhost value of pvr
2010-10-12 23:00:13.534 New DB connection, total: 1
2010-10-12 23:00:13.535 New DB connection, total: 1
2010-10-12 23:00:13.535 New DB connection, total: 1
2010-10-12 23:00:13.681 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.682 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.682 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.683 Closing DB connection named 'DBManager0'
2010-10-12 23:00:13.684 Closing DB connection named 'DBManager0'
2010-10-12 23:00:13.684 Closing DB connection named 'DBManager0'
2010-10-12 23:00:13.687 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.687 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.688 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:13.725 Current MythTV Schema Version (DBSchemaVer): 1254
2010-10-12 23:00:13.725 Current MythTV Schema Version (DBSchemaVer): 1254
2010-10-12 23:00:13.725 Current MythTV Schema Version (DBSchemaVer): 1254
2010-10-12 23:00:13.734 ProgramInfo(): Updated pathname '':'' -> '2077_20101012220000.mpg'
2010-10-12 23:00:13.735 ProgramInfo(): Updated pathname '':'' -> '2936_20101012220100.mpg'
2010-10-12 23:00:13.735 ProgramInfo(): Updated pathname '':'' -> '2011_20101012220000.mpg'
2010-10-12 23:00:14.051 AFD: Opened codec 0x8de60f0, id(MPEG2VIDEO) type(Video)
2010-10-12 23:00:14.056 AFD: codec AC3 has 0 channels
2010-10-12 23:00:14.057 AFD: Opened codec 0x8de6670, id(AC3) type(Audio)
2010-10-12 23:00:16.443 AFD: Opened codec 0x92b9340, id(MPEG2VIDEO) type(Video)
2010-10-12 23:00:16.444 AFD: codec AC3 has 2 channels
2010-10-12 23:00:16.445 AFD: Opened codec 0x92cc090, id(AC3) type(Audio)
2010-10-12 23:00:16.451 AFD: Opened codec 0x8811900, id(MPEG2VIDEO) type(Video)
2010-10-12 23:00:16.463 AFD: Warning, video codec 0x8de60f0 id(MPEG2VIDEO) type (Video) already open.
2010-10-12 23:00:16.497 AFD: codec AC3 has 2 channels
2010-10-12 23:00:16.636 AFD: Warning, audio codec 0x8de6670 id(AC3) type (Audio) already open, leaving it alone.
2010-10-12 23:00:16.640 AFD: Opened codec 0x8816ee0, id(AC3) type(Audio)
2010-10-12 23:00:16.641 AFD: codec AC3 has 0 channels
2010-10-12 23:00:16.643 NVP(0): Disabling Audio, params(0,0,0)
2010-10-12 23:00:16.996 Preview: Grabbed preview '/video/mythtv/2011_20101012220000.mpg' 704x480 at 64s
2010-10-12 23:00:17.032 AFD: Opened codec 0x8dd3060, id(MPEG2VIDEO) type(Video)
2010-10-12 23:00:17.035 AFD: codec AC3 has 0 channels
2010-10-12 23:00:17.072 AFD: Opened codec 0x8dd3490, id(AC3) type(Audio)
2010-10-12 23:00:17.075 AFD: codec AC3 has 0 channels
2010-10-12 23:00:17.078 AFD: Opened codec 0x8de88a0, id(AC3) type(Audio)
2010-10-12 23:00:17.097 Preview: Grabbed preview '/video/mythtv/2936_20101012220100.mpg' 704x480 at 64s
2010-10-12 23:00:17.223 Preview: Grabbed preview '/storage1/2077_20101012220000.mpg' 720x480 at 64s
2010-10-12 23:00:17.719 ~MythContext waiting for threads to exit.
2010-10-12 23:00:17.746 ~MythContext waiting for threads to exit.
2010-10-12 23:00:17.751 ~MythContext waiting for threads to exit.
2010-10-12 23:00:39.552 MythSocket(9bef0a8:11): readStringList: Error, timed out after 30000 ms.
2010-10-12 23:00:39.553 Connection to backend server lost
2010-10-12 23:00:39.554 New DB connection, total: 2
2010-10-12 23:00:39.555 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:39.606 MythContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2010-10-12 23:00:46.669 MythSocket(9ba1fc0:11): readStringList: Error, timed out after 7000 ms.
2010-10-12 23:00:46.670 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.
2010-10-12 23:00:46.671 Reconnection to backend server failed
2010-10-12 23:00:46.705 ~MythContext waiting for threads to exit.
2010-10-12 23:00:46.722 MythContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2010-10-12 23:00:53.726 MythSocket(9bfa348:11): readStringList: Error, timed out after 7000 ms.
2010-10-12 23:00:53.727 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.
Error in my_thread_global_end(): 1 threads didn't exit
2010-10-12 23:00:58.811 myth_system('/usr/bin/mythbackend --generate-preview 0x0 --chanid 2011 --starttime 20101012220000 '): Error: Can not redirect /dev/null to standard input, failed to open.
			eno: Bad file descriptor (9)

Obviously all of the above is more indication of troubles.

2010-10-12 23:00:58.907 mythbackend version: branches/release-0-23-fixes [26407] www.mythtv.org
2010-10-12 23:00:58.908 Using runtime prefix = /usr
2010-10-12 23:00:58.909 Using configuration directory = /home/mythtv/.mythtv
2010-10-12 23:00:58.910 Using localhost value of pvr
2010-10-12 23:00:58.919 New DB connection, total: 1
2010-10-12 23:00:58.923 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:58.924 Closing DB connection named 'DBManager0'
2010-10-12 23:00:58.925 Connected to database 'mythconverg' at host: localhost
2010-10-12 23:00:58.930 Current MythTV Schema Version (DBSchemaVer): 1254
2010-10-12 23:00:58.932 ProgramInfo(): Updated pathname '':'' -> '2011_20101012220000.mpg'
2010-10-12 23:01:01.392 AFD: Opened codec 0x94de470, id(MPEG2VIDEO) type(Video)
2010-10-12 23:01:01.393 AFD: codec AC3 has 2 channels
2010-10-12 23:01:01.394 AFD: Opened codec 0x94f32d0, id(AC3) type(Audio)
2010-10-12 23:01:01.500 Preview: Grabbed preview '/video/mythtv/2011_20101012220000.mpg' 704x480 at 64s
2010-10-12 23:01:01.608 ~MythContext waiting for threads to exit.
2010-10-12 23:01:01.695 commflag: Commercial Flagging Finished: Parenthood "The Booth Job" recorded from channel 2011 at Tue Oct 12 22:00:00 2010 (0 commercial break(s))
2010-10-12 23:03:15.326 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-12 23:18:15.521 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-12 23:18:39.692 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2010-10-12 23:18:39.823 UPnpMedia: BuildMediaMap Done. Found 107 objects
...
2010-10-13 03:03:17.747 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-13 03:18:17.888 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-13 03:19:02.334 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2010-10-13 03:19:02.377 UPnpMedia: BuildMediaMap Done. Found 107 objects
2010-10-13 03:33:18.034 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-13 03:37:57.432 mythbackend: Last message repeated 124 times: Running housekeeping thread
2010-10-13 03:37:57.436 mythbackend: Running mythfilldatabase
2010-10-13 03:37:57.436 Running mythfilldatabase
2010-10-13 03:37:57.449 myth_system('/usr/bin/mythfilldatabase --dd-grab-all >>/var/log/mythtv/mythfilldatabase 2>&1'): Error: Can not redirect /dev/null to standard input, failed to open.
			eno: Bad file descriptor (9)

More trouble, again.

2010-10-13 03:42:58.444 mythbackend: Running housekeeping thread
2010-10-13 03:48:18.180 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2010-10-13 03:49:07.388 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2010-10-13 03:49:07.433 UPnpMedia: BuildMediaMap Done. Found 107 objects
...

And the trouble continues this morning as mythweb cannot connect to the
backend either:

User Notice at /usr/share/mythtv/mythweb/classes/MythBackend.php, line 102:
Unexpected response to MYTH_PROTO_VERSION '23056':

User Notice at /usr/share/mythtv/mythweb/classes/MythBackend.php, line 124:
Failed to set php timezone to

Warning at /usr/share/mythtv/mythweb/modules/status/handler.php, line 25:
Cannot modify header information - headers already sent by (output started at /usr/share/mythtv/mythweb/includes/errors.php:148)

Warning at /usr/share/mythtv/mythweb/modules/status/handler.php, line 35:
file_get_contents(http://10.75.22.2:6544): failed to open stream: HTTP request failed!

Warning at /usr/share/mythtv/mythweb/modules/_shared/tmpl/default/header.php, line 16:
Cannot modify header information - headers already sent by (output started at /usr/share/mythtv/mythweb/includes/errors.php:148)

So the backend is clearly deadlocked somewhere, but continuing to
process regular housekeeping tasks.

Ideas, while I go restart my backend process?

b.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part
URL: <http://mythtv.org/pipermail/mythtv-users/attachments/20101013/3a16f0bf/attachment.pgp>


More information about the mythtv-users mailing list