[mythtv] backend dying while mythweb is creating previews for
recorded programs
Jim Westfall
jwestfall at surrealistic.net
Thu Feb 24 06:11:01 UTC 2005
try commenting out or bumping up the value passed to
socket_set_timeout($fp, 4) in mythbackend.php.
mythweb is using a connection cache when talking with the backend. If
the 4 second timeout is hit when waiting for a response from the backend
the fread() will return with no data. mythweb doesnt catch this and next
command sent to the backend will get the response from the previous one.
jim
Jim Westfall <jwestfall at surrealistic.net> wrote [02.23.05]:
> I found some additional information on my test x86 backend box. It
> appears that connectionClosed() signal is not always getting triggered
> when a client disconnects. There ends up being dead sockets in
> playbackList and fileTransferList.
>
> attached is a patch that adds additional logging to the backend that shows
> the issue along with a sample log.
>
> jim
>
> Risto Treksler <risto at elkhornbanff.ca> wrote [02.23.05]:
> > For what it's worth
> >
> > http://www.gossamer-threads.com/lists/mythtv/users/92985?search_string=waiting%20for%20a%20thread;#92985
> > http://www.gossamer-threads.com/lists/mythtv/users/53694?search_string=waiting%20for%20a%20thread;#53694
> > http://www.gossamer-threads.com/lists/mythtv/users/88540?search_string=0%20retries%20remaining.;#88540
> >
> > seem to be related but
> > don't point to a solution
> >
> > it's weird though since i never saw this b4 0.17
> >
> > rt
> >
> > On Tuesday 22 February 2005 09:55 am, Risto Treksler wrote:
> > > Hi,
> > >
> > > Has the code for static preview generation changed since .16
> > > to make it happen in the background?
> > >
> > > I see '(0 retries remaining)' in the logs for remote filetransfers
> > > How can I change that, so that it tries again?
> > >
> > >
> > > Here's what's happening:
> > >
> > > i start by clearing out the png files
> > > #rm -f /mnt/store/*.png /var/www/html/mythweb/image_cache/*.png
> > >
> > > then i go to the recorded_programs.php page in firefox and
> > > when the backend is busy with commflagging or recording,
> > > only a few preview images are shown
> > >
> > > sometimes the backend seems to crash,
> > > but upon further investigation it doesn't really segfault
> > > but just exits gracefully right after a
> > > 2005-02-22 00:00:16.986 Unknown file transfer socket: 18
> > > or similar, in the log
> > >
> > > other times it gets stuck with tons of
> > > "waiting for a thread" messages
> > > see preview-2.log
> > > i <ctrl-c>-ed the backend and got preview-4.bt
> > >
> > > most of the time the files are actually created in /mnt/store
> > > but they just don't get copied over to image_cache
> > > so hitting reload copies them over
> > >
> > > i have toyed with the idea of adding a timeout to let the file creation
> > > complete before trying to copy the png over but no luck so far
> > >
> > > i have added some debug statements to see what's going on
> > > preview-4.diff produces preview-4.html.txt
> > > and
> > > preview-7.diff produces preview-7.html.txt
> > > (with the backend running inside a while loop)
> > >
> > > i am stumped
> > >
> > > :(
> > >
> > > --
> > > Risto Treksler
> > > Elkhorn Lodge
> > > Banff, Alberta, Canada
> >
> > --
> > Risto Treksler
> > Elkhorn Lodge
> > Banff, Alberta, Canada
> > _______________________________________________
> > mythtv-dev mailing list
> > mythtv-dev at mythtv.org
> > http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-dev
> Index: programs/mythbackend/mainserver.cpp
> ===================================================================
> RCS file: /var/lib/mythcvs/mythtv/programs/mythbackend/mainserver.cpp,v
> retrieving revision 1.179
> diff -u -r1.179 mainserver.cpp
> --- programs/mythbackend/mainserver.cpp 23 Feb 2005 05:04:36 -0000 1.179
> +++ programs/mythbackend/mainserver.cpp 24 Feb 2005 02:39:08 -0000
> @@ -146,6 +146,7 @@
>
> void MainServer::newConnection(RefSocket *socket)
> {
> + VERBOSE(VB_ALL,"newConnection was called");
> connect(socket, SIGNAL(readyRead()), this, SLOT(readSocket()));
> }
>
> @@ -196,6 +197,9 @@
> line = line.simplifyWhiteSpace();
> QStringList tokens = QStringList::split(" ", line);
> QString command = tokens[0];
> +
> + VERBOSE(VB_ALL,QString("playbackList size: %1").arg(playbackList.size()));
> + VERBOSE(VB_ALL,QString("fileTransferList size: %1").arg(fileTransferList.size()));
> //cerr << "command='" << command << "'\n";
> if (command == "MYTH_PROTO_VERSION")
> {
> @@ -561,6 +565,7 @@
> VERBOSE(VB_ALL, QString("adding: %1 as a client (events: %2)")
> .arg(commands[2]).arg(wantevents));
> PlaybackSock *pbs = new PlaybackSock(socket, commands[2], wantevents);
> + VERBOSE(VB_ALL,"Added new playbackList item");
> playbackList.push_back(pbs);
> }
> else if (commands[1] == "SlaveBackend")
> @@ -679,6 +684,7 @@
> FileTransfer *ft = new FileTransfer(filename, socket);
>
> fileTransferList.push_back(ft);
> + VERBOSE(VB_ALL,"Added new fileTransferList item");
>
> retlist << QString::number(socket->socket());
> encodeLongLong(retlist, ft->GetFileSize());
> @@ -2748,6 +2754,7 @@
>
> void MainServer::endConnection(RefSocket *socket)
> {
> + VERBOSE(VB_ALL,"endConnection was called");
> vector<PlaybackSock *>::iterator it = playbackList.begin();
> for (; it != playbackList.end(); ++it)
> {
> @@ -2776,6 +2783,7 @@
> }
> delete (*it);
> playbackList.erase(it);
> + VERBOSE(VB_ALL,"removed item from playbackList");
> return;
> }
> }
> @@ -2789,6 +2797,7 @@
> socket->DownRef();
> delete (*ft);
> fileTransferList.erase(ft);
> + VERBOSE(VB_ALL,"removed item from fileTransferList");
> return;
> }
> }
> 2005-02-23 18:34:40.760 New DB connection, total: 1
> Starting up as the master server.
> 2005-02-23 18:34:41.015 New DB connection, total: 2
> rom1394_1 warning: read failed: 0x0000fffff0000414
> rom1394_1 error: invalid root directory length
> 2005-02-23 18:34:42.116 ret_pid(0) child(18453) status(0x0)
> 2005-02-23 18:34:42.882 ret_pid(18453) child(18453) status(0x0)
> 2005-02-23 18:34:42.886 External Tuning program exited with no error
> 2005-02-23 18:34:42.923 New DB scheduler connection
> 2005-02-23 18:34:42.973 New DB connection, total: 3
> 2005-02-23 18:34:42.991 mythbackend version: 0.17.20050223-1 www.mythtv.org
> 2005-02-23 18:34:42.998 Enabled verbose msgs : important general
> 2005-02-23 18:34:43.012 New DB connection, total: 4
> 2005-02-23 18:34:45.040 Reschedule requested for id -1.
> 2005-02-23 18:34:45.421 Scheduled 0 items in 0.4 = 0.30 match + 0.07 place
> 2005-02-23 18:34:45.449 Seem to be woken up by USER
> 2005-02-23 18:34:48.639 newConnection was called
> 2005-02-23 18:34:48.673 playbackList size: 0
> 2005-02-23 18:34:48.680 fileTransferList size: 0
> 2005-02-23 18:34:48.710 playbackList size: 0
> 2005-02-23 18:34:48.716 fileTransferList size: 0
> 2005-02-23 18:34:48.723 MainServer::HandleAnnounce Playback
> 2005-02-23 18:34:48.731 adding: mini as a client (events: 0)
> 2005-02-23 18:34:48.738 Added new playbackList item
> 2005-02-23 18:34:48.776 playbackList size: 1
> 2005-02-23 18:34:48.782 fileTransferList size: 0
> 2005-02-23 18:34:48.810 playbackList size: 1
> 2005-02-23 18:34:48.816 fileTransferList size: 0
> 2005-02-23 18:34:48.950 playbackList size: 1
> 2005-02-23 18:34:48.956 fileTransferList size: 0
> 2005-02-23 18:34:49.073 endConnection was called
> 2005-02-23 18:34:49.081 removed item from playbackList
> 2005-02-23 18:35:00.302 newConnection was called
> 2005-02-23 18:35:00.314 playbackList size: 0
> 2005-02-23 18:35:00.320 fileTransferList size: 0
> 2005-02-23 18:35:00.341 playbackList size: 0
> 2005-02-23 18:35:00.347 fileTransferList size: 0
> 2005-02-23 18:35:00.353 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:00.360 adding: mini as a client (events: 0)
> 2005-02-23 18:35:00.367 Added new playbackList item
> 2005-02-23 18:35:00.405 playbackList size: 1
> 2005-02-23 18:35:00.411 fileTransferList size: 0
> 2005-02-23 18:35:00.437 playbackList size: 1
> 2005-02-23 18:35:00.443 fileTransferList size: 0
> 2005-02-23 18:35:00.537 newConnection was called
> 2005-02-23 18:35:00.548 playbackList size: 1
> 2005-02-23 18:35:00.557 fileTransferList size: 0
> 2005-02-23 18:35:00.564 MainServer::HandleAnnounce FileTransfer
> 2005-02-23 18:35:00.571 adding: mini as a remote file transfer
> 2005-02-23 18:35:00.605 Added new fileTransferList item
> 2005-02-23 18:35:00.631 playbackList size: 1
> 2005-02-23 18:35:00.637 fileTransferList size: 1
> 2005-02-23 18:35:00.643 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:00.650 adding: mini as a client (events: 0)
> 2005-02-23 18:35:00.697 Added new playbackList item
> 2005-02-23 18:35:00.718 playbackList size: 2
> 2005-02-23 18:35:00.724 fileTransferList size: 1
> 2005-02-23 18:35:00.758 playbackList size: 2
> 2005-02-23 18:35:00.764 fileTransferList size: 1
> 2005-02-23 18:35:04.800 newConnection was called
> 2005-02-23 18:35:04.812 playbackList size: 2
> 2005-02-23 18:35:04.817 fileTransferList size: 1
> 2005-02-23 18:35:04.823 MainServer::HandleAnnounce FileTransfer
> 2005-02-23 18:35:04.830 adding: mini as a remote file transfer
> 2005-02-23 18:35:04.844 Invalid file handle when opening /mnt/store//1004_20050222185800_20050222191000.nuv.png. 0 retries remaining.
> 2005-02-23 18:35:05.357 Added new fileTransferList item
> 2005-02-23 18:35:05.382 playbackList size: 2
> 2005-02-23 18:35:05.388 fileTransferList size: 2
> 2005-02-23 18:35:05.394 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:05.401 adding: mini as a client (events: 0)
> 2005-02-23 18:35:05.407 Added new playbackList item
> 2005-02-23 18:35:05.428 playbackList size: 3
> 2005-02-23 18:35:05.434 fileTransferList size: 2
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> 2005-02-23 18:35:09.598 playbackList size: 3
> 2005-02-23 18:35:09.603 fileTransferList size: 2
> 2005-02-23 18:35:13.630 playbackList size: 3
> 2005-02-23 18:35:13.635 fileTransferList size: 2
> 2005-02-23 18:35:13.744 endConnection was called
> 2005-02-23 18:35:13.748 removed item from playbackList
> 2005-02-23 18:35:19.864 newConnection was called
> 2005-02-23 18:35:19.877 playbackList size: 2
> 2005-02-23 18:35:19.883 fileTransferList size: 2
> 2005-02-23 18:35:19.903 playbackList size: 2
> 2005-02-23 18:35:19.909 fileTransferList size: 2
> 2005-02-23 18:35:19.915 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:19.921 adding: mini as a client (events: 0)
> 2005-02-23 18:35:19.926 Added new playbackList item
> 2005-02-23 18:35:19.965 playbackList size: 3
> 2005-02-23 18:35:19.971 fileTransferList size: 2
> 2005-02-23 18:35:19.997 playbackList size: 3
> 2005-02-23 18:35:20.002 fileTransferList size: 2
> 2005-02-23 18:35:20.103 newConnection was called
> 2005-02-23 18:35:20.115 playbackList size: 3
> 2005-02-23 18:35:20.121 fileTransferList size: 2
> 2005-02-23 18:35:20.127 MainServer::HandleAnnounce FileTransfer
> 2005-02-23 18:35:20.133 adding: mini as a remote file transfer
> 2005-02-23 18:35:20.146 Added new fileTransferList item
> 2005-02-23 18:35:20.167 playbackList size: 3
> 2005-02-23 18:35:20.173 fileTransferList size: 3
> 2005-02-23 18:35:20.179 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:20.185 adding: mini as a client (events: 0)
> 2005-02-23 18:35:20.191 Added new playbackList item
> 2005-02-23 18:35:20.211 playbackList size: 4
> 2005-02-23 18:35:20.217 fileTransferList size: 3
> 2005-02-23 18:35:20.244 playbackList size: 4
> 2005-02-23 18:35:20.250 fileTransferList size: 3
> 2005-02-23 18:35:24.287 newConnection was called
> 2005-02-23 18:35:24.298 playbackList size: 4
> 2005-02-23 18:35:24.304 fileTransferList size: 3
> 2005-02-23 18:35:24.309 MainServer::HandleAnnounce FileTransfer
> 2005-02-23 18:35:24.315 adding: mini as a remote file transfer
> 2005-02-23 18:35:24.328 Invalid file handle when opening /mnt/store//1004_20050222185800_20050222191000.nuv.png. 0 retries remaining.
> 2005-02-23 18:35:24.839 Added new fileTransferList item
> 2005-02-23 18:35:24.860 playbackList size: 4
> 2005-02-23 18:35:24.866 fileTransferList size: 4
> 2005-02-23 18:35:24.872 MainServer::HandleAnnounce Playback
> 2005-02-23 18:35:24.878 adding: mini as a client (events: 0)
> 2005-02-23 18:35:24.884 Added new playbackList item
> 2005-02-23 18:35:24.905 playbackList size: 5
> 2005-02-23 18:35:24.910 fileTransferList size: 4
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> ERROR: file I/O problem in 'safe_read()': Bad file descriptor
> 2005-02-23 18:35:29.071 playbackList size: 5
> 2005-02-23 18:35:29.076 fileTransferList size: 4
> 2005-02-23 18:35:33.105 playbackList size: 5
> 2005-02-23 18:35:33.110 fileTransferList size: 4
> 2005-02-23 18:35:33.220 endConnection was called
> 2005-02-23 18:35:33.225 removed item from playbackList
> _______________________________________________
> mythtv-dev mailing list
> mythtv-dev at mythtv.org
> http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-dev
More information about the mythtv-dev
mailing list