Closed josenavas closed 7 years ago
The current failure is because in the new DB, the password for test user is "test" (as @sjanssen2 requested) while in the current DB the password is "password".
@sjanssen2 can you get this PR in your machine and run all the tests, checking if all of them pass with the new DB? If they do, I think it is safe to merge https://github.com/biocore/american-gut-web/pull/645 and re-shoot the tests in here.
I am running them now...
......................................................................F............................F............................................................F......E
======================================================================
ERROR: Failure: SMTPAuthenticationError ((535, '5.7.8 Username and Password not accepted. Learn more at\n5.7.8 https://support.google.com/mail/?p=BadCredentials b195sm2346297pfb.106 - gsmtp'))
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/nose/loader.py", line 418, in loadTestsFromName
addr.filename, addr.module)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/nose/importer.py", line 47, in importFromPath
return self.importFromDir(dir_path, fqname)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/nose/importer.py", line 94, in importFromDir
mod = load_module(part_fqname, fh, filename, desc)
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/testMail.py", line 7, in <module>
send_email(body_message, subject, 'bherickson@ucsd.edu', html=True)
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/lib/mail.py", line 77, in send_email
s.login(config.smtp_user, config.smtp_password)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/smtplib.py", line 622, in login
raise SMTPAuthenticationError(code, resp)
SMTPAuthenticationError: (535, '5.7.8 Username and Password not accepted. Learn more at\n5.7.8 https://support.google.com/mail/?p=BadCredentials b195sm2346297pfb.106 - gsmtp')
======================================================================
FAIL: test_post (knimin.tests.test_ag_add_barcode_kit.AgAddBarcodeKitHandler)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/test_ag_add_barcode_kit.py", line 36, in test_post
'num_barcodes': 1})
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/tornado_test_base.py", line 46, in post
return self.fetch(url, method='POST', body=data, headers=headers)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 330, in fetch
return self.wait()
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 269, in wait
self.__rethrow()
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 205, in __rethrow
raise_exc_info(failure)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 253, in timeout_func
timeout)
AssertionError: Async operation timed out after 45.0 seconds
-------------------- >> begin captured logging << --------------------
tornado.general: WARNING: tornado.autoreload started more than once in the same process
tornado.access: INFO: 200 POST /ag_add_barcode_kit/ (127.0.0.1) 81072.74ms
--------------------- >> end captured logging << ---------------------
======================================================================
FAIL: test_get (knimin.tests.test_ag_pulldown.testUpdateEBIStatusHandler)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/test_ag_pulldown.py", line 27, in test_get
response = self.get('/update_ebi/')
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/tornado_test_base.py", line 41, in get
return self.fetch(url, method='GET', headers=headers)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 330, in fetch
return self.wait()
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 269, in wait
self.__rethrow()
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 205, in __rethrow
raise_exc_info(failure)
File "/home/sjanssen/anaconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 253, in timeout_func
timeout)
AssertionError: Async operation timed out after 45.0 seconds
-------------------- >> begin captured logging << --------------------
tornado.general: WARNING: tornado.autoreload started more than once in the same process
tornado.access: INFO: 200 GET /update_ebi/ (127.0.0.1) 48737.06ms
--------------------- >> end captured logging << ---------------------
======================================================================
FAIL: test_post (knimin.tests.test_edit_barcode.TestEditBarcodeHandler)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/test_edit_barcode.py", line 58, in test_post
self.assertIn('Barcode was updated successfully', response.body)
AssertionError: 'Barcode was updated successfully' not found in '\n<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">\n<html xmlns="http://www.w3.org/1999/xhtml">\n<head>\n<title>wwwadmin</title>\n<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1" />\n<script src="/static/vendor/js/jquery-1.9.1.js"></script>\n<script src="/static/vendor/js/jquery-ui-1.10.1.custom.min.js"></script>\n<script src="/static/vendor/js/chosen.jquery.min.js"></script>\n<script src="/static/vendor/js/util.js"></script>\n<script type="text/javascript" src="/static/js/labmin.js"></script>\n<link rel="stylesheet" type="text/css" href="/static/vendor/css/ui-lightness/jquery-ui-1.10.1.custom.min.css">\n<link rel="stylesheet" type="text/css" href="/static/vendor/css/chosen.min.css">\n<link rel="stylesheet" href="/static/css/qiime.css" type="text/css">\n<style>body, html {width:100%; height:100%; background-image: url(/static/img/background3.jpg); background-repeat:no-repeat; background-size:cover;}</style>\n\n\n</head>\n<body>\n<div class="menu">\n<h3>American Gut Utilities</h3>\n<ul class="mainmenu">\n\n\n<li><a href="/ag_search/">Search</a></li>\n\n<li><a href="/ag_stats/">Statistics</a></li>\n<li><a href="/projects/summary/">Projects Summary</a></li>\n\n<li><a href="/ag_new_barcode/">Add/View Barcodes</a></li>\n\n\n<li><a href="/ag_new_kit/">Add New AG kits</a></li>\n<li><a href="/ag_add_barcode_kit/">Add Barcodes to AG Kits</a></li>\n\n\n<li><a href="/ag_third_party/add/">Add External Survey</a></li>\n<li><a href="/ag_third_party/data/">Add External Survey Data</a></li>\n\n\n<li><a href="/ag_pulldown/">Metadata Pulldown</a></li>\n\n\n<li><a href="/ag_participant_names/">Participant Names</a></li>\n\n</ul>\n<h3>General Project Utilities</h3>\n<ul class="mainmenu">\n\n<li><a href="/barcode_util/">Scan Barcode</a></li>\n\n</ul>\n\n<h3>Admin Utilities</h3>\n<ul class="mainmenu">\n<li><a href="/admin/edit/">Edit user groups</a></li>\n</ul>\n\n<a href="/auth/logout/">Log Out</a>\n</div>\n<div class="content">\n\n<h3>Edit AG Barcode</h3>\n\nError Updating Barcode Info\n\n\n</div>\n</body>\n</html>\n'
-------------------- >> begin captured logging << --------------------
tornado.general: WARNING: tornado.autoreload started more than once in the same process
tornado.access: INFO: 200 POST /ag_edit_barcode/ (127.0.0.1) 51.15ms
--------------------- >> end captured logging << ---------------------
Name Stmts Miss Branch BrPart Cover
-------------------------------------------------------------------------------
knimin/handlers/access_control.py 27 2 4 0 94%
knimin/handlers/access_decorators.py 29 0 8 0 100%
knimin/handlers/ag_add_barcode_kit.py 14 0 2 0 100%
knimin/handlers/ag_consent_check.py 11 0 2 0 100%
knimin/handlers/ag_edit_barcode.py 32 0 4 0 100%
knimin/handlers/ag_edit_participant.py 25 0 4 1 97%
knimin/handlers/ag_get_participant_names.py 25 0 2 0 100%
knimin/handlers/ag_new_barcode.py 63 0 10 0 100%
knimin/handlers/ag_new_kit.py 45 0 6 0 100%
knimin/handlers/ag_pulldown.py 61 0 16 0 100%
knimin/handlers/ag_results_ready.py 17 2 4 0 90%
knimin/handlers/ag_search.py 39 0 8 0 100%
knimin/handlers/ag_stats.py 11 0 4 0 100%
knimin/handlers/ag_third_party.py 63 2 14 1 96%
knimin/handlers/ag_update_geocode.py 14 0 0 0 100%
knimin/handlers/auth_handlers.py 32 3 8 1 90%
knimin/handlers/barcode_util.py 155 5 58 4 96%
knimin/handlers/base.py 22 1 4 2 88%
knimin/handlers/logged_in_index.py 9 0 2 0 100%
knimin/handlers/projects_summary.py 10 0 2 0 100%
knimin/lib/code128.py 68 7 32 6 87%
knimin/lib/configuration.py 44 0 6 0 100%
knimin/lib/constants.py 12 0 0 0 100%
knimin/lib/data_access.py 914 32 298 34 94%
knimin/lib/geocoder.py 64 1 34 2 97%
knimin/lib/mail.py 31 7 8 2 72%
knimin/lib/mem_zip.py 22 2 2 0 92%
knimin/lib/squash_barcodes.py 64 0 16 0 100%
knimin/lib/string_converter.py 36 0 10 0 100%
knimin/lib/util.py 174 4 98 3 97%
knimin/webserver.py 45 7 0 0 84%
-------------------------------------------------------------------------------
TOTAL 2178 75 666 56 95%
----------------------------------------------------------------------
Ran 168 tests in 173.786s
FAILED (errors=1, failures=3)
@sjanssen2 do you have some extra files in your environment? the first error is coming from labadmin/testMail.py
which is a file that doesn't exist on the repository. For the rest, let's meet after the meetings today and work together to make them pass.
My current error log (after merging amgut-web) looks like this, i.e. there is only the timeout problem left:
======================================================================
FAIL: test_post (knimin.tests.test_ag_add_barcode_kit.AgAddBarcodeKitHandler)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/test_ag_add_barcode_kit.py", line 36, in test_post
'num_barcodes': 1})
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/tornado_test_base.py", line 46, in post
return self.fetch(url, method='POST', body=data, headers=headers)
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 330, in fetch
return self.wait()
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 269, in wait
self.__rethrow()
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 205, in __rethrow
raise_exc_info(failure)
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 253, in timeout_func
timeout)
AssertionError: Async operation timed out after 60.0 seconds
-------------------- >> begin captured logging << --------------------
tornado.general: WARNING: tornado.autoreload started more than once in the same process
tornado.access: INFO: 200 POST /ag_add_barcode_kit/ (127.0.0.1) 77581.61ms
--------------------- >> end captured logging << ---------------------
======================================================================
FAIL: test_get (knimin.tests.test_ag_pulldown.testUpdateEBIStatusHandler)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/test_ag_pulldown.py", line 27, in test_get
response = self.get('/update_ebi/')
File "/media/barnacle/home/sjanssen/AmericanGut/labadmin/knimin/tests/tornado_test_base.py", line 41, in get
return self.fetch(url, method='GET', headers=headers)
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 330, in fetch
return self.wait()
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 269, in wait
self.__rethrow()
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 205, in __rethrow
raise_exc_info(failure)
File "/home/sjanssen/miniconda3/envs/amgut/lib/python2.7/site-packages/tornado/testing.py", line 253, in timeout_func
timeout)
AssertionError: Async operation timed out after 60.0 seconds
-------------------- >> begin captured logging << --------------------
tornado.general: WARNING: tornado.autoreload started more than once in the same process
tornado.access: INFO: 200 GET /update_ebi/ (127.0.0.1) 70430.67ms
--------------------- >> end captured logging << ---------------------
Name Stmts Miss Branch BrPart Cover
-------------------------------------------------------------------------------
knimin/handlers/access_control.py 27 2 4 0 94%
knimin/handlers/access_decorators.py 29 0 8 0 100%
knimin/handlers/ag_add_barcode_kit.py 14 0 2 0 100%
knimin/handlers/ag_consent_check.py 11 0 2 0 100%
knimin/handlers/ag_edit_barcode.py 32 0 4 0 100%
knimin/handlers/ag_edit_participant.py 25 0 4 1 97%
knimin/handlers/ag_get_participant_names.py 25 0 2 0 100%
knimin/handlers/ag_new_barcode.py 63 0 10 0 100%
knimin/handlers/ag_new_kit.py 45 0 6 0 100%
knimin/handlers/ag_pulldown.py 61 0 16 0 100%
knimin/handlers/ag_results_ready.py 17 2 4 0 90%
knimin/handlers/ag_search.py 39 0 8 0 100%
knimin/handlers/ag_stats.py 11 0 4 0 100%
knimin/handlers/ag_third_party.py 63 2 14 1 96%
knimin/handlers/ag_update_geocode.py 14 0 0 0 100%
knimin/handlers/auth_handlers.py 32 3 8 1 90%
knimin/handlers/barcode_util.py 155 5 58 4 96%
knimin/handlers/base.py 22 1 4 2 88%
knimin/handlers/logged_in_index.py 9 0 2 0 100%
knimin/handlers/projects_summary.py 10 0 2 0 100%
knimin/lib/code128.py 68 7 32 6 87%
knimin/lib/configuration.py 44 0 6 0 100%
knimin/lib/constants.py 12 0 0 0 100%
knimin/lib/data_access.py 914 32 298 34 94%
knimin/lib/geocoder.py 64 1 34 2 97%
knimin/lib/mail.py 31 3 8 2 87%
knimin/lib/mem_zip.py 22 2 2 0 92%
knimin/lib/squash_barcodes.py 64 0 16 0 100%
knimin/lib/string_converter.py 36 0 10 0 100%
knimin/lib/util.py 174 4 98 3 97%
knimin/webserver.py 45 7 0 0 84%
-------------------------------------------------------------------------------
TOTAL 2178 71 666 56 95%
----------------------------------------------------------------------
Ran 160 tests in 260.772s
FAILED (failures=2)
@sjanssen2 The timeout issue should be fixed. Apparently, doing LIMIT through SQL is expensive, so I modified the function to perform the limit on python.
That is hilarious. I thought the existence of LIMIT is to reduce query time :-) I would have never thought in that direction. Wow!
That suggests there is an underlying issue that is not understood. LIMIT
stops the cursor, and vastly reduces the cost:
mcdonadt=# create table testing (foo int);
CREATE TABLE
^
mcdonadt=# insert into testing (foo) (select floor(random() * 1000) as i from generate_series(0, 1000));
INSERT 0 1001
mcdonadt=# explain select * from testing;
Seq Scan on testing (cost=0.00..15.01 rows=1001 width=4)
mcdonadt=# explain select * from testing limit 5;
Limit (cost=0.00..0.07 rows=5 width=4)
-> Seq Scan on testing (cost=0.00..15.01 rows=1001 width=4)
mcdonadt=# explain select * from testing limit 50;
Limit (cost=0.00..0.75 rows=50 width=4)
-> Seq Scan on testing (cost=0.00..15.01 rows=1001 width=4)
mcdonadt=# explain select * from testing limit 500;
Limit (cost=0.00..7.50 rows=500 width=4)
-> Seq Scan on testing (cost=0.00..15.01 rows=1001 width=4)
I'm with @wasade, could it be that 'sql += " LIMIT %s"' is %s vs. %d?
@wasade I'm not sure what your output is showing. Empirically, having the LIMIT in the SQL made the call become really slow, not sure why, but I don't think my current solution is a deal breaker.
@antgonza when calling psycopg2 you always need to use %s, i.e. it is not normal python string formatiing.
@josenavas my output is showing that LIMIT reduces the query cost linearly w.r.t. the number of rows in the table. Have you taken the query in question and executed it directly against postgres to see how LIMIT impacts the query execution plan?
sorry @wasade I was looking in the wrong place in your output. I took the query and run it on SQL directly. On sql doesn't seem that slow. My guess is that it is something happening inside the psycopg2 library, since I can't find anything in our specific code. I run explain on the queries and this is the output that I get:
ag_test=# explain SELECT DISTINCT barcode FROM barcodes.barcode LEFT JOIN barcodes.project_barcode pb USING (barcode) WHERE pb.barcode IS NULL ORDER BY barcode ASC;
QUERY PLAN
--------------------------------------------------------------------------------------------------
Unique (cost=7334.28..7363.23 rows=5791 width=10)
-> Sort (cost=7334.28..7348.75 rows=5791 width=10)
Sort Key: barcode.barcode
-> Hash Anti Join (cost=2985.95..6972.35 rows=5791 width=10)
Hash Cond: ((barcode.barcode)::bpchar = pb.barcode)
-> Seq Scan on barcode (cost=0.00..1400.73 rows=70973 width=10)
-> Hash (cost=1448.42..1448.42 rows=88442 width=10)
-> Seq Scan on project_barcode pb (cost=0.00..1448.42 rows=88442 width=10)
(8 rows)
ag_test=# explain SELECT DISTINCT barcode FROM barcodes.barcode LEFT JOIN barcodes.project_barcode pb USING (barcode) WHERE pb.barcode IS NULL ORDER BY barcode ASC LIMIT 10;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Limit (cost=7169.88..7169.91 rows=10 width=10)
-> Sort (cost=7169.88..7184.36 rows=5791 width=10)
Sort Key: barcode.barcode
-> HashAggregate (cost=6986.83..7044.74 rows=5791 width=10)
-> Hash Anti Join (cost=2985.95..6972.35 rows=5791 width=10)
Hash Cond: ((barcode.barcode)::bpchar = pb.barcode)
-> Seq Scan on barcode (cost=0.00..1400.73 rows=70973 width=10)
-> Hash (cost=1448.42..1448.42 rows=88442 width=10)
-> Seq Scan on project_barcode pb (cost=0.00..1448.42 rows=88442 width=10)
(9 rows)
The difference that I can see is that when adding the LIMIT, postgres executes an extra HashAggregate (cost=6986.83..7044.74 rows=5791 width=10)
that is not present in the non-limited query.
Think this will solve the issue: http://stackoverflow.com/a/21386282
Ok, this is getting weirder and weirder hahaha
The ascii problem is due to a difference in the libraries used when running the tests. In an internal file of tornado (tornado.httputil) there is a call to parse_qs_bytes
. When calling the tests using python, this function is coming from <code object parse_qs at 0x10c3238b0, file "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/urlparse.py", line 364>
. However, when calling it using nosetests, this function is coming from <code object parse_qs at 0x10b3e6130, file "/Users/jose/.virtualenvs/labadmin/lib/python2.7/site-packages/future/backports/urllib/parse.py", line 540>
. That is what is making the tests fail when running with nose but not when running with python. Note that the tests are failing also on travis so I need to deal with this issue.
@wasade @antgonza @ElDeveloper @sjanssen2 do you have any idea? is the last issue that I'm dealing with.
Aaaand found a potential solution.
I've upgraded my system to use the latest tornado (4.4.2) and the issue went away, so I'm guessing it was a bug actually in how tornado was doing the decoding.
I'm going to run all the tests with the latest version of tornado. If they work fine, people see any other potential issue of running with the latest version of tornado, rather than the current 3.1.1 version?
I think it would be great to use a more recent tornado version. However, I think we should make sure that we use the same version for american-gut-web and labadmin.
On 03/28/2017 11:58 AM, Jose Navas wrote:
Aaaand found a potential solution.
I've upgraded my system to use the latest tornado (4.4.2) and the issue went away, so I'm guessing it was a bug actually in how tornado was doing the decoding.
I'm going to run all the tests with the latest version of tornado. If they work fine, people see any other potential issue of running with the latest version of tornado, rather than the current 3.1.1 version?
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/biocore/labadmin/pull/183#issuecomment-289870426, or mute the thread https://github.com/notifications/unsubscribe-auth/ALaBKAJTHbXxRQjhqZ1NBgNwGdOGlFS9ks5rqVhQgaJpZM4Mo5EA.
@sjanssen2 can you check if there is any problem on running tornado 4.2.2 on american-gut-web? There is a couple of tests that are failing here with the latest version of tornado but I'm going to fix them now. BTW, which version of tornado did you had installed on your machine when running labadmin?
@josenavas regarding tornado 4.4.2 for american-gut-web: nosetests pass on my Linux machine. Browsing the webpages also seems to work fine. Travis passes as well.
Hey @wasade @antgonza @josenavas I have only approx 10 working hours left to find the bug in the metadata pulldown and fix it, such that we can meet @EmbrietteH deadline to deliver to your pot. collaborator. Could you please prioritize fixing and merging this last PR to labadmin?
Escalating this...
On Mar 29, 2017, at 8:36 AM, Stefan Janssen notifications@github.com<mailto:notifications@github.com> wrote:
Hey @wasadehttps://github.com/wasade @antgonzahttps://github.com/antgonza @josenavashttps://github.com/josenavas I have only approx 10 working hours left to find the bug in the metadata pulldown and fix it, such that we can meet @EmbrietteHhttps://github.com/EmbrietteH deadline to deliver to your pot. collaborator. Could you please prioritize fixing and merging this last PR to labadmin?
- You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHubhttps://github.com/biocore/labadmin/pull/183#issuecomment-290129413, or mute the threadhttps://github.com/notifications/unsubscribe-auth/AB69Kb7A_fOzt0pTybZ2LLBEnebL4pyFks5rqnptgaJpZM4Mo5EA.
This is built on top of https://github.com/biocore/labadmin/pull/178 so review/merge that one first.
Fixes #169