1283859 - log-parser Bugscache.search() "ProgrammingError: (1064, 'syntax error, unexpected FTS_TEXT, expecting FTS_NUMB')"

Status: RESOLVED FIXED

(Tree Management :: Treeherder: Data Ingestion, defect, P2)

Description

[Ed Morley [:emorley]]

Googling the error finds:
http://serverfault.com/questions/531886/mysql-syntax-error-unexpected

...which mentions:
"syntax error, unexpected '-'"

...so this is presumably just the morphed signature of bug 1224931.

https://rpm.newrelic.com/accounts/677903/applications/5585473/traced_errors/556195-b0dc83b3-3f77-11e6-bd66-b82a72d22a14

project: try
job_guid: 70559775-0281-4204-a10f-26682b050f4c/0
job_log_id: 16837569
job_log_url: https://queue.taskcluster.net/v1/task/cFWXdQKBQgShDyZoKwUPTA/runs/0/artifacts/public%2Flogs%2Flive_backing.log

Traceback (most recent call last):
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/celery.py", line 81, in main
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/celery.py", line 793, in execute_from_commandline
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/base.py", line 311, in execute_from_commandline
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/celery.py", line 785, in handle_argv
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/celery.py", line 717, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/worker.py", line 179, in run_from_argv
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/base.py", line 274, in __call__
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bin/worker.py", line 212, in run
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/worker/__init__.py", line 206, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bootsteps.py", line 374, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/worker/consumer.py", line 279, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/worker/consumer.py", line 838, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/worker/loops.py", line 76, in asynloop
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/kombu/async/hub.py", line 340, in create_loop
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/concurrency/asynpool.py", line 420, in _event_process_exit
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 1260, in maintain_pool
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 1252, in _maintain_pool
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 1237, in _repopulate_pool
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/concurrency/asynpool.py", line 415, in _create_worker_process
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 1068, in _create_worker_process
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/process.py", line 137, in start
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/forking.py", line 105, in __init__
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/process.py", line 292, in _bootstrap
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 295, in run
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/billiard/pool.py", line 367, in workloop
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/app/trace.py", line 349, in _fast_trace_task
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/newrelic-2.66.0.49/newrelic/hooks/application_celery.py", line 66, in wrapper
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/celery/app/trace.py", line 438, in __protected_call__
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/workers/task.py", line 20, in inner
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/workers/taskset.py", line 24, in inner
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/log_parser/tasks.py", line 35, in inner
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/log_parser/tasks.py", line 108, in parse_log
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/log_parser/utils.py", line 55, in post_log_artifacts
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/log_parser/utils.py", line 33, in extract_text_log_artifacts
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/model/error_summary.py", line 205, in get_error_summary_artifacts
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/model/error_summary.py", line 38, in get_error_summary
File "/data/www/treeherder.allizom.org/treeherder-service/treeherder/model/models.py", line 180, in search
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/models/query.py", line 1284, in __iter__
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/models/sql/query.py", line 80, in __iter__
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/models/sql/query.py", line 98, in _execute_query
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/utils.py", line 98, in __exit__
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/django/db/backends/mysql/base.py", line 124, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/newrelic-2.66.0.49/newrelic/hooks/database_dbapi2.py", line 22, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
File "/data/www/treeherder.allizom.org/venv/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
 django.db.utils:ProgrammingError: (1064, 'syntax error, unexpected FTS_TEXT, expecting FTS_NUMB')

Comment 3

[William Lachance (:wlach)]

FYI the duplicate in bug 1305982 has this line:

"[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url=https://queue.taskcluster.net/v1/task/Qs1_DYVKQASBhy0o_Uo4jA/artifacts/public/build/target.dmg --test-packages-url=https://queue.taskcluster.net/v1/task/Qs1_DYVKQASBhy0o_Uo4jA/artifacts/public/build/target.test_packages.json --mochitest-suite=plain-gpu,chrome-gpu,browser-chrome-gpu --allow-software-gl-layers --total-chunk=1 --this-chunk=1 --download-symbols=ondemand] \" failed to run:  exit status 2"

Running that through a python interpreter in:

