Database locked error

[mvallevand]

I understood that I wanted to see the linux find command returns

find /home/pi/nas_recordings/Films/The\ Lone\ Ranger

You can't use the quote with the escape \ it is either or.

Martin

[ceejayemm]

Martin

Sorry, I read what I wanted to read not what you actually wrote.  The result of the correct use of the command is:

pi@CMTV2:~ $ find /home/pi/nas_recordings/Films/The\ Lone\ Ranger
/home/pi/nas_recordings/Films/The Lone Ranger
/home/pi/nas_recordings/Films/The Lone Ranger/The_Lone_Ranger_20200918_2246.logo.txt
/home/pi/nas_recordings/Films/The Lone Ranger/The_Lone_Ranger_20200918_2246.txt
/home/pi/nas_recordings/Films/The Lone Ranger/The_Lone_Ranger_20200918_2246.log
/home/pi/nas_recordings/Films/The Lone Ranger/The_Lone_Ranger_20200918_2246.edl
/home/pi/nas_recordings/Films/The Lone Ranger/The_Lone_Ranger.ts


BTW I previously removed the timestamp (_20200918_2246) from the .ts file in case this was causing the problem. It can be replaced if necessary.

Chris

[ceejayemm]

Martin

.... and the latest copy of the DB

Chris

[mvallevand]

Ok thanks I I found the issue, NextImport is designed for standard naming with movies with year, series with S/E and NextPVR named files so it is skipping your file since this is none of those formats. I did this to avoid bring junk into the database.

You are missing either a start or end time but this should work.

The_Lone_Ranger_20200918_20002246.ts

I suggest naming without underscores though, so that is The Lone Ranger_20200918_20002246.ts or even better The Lone Ranger (2013).ts so you can get metadata and it will calculate the real duration. You can also use NextPVR's silly . naming if you want.

Edit: This reminds me it also supports NextPVR's Plex format The Lone Ranger_2020-09-18_20002246.ts

Martin

[ceejayemm]

Ok, back to original problem.

All the 'bad' recording have been fixed following reimport via NextImport generated .xml files and no longer report problems in log file, however....

The automated EPG update started at 02:45 this morning and (right on schedule at 02:47, it has always been at this time) the process errored with the infamous 'Database is Locked'. As I have noted previously this problem has only started since I upgraded to 5.1.2 and I am obviously the only person this is affecting right not but how do we get this fixed ? At the moment the only way to sort this out is either restart the nextpvr-service or to reboot the PI.

I have attached the latest set of log files, I don't think they show anything additional to previous logs other than the 'bad' recording have been sorted.

Chris

[mvallevand]

Does your PostProcessing do any database work? The recording end at 22:15 seems to be the last database work. Otherwise I go back to thinking you need to check the system logs for other issues.

Martin

[ceejayemm]

Martin

The PostProcessing.sh only runs Comskip:

/usr/local/bin/comskip --ini='/home/pi/Comskip/comskip.ini' --playnice --ts  $1

 to take out the ads but I don't think that this uses the database in any way ?

Things I have noticed:

1. The recording of 'Romancing the Stone' ran from 20:00 to 22:10 on the schedule however the following error was logged:

2021-06-12 22:15:00.458 [ERROR][9] writer.Close() did not complete in a timely fashion

I have a 5 min post-padding so this kind of makes sense. 

At which point the PostProcessing script kicked in and completed at 22:38

2. The EPG update, via SD, starts at 02:45 each day and the 'database is locked' error always occurs at 02:47

3. The PostUpdateEPG script which runs:

rsync -v /var/opt/nextpvr/* /home/pi/nas_recordings/Backups

started at 04:05 as shown in the log:

2021-06-13 04:05:01.713 [DEBUG][51] About to run /var/opt/nextpvr/scripts/PostUpdateEPG.sh

2021-06-13 04:05:01.714 [DEBUG][51] Starting: bash -c "'/var/opt/nextpvr/scripts/PostUpdateEPG.sh' "

However it didn't complete until the NAS share behind '/home/pi/nas_recordings/Backups' became available at 07:00. The NAS share goes to sleep automatically when no activity has been detected for a while. NOTE: the DB is NOT on this share and is available 24x7 (and is locked prior to this anyway.

2021-06-13 07:00:31.958 [DEBUG][51] /var/opt/nextpvr/scripts/PostUpdateEPG.sh has completed

4. This PI is only used to run NextPVR and nothing else, thus only the NextPVR-server process uses the database.

5. The problem has only started happening since I upgraded to v5.1.2.210601/03 and I did not make any changes to the scripts with this upgrade.

6. All my NextPVR installation only uses my HDHomeRun Quattro  and its log shows no problem with the 'Romancing the Stone' recording request:

20210612-18:59:01 Tuner: tuner0 streaming http to 192.168.86.225:36806
20210612-21:15:00 Tuner: tuner0 http stream ended (remote closed)

And there was NO activity at the time of the EPG Update at 02:45 this morning.

7. Syslog notes some (uncompleted) NFS activity at the same time first database is locked error:

Jun 13 02:47:15 CMTV2 kernel: [151349.550437] nfs: server CMHOMENAS2.lan not responding, still trying

but I can't see why the EPG update would use this NFS share (its the recordings location but nothing is recording at this point)

I can't see anything else in the (/var/logs) system logs which might have a bearing on this problem.

Chris

[sub]

With an EPG update from Schedules Direct there is a couple of things go on in parallel - downloading listings, and updating the artwork cache. Both of these update the database, and have been fine to happen at the same time. I'm wondering if your RPi is slow saving a large number of listings, or large number of artwork entries, which leads to database lock timeouts to happen, resulting in what we're seeing here.

Maybe try setting the <SchedulesDirectDaysOvernight> setting to 7 in config.xml, or even less.

[ceejayemm]

Sub

I have made the change you suggest and I will see what happens overnight.

My PI is a headless RPi4B with 4GB of memory and runs Raspberry PI OS Lite (installed on an SSD) and only supports NextPVR, nothing else is installed on this machine. I have been running NextPVR on this machine setup since v5.0.1 without any previous problems of this type. These issues started with the upgrade to v5.2.1.200601/03. I am updating the EPG with UK Freeview (South) programmes, this hasn't changed in several months, from SD for my 4 tuner HDHomeRun Quatro with no other tuners installed. All tuners have the same channels.

Is there anyway we can tell what is happening with the machine whiles these updates are happening ?

Chris

[mvallevand]

Since the manual update is only a couple of seconds

2021-06-09 20:15:19.855 [DEBUG][20] Refresh@start
2021-06-09 20:15:22.057 [DEBUG][8] Refresh()@exit took 2201.2235ms

I can't help thinking it is somehow related to

Jun 13 02:47:15 CMTV2 kernel: [151349.550437] nfs: server CMHOMENAS2.lan not responding, still trying

since that is exactly the time of the EPG update

2021-06-13 02:47:15.794 [DEBUG][51] Doing EPG update from Schedules Direct JSON

Something seems to be slowing down the network. What time does the comskip finish? I am trying to figure out what "uncompleted" NFS activity your system logs could be referring to if NextPVR is the only use. I am also not sure of the impact on NextPVR if PostProcessing doesn't complete.

Martin