Mailing List Archive

On 04/22/2009 02:12 AM, Joel wrote:
> I'm not certain how long this has been going on, but I only noticed it
> recently. When I initially start mythtv, if I have a full set of guide
> data for the next 2 weeks, I get all the programs I expect scheduled for
> those next two weeks. However, as mythtv runs, even though the guide
> data gets updated, I never get new programs scheduled to record past two
> weeks after mythtv was started. I have noticed that if I add a new
> recording schedule, it will schedule recordings after that limit, but
> existing recording schedules never get updated when new guide data
> becomes available. I can view the guide data in the listings, but no new
> recordings get scheduled. I am running 0.21-fixes. Has anyone seen
> this? Any ideas? I have run optimize_mythdb.pl to make sure the
> database is healthy.

Your mythfilldatabase run is failing to finish. This could be due to
having a broken video sources or input connections configuration--i.e.
you have a video source (usually an unimportant one) whose grabber is
not working properly or you have an extra input connected (i.e. for use
with a VCR or whatever) whose video source /should/ be set to "No
Grabber", but isn't. However, I'm pretty sure we've fixed all the cases
where such broken configurations prevent mythfilldatabase from doing the
part of its job it /can/ do.

Therefore, I would guess it's happening because you have too little
memory/swap (are you sure swap is enabled?) and while mythfilldatabase
runs (and consumes a /large/ amount of memory, but likely when it's
doing post-insert processing), the OOM killer has to kill it off to
allow other programs to run. Then again, it may just happen because you
have bad hardware that causes memory corruption or something, which
causes mythfilldatabase to segfault.

Make sure you specify a location for "mythfilldatabase Log Path" in
mythfrontend's main General settings and then check the log after it
runs automatically. Do not run mythfilldatabase manually, as doing so
may run it in such a way that it does not fail. Feel free to post the
log file after the run if you need help interpreting the problem. If
you see no problems and/or the log file just stops without saying,
"mythfilldatabase run complete", look in your system log files to see if
the OOM killer is activating or some other problem is occurring during
the run.

Mike
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

Michael T. Dean wrote:
> Your mythfilldatabase run is failing to finish. This could be due to
> having a broken video sources or input connections configuration--i.e.
> you have a video source (usually an unimportant one) whose grabber is
> not working properly or you have an extra input connected (i.e. for use
> with a VCR or whatever) whose video source /should/ be set to "No
> Grabber", but isn't. However, I'm pretty sure we've fixed all the cases
> where such broken configurations prevent mythfilldatabase from doing the
> part of its job it /can/ do.

I have 3 sources (confirmed by checking videosource table), Digital
antenna, Digital cable, and Analog cable. My listings include data from
all three sources, so I believe my sources are configured properly.

>
> Therefore, I would guess it's happening because you have too little
> memory/swap (are you sure swap is enabled?) and while mythfilldatabase
> runs (and consumes a /large/ amount of memory, but likely when it's
> doing post-insert processing), the OOM killer has to kill it off to
> allow other programs to run. Then again, it may just happen because you
> have bad hardware that causes memory corruption or something, which
> causes mythfilldatabase to segfault.

I have 4 GB of RAM and 2 GB of swap. Only 6M of swap is even in use, so
there's plenty of room to spare.

>
> Make sure you specify a location for "mythfilldatabase Log Path" in
> mythfrontend's main General settings and then check the log after it
> runs automatically. Do not run mythfilldatabase manually, as doing so
> may run it in such a way that it does not fail. Feel free to post the
> log file after the run if you need help interpreting the problem. If
> you see no problems and/or the log file just stops without saying,
> "mythfilldatabase run complete", look in your system log files to see if
> the OOM killer is activating or some other problem is occurring during
> the run.

I have been running mythfilldatabase out of cron.daily, rather than
having the backend call it. If it's better to have the backend run it
for some reason, I can switch to that method. I get emailed if there is
any output on stderr, and I have only occasionally seen mythfilldatabase
segfault, though it did it 2 days in a row earlier this month. For now,
I've added -v most to mythfilldatabase and redirected to a log file
which I'll monitor more closely. I ran it once now, but I can't confirm
whether it worked or failed since the data was up to date, and I
recently restarted mythbackend. I do see some error's in mythsocket as
well as the message "Error rescheduling id -1 in
ScheduledRecording::signalChange" I'm not sure how to interpret these
errors though, as it doesn't seem to match any of your suggested
problem. You may look to see if you notice anything odd here:
http://ebel.mybox.org/mythfilldatabase.log Or you can wait until
tomorrow and I'll collect a log run in a normal environment for which I
can confirm success or failure.