>>> from treeherder.model.models import Bugscache
>>> from treeherder.model.error_summary import get_error_search_term
>>> line = "[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url=https://queue.taskcluster.net/v1/task/Qs1_DYVKQASBhy0o_Uo4jA/artifacts/public/build/target.dmg --test-packages-url=https://queue.taskcluster.net/v1/task/Qs1_DYVKQASBhy0o_Uo4jA/artifacts/public/build/target.test_packages.json --mochitest-suite=plain-gpu,chrome-gpu,browser-chrome-gpu --allow-software-gl-layers --total-chunk=1 --this-chunk=1 --download-symbols=ondemand] \" failed to run:  exit status 2"
>>> get_error_search_term(line)
'[taskcluster:error]  Command " [./test-macosx.sh --no-read-buildbot-config --installer-url=https://q'
>>> Bugscache.search(get_error_search_term(line))
Traceback (most recent call last):
  File "<console>", line 1, in <module>
  File "/home/vagrant/treeherder/treeherder/model/models.py", line 180, in search
    return {"open_recent": [model_to_dict(item, exclude=["modified"]) for item in recent],
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/models/query.py", line 1284, in __iter__
    query = iter(self.query)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/models/sql/query.py", line 80, in __iter__
    self._execute_query()
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/models/sql/query.py", line 98, in _execute_query
    self.cursor.execute(self.sql, self.params)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/backends/utils.py", line 79, in execute
    return super(CursorDebugWrapper, self).execute(sql, params)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/utils.py", line 98, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
    return self.cursor.execute(sql, params)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/django/db/backends/mysql/base.py", line 124, in execute
    return self.cursor.execute(query, args)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
    self.errorhandler(self, exc, value)
  File "/home/vagrant/venv/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
ProgrammingError: (1064, "syntax error, unexpected '-'")

I think we need to quote what we're passing into Bugscache.search() a bit better.

Comment 4

[William Lachance (:wlach)]

Here's the actual problematic query:

SELECT id, summary, crash_signature, keywords, os, resolution, status,\n            MATCH (`summary`) AGAINST ('\"[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url=https://q\"' IN BOOLEAN MODE) AS relevance\n            FROM bugscache\n            WHERE 1\n              AND resolution = ''\n              AND `summary` LIKE CONCAT ('%%', '[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url==https://q', '%%') ESCAPE '='\n              AND modified >= '2016-07-01 12:05:26.216269'\n            ORDER BY relevance DESC\n            LIMIT 0,50;

It appears that the main thing causing issues is the \" sequence after "[taskcluster:error]  Command". Take that out and it executes fine. Leave it in and I get:

mysql> SELECT id, summary, crash_signature, keywords, os, resolution, status,\n            MATCH (`summary`) AGAINST ('\"[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url=https://q\"' IN BOOLEAN MODE) AS relevance\n            FROM bugscache\n            WHERE 1\n              AND resolution = ''\n              AND `summary` LIKE CONCAT ('%%', '[taskcluster:error]  Command \" [./test-macosx.sh --no-read-buildbot-config --installer-url==https://q', '%%') ESCAPE '='\n              AND modified >= '2016-07-01 12:05:26.216269'\n            ORDER BY relevance DESC\n            LIMIT 0,50;
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
PAGER set to stdout
ERROR 1064 (42000): syntax error, unexpected '-'

It's actually Django that's generating the query for us, with quoting, so the bug might be there... but I think first we need to know why this is breaking, as I think it should be fine. Pythian, can you give us any guidance here?

Comment 5

[Pythian Team73]

Hi,

Created https://secure.pythian.com/track/cr/1094949 and I am working on it.

Marcelo
[e-mail]

Comment 6

[Pythian Team73]

HI,

I did research on this and did some tests. Trying to escape the dash. But the problem resides on dash being a special meaning character in a BOLLEAN mode full text search.
Read here: http://dev.mysql.com/doc/refman/5.6/en/fulltext-boolean.html
http://dev.mysql.com/doc/refman/5.6/en/fulltext-search.html

The dash need to be escaped somehow and I am tesing and looking into it.

Marcelo
[e-mail]

Comment 7

[Pythian Team73]

Hi,

Considering the way this works, testing is needed, I suggest you 4 options.
Suppose that you need to escape the following word: --no-read-buildbot-config

A) "--no-read-buildbot-config" : enclosure the whole word in quote
B) "--"no"-"read"-"buildbot"-"config : enclosure all the dashes with quote
C) \"--no-read-buildbot-config\" : enclosure the whole word with \"
D) \"--\"no\"-\"read\"-\"buildbot\"-\"config : enclosure all the dashes with \"

I did some tests and Option A or C may fit better for you, but testing will be needed.
Let me know if any further research and test is needed.

Comment 9

[Pythian Team73]

Hi,

I kindly ask if there is any more tests or work you want us to do with the Full Text Search and InnoDB.

Marcelo
[e-mail]

Comment 10

[GitHub Autolander Bot]

Attachment: [treeherder] mozilla:bugscache_match > mozilla:master

Comment 11

[Ed Morley [:emorley]]

Comment on attachment 8799803 [details] [review]
[treeherder] mozilla:bugscache_match > mozilla:master

Thank you for fixing this! :-)

Comment 12

[Ed Morley [:emorley]]

(In reply to Pythian Team73 from comment #9)
> I kindly ask if there is any more tests or work you want us to do with the
> Full Text Search and InnoDB.
> 
> Marcelo
> [e-mail]

I think we're done now - thank you :-)

Comment 13

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/32029361c838245e6498cefb184ea7e314d61b4d
Bug 1283859 - Fix quoting of MATCH ... AGAINST in bugscache search (#1914)

It appears that the intent of this code is to to a phrase match of the
search string against the bug summary for relevance matching. However
the code incorrectly tried to quote the string and as a result failed
to handle special characters in the AGAINST clause (e.g. + - ~ >
etc.). This change simply removes any existing quote characters from
the string and places the entire thing in quotes. Per the MySQL
documentations:

 > A phrase that is enclosed within double quote (") characters
   matches only rows that contain the phrase literally, as it was
   typed

Comment 14

[Phil Ringnalda (:philor)]

Could be any number of layers of bustage, but I'm still not seeing a suggestion of bug 1300413 for the " command timed out: 1800 seconds without output running ['/tools/buildbot/bin/python', '-u', 'scripts/scripts/desktop_unittest.py', '--cfg', 'unittests/mac_unittest.py', '--mochitest-suite', 'browser-chrome-chunked', '--total-chunks', '7', '--this-chunk', '5', '--blob-upload-branch', 'autoland', '--download-symbols', 'true'], attempting to kill
process killed by signal 9" line in https://treeherder.allizom.org/#/jobs?repo=autoland&revision=6d67a819cff05013f27677d48528ce3492f429be&selectedJob=4818988