Error while executing task (phd daemon)
Closed, ResolvedPublic
Actions

Assigned To

None

Authored By

	jsturgeon
	Jul 7 2016, 11:12 PM

Description

I'm getting the following error:

[2016-07-07 16:05:20] EXCEPTION: (PhutilProxyException) Error while executing Task ID 2297057. {>} (AphrontQueryException) #1366: Incorrect string value: '\xF0\x9F\x8E\xAA: ...' for column 'summary' at row 1 at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:355]

in my phd.log

Here's the entire trace:

07-Jul-2016 16:05:20] [2016-07-07 16:05:20] EXCEPTION: (PhutilProxyException) Error while executing Task ID 2297057. {>} (AphrontQueryException) #1366: Incorrect string value: '\xF0\x9F\x8E\xAA: ...' for column 'summary' at row 1 at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:355]
[07-Jul-2016 16:05:20] arcanist(head=stable, ref.master=9c056c5cc887, ref.stable=f1c45a3323ae), phabricator(head=stable, ref.master=b441e8b81e31, ref.stable=58375fa9e6db), phutil(head=stable, ref.master=c72eb747e706, ref.stable=119e5b12ba06)
[07-Jul-2016 16:05:20]   #0 <#2> AphrontBaseMySQLDatabaseConnection::throwQueryCodeException(integer, string) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:289]
[07-Jul-2016 16:05:20]   #1 <#2> AphrontBaseMySQLDatabaseConnection::throwQueryException(mysqli) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:185]
[07-Jul-2016 16:05:20]   #2 <#2> AphrontBaseMySQLDatabaseConnection::executeRawQuery(string) called at [<phutil>/src/xsprintf/queryfx.php:6]
[07-Jul-2016 16:05:20]   #3 <#2> queryfx(AphrontMySQLiDatabaseConnection, string, string, string, string, string)
[07-Jul-2016 16:05:20]   #4 <#2> call_user_func_array(string, array) called at [<phutil>/src/aphront/storage/connection/AphrontDatabaseConnection.php:32]
[07-Jul-2016 16:05:20]   #5 <#2> AphrontDatabaseConnection::query(string, string, string, string, string) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:1157]
[07-Jul-2016 16:05:20]   #6 <#2> LiskDAO::update() called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:1077]
[07-Jul-2016 16:05:20]   #7 <#2> LiskDAO::save() called at [<phabricator>/src/applications/repository/storage/PhabricatorRepositoryCommit.php:210]
[07-Jul-2016 16:05:20]   #8 <#2> PhabricatorRepositoryCommit::save() called at [<phabricator>/src/applications/repository/worker/commitmessageparser/PhabricatorRepositoryCommitMessageParserWorker.php:129]
[07-Jul-2016 16:05:20]   #9 <#2> PhabricatorRepositoryCommitMessageParserWorker::updateCommitData(DiffusionCommitRef) called at [<phabricator>/src/applications/repository/worker/commitmessageparser/PhabricatorRepositoryCommitMessageParserWorker.php:42]
[07-Jul-2016 16:05:20]   #10 <#2> PhabricatorRepositoryCommitMessageParserWorker::parseCommit(PhabricatorRepository, PhabricatorRepositoryCommit) called at [<phabricator>/src/applications/repository/worker/PhabricatorRepositoryCommitParserWorker.php:48]
[07-Jul-2016 16:05:20]   #11 <#2> PhabricatorRepositoryCommitParserWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:122]
[07-Jul-2016 16:05:20]   #12 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:171]
[07-Jul-2016 16:05:20]   #13 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[07-Jul-2016 16:05:20]   #14 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:184]
[07-Jul-2016 16:05:20]   #15 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:127]

Thoughts?

Revisions and Commits

rPHU libphutil
	D16279	rPHUff84abc7d857 If "utf8mb4" is unavailable on the client, fall back to "binary"

Related Objects

Mentioned In: rGITTEST22efd30e6a30: commit 981b687f8cb95c142169f200acce33e52bdb4816
Mentioned Here: rGITTEST22efd30e6a30: commit 981b687f8cb95c142169f200acce33e52bdb4816

Event Timeline

jsturgeon created this task.Jul 7 2016, 11:12 PM

jsturgeon added a subscriber: edibiase.

Follow up question, this task has failed 38022 times.. is there some way I can punt it from our queue?

Your database may not have proper column encodings configured. Run this command to verify them:

phabricator/ $ ./bin/storage adjust

If that's clean (or the problem persists after any corrections it makes) follow these steps:

Visit /daemon/task/2297057/ from the web UI.
You should see information about the task, like this:

Screen Shot 2016-07-08 at 4.24.26 AM.png (1×1 px, 158 KB)

The Data field identifies which commit the task is attempting to parse.
The commit message (which looks like it begins with "🎪") is apparently not valid UTF8. Push a commit with the same message to rGITTEST so we can try to reproduce the issue.

jsturgeon added a project: Daemons.Jul 8 2016, 3:29 PM

Herald added a subscriber: eadler. · View Herald TranscriptJul 8 2016, 3:29 PM

./storage adjust returned no errors. Pushing to the GITTEST repo gave me the following error:

fatal: unable to access 'https://secure.phabricator.com/diffusion/GITTEST/git-test.git/': The requested URL returned error: 403

/sigh, figured that out.. I needed to set a VCS password

commit pushed:
commit 22efd30e6a3069e655ab716725c8cd5e972885dc

jsturgeon mentioned this in rGITTEST22efd30e6a30: commit 981b687f8cb95c142169f200acce33e52bdb4816.Jul 8 2016, 3:50 PM

Seems like that commit imported fine.

We can fix this if you can push a commit here (or to a test Phacility instance, possibly by importing the problem repository) which reproduces the issue, or give us reproduction instructions that allow us to generate a commit which will fail in a similar way.

If you can only reproduce the issue in your environment with a private commit, we can't figure out the problem or resolve it.

Unfortunately, the repo is confidential source, we might be on our own to debug this one. Perhaps there are issues with our database configuration @edibiase might have more info.

You can likely reproduce the issue in a repeatable way with this command:

phabricator/ $ ./bin/repository reparse --message rXabcd --trace

...where rXabcd is the commit monogram, and --trace optionally provides more information about what is executing.

This error is generally consistent with an attempt to insert invalid UTF-8 data into the database. It's possible that --trace, which should show the full query, will reveal the source of the problem.

You could also try running these commands against MySQL:

mysql> set character set utf8mb4;
mysql> INSERT INTO phabricator_harbormaster.harbormaster_object (phid, dateCreated, dateModified, name) VALUES ("circus", 1, 1, "🎪");

If that fails, there may be some previously unidentified issue with how we select collations. Equivalently, you can try writing a comment with the "🎪" character on your install, which should do about the same thing. If either of those fail, some aspect of how we configure MySQL is at fault.

(The harbormaster_object table is just a test table used by unit tests.)

Here are the results of that command:

[phd@phabricator-sc10 bin]$ ./repository reparse --message 981b687f8cb9 --trace
>>> [2] <connect> phabricator_repository
<<< [2] <connect> 2,066 us
>>> [3] <query> SELECT `commit`.* FROM `repository_commit` commit  WHERE (((commit.commitIdentifier LIKE '981b687f8cb9%' AND LENGTH(commit.commitIdentifier) = 40)))   ORDER BY `commit`.`id` DESC
<<< [3] <query> 624 us
>>> [4] <query> SELECT `r`.*, r.* FROM `repository` r  WHERE (r.id IN (2))   ORDER BY `r`.`id` DESC
<<< [4] <query> 403 us
>>> [5] <query> SELECT `commit`.* FROM `repository_commit` commit  WHERE (commit.id IN (303478))   ORDER BY `commit`.`id` DESC
<<< [5] <query> 452 us
>>> [6] <query> SELECT `r`.*, r.* FROM `repository` r  WHERE (r.id IN (2))   ORDER BY `r`.`id` DESC
<<< [6] <query> 366 us
>>> [7] <conduit> diffusion.querycommits()
>>> [8] <query> SELECT `r`.*, r.* FROM `repository` r  WHERE (r.phid IN ('PHID-REPO-3p2nkuxizgwvohnvyqhd'))   ORDER BY `r`.`id` DESC
<<< [8] <query> 789 us
>>> [9] <query> SELECT `commit`.* FROM `repository_commit` commit  WHERE (commit.phid IN ('PHID-CMIT-7aq4ro5kwkz73a6czu3d')) AND (commit.repositoryID IN (2))   ORDER BY `commit`.`id` DESC LIMIT 101
<<< [9] <query> 467 us
>>> [10] <query> SELECT `r`.*, r.* FROM `repository` r  WHERE (r.id IN (2))   ORDER BY `r`.`id` DESC
<<< [10] <query> 351 us
>>> [11] <query> SELECT * FROM `repository_commitdata` WHERE commitID in (303478)
<<< [11] <query> 328 us
>>> [12] <exec> $ git log -n 1 --encoding='UTF-8' --format='%e%x00%cn%x00%ce%x00%an%x00%ae%x00%T%x00%at%x00%s%n%n%b' '981b687f8cb95c142169f200acce33e52bdb4816' --
<<< [12] <exec> 67,097 us
<<< [7] <conduit> 79,470 us
>>> [13] <query> SELECT * FROM `repository_commitdata` WHERE commitID = 303478
<<< [13] <query> 524 us
>>> [14] <connect> phabricator_user
<<< [14] <connect> 841 us
>>> [15] <query> SELECT * FROM `user` WHERE userName = '<redacted>'
<<< [15] <query> 358 us
>>> [16] <query> SELECT * FROM `user_email` WHERE address = '<redacted>'
<<< [16] <query> 292 us
>>> [17] <query> SELECT * FROM `user` WHERE realName = ''<redacted>'
<<< [17] <query> 366 us
>>> [18] <query> SELECT * FROM `user_email` WHERE address = ''<redacted>'
<<< [18] <query> 329 us
>>> [19] <query> SELECT * FROM `user` WHERE phid = 'PHID-USER-fnnjd4kcawvdd3edb5qc'
<<< [19] <query> 318 us
>>> [20] <event> diffusion.lookupUser <listeners = 1>
<<< [20] <event> 140 us
>>> [21] <query> SELECT * FROM `user` WHERE userName = '<redacted>'
<<< [21] <query> 305 us
>>> [22] <query> SELECT * FROM `user_email` WHERE address = '<redacted>'
<<< [22] <query> 270 us
>>> [23] <query> SELECT * FROM `user` WHERE realName = ''<redacted>'
<<< [23] <query> 331 us
>>> [24] <query> SELECT * FROM `user_email` WHERE address = '<redacted>'
<<< [24] <query> 303 us
>>> [25] <query> SELECT * FROM `user` WHERE phid = 'PHID-USER-fnnjd4kcawvdd3edb5qc'
<<< [25] <query> 310 us
>>> [26] <event> diffusion.lookupUser <listeners = 1>
<<< [26] <event> 131 us
>>> [27] <query> SELECT * FROM `user` WHERE phid = 'PHID-USER-fnnjd4kcawvdd3edb5qc'
<<< [27] <query> 301 us
>>> [28] <conduit> differential.parsecommitmessage()
>>> [29] <connect> phabricator_auth
<<< [29] <connect> 1,194 us
>>> [30] <query> SELECT * FROM `auth_providerconfig`  ORDER BY `id` DESC
<<< [30] <query> 442 us
<<< [28] <conduit> 14,868 us
>>> [31] <connect> phabricator_differential
<<< [31] <connect> 907 us
>>> [32] <query> (SELECT `r`.* FROM `differential_revision` r JOIN `differential_revisionhash` hash_rel ON hash_rel.revisionID = r.id WHERE (((hash_rel.type = 'gtcm' AND hash_rel.hash = '981b687f8cb95c142169f200acce33e52bdb4816') OR (hash_rel.type = 'gttr' AND hash_rel.hash = '6bf200fae25c2b06f987ad391ac726cbe4597b09')))   ORDER BY `r`.`dateModified` DESC, `r`.`id` DESC )
<<< [32] <query> 1,060 us
>>> [33] <connect> phabricator_repository
<<< [33] <connect> 791 us
>>> [34] <query> UPDATE `repository_commit` SET `repositoryID` = '2', `phid` = 'PHID-CMIT-7aq4ro5kwkz73a6czu3d', `commitIdentifier` = '981b687f8cb95c142169f200acce33e52bdb4816', `epoch` = '1461794258', `mailKey` = 'ggjvky44vjhzexszx5vp', `authorPHID` = 'PHID-USER-fnnjd4kcawvdd3edb5qc', `auditStatus` = '0', `summary` = '<rdar://problem/xxxx> 🎪: description redacted', `id` = '303478' WHERE `id` = '303478'
<<< [34] <query> 589 us
[2016-07-08 09:27:13] EXCEPTION: (AphrontQueryException) #1366: Incorrect string value: '\xF0\x9F\x8E\xAA: ...' for column 'summary' at row 1 at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:355]
arcanist(head=stable, ref.master=9c056c5cc887, ref.stable=f1c45a3323ae), phabricator(head=stable, ref.master=b441e8b81e31, ref.stable=58375fa9e6db), phutil(head=stable, ref.master=c72eb747e706, ref.stable=119e5b12ba06)
  #0 AphrontBaseMySQLDatabaseConnection::throwQueryCodeException(integer, string) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:289]
  #1 AphrontBaseMySQLDatabaseConnection::throwQueryException(mysqli) called at [<phutil>/src/aphront/storage/connection/mysql/AphrontBaseMySQLDatabaseConnection.php:185]
  #2 AphrontBaseMySQLDatabaseConnection::executeRawQuery(string) called at [<phutil>/src/xsprintf/queryfx.php:6]
  #3 queryfx(AphrontMySQLiDatabaseConnection, string, string, string, string, string)
  #4 call_user_func_array(string, array) called at [<phutil>/src/aphront/storage/connection/AphrontDatabaseConnection.php:32]
  #5 AphrontDatabaseConnection::query(string, string, string, string, string) called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:1157]
  #6 LiskDAO::update() called at [<phabricator>/src/infrastructure/storage/lisk/LiskDAO.php:1077]
  #7 LiskDAO::save() called at [<phabricator>/src/applications/repository/storage/PhabricatorRepositoryCommit.php:210]
  #8 PhabricatorRepositoryCommit::save() called at [<phabricator>/src/applications/repository/worker/commitmessageparser/PhabricatorRepositoryCommitMessageParserWorker.php:129]
  #9 PhabricatorRepositoryCommitMessageParserWorker::updateCommitData(DiffusionCommitRef) called at [<phabricator>/src/applications/repository/worker/commitmessageparser/PhabricatorRepositoryCommitMessageParserWorker.php:42]
  #10 PhabricatorRepositoryCommitMessageParserWorker::parseCommit(PhabricatorRepository, PhabricatorRepositoryCommit) called at [<phabricator>/src/applications/repository/worker/PhabricatorRepositoryCommitParserWorker.php:48]
  #11 PhabricatorRepositoryCommitParserWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:122]
  #12 PhabricatorWorker::executeTask() called at [<phabricator>/src/applications/repository/management/PhabricatorRepositoryManagementReparseWorkflow.php:325]
  #13 PhabricatorRepositoryManagementReparseWorkflow::execute(PhutilArgumentParser) called at [<phutil>/src/parser/argument/PhutilArgumentParser.php:410]
  #14 PhutilArgumentParser::parseWorkflowsFull(array) called at [<phutil>/src/parser/argument/PhutilArgumentParser.php:303]
  #15 PhutilArgumentParser::parseWorkflows(array) called at [<phabricator>/scripts/repository/manage_repositories.php:22]

