Problem/Motivation

When running Drupal on MySQL or Maria DB you can run in several errors that corrupt the database connection. Some examples for these kind of errors on the database layer are

  • 1100 - Table 'xyz' was not locked with LOCK TABLES
  • 1153 – Got a packet bigger than ‘max_allowed_packet’ bytes
  • ...

If such an error happens, the MySQL server invalidates the connection and answers all further request through this connection by 2006 - MySQL server had gone away.
Just have a look at https://www.google.com/search?q=site%3Adrupal.org+2006+MySQL+server+had+... to see that the drupal project is affected by that.

Again, 2006 - MySQL server had gone away is not the error that causes an issue, it's the symptom you face after a different error happened. The causal error might be software bug in core or a contributed module or an inappropriate setup of the environment (for example the MySQL setup).

Normally you'll find details about the causal error in the logs. But if you use dblog, which is the most common in shared hosting environments, you won't find anything in the log because the log entry is not written due to the already invalidated connection.

If you also turned off error reporting on the site, all you get is a WSOD.

Proposed resolution

The solution to this problem is easy. The 2006 - MySQL server had gone away error causes an Exception while wrinting to the log. If such an exception occurs we can simply open a second connection to the database and write the log entry again.

If you read through the comments, you'll notice that @Damien Tournoud already agreed on the proposed solution throughout the years for the different drupal versions:

Good idea, let's see how we can implement that in the new database layer.

Still applies to 8.x, which uses the default connection for watchdog messages.

Remaining tasks

Review and commit the existing patch.

User interface changes

None.

API changes

None.

The original issue description as posted for Drupal 6

If you read through different drupal bug reports you often see a quote like
Table 'watchdog' was not locked with LOCK TABLES

This could happen if you're using MySQL and a module requests a table lock and run into an error afterwards. In this case drupal is unable to store the error because it could not access the watchdog table.

I attached a patch that opens a dedicated database connection to write watchdog entries like I already proposed in these bug reports:
#298678: Impossible to lock two MySQL tables
#195812: db_error() doesn't work on default connection

Here are some issues related to this bug report:
#286176: Views causing error "Table 'watchdog' was not locked with LOCK TABLES'
#286380: Got past mem problem only to hit a timeout problem
#174705: Modify node type configuration storage to use a serialized collection stored in one variable rather than long variable names
#99718: user warning: Duplicate entry - work around available

Beta phase evaluation

Reference: https://www.drupal.org/core/beta-changes
Issue category Bug because we don't display the right error and we display errors on the site while nothing is in the log
Issue priority Major because ... Critical/Not critical because ...
Prioritized changes The main goal of this issue is a bug fix in the database error reporting.
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

mkalkbrenner’s picture

Drupal 7 seems to have the same Problem.

mkalkbrenner’s picture

Title: Ensure that enties are written to watchdog table » Ensure that entries are written to watchdog table
Damien Tournoud’s picture

Version: 6.x-dev » 7.x-dev

Good idea, let's see how we can implement that in the new database layer.

mkalkbrenner’s picture

But don't forget the "backport" to drupal 6 and drupal 5 using my patch please.

Anonymous’s picture

Status: Needs review » Needs work

The last submitted patch failed testing.

dpearcefl’s picture

This issue will not go anywhere without confirmation that this issue still exists in current Drupal 7.x and without a patch against a current version.

mkalkbrenner’s picture

It was Damien who moved the issue forward to D7 three years ago. My patch was for D5 / D6.

I don't have time to create a patch for D7 at the moment or to confirm, that the issue still exists in D7.
But it definitely exists in D6 which is still supported!

dpearcefl’s picture

What version of D6 still has this issue?

BTW: Your last patch failed. Without a valid patch this issue won't go anywhere.

mkalkbrenner’s picture

Version: 7.x-dev » 6.x-dev

My patch from 3 years ago could still be applied against 6.22 and 6.x-dev:

mkalkbrenner-laptop:drupal-6.22 mkalkbrenner$ patch -p0 < ~/dedicated_watchdog_connection.patch 
patching file includes/database.inc
Hunk #1 succeeded at 129 (offset -1 lines).
Hunk #2 succeeded at 156 (offset -1 lines).
patching file modules/dblog/dblog.module
Hunk #1 succeeded at 129 with fuzz 2 (offset 2 lines).
dpearcefl’s picture

