Database locked (one symptom: deleting ONE entry in Pi-hole diagnosis triggers deleetion of 1616 (invisible) messages which fails)

bcutter · January 10, 2023, 7:04pm

Expected Behaviour:

Deleting one single diagnosis entry from /admin/messages.php only deletes this single entry.

Actual Behaviour:

The overlay message says "1616 messages are being deleted" - and finally fails after 5 seconds.

jfb · January 10, 2023, 7:05pm

Please follow our help template. In particular, the debug token.

bcutter · January 10, 2023, 7:11pm

I ran pihole -r meanwhile which solved another issue. I need to wait for the next entry coming up in the Pi-hole diagnosis section (typically once load is high for a few seconds) to cross-check if this issue is also gone.

Possibly related to Latest version check returns "N/A" for Pi-hole.

Clearly the database was locked for quite some time. We'll probably never find out why. This is what the dashboards currently look like AFTER running pihole -r:

Seems to stopped working on 2022-01-07 after 02:45 in the morning. I could not find any cron job or something which ran at that time.

Interestingly the data came out fine (imported in Home Assistant) which is why I did not discover this database issue of Pi-hole earlier - and all data dropped now after running pihole -r:

This is what's in head of pihole-FTL.log:

[2023-01-10 00:01:01.070 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-10 00:01:01.071 22031/T22047] END TRANSACTION failed when trying to store queries to long-term database
[2023-01-10 00:01:01.071 22031/T22047] Keeping queries in memory for later new attempt
[2023-01-10 00:01:02.196 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-10 00:01:02.197 22031/T22047] WARNING: Storing devices in network table failed: database is locked
[2023-01-10 00:02:01.087 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-10 00:02:01.087 22031/T22047] END TRANSACTION failed when trying to store queries to long-term database
[2023-01-10 00:02:01.087 22031/T22047] Keeping queries in memory for later new attempt
[2023-01-10 00:02:02.208 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-10 00:02:02.208 22031/T22047] WARNING: Storing devices in network table failed: database is locked
[2023-01-10 00:03:01.110 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-10 00:03:01.110 22031/T22047] END TRANSACTION failed when trying to store queries to long-term database

