DB Log is missing watchdog table after enabling - Need to catch and ignore exceptions thrown in dblog_watchdog()

Changing issue title and bumping priority, because:

a) This happens on D7 and D8 with MySQL.
b) The module is enabled, but watchdog table does not exist, such leading to more errors.

Reproducing steps:

* Have any module that adds a message to watchdog on every page load (in this case .../modules/contrib/date/date_context/date_context_date_condition.class.php)
* Enable watchdog either during installation or afterwards.
* Watchdog _is_ enabled, but the watchdog table is missing and leads to more errors on every page load.

IMHO this is at least major, if not critical.

Adding tags

actually it should be the caller of hook_watchdog who eats up the exceptions not each module.

Lets see what testbot says to this patch / test.

( Patch does not include feedback from #3 due to x-post)

Please add a @throws directive to the docblock for dblog_watchdog() when this patch is next re-rolled.

Re-roll that fixes the path to install.inc and adds a docblock to the test method.

@Lars Toomre: The purpose of this patch is to *prevent* that an exception is thrown, not throw one, so it's not necessary to do that. We'd actually have to remove it if there would be one.

@chx: I think it's the responsibility of each module to handle this. Doing it in watchdog() would require is to try/catch each call separately so that each hook is invoked, even if one fails.

Hm. I don't really get why we need that second part of the test? It's complicated due to static caches and not what this patch is about?

Here's a version without that part...

I have a second patch, which might be better (based on chx feedback), but which needs work.

Just posting as I had worked on it already. Thanks @berdir:

Please note is a multi patch due to time constraints ...

#14: dblog-catch-exception-1784548-14.patch queued for re-testing.

What about trying to create the table inside the catch? Eventually watchdog should be a class, and that class should be responsible for installing its own schema, similar to #1167144: Make cache backends responsible for their own storage (note my opinion isn't necessarily that popular in that issue either).

I want to add an observation that appears to be related to this issue.

When these symptoms are present drush pml shows dblog as not installed but admin/modules shows it as installed. A drush en dblog -y also states that dblog is already installed.

Update:
Drupal 7.21
Drush 5.1

I also stated above initially that drush en dblog -y states dblog is not installed, I meant to say it states it is already installed and have corrected it above.

Btw, I would support this as critical too. I cannot flush cache on a site affected by this right now. See screenshot.

Drush reports as 'not installed' because it checks the schema version whereas the GUI checks the status.

Updated issue summary.

I think this could also be fixed with option b on #2153401: Uncaught InvalidArgumentException sometimes thrown by _drupal_error_handler during install which catches exceptions at a slightly higher level, so would also apply to other backends.

I'm hitting this trying to run file tests locally (drush test-run 'File Managed API') - some of the tests fail thusly:

Drupal\Core\Database\DatabaseExceptionWrapper: SQLSTATE[42S02]: Base table or view not found: 1146 Table 'd8.simpletest898368watchdog' doesn't exist: INSERT INTO {watchdog} (uid, type, message, variables, severity, link, location, referer, hostname, timestamp) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8, :db_insert_placeholder_9); Array ( [:db_insert_placeholder_0] => 0 [:db_insert_placeholder_1] => system [:db_insert_placeholder_2] => %module module installed. [:db_insert_placeholder_3] => a:1:{s:7:"%module";s:9:"file_test";} [:db_insert_placeholder_4] => 6 [:db_insert_placeholder_5] => [:db_insert_placeholder_6] => http://d8.local:8083/batch?id=2&op=do&op=do_nojs [:db_insert_placeholder_7] => http://d8.local:8083/batch?op=start&id=2 [:db_insert_placeholder_8] => 127.0.0.1 [:db_insert_placeholder_9] => 1401991161 ) in Drupal\Core\Database\Connection->query() (line 569 of /Users/mryan/Sites/d8/core/lib/Drupal/Core/Database/Connection.php). 

So, it's attempting to log the installation of the file_test module, but somehow the watchdog table is not present. A couple of WTFs here:

1. How can DbLog::log() be invoked before the table is installed?
2. Why does this fail consistently running tests manually locally (either via the UI or drush), yet the testbot doesn't seem to have a problem?

The patch here has tests, removing tag.

Unassigning for now, many things in core now create tables on the fly ...

Patch to do this in D7 as well as an update hook to fix existing systems. tested both use cases and they work.

+++ b/modules/dblog/dblog.install
@@ -155,5 +155,14 @@ function dblog_update_7002() {
+  if (db_table_exists('watchdog')) {

I think you mean if (!db_table_exists('watchdog')) {

weird... i dono how that didn't show up in the patch but yes you are correct. updated.

Testing the patch in #32 on D7. Once the test comes back please put this back to D8.

I see a lot of talk in the thread of the technical ins and outs but not why this is happening.

This can happen on D7 sites when you install a profile other then standard which doesn't have dblog enabled by default. You then go to enable dblog at a later point in time, and it's trying to write messages to a table that hasn't been created yet by the schema because of system level invocations of hook_watchdog during module enabling :). So the enabling of the module itself seems to kill the creation because the hook fires, notices this new module its currently enabling, and flakes out when the schema goes to get processed with (as the thread suggests) no fallback / current trap to ensure the table was made.

Moving back to 8.0.x and needs work. #32 passes.

Lets check first if watchdog table is not maybe already created in D8 on the fly by now ...

I think we kinda deprecated hook_schema() so chances are high and we can directly get the patch for D7 in. Just need to port the tests then (which should be pretty compatible those tests being 3 years old ... ).

What's the test against? The original ones from the patch of several years ago about tables not found not bricking the entire execution or test coverage for the existence of the watchdog table when dblog is turned on? I think the current patch with the update hook is more so fixing an issue w/ core that during install dblog needs to ensure the table is there before it tries to write to it; something possible when other modules / drupal is already installed after initial profile installation step. The current patch doesn't add any more functions so not sure what to provide coverage to.

#1784548-14: DB Log is missing watchdog table after enabling - Need to catch and ignore exceptions thrown in dblog_watchdog() / #14 has probably the best test to use. My other things were a little complicated ;).

lol yeah ok that's what I was hoping ;) Merged that patch to the end of the previous one that passed. bumping to 7 for testbost

stupid, wrong dir; rerolled and appended. lets try this one.

+++ b/modules/dblog/dblog.module
@@ -158,6 +159,12 @@ function dblog_watchdog(array $log_entry) {
+    // Exception is ignored so that watchdog does not break

Rather than ignoring this exception outright couldn't we check if MAINTENANCE_MODE == "install"? If so, ignore the exception, otherwise log the error.

If this exception is occurring at other times besides during site installation than my suggestion is invalid, but in that case we should clarify the comment to include what those other situations might be

How can we log the error though if the watchdog table is missing and dblog, implementing hook_watchdog will try and write the message to the table?

DOH!! of course... I was so focused on the comment, I forget what we were testing for. Ignore me

I'm just running into this error on D7.42 after disabling and uninstalling:

• Database Logging (dblog)
• DBLog Pager
• Statistics Blocks
• Page Not Found Reports
• Tiny-IDS

When I reload the Modules page, enable Database Logging and submit I get a nasty error:

PDOException: SQLSTATE[XXXXX]: Base table or view not found: XXXX Table 'XXXXXXX.watchdog' doesn't exist: INSERT INTO {watchdog} (uid, type, message, variables, severity, link, location, referer, hostname, timestamp) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8, :db_insert_placeholder_9); Array ( [:db_insert_placeholder_0] => 1 [:db_insert_placeholder_1] => ctools [:db_insert_placeholder_2] => Plugin @plugin of plugin type @owner:@type points to nonexistent file @file for class handler @class. [:db_insert_placeholder_3] => a:5:{s:7:"@plugin";s:8:"views_ui";s:6:"@owner";s:6:"ctools";s:5:"@type";s:9:"export_ui";s:5:"@file";s:74:"sites/all/modules/views/plugins/export_ui/views_docket_export_ui.class.php";s:6:"@class";s:7:"handler";} [:db_insert_placeholder_4] => 5 [:db_insert_placeholder_5] => [:db_insert_placeholder_6] => XXXXXXXXXXXXX/admin/modules/list/confirm [:db_insert_placeholder_7] => XXXXXXXXXXXXXXXX/admin/modules [:db_insert_placeholder_8] => XXXXXXXXXXXXXX [:db_insert_placeholder_9] => XXXXXXXXXXX ) in dblog_watchdog() (line 163 of /.../modules/dblog/dblog.module).

And again, when I reloaded the Modules page and only Database Logging seems to have installed, or partially, I get this error when trying to disable it:

PDOException: SQLSTATE[42S02]: Base table or view not found: 1146 Table 'XXXXXXXX.watchdog' doesn't exist: INSERT INTO {watchdog} (uid, type, message, variables, severity, link, location, referer, hostname, timestamp) VALUES (:db_insert_placeholder_0, :db_insert_placeholder_1, :db_insert_placeholder_2, :db_insert_placeholder_3, :db_insert_placeholder_4, :db_insert_placeholder_5, :db_insert_placeholder_6, :db_insert_placeholder_7, :db_insert_placeholder_8, :db_insert_placeholder_9); Array ( [:db_insert_placeholder_0] => 1 [:db_insert_placeholder_1] => system [:db_insert_placeholder_2] => %module module disabled. [:db_insert_placeholder_3] => a:1:{s:7:"%module";s:5:"dblog";} [:db_insert_placeholder_4] => 6 [:db_insert_placeholder_5] => [:db_insert_placeholder_6] => XXXXXXXXXXXX/admin/modules/list/confirm [:db_insert_placeholder_7] => XXXXXXXXXXXX/admin/modules [:db_insert_placeholder_8] => XXXXXXXXXXX [:db_insert_placeholder_9] => XXXXXXXXXXXX ) in dblog_watchdog() (line 163 of /.../modules/dblog/dblog.module).

So, disabling and uninstalling the dblog module deletes the watchdog table from the db, but re-enabling it doesn't create the watchdog table...or it fails/errors before it's created. Not cool. I can't imagine how this has gone unfixed for an entire version cycle.

The patch "drupal-dblog-watchdog-table-not-created-install-429188-32.patch" fixed the problem.

#429188: Watchdog table not installed when watchdog module enabled.
https://www.drupal.org/node/429188#comment-10832628
Comment #36

Could there be a race condition between dblog_schema() being executed & the table created and the rest of the site trying to log messages via watchdog() because the dblog hooks become available?

Would it be worthwhile to update the test to confirm the install-disable-uninstall-install workflow works as intended?

I am also receiving this error when re-enabling Database logging on my Drupal Site (7.41 based off Acquia Drupal 7.x.1.47)

This is a reroll of the patch from #1784548-42: DB Log is missing watchdog table after enabling - Need to catch and ignore exceptions thrown in dblog_watchdog(). The issue is definitely caused by a race condition between hook_watchdog() being called on dblog, and the schema being installed.

For the next patch, "are catched" should be "are caught".

I would RTBC this and get Stefan or David to commit this, but we still need to check if Drupal 8 is affected unfortunately.

Edit:

I just checked and D8 already eats Exceptions, then tries to log again using a dedicated DB backend, but in the end ignores DB exceptions, so this should be good to go.

Assigning to stefan for hopefully a commit.

To be fixed on commit:

1. +++ b/modules/dblog/dblog.install
   @@ -155,5 +155,14 @@ function dblog_update_7002() {
   + * Account for possible legacy systems where dblog was not installed
   
   +++ b/modules/dblog/dblog.test
   @@ -521,6 +521,33 @@ class DBLogTestCase extends DrupalWebTestCase {
   +    // to simulate it missing during installation
   ...
   +    // This should not throw an Exception, but fail silently
   

   Missing dots.

2. +++ b/modules/dblog/dblog.module
   @@ -147,20 +147,27 @@ function dblog_watchdog(array $log_entry) {
   +    // Exception is ignored so that watchdog does not break
   +    // pages during the installation process or is not able
   +    // to create the watchdog table during installation.
   
   +++ b/modules/dblog/dblog.test
   @@ -521,6 +521,33 @@ class DBLogTestCase extends DrupalWebTestCase {
   +    // Remove watchdog table temporarily
   

   Need reflowing to 80 chars.

3. +++ b/modules/dblog/dblog.test
   @@ -521,6 +521,33 @@ class DBLogTestCase extends DrupalWebTestCase {
   +   * Verifies that exceptions are catched in dblog_watchdog().
   

   caught

with #54 corrections

Committed and pushed to 7.x, thanks!

And removed the trailing whitespace on lines 72/73 :)

I just stumbled upon this during an update: I was wondering whether it is wise to silently eat up the exception and the log entry. If the watchdog table is accidentally lost, it could take some time to realize that and precious log data may be lost meanwhile. Couldn't we fall back to calling error_log() in the catch block to address that?