Please attached your patch and mark this ticket as "needs review". The automated patch review system will tell you if the patch is acceptable.

mkalkbrenner’s picture

Component: watchdog.module » dblog.module
Status: Needs work » Needs review
FileSize
1.83 KB
dpearcefl’s picture

If this is against Drupal 6.22 (which it should be), the version needs to be changed on the issue.

mkalkbrenner’s picture

Version: 6.x-dev » 6.22

It's against 6.22 and of course 6.x-dev

dpearcefl’s picture

Your patch has been "ignored". Try changing the version to 6.x-dev and resubmitting the patch.

mkalkbrenner’s picture

Version: 6.22 » 6.x-dev
FileSize
1.83 KB
Damien Tournoud’s picture

Version: 6.x-dev » 8.x-dev

Still applies to 8.x, which uses the default connection for watchdog messages.

dpearcefl’s picture

Version: 8.x-dev » 6.x-dev

Let's not confuse the system. If this patch is needed and applied cleanly to 8.x-dev, lets open a new issue in that queue.

hefox’s picture

Version: 6.x-dev » 8.x-dev

Patches go into the highest version of drupal they are applicable to first, tmk, which would be 8.x-dev. This is the appropriate issue for it.

kscheirer’s picture

kscheirer’s picture

Retesting against latest HEAD since it has been over a year.

Status: Needs review » Needs work

The last submitted patch, dedicated_watchdog_connection-298768.patch, failed testing.

mkalkbrenner’s picture

Issue summary: View changes
Status: Needs work » Needs review
FileSize
2.12 KB

Here's a initial patch for drupal 8.

mkalkbrenner’s picture

FileSize
2.26 KB

And here's an alternative patch that does "lazy opening" of the dedicated connection.

The last submitted patch, 22: 298768_22.patch, failed testing.

Status: Needs review » Needs work

The last submitted patch, 23: 298768_23.patch, failed testing.

mkalkbrenner’s picture

Status: Needs work » Needs review
FileSize
2.27 KB
mkalkbrenner’s picture

FileSize
1.79 KB

OK, before I upload an improved patch, here's a test only patch that should fail.

mkalkbrenner’s picture

FileSize
5.44 KB

And here's the real patch including the test.

mkalkbrenner’s picture

FileSize
415 bytes
5.44 KB

fixed white spaces in #28

The last submitted patch, 27: 298768_failing_test.patch, failed testing.

mkalkbrenner’s picture

Status: Needs review » Needs work

The last submitted patch, 29: 298768_29.patch, failed testing.

Status: Needs work » Needs review

mkalkbrenner queued 29: 298768_29.patch for re-testing.

dawehner’s picture

  1. +++ b/core/modules/dblog/src/Logger/DbLog.php
    @@ -60,21 +66,41 @@ public function log($level, $message, array $context = array()) {
    +        // Open a dedicated connection for logging to ensure that errors that
    +        // messed up the default connection are still logged.
    

    I think it would be great to describe the error in the issue summary. ...

  2. +++ b/core/modules/dblog/src/Tests/ConnectionFailureTest.php
    @@ -0,0 +1,48 @@
    +    // MySQL erros like "1153 – Got a packet bigger than ‘max_allowed_packet’
    +    // bytes" or "1100 - Table 'xyz' was not locked with LOCK TABLES" lead to a
    +    // database connection unusable for further request. All further request
    +    // will result in an "2006 - MySQL server had gone away" error. As a
    +    // consequence it's impossible to use this connection to log the causing
    +    // initial error itself. Using Database::closeConnection() we simulate such
    +    // a corrupted connection. In this case dblog has to establish a different
    +    // connection by itself to be able to write the log entry.
    

    Basically something like this?

The last submitted patch, 27: 298768_failing_test.patch, failed testing.

mkalkbrenner’s picture

Issue summary: View changes
mkalkbrenner’s picture

Issue summary: View changes
mkalkbrenner’s picture

FileSize
1.66 KB
6.19 KB

added verbose comments as requested by @dawehner

mkalkbrenner’s picture

Fabianx’s picture

Status: Needs review » Reviewed & tested by the community
Issue tags: +Needs beta evaluation

RTBC, this looks great how simple after all it is to setup a new DB connection! :)

Issue summary is good, needs a beta evaluation.

--

