Database locked error

[mvallevand]

The first two ERROR messages are normal not sure why sub keeps them. Also the date requested error is normal when SD does have 3 weeks of data.

Sub should probably look at the error here since he did indicated a cache error on artwork. It does look like a 30 second lock timeout and there seems to be a missing Refresh@exit.

Code:

2021-06-08 02:47:11.522    [DEBUG][20]    Refresh@start
2021-06-08 02:47:12.748    [DEBUG][20]     - (1) BBC One South: has 377 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (2) BBC Two: has 286 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (3) ITV1 (South Meridian): has 287 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (4) Channel 4: has 374 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (5) Channel 5: has 530 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (6) ITV2: has 707 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (9) BBC Four: has 206 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (10) ITV3: has 596 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (11) Sky Arts: has 373 listings
2021-06-08 02:47:12.748    [DEBUG][20]     - (12) Quest: has 431 listings
2021-06-08 02:47:12.748    [DEBUG][20]    SD using existing token
2021-06-08 02:47:13.205    [DEBUG][20]    Requesting /schedules
2021-06-08 02:47:13.205    [DEBUG][20]    SD(https://json.schedulesdirect.org/20141201/schedules)
2021-06-08 02:47:13.205    [DEBUG][20]    token header: 6f13f241602e6c8f40e81cca600b4c5c
2021-06-08 02:47:16.108    [DEBUG][20]    Got /schedules:
2021-06-08 02:47:16.553    [DEBUG][20]    token header: 6f13f241602e6c8f40e81cca600b4c5c
2021-06-08 02:47:20.157    [DEBUG][20]    Refresh@start
2021-06-08 02:47:22.165    [DEBUG][37]    Got request [192.168.86.60]: /service (recording.lastupdated)
2021-06-08 02:47:22.166    [DEBUG][37]    method=recording.lastupdated
2021-06-08 02:47:22.166    [DEBUG][37]    parameters:
2021-06-08 02:47:22.166    [DEBUG][37]       method: recording.lastupdated
2021-06-08 02:47:22.166    [DEBUG][37]       sid: ba9cb8a550a9406eab72558baef4be1b
2021-06-08 02:47:22.166    [DEBUG][37]       client_ip: 192.168.86.60
2021-06-08 02:47:22.166    [DEBUG][37]       user_agent: Kodi/19.1 (X11; Linux x86_64) LibreELEC/10.0 App_Bitness/64 Version/19.1-(19.1.0)-Git:2d78f9dfc3095b548b3928bacaa141eea10b669c
2021-06-08 02:47:22.166    [DEBUG][37]       host_callback: 192.168.86.225:8866
2021-06-08 02:47:22.166    [DEBUG][37]    LastUpdated
2021-06-08 02:47:22.166    [DEBUG][37]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
  <last_update>1623096300</last_update>
</rsp>

2021-06-08 02:47:44.529    [ERROR][53]    Unexpected error in SchedulesDirectArtwork: 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.SqliteDataReader.NextResult()
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader()
   at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
   at Microsoft.Data.Sqlite.SqliteConnectionExtensions.ExecuteNonQuery(SqliteConnection connection, String commandText, SqliteParameter[] parameters)
   at Microsoft.Data.Sqlite.SqliteTransaction.Commit()
   at NShared.Metadata.SchedulesDirectArtwork.Refresh(List`1 seriesWithArt)
2021-06-08 02:47:44.541    [DEBUG][53]    Refresh()@exit took 33018.6831ms

My thought is still you have too many table entries for this small PC and with a sqltie3 tool you could clear them with

delete from sd_artwork;

Your bad artwork doesn't help things. This might help with a sqlite3 tool

delete from scheduled_recording where event_details not like '%oid%';

Stop the service and backup your database before doing these

Martin

[ceejayemm]

Ok, deleted contents of sd_artwork table as suggested by Martin and restarted NextPVR. All was well until EPG update started at 02:45 this morning when shortly afterwards I got the same 'Database is Locked' message (at 2021-06-09 02:47:52.591). Full logs file attached

What next ?

Chris

[mvallevand]

Did you delete the bad recordings too?

Note I successfully updated from the table you posted a few day ago without and db changes, I just had to addd Youview South to my lineup and it worked. I don't get two Refresh@starts without the exit so sub might need to focus there.

Code:

2021-06-09 09:21:51.997 [DEBUG][17]     Refresh@start
2021-06-09 09:21:52.912 [DEBUG][10]     Refresh()@exit took 913.9287ms
2021-06-09 09:21:55.212 [DEBUG][17]     Refresh@start
2021-06-09 09:21:55.560 [DEBUG][10]     Refresh()@exit took 347.5511ms
2021-06-09 09:21:58.602 [DEBUG][17]     Refresh@start
2021-06-09 09:21:58.986 [DEBUG][25]     Refresh()@exit took 383.7229ms
2021-06-09 09:22:01.689 [DEBUG][17]     Refresh@start
2021-06-09 09:22:02.066 [DEBUG][25]     Refresh()@exit took 377.1847ms
2021-06-09 09:22:04.168 [DEBUG][17]     Refresh@start
2021-06-09 09:22:04.495 [DEBUG][25]     Refresh()@exit took 327.2431ms
2021-06-09 09:22:06.272 [DEBUG][17]     Refresh@start
2021-06-09 09:22:06.590 [DEBUG][25]     Refresh()@exit took 317.4861ms
2021-06-09 09:22:08.285 [DEBUG][17]     Refresh@start
2021-06-09 09:22:08.667 [DEBUG][25]     Refresh()@exit took 381.6409ms
2021-06-09 09:22:12.892 [DEBUG][17]     Refresh@start
2021-06-09 09:22:13.090 [DEBUG][17]     Refresh()@exit took 197.9854ms
2021-06-09 09:22:14.758 [DEBUG][17]     Refresh@start
2021-06-09 09:22:15.055 [DEBUG][25]     Refresh()@exit took 296.8081ms
2021-06-09 09:22:15.838 [DEBUG][17]     Refresh@start
2021-06-09 09:22:15.896 [DEBUG][17]     Refresh()@exit took 57.517ms
2021-06-09 09:22:17.245 [DEBUG][17]     Refresh@start
2021-06-09 09:22:17.550 [DEBUG][10]     Refresh()@exit took 304.6872ms
2021-06-09 09:22:18.665 [DEBUG][17]     Refresh@start
2021-06-09 09:22:19.056 [DEBUG][25]     Refresh()@exit took 390.7325ms
2021-06-09 09:22:19.581 [DEBUG][17]     Refresh@start
2021-06-09 09:22:19.838 [DEBUG][25]     Refresh()@exit took 255.9602ms
2021-06-09 09:22:20.218 [DEBUG][17]     Refresh@start
2021-06-09 09:22:20.472 [DEBUG][25]     Refresh()@exit took 252.9353ms

Martin

[sub]

The first call we see the database locked error on is SchedulesDirectArtwork, but it's probably not directly to do with that. It's probably something immediately prior to that failing. It's not obvious in the logs though

[sub]

In this set of logs it seems to have started immediately after the start of the EPG update. Does that always seem to be the case?

[mvallevand]

What I am not seeing in his logs is the "Marking recording (18...) as 'Recording service not running at recording time" etc messages on startup" since he has several old zero status recordings that should be changed. That is why I suggested cleaning out the bad records.

Martin

[sub]

ceejayemm, can you supply your npvr.db3 file?

[mvallevand]

I actually found them in the "good" log after the update. The recurring update logic is not changing the oids so the EPG update is definitely failing.

I go back to the two quick calls with only one exit.

2021-06-09 02:47:19.019 [DEBUG][91] Refresh@start
2021-06-09 02:47:27.964 [DEBUG][91] Refresh@start
2021-06-09 02:47:52.604 [DEBUG][90] Refresh()@exit took 33584.0665ms

Martin

[ceejayemm]

Sub 

Sorry didn't get an email to let me know you had updated this ticket so only just seen Martin's and your requests.

I have now deleted the sd_artwork records as suggested by Martin and also the 'dodgy' recordings from scheduled_recording.

After updating the database I restarted the NextPVR service and ran the EPG Update manually.  This seems to have completed without any problems this time around. However there now seem to be other problems:

1. The error relating to the 'dodgy' imported recordings is still present:

2021-06-09 20:20:57.691 [ERROR][26] Unexpected error parsing EPGEvent xml: 

  at System.Number.ThrowOverflowOrFormatException(ParsingStatus status, TypeCode type)

I have tried deleting the recording via the web app and then reimport it. The recording is imported but the Event metadata is not being applied and the following error is being reported in the log (the same as the error generated for (1) above:

System.FormatException: Input string was not in a correct format.

I have attached the XML file I used to import the file (which parses correctly in MS Edge), can you tell me what the problem is please ?

2) Following the successful EPG Update above I am now getting lots and lots of the following errors:

2021-06-09 20:17:28.712 [ERROR][16] TS continuity counter indicates missing packets
2021-06-09 20:17:28.712 [ERROR][16] TS packet damaged

So we seemed to have made some progress but some other problems seem to have surfaced.

I have attached the latest full log file set, the database as requested by Sub and the XML file used to import the 'Lone Ranger' recording.

Thanks

Chris

[mvallevand]

That's another bad record, it has but the OID but it is blank you need a 0. If you can delete that recording it will help. Another good set to delete is all those copies of Catch-22, with no Title. since "there was only one catch ...", also they don't have any data.. My experience is you are randomly mixing the case on your imported recordings as well as omitting the OID

Martin