drescherjm at gmail
Jan 29, 2012, 7:49 AM
Post #2 of 2
(178 views)
Permalink
|
> After the recording process has been working flawlessly for years (and
> on 0.24 fixes for over a year) recently updated a little less
> frequently I updated it a few times in the last few weeks / months and
> only now I have a serious problem that I have never seen before. It
> seems that if I record 2 programs back to back it is now very likely
> that the second program deadlocks mythbackend. I originally thought
> this was a kernel issue but I have reverted back to the kernel (3.1.4
> gentoo-sources) I had used for the last few weeks that did not have
> this issue.
>
> jmd0 mythtv # mythbackend --version
> Please attach all output as a file in bug reports.
> MythTV Version : v0.24.1-120-g294968b-dirty
> MythTV Branch : branch-fixes/0.24
> Network Protocol : 63
> Library API : 0.24.20110804-1
> QT Version : 4.7.4
> Options compiled in:
> linux release using_alsa using_oss using_pulse using_pulseoutput
> using_backend using_bindings_perl using_bindings_python using_dvb
> using_firewire using_frontend using_hdpvr using_ivtv using_mheg
> using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit
> using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld
> using_xvmcw using_bindings_perl using_bindings_python
> using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads
> using_mheg
>
>
> 2012-01-08 03:16:04.269 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.291 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.312 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.536 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.759 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.760 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.778 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:04.798 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:05.019 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:05.020 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:05.028 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:05.265 [mpeg2video @ 0x3ecc8f4780]warning: first
> frame is no keyframe
> 2012-01-08 03:16:32.053 AutoExpire: CalcParams(): Max required Free
> Space: 2.0 GB w/freq: 15 min
> 2012-01-08 03:31:32.086 AutoExpire: CalcParams(): Max required Free
> Space: 2.0 GB w/freq: 15 min
> 2012-01-08 03:45:21.591 UPnpMedia: BuildMediaMap VIDEO scan starting
> in :/share/Movies/dvd:
> 2012-01-08 03:45:21.593 UPnpMedia: BuildMediaMap Done. Found 0 objects
> 2012-01-08 03:46:33.316 AutoExpire: CalcParams(): Max required Free
> Space: 2.0 GB w/freq: 15 min
> 2012-01-08 04:00:00.994 TVRec(21): Changing from RecordingOnly to None
> 2012-01-08 04:00:00.995 Updating status for "NFL PrimeTime" on cardid
> 21 (Recording => Recorded)
> 2012-01-08 04:00:00.995 Finished recording NFL PrimeTime: channel 1014
> 2012-01-08 04:00:01.002 Reschedule requested for id 0.
> 2012-01-08 04:00:01.114 Scheduled 90 items in 0.1 = 0.00 match + 0.11 place
> 2012-01-08 04:00:01.168 Finished recording NFL PrimeTime: channel 1014
> 2012-01-08 04:00:05.714
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 2.0
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:07.715
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 4.0
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:11.716
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 8.0
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:12.717
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.0
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:12.967
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.2
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:13.468
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.8
> seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:13.718
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 10.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:13.968
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 10.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:14.219
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 10.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:14.469
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 10.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:14.719
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 11.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:14.970
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 11.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:15.220
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 11.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:15.470
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 11.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:15.721
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 12.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:15.971
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 12.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:16.221
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 12.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:16.472
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 12.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:16.722
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 13.0 seconds for data
>
> 2012-01-08 04:00:16.972
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 13.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:17.223
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 13.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:17.473
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 13.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:17.723
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 14.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:17.973
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 14.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:18.224
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 14.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:18.225 MythSocket(119f570:7): readStringList: Error,
> timed out after 7000 ms.
> 2012-01-08 04:00:18.226 RemoteFile::Read(): No response from control socket.
> 2012-01-08 04:00:18.226
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg) Error:
> RingBuffer::safe_read(RemoteFile* ...): read failed
> 2012-01-08 04:00:18.226
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 14.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:18.476
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 14.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:18.727
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 15.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:18.977
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 15.2 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:19.228
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 15.5 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:19.478
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 15.8 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:19.728
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
> 16.0 seconds for data
> to become available... 0 < 32768
> 2012-01-08 04:00:19.728
> RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg) Error:
> Waited 16 seconds for data, aborting.
> 2012-01-08 04:02:19.960 New DB connection, total: 4
> 2012-01-08 04:15:21.594 New DB connection, total: 5
> 2012-01-08 09:49:40.048 Event socket closed. No connection to the backend.
>
>
> 2012-01-08 10:21:58.666 mythbackend version: branch-fixes/0.24
> [v0.24.1-120-g294968b-dirty] www.mythtv.org
> 2012-01-08 10:21:58.669 Using runtime prefix = /usr
> 2012-01-08 10:21:58.669 Using configuration directory = /home/mythtv/.mythtv
> 2012-01-08 10:21:58.680 Using localhost value of jmd0
> 2012-01-08 10:21:58.694 New DB connection, total: 1
> 2012-01-08 10:21:58.696 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:21:58.699 Closing DB connection named 'DBManager0'
> 2012-01-08 10:21:58.700 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:21:58.701 Current locale EN_US
> 2012-01-08 10:21:58.702 Reading locale defaults from
> /usr/share/mythtv//locales/en_us.xml
> 2012-01-08 10:21:58.708 Current MythTV Schema Version (DBSchemaVer): 1264
> 2012-01-08 10:21:58.710 ThreadPool:HTTP: Initial 1, Max 25, Timeout 60000
> 2012-01-08 10:21:58.716 Enabling Upnpmedia rebuild thread.
> 2012-01-08 10:21:59.917 MythBackend: Starting up as the master server.
> 2012-01-08 10:21:59.920 New DB connection, total: 2
> 2012-01-08 10:21:59.920 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:21:59.923 New DB connection, total: 3
> 2012-01-08 10:21:59.923 Connected to database 'mythconverg' at host: jmd0
> irsend: command failed: SEND_ONCE DTA Key_Enter
> irsend: unknown command: "Key_Enter"
> 2012-01-08 10:22:02.877 New DB scheduler connection
> 2012-01-08 10:22:02.878 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:22:02.880 Main::Registering HttpStatus Extension
> 2012-01-08 10:22:02.880 Enabled verbose msgs: important general
> 2012-01-08 10:22:02.885 AutoExpire: CalcParams(): Max required Free
> Space: 1.0 GB w/freq: 15 min
> 2012-01-08 10:22:05.882 Reschedule requested for id -1.
> 2012-01-08 10:22:05.993 Scheduled 90 items in 0.1 = 0.00 match + 0.10 place
> 2012-01-08 10:22:05.995 Seem to be woken up by USER
> 2012-01-08 10:22:08.717 UPnpMedia: BuildMediaMap VIDEO scan starting
> in :/share/Movies/dvd:
> 2012-01-08 10:22:08.718 UPnpMedia: BuildMediaMap Done. Found 0 objects
> 2012-01-08 10:22:22.881 Expiring 3 MB for 1010 at 2012-01-06T20:45:04
> => Chuck:"Chuck Versus the Kept Man"
> 2012-01-08 10:22:48.215 MainServer::ANN Monitor
> 2012-01-08 10:22:48.216 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:50.798 MainServer::ANN Monitor
> 2012-01-08 10:22:50.798 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:52.513 MainServer::ANN Monitor
> 2012-01-08 10:22:52.514 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:52.518 MainServer::ANN Monitor
> 2012-01-08 10:22:52.519 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:56.139 MainServer::ANN Monitor
> 2012-01-08 10:22:56.140 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:56.144 MainServer::ANN Monitor
> 2012-01-08 10:22:56.144 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:56.182 MainServer::ANN Monitor
> 2012-01-08 10:22:56.182 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:56.183 Reschedule requested for id 693.
> 2012-01-08 10:22:56.284 Scheduled 91 items in 0.1 = 0.00 match + 0.10 place
> 2012-01-08 10:22:56.309 TVRec(21): Changing from None to RecordingOnly
> 2012-01-08 10:22:56.310 TVRec(21): HW Tuner: 21->21
> 2012-01-08 10:22:56.335 AutoExpire: CalcParams(): Max required Free
> Space: 2.0 GB w/freq: 15 min
> 2012-01-08 10:22:56.336 Started recording: "CBS News Sunday Morning":
> channel 1003 on cardid 21, sourceid 1
> 2012-01-08 10:22:56.411 MainServer::ANN Monitor
> 2012-01-08 10:22:56.411 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:56.415 MainServer::ANN Monitor
> 2012-01-08 10:22:56.415 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:22:57.026 ProgramInfo(1003_20120108102300.mpg), Error:
> GetPlaybackURL: '1003_20120108102300.mpg' should be local, but it can
> not be found.
> irsend: command failed: SEND_ONCE DTA Key_Enter
> irsend: unknown command: "Key_Enter"
> 2012-01-08 10:22:57.533 Updating status for "CBS News Sunday Morning"
> on cardid 21 (Tuning => Recording)
> 2012-01-08 10:22:57.596 TVRec(21): rec->GetPathname():
> '/mnt/mythtv/jmd0_vg_2t0_1/videos/1003_20120108102300.mpg'
> 2012-01-08 10:23:00.402 MainServer::ANN Monitor
> 2012-01-08 10:23:00.403 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:06.848 MainServer::ANN Monitor
> 2012-01-08 10:23:06.848 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:11.466 MainServer::ANN Monitor
> 2012-01-08 10:23:11.467 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:12.887 JobQueue: Commercial Detection Starting for
> "CBS News Sunday Morning" recorded from channel 1003 at
> 2012-01-08T10:23:00
> 2012-01-08 10:23:12.994 Using runtime prefix = /usr
> 2012-01-08 10:23:12.994 Using configuration directory = /home/mythtv/.mythtv
> 2012-01-08 10:23:12.995 Using localhost value of jmd0
> 2012-01-08 10:23:13.004 New DB connection, total: 1
> 2012-01-08 10:23:13.007 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:23:13.008 Closing DB connection named 'DBManager0'
> 2012-01-08 10:23:13.009 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:23:13.010 Current locale EN_US
> 2012-01-08 10:23:13.010 Reading locale defaults from
> /usr/share/mythtv//locales/en_us.xml
> 2012-01-08 10:23:13.015 Loading en_us translation for module mythfrontend
> 2012-01-08 10:23:13.019 MainServer::ANN Playback
> 2012-01-08 10:23:13.019 adding: jmd0 as a client (events: 0)
> 2012-01-08 10:23:13.020 MainServer::HandleAnnounce FileTransfer
> 2012-01-08 10:23:13.020 adding: jmd0 as a remote file transfer
> 2012-01-08 10:23:13.601 MythCoreContext: Connecting to backend server:
> 192.168.1.110:6543 (try 1 of 1)
> 2012-01-08 10:23:13.602 Using protocol version 63
> 2012-01-08 10:23:13.602 MainServer::ANN Playback
> 2012-01-08 10:23:13.603 adding: jmd0 as a client (events: 0)
> 2012-01-08 10:23:13.603 MainServer::ANN Monitor
> 2012-01-08 10:23:13.604 adding: jmd0 as a client (events: 1)
> 2012-01-08 10:23:18.405 MainServer::ANN Monitor
> 2012-01-08 10:23:18.406 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:20.818 MainServer::ANN Monitor
> 2012-01-08 10:23:20.818 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:22.885 AutoExpire: CalcParams(): Max required Free
> Space: 2.0 GB w/freq: 15 min
> 2012-01-08 10:23:22.887 Expiring 483 MB for 3184 at 2011-03-12T01:49:16 => Extra
> 2012-01-08 10:23:25.692 MainServer::ANN Monitor
> 2012-01-08 10:23:25.693 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:25.730 MainServer::ANN Monitor
> 2012-01-08 10:23:25.731 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:25.731 Reschedule requested for id 694.
> 2012-01-08 10:23:25.834 Scheduled 92 items in 0.1 = 0.00 match + 0.10 place
> 2012-01-08 10:23:25.905 MainServer::ANN Monitor
> 2012-01-08 10:23:25.906 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:28.300 MainServer::ANN Monitor
> 2012-01-08 10:23:28.301 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:23:31.653 AFD Warning: ScanATSCCaptionStreams() called with no PMT
> 2012-01-08 10:23:31.654 AFD: Opened codec 0x7fbef800fa20,
> id(MPEG2VIDEO) type(Video)
> 2012-01-08 10:23:31.654 AFD: codec MP2 has 2 channels
> 2012-01-08 10:23:31.654 AFD: Opened codec 0x7fbef80151a0, id(MP2) type(Audio)
> 2012-01-08 10:23:31.655 MythCoreContext: Connecting to backend server:
> 192.168.1.110:6543 (try 1 of 1)
> 2012-01-08 10:23:31.656 Using protocol version 63
> 2012-01-08 10:23:31.656 MainServer::ANN Playback
> 2012-01-08 10:23:31.656 adding: jmd0 as a client (events: 0)
> 2012-01-08 10:23:31.657 RecBase(21:/dev/v4l/video0):
> GetKeyframePositions(691,9223372036854775807,#20) out of 66
> 2012-01-08 10:28:55.509 MainServer::ANN Monitor
> 2012-01-08 10:28:55.510 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:29:00.871 Reschedule requested for id 0.
> 2012-01-08 10:29:00.972 Scheduled 92 items in 0.1 = 0.00 match + 0.10 place
> 2012-01-08 10:29:08.040 MainServer::ANN Monitor
> 2012-01-08 10:29:08.040 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:29:12.131 MainServer::ANN Monitor
> 2012-01-08 10:29:12.132 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:29:12.170 MainServer::ANN Monitor
> 2012-01-08 10:29:12.170 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:29:12.170 Reschedule requested for id 695.
> 2012-01-08 10:29:12.274 Scheduled 93 items in 0.1 = 0.00 match + 0.10 place
> 2012-01-08 10:29:12.379 MainServer::ANN Monitor
> 2012-01-08 10:29:12.379 adding: jmd0.comcast.net as a client (events: 2)
> 2012-01-08 10:29:29.800 TVRec(21): ASK_RECORDING 21 29 0 0
> 2012-01-08 10:30:00.810 TVRec(21): Changing from RecordingOnly to None
> 2012-01-08 10:30:00.812 Updating status for "CBS News Sunday Morning"
> on cardid 21 (Recording => Recorded)
> 2012-01-08 10:30:00.812 Finished recording CBS News Sunday Morning: channel 1003
> 2012-01-08 10:30:01.042 Finished recording CBS News Sunday Morning: channel 1003
> 2012-01-08 10:30:11.757 MythSocket(24144b0:7): readStringList: Error,
> timed out after 7000 ms.
> 2012-01-08 10:30:11.758 Remote file timeout.
> 2012-01-08 10:30:33.796 MythSocket(7fbef800cf00:10): readStringList:
> Error, timed out after 30000 ms.
> 2012-01-08 10:30:33.797 Connection to backend server lost
> 2012-01-08 10:30:33.797 New DB connection, total: 2
> 2012-01-08 10:30:33.798 Connected to database 'mythconverg' at host: jmd0
> 2012-01-08 10:30:33.799 MythCoreContext: Connecting to backend server:
> 192.168.1.110:6543 (try 1 of 1)
> 2012-01-08 10:30:40.799 MythSocket(2465860:8): readStringList: Error,
> timed out after 7000 ms.
> 2012-01-08 10:30:40.799 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.
> 2012-01-08 10:30:40.799 Reconnection to backend server failed
> 2012-01-08 10:30:40.800 ~MythContext waiting for threads to exit.
> 2012-01-08 10:30:40.850 MythCoreContext: Connecting to backend server:
> 192.168.1.110:6543 (try 1 of 1)
> 2012-01-08 10:30:47.850 MythSocket(2413f10:8): readStringList: Error,
> timed out after 7000 ms.
> 2012-01-08 10:30:47.850 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.
>
>
> I believe this is ticket 9704
>
> http://code.mythtv.org/trac/ticket/9704
>
> I have this morning applied the patch
> mythtv-0.24-backport_reconnect_fixes.patch but that has not helped at
> all. After a restart of the backend I can record again.
>
Any ideas at all how to debug this? Recording or watching in mythtv
now is totally unreliable and WAF has plummeted. Every time a
recording starts there is a chance that mythbackend will either not
process the recording at all or stop processing a minute in. It
appears the problem has to do with connections to mythbackend. Are all
of these done by upnp? If a commercial flag job starts after a
recording there is a chance it will put mythbackend in a state that it
no longer processes connection requests. Same with starting a new
recording, watching a recording or using mythweb. The mythbackend
process does not die it just quits answering. A week ago I set up
nagios to monitor the xml stream on port 6644 and when that goes down
email me. This works however last night I wanted to record a 3:00 am
program then a 5:30 am program. I had this problem on the 3:00 AM
probably because I was up and tried to look at mythweb right when the
recording started. However I went to bed shortly after that only to
wakeup at 9:40 AM with an email from nagios that at 5:37 AM it
detected that mythbackend was no longer responding.
***** Nagios *****
Notification Type:
Service: MythRecorders
Host: jmd0
Address: 192.168.1.110
State: CRITICAL
Date/Time: Sun Jan 29 05:37:17 EST 2012
The frustration is this sports program was very important to the wife.
It did replay at 9:00 AM today but I had missed the beginning and now
I am trying to record the network replay so I can get the second half.
2012-01-29 05:29:01.259 ExtractMethodFromURL(end) : xml : /
2012-01-29 05:29:01.266 JobQueue: GetJobsInQueue: findJobs search
bitmask 28, found 3 total jobs
2012-01-29 05:29:01.266 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1010 @ 20120127145900 in Finished state.
2012-01-29 05:29:01.266 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1058 @ 20120127210000 in Finished state.
2012-01-29 05:29:01.267 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1003 @ 20120128210600 in Finished state.
2012-01-29 05:29:01.332 HTTPRequest::SendResponse(xml/html) () :200 OK
-> 192.168.1.110: 1
2012-01-29 05:29:11.260 JobQueue: Currently set to run up to 3 job(s) max.
2012-01-29 05:29:11.261 JobQueue: GetJobsInQueue: findJobs search
bitmask 4, found 3 total jobs
2012-01-29 05:29:11.261 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1010 @ 20120127145900 in Finished state.
2012-01-29 05:29:11.262 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1058 @ 20120127210000 in Finished state.
2012-01-29 05:29:11.262 JobQueue: GetJobsInQueue: Ignore 'Flag
Commercials' Job for chanid 1003 @ 20120128210600 in Finished state.
2012-01-29 05:29:30.182 TVRec(21): ASK_RECORDING 21 29 0 0
2012-01-29 05:29:51.183 MainServer, Warning: Unknown socket closing
MythSocket(0x7f3e400a31f0)
2012-01-29 05:30:00.192 TVRec(21): Changing from RecordingOnly to None
2012-01-29 05:30:00.194 Updating status for "15 (ESPN2)":"Sun Jan 29
03:00:00 2012" on cardid 21 (Recording => Recorded)
2012-01-29 05:30:11.262 JobQueue: Currently set to run up to 3 job(s) max.
2012-01-29 05:30:21.189 New DB connection, total: 4
2012-01-29 05:32:31.681
===============================================================================
2012-01-29 05:32:31.682 URI (type) - Found: 19 Entries - 19 have been
Allocated.
2012-01-29 05:32:31.682 USN (unique id) |
Expires | Location
2012-01-29 05:32:31.682
-------------------------------------------------------------------------------
2012-01-29 05:32:31.683 upnp:rootdevice
2012-01-29 05:32:31.683 *
uuid:0012-1733-5a2c0000cedc::upnp:rootdevice | 141 |
http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.683 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::upnp:rootdevice |
1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.683
2012-01-29 05:32:31.684 urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1
2012-01-29 05:32:31.684 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::urn:microsoft.com:service:X_MS_MediaReceiverRegistrar:1
| 1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.684
2012-01-29 05:32:31.684 urn:schemas-mythtv-org:device:MasterMediaServer:1
2012-01-29 05:32:31.685 *
uuid:91da507e-5346-48c4-882f-47d2deaabeca::urn:schemas-mythtv-org:device:MasterMediaServer:1
| 1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.685
2012-01-29 05:32:31.685 urn:schemas-mythtv-org:service:MythTv:1
2012-01-29 05:32:31.685 *
uuid:91da507e-5346-48c4-882f-47d2deaabeca::urn:schemas-mythtv-org:service:MythTv:1
| 1833 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.686
2012-01-29 05:32:31.686 urn:schemas-upnp-org:device:InternetGatewayDevice:1
2012-01-29 05:32:31.686 *
uuid:0012-1733-5a2c0000cedc::urn:schemas-upnp-org:device:InternetGatewayDevice:1
| 141 |
http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.687
2012-01-29 05:32:31.687 urn:schemas-upnp-org:device:MediaServer:1
2012-01-29 05:32:31.687 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::urn:schemas-upnp-org:device:MediaServer:1
| 1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.687
2012-01-29 05:32:31.688 urn:schemas-upnp-org:device:WANConnectionDevice:1
2012-01-29 05:32:31.688 *
uuid:0012-1733-5a2c0200cedc::urn:schemas-upnp-org:device:WANConnectionDevice:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.688
2012-01-29 05:32:31.689 urn:schemas-upnp-org:device:WANDevice:1
2012-01-29 05:32:31.689 *
uuid:0012-1733-5a2c0100cedc::urn:schemas-upnp-org:device:WANDevice:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.689
2012-01-29 05:32:31.690 urn:schemas-upnp-org:service:ConnectionManager:1
2012-01-29 05:32:31.690 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::urn:schemas-upnp-org:service:ConnectionManager:1
| 1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.691
2012-01-29 05:32:31.691 urn:schemas-upnp-org:service:ContentDirectory:1
2012-01-29 05:32:31.691 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::urn:schemas-upnp-org:service:ContentDirectory:1
| 1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.692
2012-01-29 05:32:31.692 urn:schemas-upnp-org:service:Layer3Forwarding:1
2012-01-29 05:32:31.692 *
uuid:0012-1733-5a2c0000cedc::urn:schemas-upnp-org:service:Layer3Forwarding:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.692
2012-01-29 05:32:31.693 urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1
2012-01-29 05:32:31.693 *
uuid:0012-1733-5a2c0100cedc::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.693
2012-01-29 05:32:31.693 urn:schemas-upnp-org:service:WANIPConnection:1
2012-01-29 05:32:31.694 *
uuid:0012-1733-5a2c0200cedc::urn:schemas-upnp-org:service:WANIPConnection:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.694
2012-01-29 05:32:31.694 urn:schemas-upnp-org:service:WANPPPConnection:1
2012-01-29 05:32:31.694 *
uuid:0012-1733-5a2c0200cedc::urn:schemas-upnp-org:service:WANPPPConnection:1
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.695
2012-01-29 05:32:31.695 uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.695 * uuid:0012-1733-5a2c0000cedc
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.695
2012-01-29 05:32:31.696 uuid:0012-1733-5a2c0100cedc
2012-01-29 05:32:31.696 * uuid:0012-1733-5a2c0100cedc
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.696
2012-01-29 05:32:31.696 uuid:0012-1733-5a2c0200cedc
2012-01-29 05:32:31.696 * uuid:0012-1733-5a2c0200cedc
| 141 | http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 05:32:31.697
2012-01-29 05:32:31.697 uuid:91da507e-5346-48c4-882f-47d2deaabeca
2012-01-29 05:32:31.697 *
uuid:91da507e-5346-48c4-882f-47d2deaabeca | 1832 |
http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.697
2012-01-29 05:32:31.698 uuid:d09977b6-6acb-472d-b6ea-be46980f34ae
2012-01-29 05:32:31.698 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae | 1832 |
http://192.168.1.110:6544/getDeviceDesc
2012-01-29 05:32:31.698
2012-01-29 05:32:31.698
-------------------------------------------------------------------------------
2012-01-29 05:32:31.699 Found: 20 Entries - 20 have been Allocated.
2012-01-29 05:32:31.699
===============================================================================
2012-01-29 06:02:32.616
===============================================================================
2012-01-29 06:02:32.617 URI (type) - Found: 19 Entries - 19 have been
Allocated.
2012-01-29 06:02:32.617 USN (unique id) |
Expires | Location
2012-01-29 06:02:32.617
-------------------------------------------------------------------------------
2012-01-29 06:02:32.617 upnp:rootdevice
2012-01-29 06:02:32.618 *
uuid:0012-1733-5a2c0000cedc::upnp:rootdevice | 141 |
http://192.168.1.1:5431/dyndev/uuid:0012-1733-5a2c0000cedc
2012-01-29 06:02:32.618 *
uuid:d09977b6-6acb-472d-b6ea-be46980f34ae::upnp:rootdevice |
1832 | http://192.168.1.110:6544/getDeviceDesc
2012-01-29 06:02:32.618
John
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://www.mythtv.org/mailman/listinfo/mythtv-users
|