I wonder if simply doing what you do in the test would not be easier? (closeConnection, openConnection)

Though that would restore DB access for all of Drupal, which could lead to severe errors in itself as it might have been missing out on data, then trying to write it to cache.

So this is fine as is - also while dependency injection is nicer, in this case it is fine to go via the lowest subsystem level possible as in the mean time e.g. the container might be corrupted already, or other things have happened.

I love how dependency-injection overall makes this issue (quite) easy and clean.

Thanks!

stefan.r’s picture

  1. +++ b/core/modules/dblog/src/Logger/DbLog.php
    @@ -60,21 +66,52 @@ public function log($level, $message, array $context = array()) {
    +      // When running Drupal on MySQL or Maria DB you can run in several errors
    

    MariaDB, run into

  2. +++ b/core/modules/dblog/src/Tests/ConnectionFailureTest.php
    @@ -0,0 +1,48 @@
    + * Tests loging of connection failures.
    

    logging

  3. +++ b/core/modules/dblog/src/Tests/ConnectionFailureTest.php
    @@ -0,0 +1,48 @@
    +   * Tests loging of connection failures.
    

    logging

  4. +++ b/core/modules/dblog/src/Tests/ConnectionFailureTest.php
    @@ -0,0 +1,48 @@
    +    // MySQL erros like "1153 – Got a packet bigger than ‘max_allowed_packet’
    

    errors

  5. +++ b/core/modules/dblog/src/Tests/ConnectionFailureTest.php
    @@ -0,0 +1,48 @@
    +    // database connection unusable for further request. All further request
    

    requests

mkalkbrenner’s picture

Status: Reviewed & tested by the community » Needs review
FileSize
1.92 KB
6.2 KB

Just fixed the comments. Thanks @stefan.r.

stefan.r’s picture

Issue summary: View changes
Issue tags: -Needs beta evaluation
FileSize
6.19 KB
1.86 KB

We forgot a second "request" :)

Gave the code a quick look if you think this looks good now, I think this can go back to RTBC.

stefan.r’s picture

FileSize
1.97 KB
6.18 KB

Fixing a 81 character line

mkalkbrenner’s picture

mkalkbrenner’s picture

Status: Needs review » Reviewed & tested by the community

Back to RTBC because we just fixed typos within comments.

hchonov’s picture

I just wanted to test the patch with some real use case and excahged
Database::closeConnection()
with

    try {
      $max_allowed_packet = db_query("SELECT @@global.max_allowed_packet")->fetchField();
      $long_name = str_repeat("a", $max_allowed_packet + 10);

      Database::getConnection('default')
        ->insert('watchdog')
        ->fields(array(
          'uid' => 20,
          'type' => 'test',
          'message' => $long_name,
          'variables' => '',
          'severity' => '',
          'link' => '',
          'location' => '',
          'referer' => '',
          'hostname' => '',
          'timestamp' => 12345,
        ))
        ->execute();
    }
    catch (\Exception $e) {}

My point was to actually break the connection. Now the test fails locally with

exception 'PDOException' with message 'SQLSTATE[HY000]: General error: 2006 MySQL server has gone away' in core/lib/Drupal/Core/Database/Statement.php:61

Next exception 'Drupal\Core\Database\DatabaseExceptionWrapper' with message 'SQLSTATE[HY000]: General error: 2006 MySQL server has gone away: SELECT table_name FROM information_schema.tables WHERE  (table_schema = :db_condition_placeholder_0) AND (table_name LIKE :db_condition_placeholder_1 ESCAPE '\\') ; Array
(
    [:db_condition_placeholder_0] => dev_d8
    [:db_condition_placeholder_1] => simpletest466931%
)
' in core/lib/Drupal/Core/Database/Connection.php:609

Am I missing something or doing the test wrong?

mkalkbrenner’s picture

@hchonov:
if you read through the already referenced follow-up issue #972528: dblog fails to log MAX_ALLOWED_PACKET errors because they're longer than MAX_ALLOWED_PACKET it's obvious what you're missing in your "test".
The large packet breaks the default connection. That immediately causes a log entry that opens a dedicated connection. But this one breaks as well because it logs the large packet.

So, my test is OK and the issue is still RTBC here.

But the follow-up #972528: dblog fails to log MAX_ALLOWED_PACKET errors because they're longer than MAX_ALLOWED_PACKET which targets a MySQL specific problem will turn your "test" green, too.