Thank you for considering my problem
Joel

_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

On 04/22/2009 06:18 PM, Joel wrote:
> I have been running mythfilldatabase out of cron.daily, rather than
> having the backend call it. If it's better to have the backend run
> it for some reason, I can switch to that method.

I recommend switching and letting the backend call it.

> I get emailed if
> there is any output on stderr, and I have only occasionally seen
> mythfilldatabase segfault, though it did it 2 days in a row earlier
> this month. For now, I've added -v most to mythfilldatabase and
> redirected to a log file which I'll monitor more closely. I ran it
> once now, but I can't confirm whether it worked or failed since the
> data was up to date, and I recently restarted mythbackend. I do see
> some error's in mythsocket as well as the message "Error rescheduling
> id -1 in ScheduledRecording::signalChange" I'm not sure how to
> interpret these errors though, as it doesn't seem to match any of
> your suggested problem. You may look to see if you notice anything
> odd here: http://ebel.mybox.org/mythfilldatabase.log Or you can wait
> until tomorrow and I'll collect a log run in a normal environment for
> which I can confirm success or failure.


The errors you're getting are due to the socket errors. A lot of people
seem to get them. I don't know that anyone knows any specific reasons
why some people get them a lot and others don't.

> 2009-04-22 11:48:43.601 MythSocket(8187d90:-1): writeStringList: Error, called with unconnected socket.
> 2009-04-22 11:48:43.601 MythSocket(8187d90:-1): readStringList: Error, called with unconnected socket.

Those socket errors are preventing mythfilldatabase from telling
mythbackend to run a reschedule (thus the error you quoted). I'd ask
other users of your distro if they've seen similar socket errors and
whether they've found a way to fix them.

It's also possible that mythfilldatabase running in the same environment
as your mythbackend will fix the issue--another good reason to let
mythbackend run mythfilldatabase.

Mike
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

On Thu, Apr 23, 2009 at 10:48 AM, Michael T. Dean
<mtdean@thirdcontact.com> wrote:
>
> The errors you're getting are due to the socket errors.  A lot of people
> seem to get them.  I don't know that anyone knows any specific reasons why
> some people get them a lot and others don't.

> Those socket errors are preventing mythfilldatabase from telling mythbackend
> to run a reschedule (thus the error you quoted).  I'd ask other users of
> your distro if they've seen similar socket errors and whether they've found
> a way to fix them.
>
> It's also possible that mythfilldatabase running in the same environment as
> your mythbackend will fix the issue--another good reason to let mythbackend
> run mythfilldatabase.
>
> Mike
>

In the interim would mythbackend --reshed help the poster?
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

Michael T. Dean wrote:
> On 04/22/2009 06:18 PM, Joel wrote:
>> I have been running mythfilldatabase out of cron.daily, rather than
>> having the backend call it. If it's better to have the backend run
>> it for some reason, I can switch to that method.
>
> I recommend switching and letting the backend call it.

Ok. I switched to letting the backend call it.

> The errors you're getting are due to the socket errors. A lot of people
> seem to get them. I don't know that anyone knows any specific reasons
> why some people get them a lot and others don't.
>
>> 2009-04-22 11:48:43.601 MythSocket(8187d90:-1): writeStringList:
>> Error, called with unconnected socket.
>> 2009-04-22 11:48:43.601 MythSocket(8187d90:-1): readStringList: Error,
>> called with unconnected socket.
>
> Those socket errors are preventing mythfilldatabase from telling
> mythbackend to run a reschedule (thus the error you quoted). I'd ask
> other users of your distro if they've seen similar socket errors and
> whether they've found a way to fix them.

I'm building from svn regularly on slackware 12.1. I doubt there's that
large of a userbase on slackware, but if anyone has solved this please
tell me how. My only configure options are --disable-distcc and
--enable-proc-opt. Processor is a core 2 quad Q6600.

From the logs it looks like it's making a connection and negotiating
the protocol version, then failing when it tried to read or write
additional data. Any thoughts on how to continue debugging why the
socket is failing and how to fix it?