Whatever string this is:

'rdar://problem/xxxx 🎪: description redacted'

...is causing the issue, but since the whole thing is redacted and 🎪 works fine here there's not much more I can do from our end.

it's definitely the 🎪 that's causing the issue, not the redacted bit. I think it's an issue with our DB, but ./storage status thinks it's fine.

We're seeing an identical issue on our install. What version of MySQL are you using? Maybe we can work together and figure out how to get Emoji to work!

In T11291#185026, @eadler wrote:

We're seeing an identical issue on our install. What version of MySQL are you using? Maybe we can work together and figure out how to get Emoji to work!

$mysql --version
mysql  Ver 14.14 Distrib 5.6.31, for Linux (x86_64)

I'm thinking the problem with our DB can be fixed by this:
https://mathiasbynens.be/notes/mysql-utf8mb4

I don't have root on our mysql db atm, but I hope to soon.

chad awarded a token.Jul 8 2016, 9:54 PM

@eadler, I was just able to resolve this on our installation by installing the php56w-mysqlnd package instead of php56w-mysql, which is what we had installed before.

I can't say I had a particularly scientific way of figuring this out. I added a line to AphrontMySQLiDatabaseConnection.php to exit if it couldn't set the charset to utf8mb4, and, indeed, it couldn't, failing with:

Can't initialize character set utf8mb4 (path: /usr/share/mysql/charsets/)

Some Googling found this Stack Overflow article, which suggested that using mysqlnd would fix the issue, and, lo and behold, it did!

