1224931 - log-parser Bugscache.search() "ProgrammingError: (1064, "syntax error, unexpected ')', expecting $end")"

Status: NEW

(Tree Management :: Treeherder, defect, P2)

Description

[Ed Morley [:emorley]]

https://rpm.newrelic.com/accounts/677903/applications/7385291/traced_errors/70b0cd-63d181f0-8bc5-11e5-900f-b82a72d22a14

Traceback (most recent call last):
File "/app/.heroku/python/bin/gunicorn", line 11, in <module>
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/app/wsgiapp.py", line 74, in run
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/app/base.py", line 189, in run
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/app/base.py", line 72, in run
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/arbiter.py", line 181, in run
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/arbiter.py", line 477, in manage_workers
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/arbiter.py", line 540, in spawn_workers
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/arbiter.py", line 507, in spawn_worker
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/base.py", line 124, in init_process
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 119, in run
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 66, in run_for_one
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 30, in accept
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 130, in handle
File "/app/.heroku/python/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 176, in handle_request
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/api/web_transaction.py", line 711, in __iter__
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/api/web_transaction.py", line 1087, in __call__
File "/app/.heroku/python/lib/python2.7/site-packages/whitenoise/base.py", line 119, in __call__
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/api/web_transaction.py", line 1215, in _nr_wsgi_application_wrapper_
File "/app/.heroku/python/lib/python2.7/site-packages/django/core/handlers/wsgi.py", line 189, in __call__
File "/app/.heroku/python/lib/python2.7/site-packages/django/core/handlers/base.py", line 132, in get_response
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/hooks/framework_django.py", line 499, in wrapper
File "/app/.heroku/python/lib/python2.7/site-packages/django/views/decorators/csrf.py", line 58, in wrapped_view
File "/app/.heroku/python/lib/python2.7/site-packages/rest_framework/viewsets.py", line 87, in view
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/hooks/component_djangorestframework.py", line 27, in _nr_wrapper_APIView_dispatch_
File "/app/.heroku/python/lib/python2.7/site-packages/rest_framework/views.py", line 466, in dispatch
File "/app/.heroku/python/lib/python2.7/site-packages/rest_framework/views.py", line 463, in dispatch
File "/app/treeherder/webapp/api/refdata.py", line 85, in list
File "/app/treeherder/model/derived/refdata.py", line 1250, in get_bug_suggestions
File "/app/treeherder/model/derived/refdata.py", line 126, in execute
File "/app/treeherder/model/utils.py", line 66, in retry_execute
File "/app/.heroku/python/lib/python2.7/site-packages/datasource/bases/RDBSHub.py", line 37, in wrapper
File "/app/.heroku/python/lib/python2.7/site-packages/datasource/bases/SQLHub.py", line 136, in execute
File "/app/.heroku/python/lib/python2.7/site-packages/datasource/bases/SQLHub.py", line 300, in __execute
File "/app/.heroku/python/lib/python2.7/site-packages/datasource/bases/SQLHub.py", line 317, in __cursor_execute
File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.54.0.41/newrelic/hooks/database_dbapi2.py", line 22, in execute
File "/app/.heroku/python/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
File "/app/.heroku/python/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
 _mysql_exceptions:ProgrammingError: (1064, "syntax error, unexpected '-'") 

From a request to /api/bugscache/

Papertrail on Heroku (this is also occurring on stage/prod, just easier to search logs on Heroku):

 Nov 15 18:37:10 treeherder heroku/router: at=info method=GET path="/api/bugscache/?search=%28try+%22hg+help+--keyword+share%22%29" host=treeherder-heroku.herokuapp.com request_id=3be31734-a955-4d4c-ac78-f59b66dcbb21 fwd="107.22.7.229" dyno=web.1 connect=6ms service=105ms status=500 bytes=467 

https://papertrailapp.com/systems/treeherder/events?r=602618115096096770-602618410035359745

Comment 1

[Ed Morley [:emorley]]