From the backend logs, I see the following, which is interesting
because it looks like mythfilldatabase segfaulted this time:

2009-04-22 23:06:47.174 Running mythfilldatabase
2009-04-22 23:11:48.276 mythfilldatabase still running, skipping checks.
2009-04-22 23:16:38.878 MainServer::HandleAnnounce Monitor
2009-04-22 23:16:45.880 MainServer::HandleAnnounce Monitor
2009-04-22 23:16:51.508 adding: zion as a client (events: 0)
2009-04-22 23:16:51.565 adding: zion as a client (events: 1)
2009-04-22 23:16:51.583 MythSocket(8430550:-1): writeStringList: Error,
socket went unconnected.
2009-04-22 23:16:51.587 MainServer::HandleAnnounce Monitor
2009-04-22 23:16:51.607 adding: zion as a client (events: 0)
2009-04-22 23:16:53.283 mythfilldatabase still running, skipping checks.
2009-04-22 23:17:21.620 MainServer::HandleAnnounce Monitor
2009-04-22 23:17:21.626 adding: zion as a client (events: 0)
2009-04-22 23:17:21.628 Received a remote 'Clear Cache' request
sh: line 1: 4945 Segmentation fault
/usr/local/bin/mythfilldatabase -v most
>>/usr/local/var/log/mythtv/mythfilldatabase.log 2>&1

The mythfilldatabase logs look about the same except they stop at the
clear cache request right before the segfault appears to have occurred.
Log is here if it is of additional interest:
http://ebel.mybox.org/mythfilldatabase2.log

>
> It's also possible that mythfilldatabase running in the same environment
> as your mythbackend will fix the issue--another good reason to let
> mythbackend run mythfilldatabase.

This doesn't seem to be the case. My last run was called by mythbackend
and seems to have done no better.

Thanks again,
Joel

_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

Michael T. Dean wrote:
> The errors you're getting are due to the socket errors. A lot of people
> seem to get them. I don't know that anyone knows any specific reasons
> why some people get them a lot and others don't.

<short_version>
I started writing this email before I figured out what was going on, so
here's the short version at the top to prevent TLDR. If you're curious
the method followed to arrive at this, feel free to read below.

When mythfilldatabase is running, it's putting a significant load on
mysql, which persists for a period of time (for me about 22 seconds)
after mythfilldatabase is done. Mythbackend is apparently blocking on
some mysql queries and can't respond to the socket mythfilldatabase
opened up within the 7 second quick timeout being used.

So, I have three questions/recommendations:
1. Not being a mysql expert, what are some settings I can give mysql so
that it will not refuse to respond to the frontend while
mythfilldatabase is running?

2. It would be nice to not make the backend block on these mysql
queries so it can proceed with the socket communication? I could file a
bug for this if you like, but I wouldn't know where to begin with a patch.

3. In case either of these fails, I'd recommend setting the timeout for
this socket connection to be longer. Perhaps by just not using the
quick timeout in this case.

Thanks for your help finding this. It's been bugging me for a while, so
I'm glad I got closer to the bottom of it.

Joel

</short_version>

I've taken a closer look at the communication that's going on.
mythbacked --resched appears to work, where mythfilldatabase fails, so I
compared the network traffic between the two. Here are some tcpdumps
you can open up in wireshark to see what happened:

http://ebel.mybox.org/mythbackend_--resched.dump
http://ebel.mybox.org/mythfilldatabase.dump

Sadly I still don't have a good explanation because from what I can
tell, the network communication is exactly identical, until mythbackend
simply chooses not to respond to mythfilldatabase in a timely manner.
But I can't figure how it can even tell the difference, because the
payload is bit for bit identical between the two. I can even telnet to
port 6543 and send "21 MYTH_PROTO_VERSION 40" and I immediately get
back "13 ACCEPT[]:[]40" but for mythfilldatabase, it waits for
nearly 14 seconds to send back that response, and by then,
mythfilldatabase has given up and closed the connection after 7 seconds,
strangely exactly half the time it took for mythbackend to respond.
mythfilldatabase tries again and waits seven seconds, only to just miss
the response by 0.2 seconds.

So here's a summary:

0s: mythfilldatabase opens a connection and sends "21
MYTH_PROTO_VERSION 40" the server acks the packet