I hope that helps you get your installation Emojified, as well! 💫

impressive

It's possible that we're in the wrong by falling back to set character set utf8;.

For anyone who can reproduce this, does this fail?

mysql> set character set utf8mb4;

If you make this change to libphutil, do things work?

diff --git a/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php b/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
index 7371863..40a2c6c 100644
--- a/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
+++ b/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
@@ -91,7 +91,7 @@ final class AphrontMySQLDatabaseConnection
 
     $ok = @mysql_set_charset('utf8mb4', $conn);
     if (!$ok) {
-      mysql_set_charset('utf8', $conn);
+      mysql_set_charset('binary', $conn);
     }
 
     return $conn;
diff --git a/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php b/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
index f3c5d88..240dff4 100644
--- a/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
+++ b/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
@@ -74,7 +74,7 @@ final class AphrontMySQLiDatabaseConnection
 
     $ok = @$conn->set_charset('utf8mb4');
     if (!$ok) {
-      $ok = $conn->set_charset('utf8');
+      $ok = $conn->set_charset('binary');
     }
 
     return $conn;

(I made about six typos in the original version of that comment, so reload if you're following the steps from email.)

I think it would be better not to fallback at all and raise a setup warning. We'll likely have other issues in the future for not using the native driver.

In T11291#185175, @epriestley wrote:
It's possible that we're in the wrong by falling back to set character set utf8;.

For anyone who can reproduce this, does this fail?
mysql> set character set utf8mb4;

This appears to succeed on our installation:

mysql> set character set utf8mb4;
Query OK, 0 rows affected (0.00 sec)

If you make this change to libphutil, do things work?

diff --git a/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php b/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
index 7371863..40a2c6c 100644
--- a/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
+++ b/src/aphront/storage/connection/mysql/AphrontMySQLDatabaseConnection.php
@@ -91,7 +91,7 @@ final class AphrontMySQLDatabaseConnection
 
     $ok = @mysql_set_charset('utf8mb4', $conn);
     if (!$ok) {
-      mysql_set_charset('utf8', $conn);
+      mysql_set_charset('binary', $conn);
     }
 
     return $conn;
diff --git a/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php b/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
index f3c5d88..240dff4 100644
--- a/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
+++ b/src/aphront/storage/connection/mysql/AphrontMySQLiDatabaseConnection.php
@@ -74,7 +74,7 @@ final class AphrontMySQLiDatabaseConnection
 
     $ok = @$conn->set_charset('utf8mb4');
     if (!$ok) {
-      $ok = $conn->set_charset('utf8');
+      $ok = $conn->set_charset('binary');
     }
 
     return $conn;

After I temporarily replaced php56w-mysqlnd with php56w-mysql and applied your patch,

./bin/repository reparse --message 981b687f8cb9 --trace

ran without error, and I confirmed (by querying MySQL) that its updates to repository_commit and repository_commitdata contained the "🎪" character.

(As a sanity check, I also verified that the reparse failed as expected after swapping the drivers but before applying your patch.)

Alright, that's promising at least. Thanks for testing!

There should be no advantage to using the utf8 charset over binary when utf8mb4 is unavailable: we verify strings are valid UTF8 during query construction anyway. It's possible that there are additional subtleties here, but nothing leaps out at me.

In particular, I suspect the most common case of this is old client + old server (prior to MySQL ~5.5, which introduced utf8mb4). In these environments, bin/storage adjust converts the columns to binary anyway because no UTF8 type can store "🎪" or other 4-byte characters. If there were problems lurking with binary, I would expect to have seen them with installs using older MySQL.

epriestley added a revision: D16279: If "utf8mb4" is unavailable on the client, fall back to "binary".Jul 12 2016, 3:03 PM

epriestley closed this task as Resolved by committing rPHUff84abc7d857: If "utf8mb4" is unavailable on the client, fall back to "binary".Jul 12 2016, 11:29 PM

epriestley added a commit: rPHUff84abc7d857: If "utf8mb4" is unavailable on the client, fall back to "binary".

(Presuming that fixed things until we see evidence otherwise.)

	F1716184: Screen Shot 2016-07-08 at 4.24.26 AM.png
	Jul 8 2016, 11:29 AM

Error while executing task (phd daemon)Closed, ResolvedPublicActions

Description

Revisions and Commits

Related Objects

Event Timeline

Error while executing task (phd daemon)
Closed, ResolvedPublic
Actions