3.1.1 database locked

[boringgit]

Mine's just come back.

Here are the logs.

I could just possibly have had an instance of XBMC on the Apple TV in the other room open while upgrading, but the upgrade did appear to be successful and I'm only aware that this problem started after I swapped the DLL to fix the null.ts issue...

TIA

[mvallevand]

Here are the logs.

You ran xbmc all night too and it makes lots of regular calls to the database even during the epg update including reloads and it has lock errors too so I suspect some collisions there.

Martin

[boringgit]

Yeah,

It was quite possibly open on the Apple TV overnight.

Do you think exiting XMBC would help? I used to leave it open for weeks at a time with the older version of nprv - admittedly, I used to have to close XBMC and re-open in order to refresh the recording list, but that perhaps sounds better than locking the database?

[gEd]

Full set of logs from recording service restart 5am to database locked at 21:14 when I tried to add a recording via TV Listings.
No X-EWA or XBMC installed, NEWA not being used, just a couple of recordings and the kids watched a movie earlier (via movie plugin I think).

2013-11-13 21:14:38.697 [ERROR][8] Unexpected error in AddEPGEvents: System.Data.SQLite.SQLiteException (0x80004005): database is locked
database is locked.

Plugins installed: TV Listings, Seachlite, ReclockorNot, MovieTrailers, Movies, NDROID.

[gEd]

I got a database locked problem again. It seems to be related to my attempting to use NEWA (as mentioned by a previous poster)
on 20 Nov at 21:55, I attempted to load up NEWA in order to schedule a show. the guide never appeared, I recall that I just got an error in the browser.
Next thing, NextPVR is playing up (as it does when the database is locked).

Code:

2013-11-20 21:55:52.784    [INFO][13]    RecorderHelperConfig: SaveToFile()
2013-11-20 21:55:53.669    [INFO][13]    **********************************************
2013-11-20 21:55:53.669    [INFO][13]    *                                            *
2013-11-20 21:55:53.669    [INFO][13]    *                                            *
2013-11-20 21:55:53.670    [INFO][13]    *  NEWA Application Starting......Opening DB *
2013-11-20 21:55:53.670    [INFO][13]    *                                            *
2013-11-20 21:55:53.670    [INFO][13]    *                                            *
2013-11-20 21:55:53.670    [INFO][13]    **********************************************
2013-11-20 21:55:53.670    [INFO][13]    
2013-11-20 21:55:53.670    [INFO][13]    


2013-11-20 21:56:03.383    [INFO][30]    
2013-11-20 21:56:03.383    [INFO][30]    Where command for search:  where EPG_EVENT.start_time >= datetime('2013-11-20T01:01:00Z') and EPG_EVENT.end_time <= datetime('2013-12-20T01:01:00Z')
2013-11-20 21:56:03.447    [INFO][30]    Where command for search:  where EPG_EVENT.start_time >= datetime('2013-11-20T01:01:00Z') and EPG_EVENT.end_time <= datetime('2013-12-20T01:01:00Z')
2013-11-20 21:56:03.447    [INFO][30]    Search day filtering found.....
2013-11-20 21:56:03.447    [INFO][30]    *** Total events to process = 8
2013-11-20 21:56:03.477    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/22/2013 13:00:00 Friday  ==> 11/22/2013 14:45:00 Friday
2013-11-20 21:56:03.478    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/22/2013 15:55:00 Friday  ==> 11/22/2013 17:35:00 Friday
2013-11-20 21:56:03.480    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/23/2013 09:30:00 Saturday  ==> 11/23/2013 11:15:00 Saturday
2013-11-20 21:56:03.480    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/23/2013 11:15:00 Saturday  ==> 11/23/2013 12:55:00 Saturday
2013-11-20 21:56:03.481    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/23/2013 12:55:00 Saturday  ==> 11/23/2013 14:05:00 Saturday
2013-11-20 21:56:03.481    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 1   11/23/2013 15:00:00 Saturday  ==> 11/23/2013 17:20:00 Saturday
2013-11-20 21:56:03.481    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 1   11/24/2013 15:00:00 Sunday  ==> 11/24/2013 18:05:00 Sunday
2013-11-20 21:56:03.482    [INFO][30]    .....Processing title for days: Formula 1 on channel/date/time: BBC 2   11/24/2013 19:00:00 Sunday  ==> 11/24/2013 20:00:00 Sunday
2013-11-20 21:56:03.482    [INFO][30]    Found: 6 matches for search: Formula 1
2013-11-20 21:56:03.482    [INFO][30]    
2013-11-20 21:56:03.533    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/23/2013 at 9:30 AM
2013-11-20 21:56:04.309    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/23/2013 at 11:15 AM
2013-11-20 21:56:04.454    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/23/2013 at 12:55 PM
2013-11-20 21:56:04.646    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/23/2013 at 3:00 PM
2013-11-20 21:56:04.803    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/24/2013 at 3:00 PM
2013-11-20 21:56:04.818    [DEBUG][30]    Checking if multi-record possible...
2013-11-20 21:56:05.107    [INFO][30]         Scheduleing epgevent: Formula 1 on 11/24/2013 at 7:00 PM
2013-11-20 21:56:05.121    [DEBUG][30]    Checking if multi-record possible...
2013-11-20 21:56:05.204    [INFO][30]    
2013-11-20 21:56:05.204    [INFO][30]    Setting last auto search date to today so this routine does not run again until tommorow....
2013-11-20 21:56:05.204    [INFO][30]    RecorderHelperConfig: SaveToFile()
2013-11-20 21:56:05.205    [INFO][30]    