7s: mythfilldatabase times out and sends a FIN. It opens a new
connection and sends the same thing again. The server ACKs the packet.
The server then ACKs the FIN on the original connection.

14s: mythbackend finally responds to the first connection with "13
ACCEPT[]:[]40" but it's too late. The client sends a RST.
The client also gives up on the second connection and sends a FIN. the
server responds with "13 ACCEPT[]:[]40" on the second connection
0.2 seconds later, and the client sends an RST.

I ran this again, and mythbackend waited 22 seconds before it responded
to both connections which had both given up by then. And another time
it took 21 seconds. So it seems the backend is blocking on something
when mythfilldatabase is finishing preventing it from responding to
mythfilldatabase in a timely fashion. But what? The backend logs are
conspicuously silent for those 22 seconds even with -v all. Since
mythbackend --resched responds immediately, I don't understand why it's
taking so long for mythfilldatabase.

I tried lengthening the quick timout in mythsocket.cpp to 30 seconds,
and mythfilldatabase successfully requested rescheduling in about 23
seconds.

Ah. Now I see what's happening. mysql is refusing to respond to
mythbackend's queries in a timely fashion while mythfilldatabase is
running, and for a period of about 22 seconds (apparently) afterwards.
once it's freed up to respond, mythbackend is able to catch up and
respond to the socket.
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

On 04/24/2009 04:57 AM, Joel wrote:
> Ah. Now I see what's happening. mysql is refusing to respond to
> mythbackend's queries in a timely fashion while mythfilldatabase is
> running, and for a period of about 22 seconds (apparently) afterwards.
> once it's freed up to respond, mythbackend is able to catch up and
> respond to the socket.

This sounds like a problem with a MySQL version/configuration that's
becoming relatively common on several distros. I don't know what the
misconfiguration (or solution) is, but it seems that for some reason,
Myth's attempt to detect dead connections is taking a long time, causing
issues.

Greg Estabrooks was looking into the problem back in January, but I
don't know if he's found a solution, yet. If you'd like to see if this
is the problem you're having, just set your MySQL timeouts to something
ridiculously low and see if you can get repeat behaviors after the
timeout interval. To do this, just set wait_timeout and
interactive_timeout (in your my.cnf) to something like 120 (for 2 minutes).

Mike
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

On 5/25/09, Michael T. Dean <mtdean@thirdcontact.com> wrote:
> On 04/24/2009 04:57 AM, Joel wrote:
>
> > Ah. Now I see what's happening. mysql is refusing to respond to
> mythbackend's queries in a timely fashion while mythfilldatabase is running,
> and for a period of about 22 seconds (apparently) afterwards. once it's
> freed up to respond, mythbackend is able to catch up and respond to the
> socket.
> >
>
> This sounds like a problem with a MySQL version/configuration that's
> becoming relatively common on several distros. I don't know what the
> misconfiguration (or solution) is, but it seems that for some reason, Myth's
> attempt to detect dead connections is taking a long time, causing issues.
>
> Greg Estabrooks was looking into the problem back in January, but I don't
> know if he's found a solution, yet. If you'd like to see if this is the
> problem you're having, just set your MySQL timeouts to something
> ridiculously low and see if you can get repeat behaviors after the timeout
> interval. To do this, just set wait_timeout and interactive_timeout (in
> your my.cnf) to something like 120 (for 2 minutes).
>

I noticed this recently and am using Fedora 10. Log is below. I also
have encountered some other issues that could be related.

1. One recording failed when the channel change script didn't complete
during a mythfilldatabase run.

2009-05-13 04:03:08.439 mythfilldatabase still running, skipping checks.
2009-05-13 04:04:26.788 External Tuning program timed out, killing
2009-05-13 04:05:13.625 5120 @ 2009-05-13T04:01:00 in use by
recorder on mythfrontend2
2009-05-13 04:05:58.243 MythSocket(a8970618:-1): writeStringList:
Error, socket went unconnected.
2009-05-13 04:08:00.080 TVRec(1) Error: Failed to set channel to 758.
Reverting to kState_None
2009-05-13 04:08:07.260 5758 @ 2009-05-13T04:01:00 in use by
recorder on masterbackend
2009-05-13 04:08:11.413 TVRec(1): Changing from Watching RecordingOnly to None

