Problem/Motivation

I got the following error as I try to save a node when non-English language (Chinese in my case) is enabled. The problem does not exist when English is the default language.
PDOException: 在 dblog_watchdog() (行 157 在 D:\xampp\htdocs\modules\dblog\dblog.module).

When I catch the exception, I found the following issue:
Incorrect string value: '\xE6\x9F' for column 'link' at row 1

The problematic code is:

  Database::getConnection('default', 'default')->insert('watchdog')
    ->fields(array(
      'uid' => $user_uid,
      'type' => substr($log_entry['type'], 0, 64),
      'message' => $log_entry['message'],
      'variables' => serialize($log_entry['variables']),
      'severity' => $log_entry['severity'],
      'link' => substr($log_entry['link'], 0, 255), // <----- problematic
      'location' => $log_entry['request_uri'],
      'referer' => $log_entry['referer'],
      'hostname' => substr($log_entry['ip'], 0, 128),
      'timestamp' => $log_entry['timestamp'],
    ))
    ->execute();

In my case, the link is: 查看

So, substr($log_entry['link'], 0, 255) truncates in the middle of the Chinese characters: 查看.

I tried to reduce the substr length to 200: substr($log_entry['link'], 0, 200), then I don't see the problem.

I don't care about such logs, I'd be happy if it is just caught. But I'm sure there is a nice way to fix it.

To reproduce the issue one can for example store a node with a long URL alias including non-standard characters. You can use some of the Chinese characters above or just this exact URL alias:

åååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååååå

Proposed resolution

See patch.

Remaining tasks

User interface changes

API changes

Beta phase evaluation

Reference: https://www.drupal.org/core/beta-changes
Issue category Bug because PDOExceptions
Prioritized changes The main goal of this issue is to fix a bug and reduce fragility of code. The bug also exists in Drupal 7.
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

sf_wind’s picture

Issue summary: View changes

I want to show the raw link content instead of show the actual link

sf_wind’s picture

Issue summary: View changes

OK, my previous try was not successful

franz’s picture

Version: 7.9 » 7.x-dev

I wonder if you replaced substr() with drupal_substr() would do it, but that doesn't sound right either. Can you provide a way we can reproduce the error?

superspring’s picture

I have reproduced it with the following code.

dblog_watchdog(array(
  'uid' => 5,
  'type' => 'type',
  'message' => 'a message',
  'variables' => array(),
  'severity' => 1,
  'link' => urldecode('/content/xo%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A-lake-isabelle'),
  'request_uri' => 'http://localhost/abc',
  'referer' => 'http://www.google.com',
  'ip' => '255.255.255.255',
  'timestamp' => time(),
));

Attached is my patch which fixes it as described above.

superspring’s picture

Status: Active » Needs review
Berdir’s picture

Version: 7.x-dev » 8.x-dev
Issue tags: +Needs backport to D7

Makes sense, but this needs to be fixed in 8.x first and then backported.

Status: Needs review » Needs work

The last submitted patch, dblog_unicode_bug-1328014-1.patch, failed testing.

superspring’s picture

Status: Needs work » Needs review
FileSize
2.52 KB

Attempt two.

superspring’s picture

A few changes after the review with berdir

superspring’s picture

Version: 8.x-dev » 7.x-dev
FileSize
2.63 KB

This is the D7 backport.

superspring’s picture

Minor bug-fix to the D7 version.

chx’s picture

Version: 7.x-dev » 8.x-dev
Status: Needs review » Needs work
Issue tags: +Needs tests

Thanks for the hard work you are doing! I see you are rolling a lot of patches lately. Great! A few minor issues here:

This indicates a failure in the process. <= what process?
You have both is_null($text) vs and $length === NULL to check for NULL-ity and yet the fastest is isset($length).
This comment here: // Requires Unicode module to ensure strings are handled properly is a) not necessary b) not correct since it's not a module. Just delete it :)

Can we have a test please? Amend existing statistics tests for a quick easy win?

superspring’s picture

Status: Needs work » Needs review
FileSize
6.75 KB

This patch addresses chx's review.

I have added to the dblog test code since this calls it directly.

chx’s picture

Status: Needs review » Reviewed & tested by the community

I can't find anything to complain about (OK, the !isset ?: could be switched to isset?: but meh.)

catch’s picture

Status: Reviewed & tested by the community » Needs review
+  if (!function_exists('drupal_substr')) {
+    require_once DRUPAL_ROOT . '/core/includes/unicode.inc';
+  }

If it's require_once()'d elsewhere, why not just require_once() it here?

superspring’s picture

Hey @catch,

Are you saying that the unicode library should be loaded inside watchdog instead of elsewhere?

Can you clarify your comment please.

franz’s picture

@superspring, I think he meant that you can drop the if(), given the include is already being included in several places like that with a simple require_once().

franz’s picture