I think this may go away with bug 1280761.

Comment 2

[Ed Morley [:emorley]]

I believe this has morphed into the form seen in bug 1283859, after bug 1280761.

Comment 3

[Ed Morley [:emorley]]

Though I'm also seeing the original form (though obviously not as a web transaction failure now). Un-duping.

https://rpm.newrelic.com/accounts/677903/applications/4180461/traced_errors/4eda72-047fc513-426a-11e6-bd66-b82a72d22a14

repo: try
job_log_id: 32657660
job_log_url: http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-323f805d7c6f60d7825c6b8c8d4a342712050314/try-macosx64-debug/try-macosx64-debug-bm87-try1-build18607.txt.gz

Corresponding to:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=323f805d7c6f60d7825c6b8c8d4a342712050314&selectedJob=23336878

Traceback (most recent call last):
...
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/workers/task.py", line 20, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/workers/taskset.py", line 24, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/tasks.py", line 35, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/tasks.py", line 108, in parse_log
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/utils.py", line 54, in post_log_artifacts
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/utils.py", line 32, in extract_text_log_artifacts
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/error_summary.py", line 205, in get_error_summary_artifacts
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/error_summary.py", line 38, in get_error_summary
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/model/models.py", line 182, in search
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/models/query.py", line 1284, in __iter__
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/models/sql/query.py", line 80, in __iter__
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/models/sql/query.py", line 98, in _execute_query
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/utils.py", line 98, in __exit__
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/django/db/backends/mysql/base.py", line 124, in execute
File "/data/www/treeherder.mozilla.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.mozilla.org/venv/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
File "/data/www/treeherder.mozilla.org/venv/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
django.db.utils:ProgrammingError: (1064, "syntax error, unexpected ')', expecting $end")

Comment 5

[James Graham [:jgraham]]

I am getting a similar error from the log parser with input like:

13:46:09     INFO - TEST-START | /webrtc/RTCPeerConnection-getIdentityAssertion.html
13:46:09     INFO - PID 4236 | ++DOCSHELL 1EC2BC00 == 11 [pid = 2864] [id = {a1acd4fe-3774-4acf-a0bd-dc605dc6ffcc}]
13:46:09     INFO - PID 4236 | ++DOMWINDOW == 32 (1EC2C000) [pid = 2864] [serial = 77] [outer = 00000000]
13:46:09     INFO - PID 4236 | [Parent 4236] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
13:46:09     INFO - PID 4236 | : file z:/build/build/src/dom/base/nsFrameLoader.cpp, line 794
13:46:09     INFO - PID 4236 | ++DOMWINDOW == 33 (1EC2CC00) [pid = 2864] [serial = 78] [outer = 1EC2C000]
13:46:09     INFO - PID 4236 | 1502718369976	Marionette	DEBUG	Register listener.js for window 4294967373
13:46:10     INFO - PID 4236 | ++DOMWINDOW == 34 (1EC30800) [pid = 2864] [serial = 79] [outer = 1EC2C000]
13:46:10     INFO - PID 4236 | [Child 2864] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file z:/build/build/src/media/webrtc/signaling/src/jsep/JsepSessionImpl.cpp, line 752
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03a\xe4\xa4Q\xb6kE\xa1t\xc4F\xf7[\xc5gxyW\xf8b[\xa4\x12\xe6E\x8cv\x18\x95')
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "���a�Q�kE�t�F�[�gxyW�b[��E�v�
13:46:10 CRITICAL - �����+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xf4Q?\x07\x96\x1fn\xd2TS\xdb~\x9aJ1s\xda\x9b\x01\xfb9\x8a\xff\\\xc3\xfe\x02\x1e\xd2\x8a\x04\xcb\x00\x00\x1a\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x01\x00\x01\xb9\x00\x00\x00\x1b\x00\x19\x00\x00\x16www1.web-platform.test\x00\x17\x00\x00\xff\x01\x00\x01\x00\x00')
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "����Q?�n�TS�~�J1sڛ�9��\��
13:46:10 CRITICAL - Ҋ����+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad HTTP/0.9 request type ("\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\x1bQ\xc7\xc8\xfc\xf1K\x88q\x87\x04)\xe0}_:f](\xd4;T'\x93Z")
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "���Q����K�q�)�}_:f](�;T'�Z
13:46:10 CRITICAL - T�?B����+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xd9\x83\xa9\xa8\xdb\xe7;\x97\xcf`r\xdb"\x96\x00z0\xb3\xdb\xd1\xe75\x11c\xa3bm`\x1dauB\x00\x00\x1a\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x01\x00\x01\xb9\x00\x00\x00\x1b\x00\x19\x00\x00\x16www1.web-platform.test\x00\x17\x00\x00\xff\x01\x00\x01\x00\x00')
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "���ك����;��`r�"��z0����5c�bm`
13:46:10 CRITICAL - auB���+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xb5:\x8cgn\x8f\xaeL\xc0\xb3\x00\x80\xfd\xda\x11\xe2\x87\xd4\xf8~\xa2\xadZ\x829\xf1\x9eP\x12\xf8\xbdn\x00\x00\x1a\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x01\x00\x01\xb9\x00\x00\x00\x1b\x00\x19\x00\x00\x16www1.web-platform.test\x00\x17\x00\x00\xff\x01\x00\x01\x00\x00')
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "����:�gn��L���������~��Z�9�P��n���+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request version ("\xf31\xe6'\x9b\xdf\x00\x00\x1a\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x01\x00\x01\xb9\x00\x00\x00\x1b\x00\x19\x00\x00\x16www1.web-platform.test\x00\x17\x00\x00\xff\x01\x00\x01\x00\x00")
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "����}��]
13:46:10 CRITICAL - ���q�O	���+7h���
13:46:10 CRITICAL - �1�'�����+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xc1\xa9\xf6\xec\xf5\x8ea\xc8\xcc\x95\x8bca\xebaWy\xe3\xf6\x12H')
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "���������a�̕�ca�aWy��H
13:46:10 CRITICAL - ���p���9�4���+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request syntax ("\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03Ck\x02\x15x`JS\x7f~%\x8b\xdb^D+\xa1'\xed\x92w\xb7\xbf#\xe2o\x0f\x01\x15\xfat\xa5\x00\x00\x1a\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x01\x00\x01\xb9\x00\x00\x00\x1b\x00\x19\x00\x00\x16www1.web-platform.test\x00\x17\x00\x00\xff\x01\x00\x01\x00\x00")
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] "���Ckx`JS~%��^D+�'�w��#�o�t����+�/̨̩�,�0���/�5��������www1.web-platform.test�������" 400 -
13:46:10 CRITICAL - Test harness output was not a valid structured log message: 
13:46:10 CRITICAL - 127.0.0.1 - - [14/Aug/2017 13:46:10] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03w}\xe4\xf8\x9d\xdd\xbe\xef\x16\xe4\x99\x16\xb4\xcc\x9c\x9eU\x06\xcdD\xd0\xdb\{"thread": "ProcessReader", "process": "4236", "pid": 3432, "source": "web-platform-tests", "command": "Z:\\task_1502716000\\build\\application\\firefox\\firefox.exe -marionette about:blank -profile c:\\users\\genericworker\\appdata\\local\\temp\\tmpep1l4v.mozrunner", "time": 1502718370409, "action": "process_output", "data": "[Child 2864] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file z:/build/build/src/media/webrtc/signaling/src/jsep/JsepSessionImpl.cpp, line 752"}
13:46:10     INFO - ............
13:46:10     INFO - TEST-OK | /webrtc/RTCPeerConnection-getIdentityAssertion.html | took 571ms

(dunno how badly mangled that will get in bugzilla, but it seems like lots of non-UTF8 and control characters resulting from binary-interpreted-as-text).