2. My remote front end pretty much becomes unusable during a
mythfilldatabase run (cannot connect to backend messages).

In any case I have mythbackend run mythfilldatabase between 4-7am but
even at that time it occasionally causes a problem.

===============================================================
| Attempting to contact the master backend for rescheduling. |
| If the master is not running, rescheduling will happen when |
| the master backend is restarted. |
===============================================================
2009-05-25 04:25:40.371 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'idleTimeoutSecs' AND hostname = 'masterbackend' ;"
2009-05-25 04:25:40.372 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'idleTimeoutSecs' AND hostname IS NULL;"
2009-05-25 04:25:40.373 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'MasterServerIP' AND hostname = 'masterbackend' ;"
2009-05-25 04:25:40.374 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'MasterServerIP' AND hostname IS NULL;"
2009-05-25 04:25:40.375 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'MasterServerPort' AND hostname = 'masterbackend' ;"
2009-05-25 04:25:40.376 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'MasterServerPort' AND hostname IS NULL;"
2009-05-25 04:25:40.376 MythSocket(9da7270:12): new socket
2009-05-25 04:25:40.377 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'WOLbackendReconnectWaitTime' AND hostname =
'masterbackend' ;"
2009-05-25 04:25:40.377 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'WOLbackendReconnectWaitTime' AND hostname IS NULL;"
2009-05-25 04:25:40.378 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'WOLbackendConnectRetry' AND hostname = 'masterbackend'
;"
2009-05-25 04:25:40.378 MSqlQuery::exec() "SELECT data FROM settings
WHERE value = 'WOLbackendConnectRetry' AND hostname IS NULL;"
2009-05-25 04:25:40.378 Connecting to backend server:
192.168.1.26:6543 (try 1 of 5)
2009-05-25 04:25:40.379 MythSocket(9dbad78:13): new socket
2009-05-25 04:25:40.592 MythSocket(9dbad78:13): attempting connect()
to (192.168.1.26:6543)
2009-05-25 04:25:40.592 MythSocket(9dbad78:13): state change Idle -> Connected
2009-05-25 04:25:40.592 write -> 13 21 MYTH_PROTO_VERSION 45
2009-05-25 04:25:47.592 MythSocket(9dbad78:13): readStringList: Error,
timeout (quick).
2009-05-25 04:25:47.592 MythSocket(9dbad78:13): state change Connected -> Idle
2009-05-25 04:25:47.592 Protocol version check failure. The response
to MYTH_PROTO_VERSION was empty.
2009-05-25 04:25:47.592 MythSocket(9dbad78:-1): DownRef: -1
2009-05-25 04:25:47.592 MythSocket(9dbad78:-1): delete socket
2009-05-25 04:25:47.592 Error rescheduling id -1 in
ScheduledRecording::signalChange
2009-05-25 04:25:47.592 Connecting to backend server:
192.168.1.26:6543 (try 1 of 5)
2009-05-25 04:25:47.592 MythSocket(9dbbc38:13): new socket
2009-05-25 04:25:47.592 MythSocket(9dbbc38:13): attempting connect()
to (192.168.1.26:6543)
2009-05-25 04:25:47.592 MythSocket(9dbbc38:13): state change Idle -> Connected
2009-05-25 04:25:47.593 write -> 13 21 MYTH_PROTO_VERSION 45
2009-05-25 04:25:54.597 MythSocket(9dbbc38:13): readStringList: Error,
timeout (quick).
2009-05-25 04:25:54.597 MythSocket(9dbbc38:13): state change Connected -> Idle
2009-05-25 04:25:54.597 Protocol version check failure. The response
to MYTH_PROTO_VERSION was empty.
2009-05-25 04:25:54.597 MythSocket(9dbbc38:-1): DownRef: -1
2009-05-25 04:25:54.597 MythSocket(9dbbc38:-1): delete socket
2009-05-25 04:25:54.597 MythSocket(9da7270:12): DownRef: -1
2009-05-25 04:25:54.597 MythSocket(9da7270:-1): delete socket
2009-05-25 04:25:54.598 mythfilldatabase run complete.
2009-05-25 04:25:54.598 DataDirect: Deleting temporary files
_______________________________________________
mythtv-users mailing list
mythtv-users@mythtv.org
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users