SQLite Error 5: 'database is locked'

[BrettB]

At 18:59:00, it started the Connors OK:

Code:

2019-10-08 18:59:00.182 [DEBUG][9] Started recording (11338:16:E:\Recordings2\NCIS\Season 17\NCIS.S17E03.Going.Mobile.ts)
2019-10-08 18:59:00.199 [DEBUG][9] No C:\Users\Public\NPVR-data\scripts\ParallelProcessing.bat
2019-10-08 18:59:00.207 [DEBUG][9] Looking for recording directory with most space available
2019-10-08 18:59:00.208 [DEBUG][9] Default Recording Directory has 292266684416 bytes available space
2019-10-08 18:59:00.208 [DEBUG][9] Preferred filename is 'The.Conners.S02E03.The.Preemie.Monologues'

But then at 18:59:29, it gets a database locked error when it's starting The Resident:

Code:

2019-10-08 18:59:29.955 [DEBUG][22] Got request [192.168.143.25]: /activity
2019-10-08 18:59:30.343 [ERROR][9] Unexpected error saving scheduled recording: Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
  at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
  at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
  at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
  at NUtility.ScheduledRecording.Save()
2019-10-08 18:59:30.345 [DEBUG][9] No C:\Users\Public\NPVR-data\scripts\ParallelProcessing.bat
2019-10-08 18:59:30.349 [DEBUG][9] Looking for recording directory with most space available
2019-10-08 18:59:30.349 [DEBUG][9] Default Recording Directory has 292186460160 bytes available space
2019-10-08 18:59:30.350 [DEBUG][9] Preferred filename is 'The.Resident.S03E03.Saints.&.Sinners'

Since then, I'm getting lots of database is locked errors. Here's one example of the error as a recording is finishing:

Code:

2019-10-08 20:01:30.454 [DEBUG][115] Got request [192.168.143.25]: /activity
2019-10-08 20:01:31.473 [DEBUG][86] Got request [192.168.143.25]: /activity
2019-10-08 20:01:31.998 [ERROR][9] Unexpected error saving scheduled recording: Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
  at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
  at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
  at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
  at NUtility.ScheduledRecording.Save()
2019-10-08 20:01:32.000 [DEBUG][9] StoreMetaData@1
2019-10-08 20:01:32.003 [DEBUG][9] Storing Ensemble XML
2019-10-08 20:01:32.004 [DEBUG][9] ensemble@1
2019-10-08 20:01:32.004 [DEBUG][9] ensemble@2
2019-10-08 20:01:32.004 [DEBUG][9] ensemble@3
2019-10-08 20:01:32.004 [DEBUG][9] ensemble@4
2019-10-08 20:01:32.004 [DEBUG][9] ensemble@5
2019-10-08 20:01:32.012 [DEBUG][9] ensemble@exit
2019-10-08 20:01:32.012 [DEBUG][9] StoreMetaData@exit
2019-10-08 20:01:32.013 [DEBUG][9] Starting: C:\Users\Public\NPVR-data\scripts\PostProcessing.bat "E:\Recordings2\The Resident\Season 03\The.Resident.S03E03.Saints.&.Sinners.ts" 809 11360 35 "The Resident"
2019-10-08 20:01:32.154 [DEBUG][115]
2019-10-08 20:01:33.494 [DEBUG][135] Got request [192.168.143.25]: /activity
2019-10-08 20:01:34.514 [DEBUG][135] Got request [192.168.143.25]: /activity
2019-10-08 20:01:35.532 [DEBUG][135] Got request [192.168.143.25]: /activity

I can't access the server via knewc or the web app on the server. But the recordings seem to still be running (at least files are being written to the disk). So I'm trying to let it run to get my night's recordings done.

I've manually created a zip of the logs directory while its still running.
  logs.zip (Size: 1.12 MB / Downloads: 4)

P.S. all of the "2019-10-08 20:01:34.514 [DEBUG][135] Got request [192.168.143.25]: /activity" logging makes it more difficult to find things in the log file.

[mvallevand]

Unless you love ntray turn it off to get normal logging.

Martin

[BrettB]

Unless you love ntray turn it off to get normal logging.

I'm not running ntray on that server. And the ip address it's coming from is the RPi running kodi with knewc displaying.

[mvallevand]

Ah right I forgot UI  client currently logs without giving anything of value also

Martin

