[mythtv-users] Scheduling new recordings requires mythtv restart

[Michael Rice]

On 5/25/09, Michael T. Dean <mtdean at 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