NPVR.log
2013-11-20 21:56:03.842    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:03.952    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.045    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, starting schedule update timer.
2013-11-20 21:56:04.062    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.172    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.282    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.393    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.419    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, increasing schedule update timer interval.
2013-11-20 21:56:04.499    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.514    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, increasing schedule update timer interval.
2013-11-20 21:56:04.609    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.719    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.756    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, increasing schedule update timer interval.
2013-11-20 21:56:04.829    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:04.905    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, increasing schedule update timer interval.
2013-11-20 21:56:04.939    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:05.039    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:05.159    [DEBUG][1]    GetDuration returning 3835
2013-11-20 21:56:05.169    [DEBUG][8]    TV Listings: RecordingSchedule: database file change detected, increasing schedule update timer interval.


web.log
2013-11-20 21:58:36.096    [DEBUG][24]    Got Web Request (192.168.1.102): /AjaxService.asmx/GetServerTime    
2013-11-20 21:58:37.118    [DEBUG][35]    Got Web Request (192.168.1.102): /AjaxService.asmx/GetReminders    
2013-11-20 21:58:41.021    [ERROR][19]    Unexpected error in EPGEvent.LoadByOID(): System.Data.SQLite.SQLiteException (0x80004005): database is locked
database is locked
   at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
   at System.Data.SQLite.SQLiteDataReader.NextResult()
   at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
   at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.SQLite.SQLiteCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.ExecuteReader()
   at NUtility.EPGEvent.LoadByOID(Int32 oid)


NPVR.log
2013-11-20 22:54:55.533    [DEBUG][1]    PlaybackPositionHelper.StorePlaybackPosition(MasterChef The Professionals_20131120_20002100.ts, 3600, 3835)
2013-11-20 22:54:55.627    [DEBUG][1]    PlaybackPositionHelper.DeletePlaybackPosition(R:\Recordings\MasterChef The Professionals\MasterChef The Professionals_20131120_20002100.ts)
2013-11-20 22:55:27.802    [ERROR][1]    Unexpected error deleting PLAYBACK_POSITION: System.Data.SQLite.SQLiteException (0x80004005): database is locked
database is locked
   at System.Data.SQLite.SQLite3.Prepare(SQLiteConnection cnn, String strSql, SQLiteStatement previous, UInt32 timeoutMS, String& strRemain)
   at System.Data.SQLite.SQLiteCommand.BuildNextCommand()
   at System.Data.SQLite.SQLiteCommand.GetStatement(Int32 index)
   at System.Data.SQLite.SQLiteDataReader.NextResult()
   at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
   at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
   at NShared.PlaybackPositionHelper.DeletePlaybackPosition(String filename)

[boringgit]

So I've just had this again.

I don't use NEWA and I've only used XBMC twice - as a viewer of the directory which NPVR saves its recordings in - I didnt use it as a client, although it will still have connected.

I just dont understand why it locks at such a random time... Is there any way to turn on even more verbose logging?

[sub]

Unfortunately there is no real easy way to pinpoint the cause of this. It's going to matter of spotting a pattern to what is happening beforehand when the problem happens. Then we can try to get more logging put in that area. It might not be in NextPVR itself though - it could be in NEWA or a plugin, in which case we'd need the help of others to fix.

[mvallevand]

.I just dont understand why it locks at such a random time... Is there any way to turn on even more verbose logging?

It looks you might be running a scheduled task (at system level causing other problems) to do an epg update in the middle of a recording.

Martin

[Kiwi]

Unfortunately there is no real easy way to pinpoint the cause of this. It's going to matter of spotting a pattern to what is happening beforehand when the problem happens. Then we can try to get more logging put in that area. It might not be in NextPVR itself though - it could be in NEWA or a plugin, in which case we'd need the help of others to fix.

It probably isn't a problem with NEWA or other plugins as I use neither.

Unfortunately I also can't identify any specific pattern that leads to an error. All I know is that it seems to occur when I try to modify the details of a recurring recording (ie manual recordings).

[boringgit]

It looks you might be running a scheduled task (at system level causing other problems) to do an epg update in the middle of a recording.

Martin

Aahhhhh!

After problems with automatic EPG updates in the past I probably do have a couple of scheduled tasks which are running a standalone update... No reason to expect the same problems with the new version, but I never thought to disable it

I've disabled them and will let you know - sounds very promising though

Cheers for your help!