[mythtv-users] Automatically running Mythfilldatabase

[Phil Bridges]

On Sun, Dec 20, 2009 at 1:26 PM, Phil Bridges <gravityhammer at gmail.com> wrote:
> On Sat, Dec 19, 2009 at 10:16 PM, Michael T. Dean
> <mtdean at thirdcontact.com> wrote:
>> On 12/19/2009 03:26 PM, Phil Bridges wrote:
>>>
>>> On Fri, Dec 18, 2009 at 11:29 AM, Phil Bridges wrote:
>>>
>>>>
>>>> On Fri, Dec 18, 2009 at 11:22 AM, Patrick Oglesby wrote:
>>>>
>>>>>
>>>>> On Fri, Dec 18, 2009 at 8:19 AM, Phil Bridges wrote:
>>>>>
>>>>>>
>>>>>> Does anybody have any suggestions on where to look to debug why
>>>>>> mythfilldatabase isn't automatically being run?  The option is set,
>>>>>> and is supposed to be run at SchedulesDirect's suggested time, but
>>>>>> nothing is happening.  Mythweb doesn't show "Next scheduled time".
>>>>>>
>>>>>> This is on a new .22 install.
>>>>>
>>>>> Did you try running it once manually after setup?  Try running it once
>>>>> by yourself and see if it picks up another time to run.
>>>>>
>>>>
>>>> Yep.  In fact, I just ran it, and my MythWeb status page says:
>>>>
>>>> Last mythfilldatabase run started on 2009-12-18 11:11 and ended on
>>>> 2009-12-18 11:11. Successful.
>>>> There's guide data until 2010-01-01 06:00 (14 days).
>>>> DataDirect Status: Your subscription expires on Sun Jun 20 (2010) 10:28
>>>> PM
>>>>
>>>> I'd rather follow SD's wishes and use their suggested time, but I may
>>>> have to put it in a cron job.
>>>
>>> Anybody have any suggestions?
>>
>> For now, restart all of your mythtv system (shut down all frontends, all
>> remote backends, and then the master backend and then restart).
>>
>> Someone reported a similar issue and basically said, "Myth thought it was
>> still running mythfilldatabase, so it didn't try again."  He never explained
>> what he meant by that, but the only place I see where Myth records that it's
>> currently running mythfilldatabase is an in-memory variable, so it should be
>> fixed by a restart.
>>
>> If not, figure out where it's storing that it's still running mfdb, and I'll
>> fix it for you.
>>
>
> Thanks for the response.
>
> This is weird - the Mythweb pages currently shows:
>
> Last mythfilldatabase run started on 2009-12-20 11:56 and ended on
> 2009-12-20 11:56. mythfilldatabase ran, but did not insert any new
> data into the Guide for 2 of 2 sources. This can indicate a potential
> grabber failure.
> There's guide data until 2010-01-03 06:00 (14 days).
> DataDirect Status: Your subscription expires on Sun Jun 20 (2010) 10:28 PM
>
> I see in my backend log that it ran, as well:
>
> 2009-12-20 11:57:15.094 Grabbing next suggested grabbing time
> 2009-12-20 11:57:16.829 DataDirect: BlockedTime is: 2009-12-20T11:57:15
> 2009-12-20 11:57:16.831 DataDirect: NextSuggestedTime is: 2009-12-21T12:51:54
>
> I do see a mythfilldatabase process still running in ps:
>
> ~ # ps ax|grep myth
>  9969 pts/7    S+     0:00 tail -f /var/log/mythtv/mythbackend.log
> 11019 ?        Ssl    7:15 /usr/bin/mythbackend --verbose
> important,general --logfile /var/log/mythtv/mythbackend.log
> 13020 ?        SNl    0:13 /usr/bin/mythfilldatabase
> 13174 pts/1    R+     0:00 grep --colour=auto myth
>
> I've had everything shut down over the past few days due to my
> firewire problems, and it still doesn't seem to be doing right.
>

Huh.  I just noticed this (in my mythbackend log, after the lines I
copied above):

2009-12-20 11:57:16.834
===============================================================
| Attempting to contact the master backend for rescheduling.  |
| If the master is not running, rescheduling will happen when |
| the master backend is restarted.                            |
===============================================================
2009-12-20 11:57:16.839 MythContext: Connecting to backend server:
192.168.1.50:6543 (try 1 of 1)
2009-12-20 11:57:16.840 Using protocol version 50
2009-12-20 11:57:16.841 MainServer::ANN Monitor
2009-12-20 11:57:16.842 adding: strongsad as a client (events: 0)
2009-12-20 11:57:16.843 MainServer::ANN Monitor
2009-12-20 11:57:16.843 adding: strongsad as a client (events: 1)
2009-12-20 11:57:16.845 Reschedule requested for id -1.
2009-12-20 11:57:16.845 Received a remote 'Clear Cache' request
QMutex::unlock: mutex lock failure:
2009-12-20 11:57:16.850 mythfilldatabase run complete.
2009-12-20 11:57:16.852 DataDirect: Deleting temporary files

I'd bet that mutex lock failure has something to do with the issue.