hchonov’s picture

@mkalkbrenner:
only uncaught exceptions get logged. That is why I do the test in a try catch block, so that the exception does not reach the ExceptionLoggingSubscriber.

mkalkbrenner’s picture

@hchonov:
You're right that my explanation was not 100% correct.

Nevertheless the answer could be found in #972528: dblog fails to log MAX_ALLOWED_PACKET errors because they're longer than MAX_ALLOWED_PACKET in LargeQueryTest:

// Close and re-open the connection. Otherwise we will run into error
// 2006 "MySQL server had gone away" afterwards.
Database::closeConnection();
Database::getConnection();

You leave the test with a corrupted default connection. So my assumption is that the logging using a dedicated connection works but $wid = db_query("SELECT MAX(wid) FROM {watchdog} WHERE message = 'testConnectionFailureLogging'")->fetchField(); leads to error 2006 until you add Database::closeConnection(); .

hchonov’s picture

@mkalkbrenner
you are right. In this case the patch and the test look good to me.
@mkalkbrenner++ very good work!

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 44: 298768_44.patch, failed testing.

stefan.r’s picture

Requeueing as tests failed with copy(/var/lib/drupaltestbot/sites/default/files/checkout/sites/simpletest/996777/settings.php): failed to open stream: No such file or directorycopy('/var/lib/drupaltestbot/sites/default/files/checkout/sites/default/default.settings.php', '/var/lib/drupaltestbot/sites/default/files/checkout/sites/simpletest/996777/settings.php')

Status: Needs work » Needs review

stefan.r queued 44: 298768_44.patch for re-testing.

mkalkbrenner’s picture

Status: Needs review » Reviewed & tested by the community

thanks @stefan.r

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

This change is really going to help people what has gone wrong. Nice work on a nearly 7 year old bug.

I agree that there is no disruption with this change and it is tested. Committed 2c0f5e1 and pushed to 8.0.x. Thanks!

diff --git a/core/modules/dblog/src/Logger/DbLog.php b/core/modules/dblog/src/Logger/DbLog.php
index 69fbdb5..03ecbd8 100644
--- a/core/modules/dblog/src/Logger/DbLog.php
+++ b/core/modules/dblog/src/Logger/DbLog.php
@@ -45,7 +45,7 @@ class DbLog implements LoggerInterface {
   /**
    * Constructs a DbLog object.
    *
-   * @param \Drupal\Core\Database\Connection $database
+   * @param \Drupal\Core\Database\Connection $connection
    *   The database connection object.
    * @param \Drupal\Core\Logger\LogMessageParserInterface $parser
    *   The parser to use when extracting message variables.

Minor fix on commit.

  • alexpott committed 2c0f5e1 on 8.0.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...
mkalkbrenner’s picture

Thanks :-)

Would be nice if someone can do a review on the related issue #972528: dblog fails to log MAX_ALLOWED_PACKET errors because they're longer than MAX_ALLOWED_PACKET now.

David_Rothstein’s picture

Version: 8.0.x-dev » 7.x-dev
Status: Fixed » Patch (to be ported)
Issue tags: +Needs backport to D7

Looks like this issue affects Drupal 7 too? (In fact, was originally filed for Drupal 6 :)

  • alexpott committed 2c0f5e1 on 8.1.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...

  • alexpott committed 2c0f5e1 on 8.3.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...

  • alexpott committed 2c0f5e1 on 8.3.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...
aerozeppelin’s picture

Status: Patch (to be ported) » Needs review
FileSize
2.72 KB

Rerolled patch to D7.

Status: Needs review » Needs work

The last submitted patch, 63: 298768-63.patch, failed testing.

aerozeppelin’s picture

Status: Needs work » Needs review

  • alexpott committed 2c0f5e1 on 8.4.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...

  • alexpott committed 2c0f5e1 on 8.4.x
    Issue #298768 by mkalkbrenner, stefan.r: Ensure that entries are written...
dagmar’s picture

Status: Needs review » Needs work

This is the code that was committed to 8.x http://cgit.drupalcode.org/drupal/commit/?id=2c0f5e1

@aerozeppelin it seems you rerolled a different patch.

kscheirer’s picture

aerozepellin's patch in #63 is for D7, @dagmar are you saying it doesn't accomplish the same thing?