Heres where the issue started (/var/log/pihole/FTL.log.3`):

[2023-01-07 00:09:00.115 22031/T22047] Notice: Database size is 2710.27 MB, deleted 54 rows
[2023-01-07 00:20:00.065 22031/T22047] Notice: Database size is 2710.28 MB, deleted 22 rows
[2023-01-07 00:30:00.109 22031/T22047] Notice: Database size is 2710.30 MB, deleted 27 rows
[2023-01-07 00:40:00.107 22031/T22047] Notice: Database size is 2710.32 MB, deleted 126 rows
[2023-01-07 00:45:59.227 22031/T22048] WARNING: Long-term load (15min avg) larger than number of processors: 4.1 > 4
[2023-01-07 00:50:00.064 22031/T22047] Notice: Database size is 2710.37 MB, deleted 26 rows
[2023-01-07 01:00:00.104 22031/T22047] Notice: Database size is 2710.39 MB, deleted 76 rows
[2023-01-07 01:10:00.126 22031/T22047] Notice: Database size is 2710.41 MB, deleted 14 rows
[2023-01-07 01:19:00.123 22031/T22047] Notice: Database size is 2710.42 MB, deleted 5 rows
[2023-01-07 01:30:00.099 22031/T22047] Notice: Database size is 2710.46 MB, deleted 2 rows
[2023-01-07 01:31:36.845 22031M] Resizing "FTL-dns-cache" from 372736 to (23552 * 16) == 376832 (/dev/shm: 5.4MB used, 2.0GB total, FTL uses 5.4MB)
[2023-01-07 01:40:00.106 22031/T22047] Notice: Database size is 2710.50 MB, deleted 2 rows
[2023-01-07 01:50:00.089 22031/T22047] Notice: Database size is 2710.53 MB, deleted 2 rows
[2023-01-07 02:00:00.099 22031/T22047] Notice: Database size is 2710.56 MB, deleted 11 rows
[2023-01-07 02:10:00.116 22031/T22047] Notice: Database size is 2710.59 MB, deleted 2 rows
[2023-01-07 02:20:00.124 22031/T22047] Notice: Database size is 2710.60 MB, deleted 2 rows
[2023-01-07 02:30:00.050 22031/T22047] Notice: Database size is 2710.61 MB, deleted 362 rows
[2023-01-07 02:40:00.106 22031/T22047] Notice: Database size is 2710.61 MB, deleted 2 rows
[2023-01-07 02:46:00.000 22031/T22048] WARNING: Long-term load (15min avg) larger than number of processors: 5.2 > 4
[2023-01-07 02:46:00.057 22031/T22047] Encountered error while trying to store client in long-term database
[2023-01-07 02:46:00.057 22031/T22047] Statement finalization failed when trying to store queries to long-term database
[2023-01-07 02:46:00.057 22031/T22047] Error while trying to close database: database is locked
[2023-01-07 02:46:00.066 22031/T22047] SQLite3 message: database is locked in "DELETE FROM network_addresses WHERE lastSeen < 1578447960;" (5)
[2023-01-07 02:46:00.066 22031/T22047] ERROR: SQL query "DELETE FROM network_addresses WHERE lastSeen < 1578447960;" failed: database is locked (SQLITE_BUSY)
[2023-01-07 02:46:01.057 22031/T22048] add_message(type=6, message=excessive load) - SQL error step DELETE: database is locked
[2023-01-07 02:46:01.058 22031/T22048] Error while trying to close database: database is locked
[2023-01-07 02:47:01.058 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-07 02:47:01.058 22031/T22047] END TRANSACTION failed when trying to store queries to long-term database
[2023-01-07 02:47:01.058 22031/T22047] Keeping queries in memory for later new attempt
[2023-01-07 02:47:02.125 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-07 02:47:02.125 22031/T22047] WARNING: Storing devices in network table failed: database is locked
[2023-01-07 02:48:01.010 22031/T22047] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2023-01-07 02:48:01.010 22031/T22047] END TRANSACTION failed when trying to store queries to long-term database
[2023-01-07 02:48:01.010 22031/T22047] Keeping queries in memory for later new attempt

So immediately after
[2023-01-07 02:46:00.000 22031/T22048] WARNING: Long-term load (15min avg) larger than number of processors: 5.2 > 4

the database went into read only / write protection mode. Interesting!

Ran sqlite3 /etc/pihole/pihole-FTL.db "PRAGMA integrity_check;" now according to Database locked (dashboard and query log are empty) - #2 by heis2201 which took some time as the database has few gigabytes, Result: ok.

Database lock messages in FTL log same issue.

@jfb I think there's not much left to do here, right? Debug token won't help now that everything is up and running again - and I explored all relevant logs related to the database locking (see above).

I'm just wondering how I could detect this issue in future (right in time instead of many days later by accident!)... maybe

grep-ing the pihole-FTL.log regularly for the appearance of database is locked?
Can Pi-hole run some kind of self-check and announce this issue somehow? Possibly by replacing the "Active" with "Error!" or something like that?

bcutter · January 15, 2023, 4:33pm

@jfb Any words on what I discovered and documented in detail in my last post?
I still could not track down the reason for the lock state of the Pi-Hole database.

yubiuser · January 16, 2023, 9:35pm

The statement is a bit misleading. We did not implement a check of how many messages you are deleting, so it is always "messages", even if it's just one "message". 1616 is the message_id (database_id) of the message you just deleted. If you would have deleted two it would state

Deleting messages: 1616, 1617

bcutter · January 16, 2023, 11:29pm

Interesting, I would never imagined this.
Indeed it can easily get misinterpreted without an „id“, „number“ or something like that.

At least that miracle is solved. Classic „false trap“ in this case

yubiuser · January 17, 2023, 6:18am

github.com/pi-hole/AdminLTE

Tweak deleting message

pi-hole:devel ← pi-hole:tweak/messages

opened 06:18AM - 17 Jan 23 UTC

yubiuser

+5 -5

**What does this PR aim to accomplish?:** Be more specific what we delete fro…m one of the tables. The current wording could be misinterpreted. See: https://discourse.pi-hole.net/t/database-locked-one-symptom-deleting-one-entry-in-pi-hole-diagnosis-triggers-deleetion-of-1616-invisible-messages-which-fails/60388/7?u=yubiuser --- **By submitting this pull request, I confirm the following:** 1. I have read and understood the [contributors guide](https://docs.pi-hole.net/guides/github/contributing/), as well as this entire template. I understand which branch to base my commits and Pull Requests against. 2. I have commented my proposed changes within the code and I have tested my changes. 3. I am willing to help maintain this change if there are issues with it later. 4. It is compatible with the [EUPL 1.2 license](https://opensource.org/licenses/EUPL-1.1) 5. I have squashed any insignificant commits. ([`git rebase`](http://gitready.com/advanced/2009/02/10/squashing-commits-with-rebase.html)) 6. I have checked that another pull request for this purpose does not exist. 7. I have considered, and confirmed that this submission will be valuable to others. 8. I accept that this submission may not be used, and the pull request closed at the will of the maintainer. 9. I give this submission freely, and claim no ownership to its content. --- - [x] I have read the above and my PR is ready for review. *Check this box to confirm*

system · February 7, 2023, 6:18am

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.