[mvallevand]

I'm think the lock is a timeout for "The Connors"

Also back to spam, I've moved my comskip processing out of NextPVR control because of the logging. It is a good idea for debugging batch files but not for debugging NextPVR.

Martin

[BrettB]

Also back to spam, I've moved my comskip processing out of NextPVR control because of the logging.  It is a good idea for debugging batch files but not for debugging NextPVR.

Yeah, I agree about the comskip output also going into the log file. I'm thinking about making a change there.

[BrettB]

I'm think the lock is a timeout for "The Connors"

Back to the real problem--the lock(s). It looks like the recordings weren't actually working. They should all be done now, but the 3 HDHR tuners are still showing in use. The strange thing is that when I look at the Performance Monitor, it's showing lots of writing to 3 .ts files (FBI, mixed-ish, This Is Us):    

But when I look at those .ts files in a Windows Explorer window, they are all showing up as 0 byte files!

[BrettB]

I'm think the lock is a timeout for "The Connors"

Back to the real problem--the lock(s). It looks like the recordings weren't actually working. They should all be done now, but the 3 HDHR tuners are still showing in use. The strange thing is that when I look at the Performance Monitor, it's showing lots of writing to 3 .ts files (FBI, mixed-ish, This Is Us):

But when I look at those .ts files in a Windows Explorer window, they are all showing up as 0 byte files!

It gets stranger... I went to the command window where NextPVRServer.exe was running so that I could kill it. I pressed Ctrl-C once. And all of a sudden it took off! Looking in the log file I see:

Code:

2019-10-08 20:29:00.074 [DEBUG][9] Looking for recording directory with most space available
2019-10-08 20:30:12.548 [DEBUG][130] Got request [192.168.143.31]: /recordings.html
2019-10-08 22:34:14.495 [ERROR][18] 0:13:57 - 28993 frames in 112.20 sec(258.40 fps), 1.05 sec(191.43 fps), 21%
2019-10-08 22:34:14.510 [DEBUG][85] PreventMonitorStandby() needs implementation
2019-10-08 22:34:14.511 [DEBUG][49]
2019-10-08 22:34:14.537 [DEBUG][49] Waiting for 60 seconds, press a key to continue ...5958575655545352515049484746454443424140393837363534333231302928272625242322212019181716151413121110 9 8 7 6 5 4 3 2 1 0
2019-10-08 22:34:14.537 [DEBUG][9] Default Recording Directory has 222107144192 bytes available space
2019-10-08 22:34:14.537 [ERROR][18] 0:14:05 - 29240 frames in 113.19 sec(258.33 fps), 1.00 sec(247.00 fps), 21%
2019-10-08 22:34:14.540 [DEBUG][49]
2019-10-08 22:34:14.541 [DEBUG][9] Preferred filename is 'black-ish.S06E03.Feminisn't'

And then I could connect from the web app again. (I didn't try from knewc.)

I went and looked at those 3 .ts files, and now it appears they have 2+ hours of recording in them. I'm letting the process continue to run. The comskips for those 3 huge files are going to take a while. Plus, now, I think it's recording The Late Show.

I'm attaching a snapshot of the NRecord.log file as it is right now. After it all gets done, I do another log files zip from the web app to have a complete set.
  nrecord - Copy (2).zip (Size: 218.85 KB / Downloads: 0)

[sub]

It gets stranger... I went to the command window where NextPVRServer.exe was running so that I could kill it. I pressed Ctrl-C once. And all of a sudden it took off!

Had you clicked on the command window with a mouse? ie, highlighting a character, and effectively freezing that process until you press a key (and you press Ctrl-C, which started it going again)

Ultimately people will be running via a service, so this wont be a potential issue.

[BrettB]

It gets stranger... I went to the command window where NextPVRServer.exe was running so that I could kill it. I pressed Ctrl-C once. And all of a sudden it took off!

Had you clicked on the command window with a mouse? ie, highlighting a character, and effectively freezing that process until you press a key (and you press Ctrl-C, which started it going again)

Ultimately people will be running via a service, so this wont be a potential issue.

It's definitely possible that I had selected a section of that text to paste into a post. I had definitely been scrolling it looking for the problem(s).

Any ideas about the original problem of the database being locked?

Edit: added logs from the Settings download
  logs-20191009-0707.zip (Size: 1.52 MB / Downloads: 1)