Issue summary: View changes

another typo, change 255 to 200.

Status: Needs review » Needs work

The last submitted patch, 11: dblog_unicode_bug-1328014-12.patch, failed testing.

eiriksm’s picture

Reroll with tests only patch.

eiriksm’s picture

Status: Needs work » Needs review

status change

Status: Needs review » Needs work

The last submitted patch, 18: dblog_unicode_bug-1328014-18-TEST-ONLY.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review

yup, as expected.

jhedstrom’s picture

Status: Needs review » Needs work
Issue tags: -Needs tests +Needs reroll

The test no longer applies. Removing the 'needs tests' tag since this has tests now.

eiriksm’s picture

Status: Needs work » Needs review
FileSize
3.74 KB
4.74 KB

Reroll. And a reroll of the test only patch.

Status: Needs review » Needs work

The last submitted patch, 23: dblog_unicode_bug-1328014-23.patch, failed testing.

The last submitted patch, 23: dblog_unicode_bug-1328014-23-TEST-ONLY.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review
FileSize
4.96 KB

Updated patch without the removed drupal_substr function and instead with Unicode::substr. I guess the "test-only" patch from the last post will speak for itself (since a new one would end up identical).

jhedstrom’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs reroll

I added a beta phase evaluation to the issue summary, and cleaned it up a bit.

I think this is back to RTBC.

jhedstrom’s picture

Issue summary: View changes

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 26: dblog_unicode_bug-1328014-26.patch, failed testing.

piyuesh23’s picture

Issue tags: +#drupalgoa2015
piyuesh23’s picture

Status: Needs work » Needs review

Patch applied cleanly. Re-queuing for testing.

eiriksm’s picture

So... Tests still pass. Maybe back to RTBC?

jhedstrom’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community

Back to RTBC.

alexpott’s picture

Status: Reviewed & tested by the community » Needs review
+++ b/core/modules/dblog/src/Logger/DbLog.php
@@ -60,14 +61,14 @@ public function log($level, $message, array $context = array()) {
-        'link' => substr($context['link'], 0, 255),
+        'link' => Unicode::substr($context['link'], 0, 255),

Truncating links seems like a bad idea. Why are we doing this and not changing how dblog stores the field?

eiriksm’s picture

It does seem like a bad idea. But I guess that is more of a change than is going on here, though? This issue was created because dblog was trying to truncate to match the length of the db field, but was not successful at it. So the patch is for being successful at truncating and storing messages.

Should we open another issue about storing longer links? In which case this issue would be completely solved by that one :)

jhedstrom’s picture

The link field type in core specifies storage length of 2048 (we might still need to truncate though to avoid errors when logging errors on really long url pages). Perhaps the fix for 8.0 can simply be to update the watchdog table to match? The fix for 7.x would still need to update the truncation approach.

eiriksm’s picture

Hm, I could have sworn I pressed save and uploaded those files?

Trying again...

- Changed the dblog link field to be 2048
- Changed the truncating to match.

Status: Needs review » Needs work

The last submitted patch, 40: dblog_unicode_bug-1328014-40-test-only.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review

As expected :)

jhedstrom’s picture

Status: Needs review » Reviewed & tested by the community

Thanks @eiriksm! I think this has addressed @alexpott's concern from ##3. Back to RTBC.

alexpott’s picture

Status: Reviewed & tested by the community » Needs work

git commit -m 'Issue #1888592 by orb, dzhu: Non latin characters in url, PDOException: dblog_watchdog() in line 155'

+++ b/core/modules/dblog/dblog.install
@@ -53,7 +53,7 @@ function dblog_schema() {
       'link' => array(
         'type' => 'varchar',
-        'length' => 255,
+        'length' => 2048,
         'not null' => FALSE,

+++ b/core/modules/dblog/src/Logger/DbLog.php
@@ -61,14 +62,14 @@ public function log($level, $message, array $context = array()) {
-        'link' => substr($context['link'], 0, 255),
+        'link' => Unicode::substr($context['link'], 0, 2048),

Actually let's make this a text field like the other url columns (referer and location) in this table. And completely remove the necessity to truncate.

alexpott’s picture

Discussed this with @xjm wrt to https://www.drupal.org/node/159605 and have concluded that changing the field type is fine as it is not used in any indexes so this will work on portgres and sqlite.

alexpott’s picture

Priority: Normal » Major

Given the number of duplicates I've found of this issue - its a major.

eiriksm’s picture

Status: Needs work » Needs review
FileSize
5.5 KB
1.22 KB

Sure let's try this one.

Too bad you beat me to posting comment #46, so the file names are wrong ;)

Berdir’s picture

This will also need to be backported, where I think we don't want to change the schema just for this? So the 7.x will probably be different...

Status: Needs review » Needs work

The last submitted patch, 47: dblog_unicode_bug-1328014-46.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review
FileSize
5.54 KB

Ah, sorry about that.

I forgot to take out the default value. Now done

phillamb168’s picture

Status: Needs review » Needs work
Issue tags: +Needs reroll, +Needs steps to reproduce, +Triaged at DrupalCon Los Angeles 2015

Triaging this with @cilefen.

Issue summary is up-to-date and clear.

Simulated the issue using direct calls to the logging API, but need steps to reproduce.

Spoke with alexpott & wimleers, this is definitely a Major issue. Scope is limited to content that may be saved with non-Latin character sets in the path.

Duplicates were noted in the comments but a quick search yielded no results

A Beta Evaluation had already been done and seems correct.

A patch is available but does not apply; needs a re-roll.

eiriksm’s picture

Issue summary: View changes

Updated the IS with steps to reproduce through clicking and typing (not only programatically).

eiriksm’s picture

Ah, you beat me to it.

I was about to upload the files when I got the error message that someone had "changed the Files field".

So I downloaded your patch and it is identical to the file I was going to upload. So more "reviewed" and "tested" than that it can hardly become I think. :)

I'll leave the status so someone else can look at it as well (and so the testbot can finish).

eiriksm’s picture

Ah sorry. The files got included anyway. Oh well, they are identical at least (and it includes another test-only patch).

Status: Needs review » Needs work

The last submitted patch, 54: pdoexception_when-1328014-53-test-only.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review

...test only failed as expected.

jhedstrom’s picture

Status: Needs review » Reviewed & tested by the community

I think this is at RTBC based on #51.

  • catch committed 0028658 on 8.0.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...
catch’s picture

Version: 8.0.x-dev » 7.x-dev
Status: Reviewed & tested by the community » Patch (to be ported)
Issue tags: +D8 upgrade path

Committed/pushed to 8.0.x, thanks!

Moving to 7.x for backport. This also needs a head2head issue (although uninstalling then re-installing dblog would cover it really).

xjm’s picture

(Saving proposed issue credit for discussion and triage participants at LA. We missed them from the 8.0.x commit message unfortunately for this issue, but we can ensure they get credit stored on d.o.)

eiriksm’s picture

eiriksm’s picture

Status: Patch (to be ported) » Needs review

Sorry. Forgot to put it to needs review.

The last submitted patch, 62: pdoexception_when-1328014-62.patch, failed testing.

Status: Needs review » Needs work

The last submitted patch, 62: pdoexception_when-1328014-62-test-only.patch, failed testing.

eiriksm’s picture

Status: Needs work » Needs review
FileSize
4.81 KB

OK, so here is a patch that is a little less "disruptive". Keeping in mind that @Berdir in #48 mentioned we should probably not change the schema in d7.

At least the test-only patch proved the point :)

Status: Needs review » Needs work

The last submitted patch, 66: pdoexception_when-1328014-66.patch, failed testing.

eiriksm’s picture

Hm. Probably should have read the actual error messages for the failures.

Here is one that should pass. The only thing left to decide is if we want to alter the schema or not? (this patch does not alter the schema).

eiriksm’s picture

Status: Needs work » Needs review
cilefen’s picture

Status: Needs review » Needs work
Issue tags: +Needs reroll
cilefen’s picture

Status: Needs work » Needs review
Issue tags: -Needs reroll

I was wrong.

DuaelFr’s picture

Issue tags: +HappyDays1506
eugene.ilyin’s picture

Status: Needs review » Reviewed & tested by the community

Patch #68 solves my problem. Please commit it.

  • catch committed 0028658 on 8.1.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...
David_Rothstein’s picture

Status: Reviewed & tested by the community » Fixed

Committed to 7.x - thanks!

Pretty sure we could change the database schema in Drupal 7 if we thought it would be helpful to (I seem to recall making an exactly analogous varchar=>text change to some other database table not so long ago). However the patch here certainly seems sufficient to fix the bug.

  • David_Rothstein committed d77ba6e on 7.x
    Issue #1328014 by eiriksm, superspring, jhedstrom, alexpott, franz, chx...

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.

cilefen’s picture

csc4’s picture

New install Drupal 7.44 which appears to have this patch in it
PDOException: in dblog_watchdog() (line 163 when creating new node
believe issue may be 8bit quote character instead of straight apostrophe in node title?

csc4’s picture

Component: watchdog.module » ajax system
Status: Closed (fixed) » Active
David_Rothstein’s picture

@csc4 can you create a new issue with details and link to it here?

  • catch committed 0028658 on 8.3.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...

  • catch committed 0028658 on 8.3.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...

  • catch committed 0028658 on 8.4.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...

  • catch committed 0028658 on 8.4.x
    Issue #1328014 by eiriksm, superspring: PDOException when saving a node...
Eric_A’s picture

Component: ajax system » dblog.module
Status: Active » Fixed

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.